Discussion:
callgraph not working
(too old to reply)
enrico .
2016-11-18 12:04:17 UTC
Permalink
Raw Message
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;
}
William Cohen
2016-11-28 16:39:22 UTC
Permalink
Raw Message
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

[***@santana callgraph]$ rpm -q oprofile
oprofile-1.1.0-4.fc24.x86_64
[***@santana callgraph]$ uname -r
4.8.8-200.fc24.x86_64
[***@santana callgraph]$ gcc -fno-omit-frame-pointer -g foo.cpp -o ./foo

[***@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.
[***@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:

[***@santana callgraph]$ rm -rf oprofile_data/
[***@santana callgraph]$ gcc -O0 -g foo.cpp -o ./foo
[***@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.
[***@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]
-------------------------------------------------------------------------------




------------------------------------------------------------------------------
enrico .
2016-11-28 17:01:33 UTC
Permalink
Raw Message
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 <***@redhat.com>
Inviato: lunedì 28 novembre 2016 17.39
A: enrico .; oprofile-***@lists.sourceforge.net
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

[***@santana callgraph]$ rpm -q oprofile
oprofile-1.1.0-4.fc24.x86_64
[***@santana callgraph]$ uname -r
4.8.8-200.fc24.x86_64
[***@santana callgraph]$ gcc -fno-omit-frame-pointer -g foo.cpp -o ./foo

[***@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.
[***@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:

[***@santana callgraph]$ rm -rf oprofile_data/
[***@santana callgraph]$ gcc -O0 -g foo.cpp -o ./foo
[***@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.
[***@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]
-------------------------------------------------------------------------------
William Cohen
2016-11-28 19:42:51 UTC
Permalink
Raw Message
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!

Which version of gcc and what are the default options is gcc using?

include a -v in the gcc compilation command line and include the results. Below is what gcc-5.2.1-2.fc24.x86_64 is using on fedora 24.

-Will

$ gcc -v -O0 -g foo.cpp -o ./foo
Using built-in specs.
COLLECT_GCC=/usr/bin/gcc
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --enable-bootstrap --enable-languages=c,c++,objc,obj-c++,fortran,ada,go,lto --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-shared --enable-threads=posix --enable-checking=release --enable-multilib --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-linker-build-id --with-linker-hash-style=gnu --enable-plugin --enable-initfini-array --disable-libgcj --with-isl --enable-libmpx --enable-gnu-indirect-function --with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 6.2.1 20160916 (Red Hat 6.2.1-2) (GCC)
COLLECT_GCC_OPTIONS='-v' '-O0' '-g' '-o' './foo' '-mtune=generic' '-march=x86-64'
/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/cc1plus -quiet -v -D_GNU_SOURCE foo.cpp -quiet -dumpbase foo.cpp -mtune=generic -march=x86-64 -auxbase foo -g -O0 -version -o /tmp/cc19JmoT.s
GNU C++14 (GCC) version 6.2.1 20160916 (Red Hat 6.2.1-2) (x86_64-redhat-linux)
compiled by GNU C version 6.2.1 20160916 (Red Hat 6.2.1-2), GMP version 6.1.1, MPFR version 3.1.4, MPC version 1.0.2, isl version 0.14 or 0.13
warning: MPFR header version 3.1.4 differs from library version 3.1.5.
GGC heuristics: --param ggc-min-expand=100 --param ggc-min-heapsize=131072
ignoring nonexistent directory "/usr/lib/gcc/x86_64-redhat-linux/6.2.1/include-fixed"
ignoring nonexistent directory "/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../x86_64-redhat-linux/include"
#include "..." search starts here:
#include <...> search starts here:
/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../include/c++/6.2.1
/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../include/c++/6.2.1/x86_64-redhat-linux
/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../include/c++/6.2.1/backward
/usr/lib/gcc/x86_64-redhat-linux/6.2.1/include
/usr/local/include
/usr/include
End of search list.
GNU C++14 (GCC) version 6.2.1 20160916 (Red Hat 6.2.1-2) (x86_64-redhat-linux)
compiled by GNU C version 6.2.1 20160916 (Red Hat 6.2.1-2), GMP version 6.1.1, MPFR version 3.1.4, MPC version 1.0.2, isl version 0.14 or 0.13
warning: MPFR header version 3.1.4 differs from library version 3.1.5.
GGC heuristics: --param ggc-min-expand=100 --param ggc-min-heapsize=131072
Compiler executable checksum: 67ace16233bb78a15f6542a6d83e72a1
COLLECT_GCC_OPTIONS='-v' '-O0' '-g' '-o' './foo' '-mtune=generic' '-march=x86-64'
as -v --64 -o /tmp/ccJue2s1.o /tmp/cc19JmoT.s
GNU assembler version 2.26.1 (x86_64-redhat-linux) using BFD version version 2.26.1-1.fc24
COMPILER_PATH=/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/:/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/:/usr/libexec/gcc/x86_64-redhat-linux/:/usr/lib/gcc/x86_64-redhat-linux/6.2.1/:/usr/lib/gcc/x86_64-redhat-linux/
LIBRARY_PATH=/usr/lib/gcc/x86_64-redhat-linux/6.2.1/:/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../lib64/:/lib/../lib64/:/usr/lib/../lib64/:/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../:/lib/:/usr/lib/
COLLECT_GCC_OPTIONS='-v' '-O0' '-g' '-o' './foo' '-mtune=generic' '-march=x86-64'
/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/collect2 -plugin /usr/libexec/gcc/x86_64-redhat-linux/6.2.1/liblto_plugin.so -plugin-opt=/usr/libexec/gcc/x86_64-redhat-linux/6.2.1/lto-wrapper -plugin-opt=-fresolution=/tmp/cctcLEy9.res -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lc -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s --build-id --no-add-needed --eh-frame-hdr --hash-style=gnu -m elf_x86_64 -dynamic-linker /lib64/ld-linux-x86-64.so.2 -o ./foo /usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../lib64/crt1.o /usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../lib64/crti.o /usr/lib/gcc/x86_64-redhat-linux/6.2.1/crtbegin.o -L/usr/lib/gcc/x86_64-redhat-linux/6.2.1 -L/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../lib64 -L/lib/../lib64 -L/usr/lib/../lib64 -L/usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../.. /tmp/ccJue2s1.o -lgcc --as-needed -lgcc_s --no-as-needed -lc -lgcc --as-needed -lgcc_s --no-as-needed /usr/lib/gcc/x86_64-redhat-linux/6.2.1/crtend.o /usr/lib/gcc/x86_64-redhat-linux/6.2.1/../../../../lib64/crtn.o
COLLECT_GCC_OPTIONS='-v' '-O0' '-g' '-o' './foo' '-mtune=generic' '-march=x86-64'

>
>
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> *Da:* William Cohen <***@redhat.com>
> *Inviato:* lunedì 28 novembre 2016 17.39
> *A:* enrico .; oprofile-***@lists.sourceforge.net
> *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
>
> [***@santana callgraph]$ rpm -q oprofile
> oprofile-1.1.0-4.fc24.x86_64
> [***@santana callgraph]$ uname -r
> 4.8.8-200.fc24.x86_64
> [***@santana callgraph]$ gcc -fno-omit-frame-pointer -g foo.cpp -o ./foo
>
> [***@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.
> [***@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:
>
> [***@santana callgraph]$ rm -rf oprofile_data/
> [***@santana callgraph]$ gcc -O0 -g foo.cpp -o ./foo
> [***@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.
> [***@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]
> -------------------------------------------------------------------------------
>
>
>
>
>
> ------------------------------------------------------------------------------
>
>
>
> _______________________________________________
> oprofile-list mailing list
> oprofile-***@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
>

------------------------------------------------------------------------------
William Cohen
2016-11-28 19:48:57 UTC
Permalink
Raw Message
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 <***@redhat.com>
> *Inviato:* lunedì 28 novembre 2016 17.39
> *A:* enrico .; oprofile-***@lists.sourceforge.net
> *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
>
> [***@santana callgraph]$ rpm -q oprofile
> oprofile-1.1.0-4.fc24.x86_64
> [***@santana callgraph]$ uname -r
> 4.8.8-200.fc24.x86_64
> [***@santana callgraph]$ gcc -fno-omit-frame-pointer -g foo.cpp -o ./foo
>
> [***@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.
> [***@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:
>
> [***@santana callgraph]$ rm -rf oprofile_data/
> [***@santana callgraph]$ gcc -O0 -g foo.cpp -o ./foo
> [***@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.
> [***@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

[***@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) ]
[***@santana callgraph]$ perf report > perf.out
[***@santana callgraph]$ more perf.out

[***@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
> oprofile-***@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/oprofile-list
>

------------------------------------------------------------------------------
Loading...