CPUPROFILER grossly overestimates the number of calls to functions

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Download a build mosesdecoder https://github.com/moses-smt/mosesdecoder with 
-with-cmph=/usr/include/ --full-tcmalloc link=shared
2. Build a binary phrase table, reordering table and a KenLM model. Files can 
be found here, http://www.statmt.org/moses/RELEASE-2.1/models/ tutorial can be 
found here http://www.statmt.org/moses/?n=Moses.Tutorial
3. Translate a 100 sentences, while profiling under Valgrind with callgrind. 
And then do the same with gperftools CPUPROFILE

What is the expected output? What do you see instead?
You expect the main function "Run()" which is located in moses-cmd/Main.cpp to 
be executed a 100 times, as is indeed the case with callgrind. With Gperftools 
Run() is shown to be executed several thousand times, which vary slightly 
between runs. I have tried both in singlethreaded and multithreaded setting, 
with and without registering additional threads and I can never get the correct 
number of runs of the function. It is always overestimated by a factor of 20-60.

What version of the product are you using? On what operating system?
gperftools 2.2, Arch linux 3.15.3

Please provide any additional information below.
Unfortunately the reproduce steps are quite lengthy. If anyone is interested in 
pursuing this, I can provide support with setting up and running Moses.

I have also attached the output of gperftools with 1 thread. Run() Appears to 
have run 3104 times, even though it should have been 100. 

I have also attached a correct output from valgrind

Original issue reported on code.google.com by nhe...@gmail.com on 8 Jul 2014 at 10:20

Attachments:

• 1corenoreg.callgrind
• callgrind.out.1thread

[GoogleCodeExporter]

But gperftools doesn't track calls. It's a sampling profiler.

Or at least I'm not aware how to get function calls estimate. Can you elaborate 
how exactly you get function calls numbers ?

Original comment by alkondratenko on 14 Jul 2014 at 2:18

[GoogleCodeExporter]

Ehm... It is probably a misunderstanding on my part then.

When converting gperftools output to callgrind, afaik as it is shown on the 
screenshot from kcachedgrind, 1605x and 1119x are the estimated number of calls 
from the upper function to the bottom one. Since gperftools are sampling they 
could undercount or miss very fast functions, but not overestimate? Am I wrong? 
If so what do those numbers mean?

Original comment by nhe...@gmail.com on 14 Jul 2014 at 11:16

Attachments:

• gperf_callgrind.png

[GoogleCodeExporter]

gperftools don't count or even estimate function call times. Those numbers are 
likely just number of samples that some particular function accumulated. You 
should check that with authors of gperftools-to-callgrind converter.

Original comment by alkondratenko on 14 Jul 2014 at 5:51

[GoogleCodeExporter]

Hey,

Thanks for the clarification. Could you point me out some names/emails of 
people I should contact with my queries?

Original comment by nhe...@gmail.com on 15 Jul 2014 at 11:55

[GoogleCodeExporter]

>> Could you point me out some names/emails of people I should contact with my 
queries?

No. They don't seem to be active in gperftools community. AFAIK converter from 
pprof format to callgrind is simply part of kcachegrind program. So reaching 
authors of this code might be the way to go.

Original comment by alkondratenko on 15 Jul 2014 at 11:57

[GoogleCodeExporter]

closing as not a bug.

Original comment by alkondratenko on 15 Jul 2014 at 11:58

• Changed state: NotABug

[GoogleCodeExporter]

I have to apologize here. Somehow I was sure that you referred to some external 
converter from pprof format to cachegrind. But it looks like you referred to 
feature of pprof.

If you indeed refer to pprof's converted then I'm sure that number is hits 
count and not number of function calls.

Original comment by alkondratenko on 23 Aug 2014 at 9:54