perf annotate: Numeric assembly labels cause incorrect annotation
PATCH 1/1 perf annotate: Numeric assembly labels cause incorrect annotation
A perf annotate of a kernel function written in assembly shows very strange percentages:
: _GLOBAL(__copy_tofrom_user_base)
...
: addi r3,r3,1
99.67 : c00000000004d78c: addi r3,r3,1
:
0.00 : 1: bf cr7*4+2,2f
0.07 : c00000000004d790: bne- cr7,c00000000004d7a4
: err1; lhz r0,0(r4)
0.00 : c00000000004d794: lhz r0,0(r4)
: addi r4,r4,2
0.00 : c00000000004d798: addi r4,r4,2
: err1; sth r0,0(r3)
0.00 : c00000000004d79c: sth r0,0(r3)
: addi r3,r3,2
99.60 : c00000000004d7a0: addi r3,r3,2
:
0.00 : 2: bf cr7*4+1,3f
0.12 : c00000000004d7a4: ble- cr7,c00000000004d7b8
: err1; lwz r0,0(r4)
0.00 : c00000000004d7a8: lwz r0,0(r4)
: addi r4,r4,4
0.00 : c00000000004d7ac: addi r4,r4,4
: err1; stw r0,0(r3)
0.00 : c00000000004d7b0: stw r0,0(r3)
: addi r3,r3,4 99.48 : c00000000004d7b4: addi r3,r3,4
~300% in one function. Urgh.
This is caused by the way we parse objdump -S output, eg:
addi r3,r3,1
c00000000004d78c: addi r3,r3,1
1: bf cr7*4+2,2fc00000000004d790: bne- cr7,c00000000004d7a4
We assume the asm label (1:) is an address, compute a bogus offset into the function and then screw up the matching of samples to lines. I notice this also fails with c inline assembly in a similar manner.
We already have a sanity check that the address is not beyond the end of the function, so add a check against the start too.
---
Cc: <[email protected]>
tools/perf/util/annotate.c +1 -1
@@ -244,7 +244,7 @@ static int symbol__parse_objdump_line(st end =map__rip_2objdump (map, sym->end); offset = line_ip - start; -if (offset <0 || (u64 )line_ip > end) +if (offset <0 || (u64 )line_ip < start || (u64 )line_ip > end) offset =-1 ; }
Quoted 48 lines · Anton Blanchard
A perf annotate of a kernel function written in assembly shows very strange percentages:
:
_GLOBAL(__copy_tofrom_user_base)...
: addi r3,r3,1
99.67 :c00000000004d78c: addi r3,r3,1: 0.00 : 1: bf cr7*4+2,2f 0.07 : c00000000004d790: bne- cr7,c00000000004d7a4 : err1; lhz r0,0(r4) 0.00 : c00000000004d794: lhz r0,0(r4) : addi r4,r4,2 0.00 : c00000000004d798: addi r4,r4,2 : err1; sth r0,0(r3) 0.00 : c00000000004d79c: sth r0,0(r3) : addi r3,r3,2 99.60 : c00000000004d7a0: addi r3,r3,2 : 0.00 : 2: bf cr7*4+1,3f 0.12 : c00000000004d7a4: ble- cr7,c00000000004d7b8 : err1; lwz r0,0(r4) 0.00 : c00000000004d7a8: lwz r0,0(r4) : addi r4,r4,4 0.00 : c00000000004d7ac: addi r4,r4,4 : err1; stw r0,0(r3) 0.00 : c00000000004d7b0: stw r0,0(r3) : addi r3,r3,499.48 :
c00000000004d7b4: addi r3,r3,4~300% in one function. Urgh.
This is caused by the way we parse objdump -S output, eg:
addi r3,r3,1
c00000000004d78c: addi r3,r3,11: bf cr7*4+2,2f
c00000000004d790: bne- cr7,c00000000004d7a4We assume the asm label (1:) is an address, compute a bogus offset into the function and then screw up the matching of samples to lines. I notice this also fails with c inline assembly in a similar manner.
Quoted 4 lines
We already have a sanity check that the address is not beyond the end of the function, so add a check against the start too.
Signed-off-by Anton Blanchard <[email protected]>
Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
Quoted 3 lines
A perf annotate of a kernel function written in assembly shows very strange percentages:
Thanks! I think this is the same problem Mike Galbraith noticed and reported me (I guess that was in a private message), Mike, can you please test it so that I can add more Foo-by stamps to this one?
- Arnaldo
Quoted 64 lines
:
_GLOBAL(__copy_tofrom_user_base)...
: addi r3,r3,1
99.67 :c00000000004d78c: addi r3,r3,1: 0.00 : 1: bf cr7*4+2,2f 0.07 : c00000000004d790: bne- cr7,c00000000004d7a4 : err1; lhz r0,0(r4) 0.00 : c00000000004d794: lhz r0,0(r4) : addi r4,r4,2 0.00 : c00000000004d798: addi r4,r4,2 : err1; sth r0,0(r3) 0.00 : c00000000004d79c: sth r0,0(r3) : addi r3,r3,2 99.60 : c00000000004d7a0: addi r3,r3,2 : 0.00 : 2: bf cr7*4+1,3f 0.12 : c00000000004d7a4: ble- cr7,c00000000004d7b8 : err1; lwz r0,0(r4) 0.00 : c00000000004d7a8: lwz r0,0(r4) : addi r4,r4,4 0.00 : c00000000004d7ac: addi r4,r4,4 : err1; stw r0,0(r3) 0.00 : c00000000004d7b0: stw r0,0(r3) : addi r3,r3,499.48 :
c00000000004d7b4: addi r3,r3,4~300% in one function. Urgh.
This is caused by the way we parse objdump -S output, eg:
addi r3,r3,1
c00000000004d78c: addi r3,r3,11: bf cr7*4+2,2f
c00000000004d790: bne- cr7,c00000000004d7a4We assume the asm label (1:) is an address, compute a bogus offset into the function and then screw up the matching of samples to lines. I notice this also fails with c inline assembly in a similar manner.
We already have a sanity check that the address is not beyond the end of the function, so add a check against the start too.
Signed-off-by Anton Blanchard <[email protected]>---
Cc: <[email protected]>Index:
linux-tip/tools/perf/util/annotate.c
===================================================================tools/perf/util/annotate.c +1
-1@@ -244,7 +244,7 @@ static int symbol__parse_objdump_line(st end =map__rip_2objdump (map, sym->end); offset = line_ip - start; -if (offset <0 || (u64 )line_ip > end) +if (offset <0 || (u64 )line_ip < start || (u64 )line_ip > end) offset =-1 ; }
Quoted 8 lines · Arnaldo Carvalho de Melo
Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
Quoted 3 lines
A perf annotate of a kernel function written in assembly shows very strange percentages:
Thanks! I think this is the same problem Mike Galbraith noticed and reported me (I guess that was in a private message), Mike, can you please test it so that I can add more Foo-by stamps to this one?
Sorry for the slow response (bz bz).
I don't see that problem, but perf top annotation isn't working properly in tip at least. It seems to have forgotten how to average, seems to be clearing hit counts at every screen refresh or something.
-Mike
Quoted 10 lines · Mike Galbraith
Quoted 8 lines · Arnaldo Carvalho de Melo
Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
Quoted 3 lines
A perf annotate of a kernel function written in assembly shows very strange percentages:
Thanks! I think this is the same problem Mike Galbraith noticed and reported me (I guess that was in a private message), Mike, can you please test it so that I can add more Foo-by stamps to this one?
Quoted 6 lines
Sorry for the slow response (bz bz).
I don't see that problem, but perf top annotation isn't working properly in tip at least. It seems to have forgotten how to average, seems to be clearing hit counts at every screen refresh or something.
hm, seems to work fine here. We used to have such a bug recently (as of a few weeks [days?] ago), but latest -tip does not show those symptoms.
Thanks,
Ingo
Quoted 9 lines · Ingo Molnar
Quoted 4 lines · Mike Galbraith
I don't see that problem, but perf top annotation isn't working properly in tip at least. It seems to have forgotten how to average, seems to be clearing hit counts at every screen refresh or something.
hm, seems to work fine here. We used to have such a bug recently (as of a few weeks [days?] ago), but latest -tip does not show those symptoms.
Fresh pulled from git server:
marge:/usr/local/src/kernel/git/linux-3.0-tip # git describe v3.3-rc2-1940-g8819807 marge:/usr/local/src/kernel/git/linux-3.0-tip # perf --version perf version 3.3.rc2.1940.g881980.dirty
get server:
git@marge:~/linux-2.6> git checkout x86-tip Switched to branch 'x86-tip'
Your branch is ahead of 'x86-tip/master' by 566 commits
Aha, need to drop/re-checkout again. Have to be careful with tip, it wiggles around on ya :)
-Mike
Mike Galbraith
Tested-byQuoted 14 lines · Ingo Molnar
Quoted 12 lines · Mike Galbraith
Quoted 8 lines · Arnaldo Carvalho de Melo
Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
Quoted 3 lines
A perf annotate of a kernel function written in assembly shows very strange percentages:
Thanks! I think this is the same problem Mike Galbraith noticed and reported me (I guess that was in a private message), Mike, can you please test it so that I can add more Foo-by stamps to this one?
Sorry for the slow response (bz bz).
Quoted 8 lines
Quoted 4 lines
I don't see that problem, but perf top annotation isn't working properly in tip at least. It seems to have forgotten how to average, seems to be clearing hit counts at every screen refresh or something.
hm, seems to work fine here. We used to have such a bug recently (as of a few weeks [days?] ago), but latest -tip does not show those symptoms.
Build dependency buglet snuck into tip config, but annotating master v3.3-rc3-0-gd65b4e9 with tips patched perf worked fine.
marge:/usr/local/src/kernel/linux-3.x-tip # make -j4scripts/kconfig/conf --silentoldconfig Kconfig
warning: (USB_WHCI_HCD && USB_HWA_HCD) selects USB_WUSB which has unmet direct dependencies (USB_SUPPORT && EXPERIMENTAL && USB && PCI && UWB)
warning: (USB_WHCI_HCD) selects UWB_WHCI which has unmet direct dependencies (UWB && PCI)
warning: (USB_WHCI_HCD && USB_HWA_HCD) selects USB_WUSB which has unmet direct dependencies (USB_SUPPORT && EXPERIMENTAL && USB && PCI && UWB)
warning: (USB_WHCI_HCD) selects UWB_WHCI which has unmet direct dependencies (UWB && PCI)
make[1]: Nothing to be done for `all'.
CHK include/linux/version.h CHK include/generated/utsrelease.h CALL scripts/checksyscalls.sh CHK include/generated/compile.h GZIP kernel/config_data.gz CHK kernel/config_data.h
Building modules, stage 2.
Kernel: arch/x86/boot/bzImage is ready (#2077)
MODPOST 611 modules
ERROR: "uwb_rsv_establish" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_pal_register" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rsv_get_usable_mas" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rsv_destroy" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_radio_stop" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rsv_terminate" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_pal_unregister" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_pal_init" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rc_reset_all" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_radio_start" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rsv_create" [drivers/usb/wusbcore/wusbcore.ko] undefined!
ERROR: "uwb_rc_put" [drivers/usb/host/whci/whci-hcd.ko] undefined!
ERROR: "uwb_rc_get_by_grandpa" [drivers/usb/host/whci/whci-hcd.ko] undefined!
ERROR: "__umc_driver_register" [drivers/usb/host/whci/whci-hcd.ko] undefined!
ERROR: "umc_driver_unregister" [drivers/usb/host/whci/whci-hcd.ko] undefined!
ERROR: "whci_wait_for" [drivers/usb/host/whci/whci-hcd.ko] undefined! make[1]: *** [__modpost] Error 1
make: *** [modules] Error 2 marge:/usr/local/src/kernel/linux-3.x-tip # git describe v3.3-rc2-1377-gf4ab688