making sense of unexpected callgraph output on ppc64, questions.
Will Schmidt <[email protected]>
| Newsgroups | gmane.linux.oprofile |
|---|---|
| Message-ID | <[email protected]> |
Hi Folks,
I'm seeing what I believe is some weirdness on powerpc64, both LE and
BE, regarding callgraph output.
I suspect what I am seeing is a flavor of the "a()->c()" as described at
http://oprofile.sourceforge.net/doc/interpreting-callgraph.html ; but
I've not yet convinced myself.
I've been poking at the callgraph_container.* code to try to add
more debug to get a sense for what may be happening, but Its code I'm
not familiar with, so going slowly.. Thoughts and suggestions of where
to poke, or outright answers to whats going on here are welcomed. :-)
What I see is:
$ operf -g ./callgraph_simple_test
# - callgraph_simple_test contains a chain of functions,
main()->function_one()->function_two()... where each function spins
doing some simple math, then calls the next function in line once before
it returns.
$ opreport -x -c
samples % symbol name
--------------------------------------------
6331 100.000 .function_one
6331 92.9799 .function_two
6331 100.000 .function_two [self]
--------------------------------------------
10974 100.000 .function_one <<==-- what??
478 7.0201 .function_one
10974 61.7106 .function_one <<==-- "" Not sure where
this is coming from.
6331 35.6014 .function_two
478 2.6880 .function_one [self]
--------------------------------------------
Note that per the above, and per how the callgraph output should be
interpreted, when a function appears to call itself (and is not marked
[self]), its typically recursive. So due the lines marked with the
arrows, we'd think that function_one() is recursive, but it's not.
(honest!). Also note that there is a caller entry that mirrors the
callee for .function_one.
Some other data points:
-The sample count numbers generated by 'opannotate --assembly' matches
the [self] entries, and appears consistent with the individual
instruction sample counts within the function.
0000000010000688 <.function_two>: /* .function_two total: 6331 92.9799 */
00000000100009f8 <.function_one>: /* .function_one total: 478 7.0201 */
-I can't tell where the sample counts (10974) from the extra entry are
coming from. I've added and subtracted and played a few games with numbers
generated by opannotate, but nothing jumping out at me.
-I've used "-x" to eliminate kernel/libc noise from the output, the
addition of that does not affect what I am seeing. I'll note that
'main' also seems to indicate that it calls itself.
- If I add function_three, function_four to the chain, those also
exhibit the same behavior, where they appear to be callers/callees of
themselves. Only the last function in the chain appears without the
unexpected entry.
- if I actually make the last one of the functions in the chain (i.e.
function_four()) recursive, the output then seems reasonable, showing
the function calling itself as well as having the [self] line.
- I don't see this weirdness with any of the kernel or library
functions..
- adding "-fomit-frame-pointer" to the compile does not change the
behavior.
Thanks,
-Will
------------------------------------------------------------------------------
Site24x7 APM Insight: Get Deep Visibility into Application Performance
APM + Mobile APM + RUM: Monitor 3 App instances at just $35/Month
Monitor end-to-end web transactions and take corrective actions now
Troubleshoot faster and improve end-user experience. Signup Now!
http://pubads.g.doubleclick.net/gampad/clk?id=267308311&iu=/4140