OProfile

On Tue, Apr 26, 2005 at 02:11:02PM +0200, Joerg Maier wrote:

> i have a few questions concerning the usage of oprofile on a SLES9-rc5
> kernel (2.6.5-7.111) (oprofile codelevel oprofile 0.8.2)
> 
> # opreport -lg | head ...
> 39472    50.2905  op_model_power4.c:64 vmlinux-2.6.5-7.111.050422-debug-pseries64 par_mem .kernel_unknown_bucket
> 38249    48.7323  idle.c:133 vmlinux-2.6.5-7.111.050422-debug-pseries64 vmlinux-2.6.5-7.111.050422-debug-pseries64 .default_idle
> 147       0.1873  op_model_power4.c:64 vmlinux-2.6.5-7.111.050422-debug-pseries64 bash .kernel_unknown_bucket
> 90        0.1147  op_model_power4.c:64 vmlinux-2.6.5-7.111.050422-debug-pseries64 vmlinux-2.6.5-7.111.050422-debug-pseries64 .kernel_unknown_bucket

This is pretty odd. Maynard, is this some weird PPC64 thing? It would be
quite surprising to see 50% of the samples in op_model_power4.c,
especially the given line number. It /should/ be telling you
"power4_reg_setup" as the symbol. Can you do nm on the vmlinux and look
for that (then check it against opreport -wlg output) ?

The fact that we list random apps for code that's never called in such a
context indicates something is wrong. Are you positive it's the right up
to date vmlinux that you're running?

Have you changed your kernel, but forgotten to clean out the old data
(opcontrol --reset) ?

I'm afraid I know nothing about PPC64 so I might not be much help here.

> not kno the name? Or is the recent symbol in par-mem, then i think it
> is reasoned that the symbol may be unknown.)

The symbol would only be in par_mem if the entry in the "image name"
column" listed "par_mem". The above four entries are all kernel entries.

regards
john

he john,

> "power4_reg_setup" as the symbol. Can you do nm on the vmlinux and look
> for that (then check it against opreport -wlg output) ?
c03b01-0:~ # nm /boot/vmlinux-2.6.5-7.111.050422-debug-pseries64 | \
	   grep power4_reg_setup
c0000000002c3138 t .power4_reg_setup
c000000000651170 d power4_reg_setup

I dont have the old session anymore to start opreport mit -w option,
here is a new session. The requested address contains no symbol.

c0000000002c3204 1647089  11.1914  op_model_power4.c:64        vmlinux-2.6.5-7.111.050422-debug-pseries64 par_mem                  .kernel_unknown_bucket

> The symbol would only be in par_mem if the entry in the "image name"
> column" listed "par_mem". The above four entries are all kernel entries.

This is just to give my thoughts:
If the image name differs from the app name (as i see a lot), this is
eg during a syscall, when the kernel executes in process context
kernel code? What situations else lead to that?

Thanks for your hints.
joerg maier

On Tue, Apr 26, 2005 at 07:14:35PM +0200, Joerg Maier wrote:

> > "power4_reg_setup" as the symbol. Can you do nm on the vmlinux and look
> > for that (then check it against opreport -wlg output) ?
> c03b01-0:~ # nm /boot/vmlinux-2.6.5-7.111.050422-debug-pseries64 | \
> 	   grep power4_reg_setup
> c0000000002c3138 t .power4_reg_setup
> c000000000651170 d power4_reg_setup
> 
> I dont have the old session anymore to start opreport mit -w option,
> here is a new session. The requested address contains no symbol.
> 
> c0000000002c3204 1647089  11.1914  op_model_power4.c:64        vmlinux-2.6.5-7.111.050422-debug-pseries64 par_mem                  .kernel_unknown_bucket

This indicates even more that it's the wrong vmlinux, or there's some
problem in ppc64 binutils whereby this VMA should be covered by a
symbol range, but isn't. Can you try disassembling around this VMA (with
gdb probably) and see if it looks like sane instructions?

Also, look up the file offset of the .text section with  objdump -h. If
you add, or subtract, that value from/to  the vma, do you get anything
saner?

