Re: callgraph not working

William Cohen <[email protected]>
Newsgroups gmane.linux.oprofile
Message-ID <[email protected]>
On 11/28/2016 12:01 PM, enrico . wrote:
> Hello,
> 
> thank you for your reply (and sorry if you get this e-mail twice). I am on Debian 8.6, on a physical machine with 8 intel core i7.
> 
> $ opreport -v
> oprofile 1.2.0git compiled on Nov 15 2016 11:53:18
> $ uname -a
> Linux mymachine 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u2 (2016-10-19) x86_64 GNU/Linux
> 
> I too see no difference with or without `-fno-omit-frame-pointer`, except in both cases this is what happens:
> 
> 
> $ gcc -O0 -g foo.cpp -o ./foo
> $ operf --callgraph ./foo
> operf: Profiler started
> 
> Profiling done.
> $ opreport -cl ./test -t1
> Using /home/blue/Scratchpad/oprofile_data/samples/ for samples directory.
> CPU: Intel Haswell microarchitecture, speed 4000 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 90000get_symbol_by_filepos: no symbols at all?
> Aborted
> 
> 
> Without a `--callgraph` option, I get a callgraph with no depth:
> 
> 
> $ operf ./test
> operf: Profiler started
> 
> Profiling done.
> $ opreport -cl ./test
> Using /home/blue/Scratchpad/oprofile_data/samples/ for samples directory.
> warning: /kvm could not be found.
> CPU: Intel Haswell microarchitecture, speed 4000 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
> samples  %        image name               symbol name
> -------------------------------------------------------------------------------
> 73603    53.3819  test                     loop(unsigned int)
>   73603    100.000  test                     loop(unsigned int) [self]
> -------------------------------------------------------------------------------
> 64273    46.6152  test                     slow_f()
>   64273    100.000  test                     slow_f() [self]
> -------------------------------------------------------------------------------
> 1        7.3e-04  kvm                      /kvm
>   1        100.000  kvm                      /kvm [self]
> -------------------------------------------------------------------------------
> 1        7.3e-04  ld-2.19.so <http://ld-2.19.so/>               check_match.9457
>   1        100.000  ld-2.19.so <http://ld-2.19.so/>               check_match.9457 [self]
> -------------------------------------------------------------------------------
> 1        7.3e-04  ld-2.19.so <http://ld-2.19.so/>               dl_main
>   1        100.000  ld-2.19.so <http://ld-2.19.so/>               dl_main [self]
> -------------------------------------------------------------------------------
> 1        7.3e-04  ld-2.19.so <http://ld-2.19.so/>               do_lookup_x
>   1        100.000  ld-2.19.so <http://ld-2.19.so/>               do_lookup_x [self]
> -------------------------------------------------------------------------------
> 
> Any help is greatly appreciated!
> 
> 
> 
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> *Da:* William Cohen <[email protected]>
> *Inviato:* lunedì 28 novembre 2016 17.39
> *A:* enrico .; [email protected]
> *Oggetto:* Re: callgraph not working
>  
> On 11/18/2016 07:04 AM, enrico . wrote:
>> Dear all,
>> I am encountering a problem when trying to produce a callgraph on Debian 8, on an x86_64 machine.
>> The problem is basically what is described here: https://sourceforge.net/p/oprofile/mailman/message/24408843/
>> 
>> Basically I cannot produce a callgraph. The solution proposed in the thread I linked (i.e. compiling with the -fno-omit-frame-pointer) does not seem to help.
>> 
>> The symptoms: running `operf ./foo` and then `opreport -cl ./foo` outputs a callgraph made of single calls, with no depth (like in the thread linked above).
>> Running `operf --callgraph ./foo` and then `opreport -cl ./foo` outputs "get_symbol_by_filepos: no symbols at all?" and aborts.
>> In both cases, `opreport -l ./foo` works fine and finds the right symbols.
>> 
>> I copy below my test program, which I compiled with gcc 4.9.2 on Debian 8, both with `gcc -fno-omit-frame-pointer -g foo.cpp` and `gcc -O0 -g foo.cpp`,
>> with the results described above.
>> 
>> Cheers,
>> blue
>> 
>> 
>> ##### foo.cpp  #######
>> void loop(unsigned int n) {
>>    for(unsigned int i=0; i<n; ++i);
>>    return;
>> }
>> 
>> void slow_f() {
>>    for(unsigned int i=0; i<1000000000; ++i);
>>    loop(1000000000);
>>    return;
>> }
>> 
>> int main() {
>>    slow_f();
>>    return 0;
>> }
> 
> Hi,
> 
> I am not sure what is going on with the debian environment.  I tried to replicate the failure on fedora 24 but did not see the problem occur as seen below in the fedora 24 output.  It would be helpful to include information about the specific version of oprofile being used (opreport -v) and the precise output for the opreport command.
> 
> -Will
> 
> [wcohen@santana callgraph]$ rpm -q oprofile
> oprofile-1.1.0-4.fc24.x86_64
> [wcohen@santana callgraph]$ uname -r
> 4.8.8-200.fc24.x86_64
> [wcohen@santana callgraph]$ gcc -fno-omit-frame-pointer -g foo.cpp -o ./foo
> 
> [wcohen@santana callgraph]$ operf --callgraph ./foo
> operf: Profiler started
> 
> WARNING: Lost samples detected! See /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/operf.log for details.
> Lowering the sampling rate may reduce or eliminate lost samples.
> See the '--events' option description in the operf man page for help.
> 
> Profiling done.
> [wcohen@santana callgraph]$ opreport -cl ./foo -t1
> Using /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/ for samples directory.
> 
> WARNING: Lost samples detected! See /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/operf.log for details.
> warning: /drm could not be found.
> warning: /kvm could not be found.
> warning: /nouveau could not be found.
> CPU: Intel Ivy Bridge microarchitecture, speed 3300 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 90000
> samples  %        symbol name
> -------------------------------------------------------------------------------
>   81671    100.000  slow_f()
> 81548    51.3779  loop(unsigned int)
>   81548    99.8494  loop(unsigned int) [self]
> -------------------------------------------------------------------------------
>   158706   100.000  main
> 76549    48.2283  slow_f()
>   81671    51.4606  loop(unsigned int)
>   76549    48.2332  slow_f() [self]
> -------------------------------------------------------------------------------
> 
> 
> Compiling the code without the -fno-omit-frame-pointer still gave meaningful results:
> 
> [wcohen@santana callgraph]$ rm -rf oprofile_data/
> [wcohen@santana callgraph]$ gcc -O0 -g foo.cpp -o ./foo
> [wcohen@santana callgraph]$ operf --callgraph ./foo
> operf: Profiler started
> 
> WARNING: Lost samples detected! See /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/operf.log for details.
> Lowering the sampling rate may reduce or eliminate lost samples.
> See the '--events' option description in the operf man page for help.
> 
> Profiling done.
> [wcohen@santana callgraph]$ opreport -cl ./foo -t1
> Using /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/ for samples directory.
> 
> WARNING: Lost samples detected! See /home/wcohen/research/profiling/oprofile/callgraph/oprofile_data/samples/operf.log for details.
> warning: /dm_crypt could not be found.
> warning: /kvm could not be found.
> CPU: Intel Ivy Bridge microarchitecture, speed 3300 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 90000
> samples  %        symbol name
> -------------------------------------------------------------------------------
>   83714    100.000  slow_f()
> 83181    50.6938  loop(unsigned int)
>   83181    99.3633  loop(unsigned int) [self]
> -------------------------------------------------------------------------------
>   164061   100.000  main
> 79763    48.6108  slow_f()
>   83714    51.0261  loop(unsigned int)
>   79763    48.6179  slow_f() [self]
> -------------------------------------------------------------------------------
> 
> 

