|
From: Harry M. <hj...@ta...> - 2005-04-27 21:06:56
|
Hi All, I'm using callgrind to examine an app that does a lot of numerical work and also does a considerable amount of I/O. After battling with the -gstabs format for a while (an external lib used it), I've gotten it to run with the app with the required set of options and flags, but after several minutes of work, it exits with what looks like a normal set of messages, but the output file (callgrind.out.pid) is of zero length. If run with the same app with no arguments (which simply dumps the help file), it leaves an output file of non-zero size that can be read into kcachegrind and looks correct. the exit messages: --20478-- Start dumping at BB 840458335 (Prg.Term.)... --20478-- Dump to /home/hjm/zender/nco/callgrind.out.20478 --20478-- Dumping done. --20478-- --20478-- Distinct objects: 15 --20478-- Distinct files: 52 --20478-- Distinct fns: 2756 --20478-- Distinct contexts:2756 --20478-- Distinct BBs: 6169 --20478-- Cost entries: 3259 (Chunks 1) --20478-- Distinct BBCCs: 6402 --20478-- Distinct JCCs: 1599 --20478-- Distinct skips: 447 --20478-- BB lookups: 6169 --20478-- With full debug info: 39% (2466) --20478-- With file/line debug info: 0% (19) --20478-- With fn name debug info: 21% (1328) --20478-- With no debug info: 38% (2356) --20478-- BBCC Clones: 233 --20478-- BBs Retranslated: 0 --20478-- Distinct instrs: 32304 --20478-- --20478-- LRU Contxt Misses: 2756 --20478-- LRU BBCC Misses: 206 --20478-- LRU JCC Misses: 1599 --20478-- BBs Executed: 840458335 --20478-- Calls: 28038218 --20478-- CondJMP followed: 0 --20478-- Boring JMPs: 0 --20478-- Recursive calls: 10 --20478-- Returns: 28038218 --20478-- ==20478== Events : Ir ==20478== Collected : 5126502049 ==20478== ==20478== I refs: 5,126,502,049 --20478-- TT/TC: 0 tc sectors discarded. --20478-- 6279 tt_fast misses. --20478-- translate: new 6169 (106601 -> 670119; ratio 62:10) --20478-- discard 0 (0 -> 0; ratio 0:10). --20478-- chainings: 4335 chainings, 0 unchainings. --20478-- dispatch: 840475144 jumps (bb entries); of them 56068560 (6%) unchained. --20478-- 16810/25074 major/minor sched events. --20478-- reg-alloc: 76 t-req-spill, 160994+228 orig+spill uis, --20478-- 22247 total-reg-rank --20478-- sanity: 16811 cheap, 673 expensive checks. --20478-- ccalls: 6229 C calls, 100% saves+restores avoided (37344 bytes) --20478-- 6289 args, avg 0.1 setup instrs each (12338 bytes) --20478-- 0% clear the stack (18507 bytes) --20478-- 60 retvals, 19% of reg-reg movs avoided (22 bytes) Why the silent treatment? hjm |
|
From: Josef W. <Jos...@gm...> - 2005-04-27 22:03:41
|
On Wednesday 27 April 2005 22:19, Harry Mangalam wrote: > Hi All, > I'm using callgrind to examine an app that does a lot of numerical work and > also does a considerable amount of I/O. > After battling with the -gstabs format for a while (an external lib used > it), I've gotten it to run with the app with the required set of options > and flags, but after several minutes of work, it exits with what looks like > a normal set of messages, but the output file (callgrind.out.pid) is of > zero length. > If run with the same app with no arguments (which simply dumps the help > file), it leaves an output file of non-zero size that can be read into > kcachegrind and looks correct. > > the exit messages: > --20478-- Start dumping at BB 840458335 (Prg.Term.)... > ... > ==20478== Events : Ir > ==20478== Collected : 5126502049 > ... Yes, that looks normal. > Why the silent treatment? Can you send me the packed output of callgrind -v --ct-verbose=2 --ct-vstart=840458000 <prog> I hope your program is deterministic, so it will exit again around basic block 840458335. Josef > hjm > > > > > > ------------------------------------------------------- > SF.Net email is sponsored by: Tell us your software development plans! > Take this survey and enter to win a one-year sub to SourceForge.net > Plus IDC's 2005 look-ahead and a copy of this survey > Click here to start! http://www.idcswdc.com/cgi-bin/survey?id=105hix > _______________________________________________ > Valgrind-users mailing list > Val...@li... > https://lists.sourceforge.net/lists/listinfo/valgrind-users |
|
From: Harry M. <hj...@ta...> - 2005-04-29 21:52:53
|
Hi Josef and others - yet another data point - I recompiled the whole thing
with Intel's icc, which tries to act like gcc - I thought it might give a
clue to the mysterious lack of output but it also refuses to write a
callgrind output file, even tho it does seem to be doing so (like gcc)
The one oddity that I could see in my quick pass thru it was the note that
something segfaulted 2x in the execution of:
strace -etrace=open,close callgrind -v [command] >& out
$ grep -n -5 SEG out
185-close(3) = 0
186-close(4) = 0
187-==27566==
188-open("/home/hjm/zender/nco/callgrind.cmd.27566", O_RDONLY) = -1 ENOENT
(No such file or directory)
189-open("/usr/lib/valgrind/vg_inject.so", O_RDONLY) = 3
190:--- SIGSEGV (Segmentation fault) @ 0 (0) ---
191-==27566== Reading syms from /usr/lib/valgrind/vg_inject.so (0x3A97F000)
192-open("/usr/lib/valgrind/vg_inject.so", O_RDONLY) = 4
193-close(4) = 0
194-close(3) = 0
195-open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or
directory)
--
322-open("/home/hjm/zender/nco/callgrind.cmd", O_RDONLY) = -1 ENOENT (No
such file or directory)
323-open("/home/hjm/zender/nco/callgrind.cmd.27566", O_RDONLY) = -1 ENOENT
(No such file or directory)
324-open("/tmp/nco_test/sml_stl.nc", O_RDONLY|O_LARGEFILE) = 3
325-close(3) = 0
326-open("/tmp/nco_test/sml_stl.nc", O_RDONLY|O_LARGEFILE) = 3
327:--- SIGSEGV (Segmentation fault) @ 0 (0) ---
328-open("/tmp/nco_test/sml_stl-ncea.nc.pid27566.ncea.tmp", O_RDWR|O_CREAT
O_TRUNC|O_LARGEFILE, 0666) = 4
329-open("/etc/localtime", O_RDONLY) = 5
330-close(5) = 0
331-open("/home/hjm/zender/nco/callgrind.cmd", O_RDONLY) = -1 ENOENT (No
such file or directory)
332-open("/home/hjm/zender/nco/callgrind.cmd.27566", O_RDONLY) = -1 ENOENT
(No such file or directory)
also, the output of the command:
strace -etrace=open,close callgrind -v [command]
was 87% these two lines:
open("/home/hjm/zender/nco/callgrind.cmd", O_RDONLY) = -1 ENOENT (No such
file or directory)
open("/home/hjm/zender/nco/callgrind.cmd.27566", O_RDONLY) = -1 ENOENT (No
such file or directory)
I take it that such an error implies that there's supposed to be such a file
- why isn't it there? I have no idea..
harry
Josef Weidendorfer wrote:
> Yes, that looks normal.
>
>> Why the silent treatment?
>
> Can you send me the packed output of
> callgrind -v --ct-verbose=2 --ct-vstart=840458000 <prog>
> I hope your program is deterministic, so it will exit again
> around basic block 840458335.
>
> Josef
>
>> hjm
|
|
From: Josef W. <Jos...@gm...> - 2005-04-29 23:03:41
|
Hi,
On Friday 29 April 2005 23:51, Harry Mangalam wrote:
> The one oddity that I could see in my quick pass thru it was the note that
> something segfaulted 2x in the execution of:
> strace -etrace=open,close callgrind -v [command] >& out
I am not sure this is odd: Valgrind quite regularly uses the SEGFAULT signal
to keep track of memory needs of the client program (doing "the right thing"
in its the SEGFAULT handler).
> also, the output of the command:
> strace -etrace=open,close callgrind -v [command]
> was 87% these two lines:
> open("/home/hjm/zender/nco/callgrind.cmd", O_RDONLY) = -1 ENOENT (No such
> file or directory)
> open("/home/hjm/zender/nco/callgrind.cmd.27566", O_RDONLY) = -1 ENOENT (No
> such file or directory)
That's the quite crappy way to be able to control callgrind from the outside:
by creating a file with commands, which are executed when the file is
detected. There is quite some work done between 2 open calls for these files,
so the overhead should be neglectable. Perhaps access() would be faster then
open() to check for the file.
I did it this way to be as invisible as possible to the client: this method
does not require any open file descriptor, and an open file descriptor is a
visible client resource.
>
> I take it that such an error implies that there's supposed to be such a
> file - why isn't it there? I have no idea..
It is only there for a short moment if you send a command to the callgrind
process via "callgrind_control". After execution of the commands, callgrind
deletes the file again. This is a signal for "callgrind_control" that the
commands were executed.
But in the debug output which you sent me in private I saw that the output is
written to file descriptor 0 in the end. I have to check if there is a bug
somewhere in my code, as 0 is not the usual case. Stay tuned...
Josef
>
> harry
>
> Josef Weidendorfer wrote:
> > Yes, that looks normal.
> >
> >> Why the silent treatment?
> >
> > Can you send me the packed output of
> > callgrind -v --ct-verbose=2 --ct-vstart=840458000 <prog>
> > I hope your program is deterministic, so it will exit again
> > around basic block 840458335.
> >
> > Josef
> >
> >> hjm
>
> -------------------------------------------------------
> This SF.Net email is sponsored by: NEC IT Guy Games.
> Get your fingers limbered up and give it your best shot. 4 great events, 4
> opportunities to win big! Highest score wins.NEC IT Guy Games. Play to
> win an NEC 61 plasma display. Visit http://www.necitguy.com/?r=20
> _______________________________________________
> Valgrind-users mailing list
> Val...@li...
> https://lists.sourceforge.net/lists/listinfo/valgrind-users
|
|
From: Josef W. <Jos...@gm...> - 2005-05-01 20:02:55
|
On Saturday 30 April 2005 01:03, Josef Weidendorfer wrote:
> But in the debug output which you sent me in private I saw that the output
> is written to file descriptor 0 in the end. I have to check if there is a
> bug somewhere in my code, as 0 is not the usual case. Stay tuned...
OK. This bug should be fixed by the following 1-liner.
--- callgrind/src/dump.c 2 Apr 2005 02:13:50 -0000 1.8
+++ callgrind/src/dump.c 1 May 2005 19:57:38 -0000
@@ -150,7 +150,7 @@ static Int fwrite_fd = -1;
static __inline__
void fwrite_flush()
{
- if ((fwrite_fd>0) && (fwrite_pos>0))
+ if ((fwrite_fd>=0) && (fwrite_pos>0))
VG_(write)(fwrite_fd, (void*)fwrite_buf, fwrite_pos);
fwrite_pos = 0;
}
Can you confirm this?
Josef
|
|
From: Harry M. <hj...@ta...> - 2005-05-02 17:52:21
|
Hi Josef, Sorry for the delay - I spent the day making sawdust :)
WooHooooooo!
What a difference an '=' makes!!
Thanks very much - works exactly right!! Oh, this is
SOOOOOOOOOOoooooooooooooooo great!
May I PayPal you a beer or two??
Harry
Josef Weidendorfer wrote:
> On Saturday 30 April 2005 01:03, Josef Weidendorfer wrote:
>> But in the debug output which you sent me in private I saw that the
>> output is written to file descriptor 0 in the end. I have to check if
>> there is a bug somewhere in my code, as 0 is not the usual case. Stay
>> tuned...
>
> OK. This bug should be fixed by the following 1-liner.
>
> --- callgrind/src/dump.c 2 Apr 2005 02:13:50 -0000 1.8
> +++ callgrind/src/dump.c 1 May 2005 19:57:38 -0000
> @@ -150,7 +150,7 @@ static Int fwrite_fd = -1;
> static __inline__
> void fwrite_flush()
> {
> - if ((fwrite_fd>0) && (fwrite_pos>0))
> + if ((fwrite_fd>=0) && (fwrite_pos>0))
> VG_(write)(fwrite_fd, (void*)fwrite_buf, fwrite_pos);
> fwrite_pos = 0;
> }
>
> Can you confirm this?
>
> Josef
>
>
> -------------------------------------------------------
> This SF.Net email is sponsored by: NEC IT Guy Games.
> Get your fingers limbered up and give it your best shot. 4 great events, 4
> opportunities to win big! Highest score wins.NEC IT Guy Games. Play to
> win an NEC 61 plasma display. Visit http://www.necitguy.com/?r=20
|