> > The symbol would only be in par_mem if the entry in the "image name"
> > column" listed "par_mem". The above four entries are all kernel entries.
> 
> This is just to give my thoughts:
> If the image name differs from the app name (as i see a lot), this is
> eg during a syscall, when the kernel executes in process context
> kernel code?

Yes

> What situations else lead to that?

You also see this if there's an interrupt into the kernel when it was
in user space at the time

regards
john

dear john,

> This indicates even more that it's the wrong vmlinux, or there's some
> problem in ppc64 binutils whereby this VMA should be covered by a

If you mean wrong vmlinux as a diff in the .oprofile/daemonrc
configured and the booted one, i think there is none.
Before the benchmark is run i start a opcontrol setup script which executes:
    opcontrol --shutdown
    opcontrol --reset
    opcontrol --vmlinux=/boot/vmlinux-`uname -r`
    opcontrol --event=CYCLES:1200000
    opcontrol --verbose
    opcontrol --start-daemon
    opcontrol --start

 # uname -r
2.6.5-7.111.050422-debug-pseries64
 # /sbin/get_kernel_version /boot/vmlinux-`uname -r`
2.6.5-7.111.050422-debug-pseries64

> symbol range, but isn't. Can you try disassembling around this VMA (with
> gdb probably) and see if it looks like sane instructions?

c0000000002c3204 <.kernel_unknown_bucket>:
c0000000002c3204:       4e 80 00 20     blr
blr means branch to LR, there is no LR set in before? I did not get
used to powerpc64 assembler code at all, but 


> Also, look up the file offset of the .text section with  objdump -h. If
> you add, or subtract, that value from/to  the vma, do you get anything
> saner?
The offset to the .text section is 0 (its the first section), so it
will make no difference adding from or to the vma unknown kernel
bucket address.

Maynard,
> I've never noticed any instances of this in the testing I've done on Power4,
> Power5, and PPC970.  Please send us the information Carl requested.
My Machine is a js20  PPC970FX, altivec supported.

I hope i answered all questions satisfactory, thank you all helping me
with that strange reports.

Regards,
Joerg Maier

On Wed, Apr 27, 2005 at 10:58:36AM +0200, Joerg Maier wrote:

> > Also, look up the file offset of the .text section with  objdump -h. If
> > you add, or subtract, that value from/to  the vma, do you get anything
> > saner?
> The offset to the .text section is 0 (its the first section), so it

There must at least be some offset, there's an ELF header first :)

john

dear john,

> > > Also, look up the file offset of the .text section with  objdump -h. If
> > > you add, or subtract, that value from/to  the vma, do you get anything
> > > saner?
> > The offset to the .text section is 0 (its the first section), so it
> 
> There must at least be some offset, there's an ELF header first :)
I am sorry, objdump -h gave me:
Sections:
Idx Name          Size      VMA               LMA               File off  Algn
  0 .text         00380000  c000000000000000  c000000000000000  00010000  2**8
                  CONTENTS, ALLOC, LOAD, READONLY, CODE

I was wrong. You meant the File offset which is reasonable.

Adding 0x10000 to 0x2b3138 points to the code:
c0000000002a3138:       40 a2 ff f4     bne-    c0000000002a312c
<.matroxfb_ioc\tl+0x608>
c0000000002a313c:       4c 00 01 2c     isync
c0000000002a3140:       7c 00 07 b4     extsw   r0,r0
c0000000002a3144:       2f 80 ff ff     cmpwi   cr7,r0,-1
c0000000002a3148:       41 9c 06 d8     blt-    cr7,c0000000002a3820
<.matroxfb\_ioctl+0xcfc>
c0000000002a314c:       2f 9a 00 00     cmpwi   cr7,r26,0

Subtracting it leads to:
c0000000002c3138 <.power4_reg_setup>:
c0000000002c3138:       7c 1f 42 a6     mfpvr   r0
c0000000002c313c:       78 09 84 22     rldicl  r9,r0,48,48
c0000000002c3140:       fb c1 ff f0     std     r30,-16(r1)