Might also check to wee whether the equivalent perf command give reasonable results or fails in the same way.  There are several different callgraph methods for perf  ("fp", "dwarf", and "lbr").  Below is example run with "dwarf" mode.

-Will

[wcohen@santana callgraph]$ perf record --call-graph=dwarf ./foo
[ perf record: Woken up 610 times to write data ]
[ perf record: Captured and wrote 152.355 MB perf.data (18926 samples) ]
[wcohen@santana callgraph]$ perf report > perf.out
[wcohen@santana callgraph]$ more perf.out

[wcohen@santana callgraph]$ more perf.out
# To display the perf.data header info, please use --header/--header-only option
s.
#
#
# Total Lost Samples: 117
#
# Samples: 18K of event 'cycles:ppp'
# Event count (approx.): 14702272149
#
# Children      Self  Command  Shared Object     Symbol                         
        
# ........  ........  .......  ................  ...............................
........
#
    99.18%    49.49%  foo      foo               [.] slow_f
            |          
            |--49.69%--slow_f
            |          loop
            |          
             --49.48%--_start
                       __libc_start_main
                       main
                       slow_f

    99.17%     0.00%  foo      foo               [.] main
            |
            ---main
               slow_f
               |          
                --49.69%--loop

    99.17%     0.00%  foo      libc-2.23.so      [.] __libc_start_main
            |
            ---__libc_start_main
               main
               slow_f
               |          
                --49.69%--loop

    99.17%     0.00%  foo      foo               [.] _start
            |
            ---_start
               __libc_start_main
               main
               slow_f
               |          
                --49.69%--loop

    49.69%    49.69%  foo      foo               [.] loop
            |
            ---_start
               __libc_start_main
               main
               slow_f
               loop

     0.62%     0.62%  foo      [kernel.vmlinux]  [k] nmi
            |
            ---nmi


> 
> 
> 
> ------------------------------------------------------------------------------
> 
> 
> 
> _______________________________________________
> oprofile-list mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
> 

------------------------------------------------------------------------------
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.