|
From: Benjamin M. <be...@me...> - 2007-08-27 19:43:40
|
Been reading through the file format and had few questions In the docs here http://www.hlrs.de/organization/amt/services/tools/debugger/valgrind/ doc/html-3.2.1/cl-format.html#cl-format.overview.example2 It says "Inclusive cost of "main" is 420, which is the sum of self cost 20 and costs spent in the calls.", but wouldn't it really be 20 + 1*400 + 3*400 = 1620? The following code (QColumnView is a subclass of QAbstractItemView): QColumnView::~QColumnView() { } Gets turns into the following bits in callgrind: fn=(49088) QColumnView::~QColumnView() 82 40 cfi=(47) cfn=(4782) calls=8 -82 * 16 * 72 +2 24 cfi=(257) cfn=(49094) QAbstractItemView::~QAbstractItemView() calls=8 454 * 4986775 * 24 jcnd=8/8 * * * 32 -2 50 cfi=(47) cfn=(4782) calls=10 -82 * 20 * 90 +2 30 cfi=(257) cfn=(49094) calls=10 454 * 12217972 cob=(1) cfi=(1) cfn=(2868) calls=1 -84 * 819 * 30 jcnd=10/10 * * * 40 I understand that it is calling the parent class destructors, but where are the jcnd coming from? Specifically the jcnd=8/8 after ~QAbstractItemView()? From the spec it would seem that the jump is assigned to ~QColumnView (is that right?), but if I load it up in KCachegrind I don't see any jumps. Lastly there are a few calls= that have negative numbers. Because cfi and cfn are specified shouldn't the destination position be in the line number in the file (such as when they are 454) or is the line number of the jump relative to the current line number (resulting in 0 both times)? -Benjamin Meyer |
|
From: Josef W. <Jos...@gm...> - 2007-08-28 01:26:04
|
On Monday 27 August 2007, Benjamin Meyer wrote: > Been reading through the file format and had few questions > > In the docs here > http://www.hlrs.de/organization/amt/services/tools/debugger/valgrind/ > doc/html-3.2.1/cl-format.html#cl-format.overview.example2 > It says "Inclusive cost of "main" is 420, which is the sum of self > cost 20 and costs spent in the calls.", Good catch. Yes, the 420 is wrong, as the self cost is 20, the call to func1 is 400 and the call to func2 is 400, so it should be 820. I will fix this. > but wouldn't it really be 20 > + 1*400 + 3*400 = 1620? No. The 400 for func2 is already aggregated for all 3 calls as sum of the costs of the individual calls. Callgrind does not collect the different costs for each call; otherwise the amount of data would be linear to runtime. > The following code (QColumnView is a subclass of QAbstractItemView): > > QColumnView::~QColumnView() > { > } > > Gets turns into the following bits in callgrind: > > fn=(49088) QColumnView::~QColumnView() > 82 40 > cfi=(47) > cfn=(4782) > calls=8 -82 > * 16 > * 72 > +2 24 > cfi=(257) > cfn=(49094) QAbstractItemView::~QAbstractItemView() > calls=8 454 > * 4986775 > * 24 > jcnd=8/8 * > * > * 32 > -2 50 > cfi=(47) > cfn=(4782) > calls=10 -82 > * 20 > * 90 > +2 30 > cfi=(257) > cfn=(49094) > calls=10 454 > * 12217972 > cob=(1) > cfi=(1) > cfn=(2868) > calls=1 -84 > * 819 > * 30 > jcnd=10/10 * > * > * 40 > > I understand that it is calling the parent class destructors, but > where are the jcnd coming from? Specifically the jcnd=8/8 after > ~QAbstractItemView()? Actually, I have no idea. Perhaps the compiler does some kind of inlining here? It would be good to see the association with the assembly code here. You get more precise data here when using "--dump-instr=yes". Function (2868) seems to be a call into the runtime linker, as it is done only once, and function (4782) seems to be the call to these pseudo-functions, called to get the global offset pointer in shared libraries (as every call only spends 2 instructions). Is it possible that the conditions are because of C++ exception handling? > From the spec it would seem that the jump is > assigned to ~QColumnView (is that right?), Yes. > but if I load it up in > KCachegrind I don't see any jumps. I assume you talk about the jump annotation in the source view (as your dump data is only about line numbers as far as I see). In this case, arrows/jumps are suppressed in some situations. If you look at these lines: * 24 jcnd=8/8 * * The conditional jump source is a instruction associated to a given source line X by the debug information generated by the compiler. The jump target is the same line X. In general, jump annotations are suppressed by KCachegrind if they are from a line to the same or the next line. I had some reason for this, but I am not sure any more. But yes, it should be noted in the documentation. You will see the jump in the assembly view (with "--dump-instr=yes"). > Lastly there are a few calls= that have negative numbers. Because > cfi and cfn are specified shouldn't the destination position be in > the line number in the file (such as when they are 454) or is the > line number of the jump relative to the current line number > (resulting in 0 both times)? Callgrind by default both uses "name" and "subposition" compression as they are called in the format spec. The latter means that line numbers (which count as "subposition" as well as instruction addresses) usually are relative. The spec states that a subposition starting with a "-" is a negative difference relative to the previous subposition. As absolute subpositions can not be negative, this is non-ambiguous. So yes, the line numbers of the call destination in your example are zero (ie. unknown/no debug info given). You could argue that this spec is a little bit counter-intuitive, as you get relative line numbers from different functions. What I am not sure about is why there are the source files specified in your example despite of the fact that line number information is missing; however, file (1) could very well be the "unknown" file. I suppose you want to parse this data? If you are unsure about the correctness, it is good to switch off the compression methods ("--compress-strings=no --compress-pos=no"). This also is easier for parsing. You can also have a look at the parser in KCachegrind. Josef |
|
From: Benjamin M. <be...@me...> - 2007-08-28 11:53:24
|
>> fn=(49088) QColumnView::~QColumnView() >> 82 40 >> cfi=(47) >> cfn=(4782) >> calls=8 -82 >> * 16 >> * 72 >> +2 24 >> cfi=(257) >> cfn=(49094) QAbstractItemView::~QAbstractItemView() >> calls=8 454 <------------------ >> * 4986775 >> * 24 >> jcnd=8/8 * >> * >> * 32 >> -2 50 >> cfi=(47) >> cfn=(4782) >> calls=10 -82 >> * 20 >> * 90 >> +2 30 >> cfi=(257) >> cfn=(49094) >> calls=10 454 <--------------------- >> * 12217972 >> cob=(1) >> cfi=(1) >> cfn=(2868) >> calls=1 -84 >> * 819 >> * 30 >> jcnd=10/10 * >> * >> * 40 One last thing, callgrind_annotate says that (49094) is called 8 times, while KCachegrind says that it is called 18 times. Does callgrind_annotate have the bug? -Benjamin Meyer |
|
From: Josef W. <Jos...@gm...> - 2007-08-28 21:13:59
|
On Tuesday 28 August 2007, Benjamin Meyer wrote: > >> fn=(49088) QColumnView::~QColumnView() > >> 82 40 > >> cfi=(47) > >> cfn=(4782) > >> calls=8 -82 > >> * 16 > >> * 72 > >> +2 24 > >> cfi=(257) > >> cfn=(49094) QAbstractItemView::~QAbstractItemView() > >> calls=8 454 <------------------ > >> * 4986775 > >> * 24 > >> jcnd=8/8 * > >> * > >> * 32 > >> -2 50 > >> cfi=(47) > >> cfn=(4782) > >> calls=10 -82 > >> * 20 > >> * 90 > >> +2 30 > >> cfi=(257) > >> cfn=(49094) > >> calls=10 454 <--------------------- > >> * 12217972 > >> cob=(1) > >> cfi=(1) > >> cfn=(2868) > >> calls=1 -84 > >> * 819 > >> * 30 > >> jcnd=10/10 * > >> * > >> * 40 > > One last thing, callgrind_annotate says that (49094) is called 8 > times, while KCachegrind says that it is called 18 times. Does > callgrind_annotate have the bug? Hmm... can you check with the script from Valgrind SVN trunk? Using your excerpt, putting a short header before and a summary line afterwards, I get a call count of 18 from callgrind_annotate. Anyway. 18 is correct. BTW, if you have improvements for the wording of the format spec, please say so. Josef |
|
From: Benjamin M. <be...@me...> - 2007-08-28 22:51:31
|
>> From the spec it would seem that the jump is
>> assigned to ~QColumnView (is that right?),
>
> Yes.
Excellent, that I what I thought, but wasn't sure because it didn't
appear in KCachegrind
>> but if I load it up in
>> KCachegrind I don't see any jumps.
>
> I assume you talk about the jump annotation in the source view
> (as your dump data is only about line numbers as far as I see).
> In this case, arrows/jumps are suppressed in some situations.
> If you look at these lines:
>
> * 24
> jcnd=8/8 *
> *
>
> The conditional jump source is a instruction associated to a
> given source line X by the debug information generated by the
> compiler.
> The jump target is the same line X.
>
> In general, jump annotations are suppressed by KCachegrind if they
> are from a line to the same or the next line. I had some reason for
> this, but I am not sure any more. But yes, it should be noted in the
> documentation.
Yah it is understandable that you would want to hide many of the
jumps in the GUI as they are not what the user it looking for.
> You will see the jump in the assembly view (with "--dump-instr=yes").
>
>> Lastly there are a few calls= that have negative numbers. Because
>> cfi and cfn are specified shouldn't the destination position be in
>> the line number in the file (such as when they are 454) or is the
>> line number of the jump relative to the current line number
>> (resulting in 0 both times)?
>
> Callgrind by default both uses "name" and "subposition" compression
> as they are called in the format spec. The latter means that line
> numbers (which count as "subposition" as well as instruction
> addresses)
> usually are relative. The spec states that a subposition starting
> with a "-" is a negative difference relative to the previous
> subposition.
> As absolute subpositions can not be negative, this is non-ambiguous.
What was confusing me was that I figured it would write "0" rather
then "-84" (because 0 is only one char vs three and more likely to
occur, leading to better compression)
> So yes, the line numbers of the call destination in your example
> are zero (ie. unknown/no debug info given).
> You could argue that this spec is a little bit counter-intuitive, as
> you get relative line numbers from different functions. What I am not
> sure about is why there are the source files specified in your example
> despite of the fact that line number information is missing; however,
> file (1) could very well be the "unknown" file.
Yup, 47 (earlier in the file, is unknown)
cfi=(47) ???
cfn=(4782) 0x00121917
> I suppose you want to parse this data?
How did you guess :)
> If you are unsure about the correctness, it is good to switch off
> the compression methods ("--compress-strings=no --compress-pos=no").
> This also is easier for parsing.
See my other e-mail where I made a tiny tool to decompress callgrind
files :)
> You can also have a look at the parser in KCachegrind.
Yah I skimmed through it and the annotate script. I wrote a very
small class that can be used to extract data from a callgrind file.
My use cases are
1) give me all the lines hit in file X
2) give me all the jumps in file X
(Sidenote: beyond that I am thinking of making a tiny command line
app to easily grab information out that can be used in all sort of
scripts. Such as:
- What files/functions/lines are used
- How expensive is obj/file/function x
- How many times is x called)
This class replaces the valgrind tool I wrote last week to acquire
coverage data. It is a much cleaner solution. Once it has the
information it is combined with the ast tree for the source I want to
get coverage on and it then generates a report. Below is the first
version of this report:
Function coverage - Has each function in the program been executed?
Functions: 6/6 100%
Statement coverage - Has each line of the source code been executed?
Executed: 83/87 95%
Condition coverage - Has each evaluation point (such as a true/false
decision) been executed?
Executed: 47/50 94%
Lines not touched:
167 [c] c: ulong self;
178 [j] f: if (!isLocked) {
180 [c] c: isLocked = d->wait();
181 [c] c: Q_ASSERT_X(isLocked, "QMutex::lock", "Internal
error, infinite wait has timed out.");
184 [c] c: d->contenders.deref();
199 [j] f: if (d->owner == self)
200 [c] c: qWarning("QMutex::lock: Deadlock detected in
thread %ld", d->owner);
227 [c] c: ulong self;
283 [c] c: ulong self;
345 [j] f: if (!d->contenders.testAndSetRelease(1, 0))
346 [c] c: d->wakeUp();
-Benjamin Meyer
|
|
From: Josef W. <Jos...@gm...> - 2007-08-28 23:40:00
|
On Wednesday 29 August 2007, Benjamin Meyer wrote: > What was confusing me was that I figured it would write "0" rather > then "-84" (because 0 is only one char vs three and more likely to > occur, leading to better compression) Yeah, missed space optimization in the dump file writing. Should be easy to change. > This class replaces the valgrind tool I wrote last week to acquire > coverage data. It is a much cleaner solution. Once it has the > information it is combined with the ast tree for the source I want to > get coverage on and it then generates a report. Below is the first > version of this report: > [...] Cool. Where to you have the AST from? > Lines not touched: > 167 [c] c: ulong self; I assume there is not really code for this line... Otherwise, it looks really promising! Josef |
|
From: Benjamin M. <be...@me...> - 2007-08-29 08:14:29
|
On Aug 29, 2007, at 1:39 AM, Josef Weidendorfer wrote: >> This class replaces the valgrind tool I wrote last week to acquire >> coverage data. It is a much cleaner solution. Once it has the >> information it is combined with the ast tree for the source I want to >> get coverage on and it then generates a report. Below is the first >> version of this report: >> [...] > > Cool. > Where to you have the AST from? I parse the source with robertos c++ parser which will give me the ast. I was also using his preprocessor, but have switched to gcc's until I fix a line number bug I found. >> Lines not touched: >> 167 [c] c: ulong self; > > I assume there is not really code for this line... > Otherwise, it looks really promising! "self" was declared, initialized later and used once. Looks like gcc was just performing a basic optimization. A very interesting find I must say :) int self ... self = 3; ... foo = self; But the jumps have been the more rewarding feature. For example I get notification if in my autotest bar is always false in the following statement (meaning I never test with foo false and bar true). if (foo || bar) -Benjamin Meyer |