We have another idea what may lead to the unexpected
unknown_kernel_bucket, even if not in that dimension. If oprofile
looks which binary image is executing actually and the pointer to the
code points to firmware code, it cant decide correct? 

Am i right that if executing code that is prior to the kernel image in
ram (openfirmware code), we will see unknown_kernel_bucket symbol? I
am not sure why i see the strange sourcefile then
(op_model_power4.c:64).

thank you 
joerg

On Wed, Apr 27, 2005 at 07:23:22PM +0200, Joerg Maier wrote:

> Am i right that if executing code that is prior to the kernel image in
> ram (openfirmware code), we will see unknown_kernel_bucket symbol? I

Sounds reasonable.

> am not sure why i see the strange sourcefile then
> (op_model_power4.c:64).

Me neither, perhaps you could add some debug to op_bfd.cpp to see which
bit of get_linenr is returning that

regards
john

Hi,

> My Machine is a js20  PPC970FX, altivec supported.

I think this is your problem. Orginally we enabled a feature that tells
you if a sample is kernel or userspace (SIHV bit in the MMCRA). It turns
out it doesnt work as expected on 970.

More recent kernels have the correct check. You can simply comment out
the code in op_model_power4.c that sets mmcra_has_sihv to 1. This
feature works as expected in POWER5, so we enable it there in mainline.

The bug means all user samples get marked as kernel and then get thrown
into kernel_unknown.

Anton

Hi,

> This is pretty odd. Maynard, is this some weird PPC64 thing? It would be
> quite surprising to see 50% of the samples in op_model_power4.c,
> especially the given line number. It /should/ be telling you
> "power4_reg_setup" as the symbol. Can you do nm on the vmlinux and look
> for that (then check it against opreport -wlg output) ?

This issue highlights the current hacks we have on ppc64:

- all unknown kernel ticks go to kernel_unknown_bucket.
- all hypervisor ticks go to the hypervisor_bucket
- all rtas ticks (rtas can be thought of as part of firmware) go to
  the rtas_bucket

We can clean this up with a few changes:

- Dont drop unknown samples. unknown_kernel_bucket was a quick hack to
  make sure we never lost samples. We should be doing that in the
  oprofile userspace instead. It would be nice to summarize
  these unknown user/kernel/hypervisor ticks separately.

- Create a new state for hypervisor samples. We can then pass this data
  straight out to oprofile. 

- Keep the rtas_bucket. Its a pain to work out if a tick happened in
  RTAS and time spent there should be fairly low. So adding them all
  into this bucket sounds reasonable, its a ppc specific thing anyway.

Anton

On Fri, Apr 29, 2005 at 11:29:15PM +1000, Anton Blanchard wrote:

> - Dont drop unknown samples. unknown_kernel_bucket was a quick hack to
>   make sure we never lost samples. We should be doing that in the
>   oprofile userspace instead. It would be nice to summarize
>   these unknown user/kernel/hypervisor ticks separately.

Yes, this is something we've needed for some time. It's not entirely
trivial as the analysis code is symbol-based, but I think we can do it.

regards
john

Hey,

> Hi,
> 
> > My Machine is a js20  PPC970FX, altivec supported.
> 
> I think this is your problem. Orginally we enabled a feature that tells
> you if a sample is kernel or userspace (SIHV bit in the MMCRA). It turns
> out it doesnt work as expected on 970.

i heard of this problem before, but had no detailed description.

> More recent kernels have the correct check. You can simply comment out
> the code in op_model_power4.c that sets mmcra_has_sihv to 1. This
> feature works as expected in POWER5, so we enable it there in mainline.

i will try that.

> the bug means all user samples get marked as kernel and then get thrown
> into kernel_unknown.

thanks for that hint.
joerg

That did it! thanks a lot! Cant we check if the cpu is ppc970 as well
and then dont set mmcra_has_sihv?

> > More recent kernels have the correct check. You can simply comment out
> > the code in op_model_power4.c that sets mmcra_has_sihv to 1. This
> > feature works as expected in POWER5, so we enable it there in mainline.

regards,
joerg