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,2f
c00000000004d790: 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.
Signed-off-by: Anton Blanchard <[email protected]>
---
Cc: <[email protected]>
Index: linux-tip/tools/perf/util/annotate.c
===================================================================
--- linux-tip.orig/tools/perf/util/annotate.c 2012-01-09 17:45:09.056373433 +1100
+++ linux-tip/tools/perf/util/annotate.c 2012-02-07 13:53:01.610970209 +1100
@@ -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;
}
On Tue, 07 Feb 2012, Anton Blanchard wrote:
>
> 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,2f
> c00000000004d790: 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.
>
> Signed-off-by: Anton Blanchard <[email protected]>
Acked-by: Eric B Munson <[email protected]>
Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
>
> 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
> : _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,2f
> c00000000004d790: 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.
>
> Signed-off-by: Anton Blanchard <[email protected]>
> ---
> Cc: <[email protected]>
>
> Index: linux-tip/tools/perf/util/annotate.c
> ===================================================================
> --- linux-tip.orig/tools/perf/util/annotate.c 2012-01-09 17:45:09.056373433 +1100
> +++ linux-tip/tools/perf/util/annotate.c 2012-02-07 13:53:01.610970209 +1100
> @@ -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;
> }
>
On Tue, 2012-02-07 at 12:40 -0200, Arnaldo Carvalho de Melo wrote:
> Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
> >
> > 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
* Mike Galbraith <[email protected]> wrote:
> On Tue, 2012-02-07 at 12:40 -0200, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
> > >
> > > 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.
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
On Thu, 2012-02-09 at 14:31 +0100, Ingo Molnar wrote:
> * Mike Galbraith <[email protected]> wrote:
> > 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
On Thu, 2012-02-09 at 14:31 +0100, Ingo Molnar wrote:
> * Mike Galbraith <[email protected]> wrote:
>
> > On Tue, 2012-02-07 at 12:40 -0200, Arnaldo Carvalho de Melo wrote:
> > > Em Tue, Feb 07, 2012 at 02:55:35PM +1100, Anton Blanchard escreveu:
> > > >
> > > > 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.
>
> 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.
Tested-by: Mike Galbraith <[email protected]>
marge:/usr/local/src/kernel/linux-3.x-tip # make -j4
scripts/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