|
From: Nicholas S. <nic...@cs...> - 2003-12-23 11:45:22
|
Hi,
I sent this to the users' list a little while ago, but it might be better
answered by a valgrind developer.
I've been trying to get a valgrind skin i'm tinkering with to get a
program to report whenever it calls or returns from a function. However,
I'm getting some really wierd data. This is the instrumentation:
UCodeBlock* SK_(instrument)(UCodeBlock* cb, Addr a){
UCodeBlock *newCb;
Int i;
UInstr* u;
newCb=VG_(setup_UCodeBlock)(cb);
if (VG_(get_fnname_if_entry)(a, name, 100)){
if (VG_(get_filename_linenum)(a, file, 100,&line)){
VG_(call_helper_0_0)(newCb, (Addr) & printNameAndInfo);
}else {
VG_(call_helper_0_0)(newCb, (Addr) & printName);
}
}
for (i = 0; i < VG_(get_num_instrs)(cb); i++) {
u = VG_(get_instr)(cb, i);
if (((u->opcode) == JMP) &&
((u->jmpkind)==JmpRet) )
{
VG_(get_fnname)(a, name, 100); // hopefully always works?
VG_(call_helper_0_0)(newCb, (Addr) &printRet);
}
if (((u->opcode) == JMP) &&
((u->jmpkind)==JmpCall) )
{
VG_(get_fnname)(a, name, 100); // hopefully always works?
VG_(call_helper_0_0)(newCb, (Addr) &printCall);
}
VG_(copy_UInstr)(newCb, u);
}
VG_(free_UCodeBlock)(cb);
return newCb;
}
For the following program:
int main(int argc, char **argv){
a();
b();
return 0;
}
void a(){
printf("in a\n");
};
int b(){
printf("in b\n");
return 1;
};
we start with
CALL from __libc_start_main
main @ a.c LINE 6
CALL from main
a @ a.c LINE 13
Which is good. All execution inside the program seems to be fine
as long as no library functions are called ;) However, a() calls a
library
function, and I get told:
CALL from a
CALL from a
CALL from a
RET from a
CALL from a
a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
CALL from a
RET from a
RET from a
RET from a
RET from a
RET from a
_IO_printf
CALL from _IO_printf
...
And then a whole load of stuff inside libc, which I can't easily verify
as
correct or incorrect atm.
I just tried this again and setting LD_BIND_NOW=1 seems to cause the
calling of a() to behave as expected, and a lot of other junk to
disappear, but b() is still the same. (loads of "CALL" and "RET"
statements spewed out saying that they're at the address of the entry
point of the function, according to the %eip as reported by valgrind)
Am I misunderstanding something about UCode or what? I'm sure this is a
solved problem,
since I imagine every single skin would depend on the behavior that I am
hoping for (one
call of the instrumentation code for every call/ret).
Thanks a million,
Nick
|
|
From: Julian S. <js...@ac...> - 2003-12-24 01:51:18
|
> I've been trying to get a valgrind skin i'm tinkering with to get a > program to report whenever it calls or returns from a function. Simple as it sounds, this is a real swamp. For one thing, tail-calls from one function to another just look like plain Jmps, not JmpCall, and so you can't reliably use the mechanism you proposed. Similarly, there are 99 ways to return from a function (98 of them admittedly really stupid), such as popl %edx; jmp *%edx Josef Wiedendorfer is the real guru here as I think kcachegrind/calltree manages to track calls/returns. I'm sure he can elaborate. > Am I misunderstanding something about UCode or what? I'm sure this is a > solved problem, > since I imagine every single skin would depend on the behavior that I am > hoping for (one > call of the instrumentation code for every call/ret). Well, actually, no. As far as I know only calltree does this. For the most part skins like memcheck just see the client program moving values on/off the stack and jumping round the place, but have no concept of calls/returns happening. The stack backtraces you see in error messages are made by walking the stack when an error occurs, but nobody keeps track of when functions are entered/exited, basically because it's nearly impossible to do so reliably. Having said all that ... what is it you are trying to achieve with your skin? J |
|
From: Nicholas S. <nic...@cs...> - 2003-12-24 02:46:05
|
> > Josef Wiedendorfer is the real guru here as I think kcachegrind/calltree > manages to track calls/returns. I'm sure he can elaborate. > Ah. He's the one who originally suggested to me that it might be a linkage gotcha. I'd been digging through the calltree code to try and find out how it deals with this, but I've had little success groking it so far. > Having said all that ... what is it you are trying to achieve with > your skin? Our tool (www.cse.unsw.edu.au/~drt) currently uses compile-time instrumentation to gain call traces of programs, but this is a pain for us and users of the tools. Since valgrind wouldn't require compile-time hacks or a recompile, allows basic block instrumentation and seems to have been successfully used on a number of nontrivial programs, my supervisor thought that it would be a good idea to see if we could use it for our instrumentation instead. I've had a go at using dyninst for this (www.dyninst.org), but it's very experimental and we had limited success getting it to compile and run on our various systems (Various versions of Redhat and Debian). Cheers, Nick |
|
From: Nicholas S. <nic...@cs...> - 2003-12-24 02:54:15
|
> Well, actually, no. As far as I know only calltree does this. For the > most part skins like memcheck just see the client program moving values > on/off the stack and jumping round the place, but have no concept of > calls/returns happening. The stack backtraces you see in error messages Actually, I still don't understand. Despite the fact that my points of instrumentation were meant to be function entries/exits, and as you say this isn't necessarily the case, the code added during instrumentation is _still_ being called multiple times despite the instrumented code only being executed once, isn't it? Nick |
|
From: Josef W. <Jos...@gm...> - 2003-12-31 02:14:03
|
Hi, (hope you all had a nice XMas :-) Am Mittwoch, 24. Dezember 2003 03:45 schrieb Nicholas Seow: > > Josef Wiedendorfer is the real guru here as I think kcachegrind/calltree > > manages to track calls/returns. I'm sure he can elaborate. > > Ah. He's the one who originally suggested to me that it might be a linkage > gotcha. I'd been digging through the calltree code to try and find out how > it deals with this, but I've had little success groking it so far. Hmm, I should clean up and comment the code... You are using VG_(get_fnname_if_entry)() only for the first instruction of every basic block. I'm not quite sure this is always correct. Does it work if you check at every instruction? As Julian said, function calls are sometimes done by JMP or PUSH/RET (runtime linker), and there are setjmp/longjmp and C++ exceptions, unwinding multiple stack frames with a ESP write. Besides, I'm sure there are functions with multiple entry points. In calltree, I unconditionally need a call to a helper function at start of every basic block, and so I am doing a lot of things dynamically which perhaps could be done once at instrumentation time. This isn't the best solution efficiency-wise, but fairly robust. To locate the multiple "CALL from a", it can help to print instruction addresses and compare with the disassembled code, and use --tracegen=10100. > I've had a go at using dyninst for this (www.dyninst.org), but it's very > experimental and we had limited success getting it to compile and run on > our various systems (Various versions of Redhat and Debian). Doesn't have dyninst the same problems as it is manipulating instructions directly, too? Cheers, Josef |
|
From: Nick <ni...@sa...> - 2003-12-31 02:58:51
|
Hi, > (hope you all had a nice XMas :-) You too 8) > You are using VG_(get_fnname_if_entry)() only for the first instruction of > every basic block. I'm not quite sure this is always correct. Does it work if > you check at every instruction? Given that it's incorrect, then that means that I'm getting less than or equal to the amount of calls to the code added during instrumentation that I should. But I haven't seen evidence of that yet. Nevertheless, I'll do as you suggest. > > I've had a go at using dyninst for this (www.dyninst.org), but it's very > > experimental and we had limited success getting it to compile and run on > > our various systems (Various versions of Redhat and Debian). > > Doesn't have dyninst the same problems as it is manipulating instructions > directly, too? It was a while ago that I played around with dyninst - I'll try to track down the results I got. I seem to remember them looking sensible. > To locate the multiple "CALL from a", it can help to print instruction > addresses and compare with the disassembled code, and use --tracegen=10100. I mentioned this to Julian Seward yesterday: """ I got the idea yesterday of enclosing CALLs with debugging statements, so I wouldn't have to deal with the 99 different RETs as you said ;) VG_(call_helper_0_0)(newCb, (Addr) &printBeforeCall); VG_(copy_UInstr)(newCb, u); VG_(call_helper_0_0)(newCb, (Addr) &printAfterCall); However, I still can't figure out what the heck is going on. printAfterCall never gets called, for one. """ shouldn't a function return (by whatever message) result in the instruction following the call being executed? I tried the following code on this toy program: //---------------------------- #include <stdio.h> void a(); int b(); int main(){ a(); b(); return 0; } void a(){ printf("hi\n"); } int b(){ printf("bye\n"); return 1; } //---------------------------- main() containing 804834c: e8 0c 00 00 00 call 804835d <a> 8048351: e8 1f 00 00 00 call 8048375 <b> but from the output below, printAfterCall() isn't reached. //---------------------------- #include "vg_skin.h" char name[100]; char file[100]; char line[100]; VG_DETERMINE_INTERFACE_VERSION void printName(void){ Addr a; ThreadId tid; tid=VG_(get_current_tid)(); a=VG_(get_EIP)(tid); if (VG_(get_fnname_if_entry)(a, name, 100)){ VG_(printf) ("-> Entering %s :)\n",name); } else { VG_(printf) ("-> oh no\n"); } } void printBeforeCall(void){ VG_(printf) ("-> Going to call\n"); } void printAfterCall(void){ VG_(printf) ("-> After call\n"); } void SK_(pre_clo_init)(void){ VG_(details_name) ("Foo"); VG_(details_version) ("0.0.1"); VG_(details_description) ("an example Valgrind skin"); VG_(details_copyright_author)( "Copyright (C) 2002-2003, Nick Seow."); VG_(details_bug_reports_to) ("nowhere"); VG_(register_compact_helper)((Addr) & printName); VG_(register_compact_helper)((Addr) & printBeforeCall); VG_(register_compact_helper)((Addr) & printAfterCall); } void SK_(post_clo_init)(void){ } void SK_(fini)(exitcode) { } UCodeBlock* SK_(instrument)(UCodeBlock* cb, Addr a){ UCodeBlock *newCb; Int i; UInstr* u; newCb=VG_(setup_UCodeBlock)(cb); if (VG_(get_fnname_if_entry)(a, name, 100)){ VG_(call_helper_0_0)(newCb, (Addr) & printName); } for (i = 0; i < VG_(get_num_instrs)(cb); i++) { u = VG_(get_instr)(cb, i); if (((u->opcode) == JMP) && ((u->jmpkind)==JmpCall) ) { VG_(call_helper_0_0)(newCb, (Addr) &printBeforeCall); VG_(copy_UInstr)(newCb, u); VG_(call_helper_0_0)(newCb, (Addr) &printAfterCall); } else VG_(copy_UInstr)(newCb, u); } VG_(free_UCodeBlock)(cb); return newCb; } //--------------------------------- <insert a bunch of stuff preceding main> -> Entering main :) -> Going to call -> Entering a :) -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _dl_lookup_versioned_symbol :) -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _IO_printf :) -> Going to call -> Going to call -> Entering _IO_vfprintf :) -> Going to call -> Going to call -> Entering __errno_location :) -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _dl_lookup_versioned_symbol :) -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _IO_flockfile :) -> Going to call -> Going to call -> Entering _IO_file_xsputn :) -> Going to call -> Going to call -> Entering _IO_file_overflow :) -> Going to call -> Going to call -> Entering _IO_doallocbuf :) -> Going to call -> Going to call -> Entering _IO_file_doallocate :) -> Going to call -> Going to call -> Entering _IO_file_stat :) -> Going to call -> Entering __fxstat64 :) -> Going to call -> Going to call -> Entering __errno_location :) -> Going to call -> Going to call -> Entering mmap :) -> Going to call -> Entering _IO_setb :) -> Going to call -> Going to call -> Entering _IO_do_write :) -> Going to call -> Entering _IO_default_xsputn :) -> Going to call -> Entering _IO_file_overflow :) -> Going to call -> Going to call -> Entering _IO_file_overflow :) -> Going to call -> Going to call -> Entering _IO_file_overflow :) -> Going to call -> Going to call -> Entering _IO_do_write :) -> Going to call -> Going to call -> Going to call -> Entering _IO_file_write :) -> Going to call -> Entering __libc_write :) -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _dl_lookup_versioned_symbol :) -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Going to call -> Entering _IO_funlockfile :) -> Going to call -> Going to call -> Entering b :) <et cetera> |
|
From: Josef W. <Jos...@gm...> - 2003-12-31 13:04:21
|
Am Mittwoch, 31. Dezember 2003 14:51 schrieb Nick:
> > You are using VG_(get_fnname_if_entry)() only for the first instruction
> > of every basic block. I'm not quite sure this is always correct. Does it
> > work if you check at every instruction?
>
> Given that it's incorrect, then that means that I'm getting less than or
> equal to the amount of calls to the code added during instrumentation that
> I should. But I haven't seen evidence of that yet. Nevertheless, I'll do =
as
> you suggest.
Shouldn't be the number of calls reported the same?
> I got the idea yesterday of enclosing CALLs with debugging statements, so
> I wouldn't have to deal with the 99 different RETs as you said ;)
Sorry, I don't get your point.
>
> VG_(call_helper_0_0)(newCb, (Addr) &printBeforeCall);
> VG_(copy_UInstr)(newCb, u);
> VG_(call_helper_0_0)(newCb, (Addr) &printAfterCall);
>
> However, I still can't figure out what the heck is going on.
> printAfterCall never gets called, for one.
=46or Valgrind UCode, a x86 CALL is translated to a PUSH/JMP. And every jum=
p is=20
translated to a jump to valgrinds main loop. So your second helper call=20
(printAfterCall) of course is dead code. Look at the info which=20
=2D-trace-codegen is giving you.
> shouldn't a function return (by whatever message) result in the instructi=
on
> following the call being executed?
After return, a new basic block is executed, but your call to printAfterCal=
l=20
is put at a dead end of the basic block where the call started.
> void printName(void){
> Addr a;
> ThreadId tid;
>
> tid=3DVG_(get_current_tid)();
> a=3DVG_(get_EIP)(tid);
> if (VG_(get_fnname_if_entry)(a, name, 100)){
> VG_(printf) ("-> Entering %s :)\n",name);
> } else {
> VG_(printf) ("-> oh no\n");
> }
> }
Why are you calling get_fnname_if_entry in the helper again? There's no nee=
d=20
to do this: for a given basic block, debug info won't change in the course =
of=20
a program run.
Am Mittwoch, 31. Dezember 2003 15:02 schrieb Nick:
> > As Julian said, function calls are sometimes done by JMP or PUSH/RET
> > (runtime linker), and there are setjmp/longjmp and C++ exceptions,
> > unwinding multiple stack frames with a ESP write. Besides, I'm sure the=
re
> > are functions with multiple entry points.
>
> Well, a program making a call to a function in a dynamically linked libra=
ry
> would be an x86 CALL to the PLT section of that program's binary, wouldn't
Yes. But as PLT entries don't export any symbols and have no line debug inf=
o,
you will get never get any information from get_fnname_if_entry for=20
instructions in PLT sections.
=46rom the PLT section, there will be a JMP either into the runtime linker =
or in=20
into the requested function (on further calls)...
> it? If so would this mean my "give output before and after a CALL" is
> always correct for detecting function calls and returns within a particul=
ar
> binary? Or does valgrind translate the asm into something different? :)
As I said above, your printAfterCall is never called. You would have to pla=
ce=20
this at the beginning of the instrumentated version of the basic block=20
following the CALL instruction, but instrumentation of this basic block wil=
l=20
be done probably much later in time, perhaps never.
Josef
|
|
From: Nick <ni...@sa...> - 2003-12-31 03:02:35
|
> As Julian said, function calls are sometimes done by JMP or PUSH/RET (runtime > linker), and there are setjmp/longjmp and C++ exceptions, unwinding multiple > stack frames with a ESP write. Besides, I'm sure there are functions with > multiple entry points. Well, a program making a call to a function in a dynamically linked library would be an x86 CALL to the PLT section of that program's binary, wouldn't it? If so would this mean my "give output before and after a CALL" is always correct for detecting function calls and returns within a particular binary? Or does valgrind translate the asm into something different? :) Nick |
|
From: Nicholas N. <nj...@ca...> - 2004-01-03 17:54:34
Attachments:
sp_main.c
|
On Tue, 23 Dec 2003, Nicholas Seow wrote:
> I've been trying to get a valgrind skin i'm tinkering with to get a
> program to report whenever it calls or returns from a function. However,
> I'm getting some really wierd data.
I've attached a tool (skin) I wrote, called Sparrow, that does exactly
this. Here's some example output:
call _init
call __init_misc
call strrchr
exit strrchr
exit __init_misc
call __libc_global_ctors
call _IO_check_libio
exit _IO_check_libio
exit __libc_global_ctors
exit _init
Unfortunately, it falls over sometimes. The reason is, I maintain a stack
of activation records, and if the function returned from doesn't match
that on the top, it dies. Actually, I do some fiddling with %esp which
catches many uses of longjmp, but not all.
Generally, this function entry/exit tracking is a total pain, much harder
than you'd expect. Anyway, it might be useful for you.
N |
|
From: Josef W. <Jos...@gm...> - 2004-01-04 00:20:32
Attachments:
sparrow.tgz
|
Am Samstag, 3. Januar 2004 18:54 schrieb Nicholas Nethercote: > I've attached a tool (skin) I wrote, called Sparrow, that does exactly > ... Hi, for easy installation of sparrow, and to encourage you all to release future tools as separate packages, I attached sparrow.tgz, which adds a configure.in and a Makefile.am to get everything needed for a separate tool package. sp_main.c is left unmodified. Use ./autogen.sh before for the automake run. A "./configure" and "make dist" would produce the package. Josef PS: For robust call tracing, a helper at start of every basic block seems needed for PLT and code pieces without debug info... |
|
From: Nick <ni...@sa...> - 2004-01-04 00:31:53
|
Thanks a million - this is a great help. Even if it's not entirely robust, I can start investigating how we need to modify the rest of our application to accept data from valgrind now. > > Unfortunately, it falls over sometimes. The reason is, I maintain a stack > of activation records, and if the function returned from doesn't match > that on the top, it dies. Actually, I do some fiddling with %esp which > catches many uses of longjmp, but not all. What would you call "sometimes", as a short test case? > > Generally, this function entry/exit tracking is a total pain, much harder > than you'd expect. Anyway, it might be useful for you. > Definitly useful. I still have hopes of understanding calltree's method, but I'm a lot wiser to the magnitude of the problem now. Nick |
|
From: Nicholas N. <nj...@ca...> - 2004-01-04 10:43:05
|
On Sun, 4 Jan 2004, Nick wrote: > > Unfortunately, it falls over sometimes. The reason is, I maintain a stack > > of activation records, and if the function returned from doesn't match > > that on the top, it dies. Actually, I do some fiddling with %esp which > > catches many uses of longjmp, but not all. > > What would you call "sometimes", as a short test case? IIRC, it gets most programs right, but falls over on some big ones like OpenOffice. N |