warning dump

warning dump

[ersatz splatt]

When I run a script to trace activity of a loaded driver, I get a
warning dump (below).  This is not really a big problem for me ...
since it does drive a trace output.  I would like to understand the
source of the problem more clearly though -- to better trust my
results.

I have a couple of theories -- one is that systemtap is having trouble
finding all the symbols it sees a reference too (since the script asks
for every function entry and exit point).  The other theory is that
there is some problem with the extent of interrupt activity when the
script is run.  That doesn't seem very likely since I modified the
script to start tracing activity later -- so I can start stap first
and then generate I/O (using fio to generate reads) after the script
has started but before the trace is triggered.  [that is: 1. start
script  2. start I/O 3. script starts tracing ]  I also tried
commenting out the prints -- and still a warning dump.

I also see a pretty heavy load on the system when running this -- even
when I comment the prints out.  Without systemtap, I'm getting about
70k IOPS per fio.  With the systemtap script running (see below the
warning dump -- though the prints are not commented out) I get about
17K IOPS.  I know I can make a scripts that is not as heavy (by being
more selective about which functions I'm probing) and I (think I) get
the call trace I'm looking for anyhow.  Some other work I'm doing I
still see a very heavy hit on I/O performance with only a few probe
points ... but that is getting too deep into another discussion.

This is running on a custom built kernel 2.6.34.7 on fc14.  System is
a 24 core x86_64.  I/O is through SAS via PCIe HBA.

Thanks in advance for any insight regarding the warnings.  I'm in no
rush though, since I'm getting by as is.


Regards,
David



pm8001_eg]# stap sampleSpcMod1.stp > pm8001outputMod1.txt
WARNING: probe module("pm8001").function("clear_bit@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/bitops.h:98")
(address 0xffffffffa0019611) registration error (rc -22)
WARNING: probe module("pm8001").function("test_and_set_bit@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/bitops.h:195")
(address 0xffffffffa0019373) registration error (rc -22)
WARNING: probe module("pm8001").function("tasklet_schedule@include/linux/interrupt.h:471")
(address 0xffffffffa0019373) registration error (rc -22)
WARNING: probe module("pm8001").function("kmalloc@include/linux/slub_def.h:235")
(address 0xffffffffa00196e4) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_chip_msix_interrupt_enable@drivers/scsi/pm8001/pm8001_hwi.c:1135")
(address 0xffffffffa001b9ae) registration error (rc -84)
WARNING: probe module("pm8001").function("kmalloc@include/linux/slub_def.h:235")
(address 0xffffffffa00214ba) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_chip_msix_interrupt_disable@drivers/scsi/pm8001/pm8001_hwi.c:1153")
(address 0xffffffffa001b9cf) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001b9b5) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001b9d6) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001cc1a) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001d201) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001d374) registration error (rc -84)
WARNING: probe module("pm8001").function("writel@/home/david/lbld/linux-2.6.34.7/arch/x86/include/asm/io.h:64")
(address 0xffffffffa001d37a) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001c866) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001c8c3) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001cafc) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001ca98) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d488) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001ce4a) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001ceb4) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d1ae) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d1f0) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d324) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d359) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d396) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d3c3) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d3f9) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cr32@drivers/scsi/pm8001/pm8001_chips.h:54")
(address 0xffffffffa001d42a) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001b9ae) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001b9cf) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001cb95) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001cc13) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001d1b8) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001d36d) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa001d37a) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa002130c) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_cw32@drivers/scsi/pm8001/pm8001_chips.h:60")
(address 0xffffffffa00212d5) registration error (rc -84)
WARNING: probe module("pm8001").function("pm8001_read_32@drivers/scsi/pm8001/pm8001_chips.h:44")
(address 0xffffffffa00213f2) registration error (rc -84)
WARNING: Number of errors: 0, skipped probes: 4



Begin script:


global triggerTrace, exitCount
global startTime


probe begin {
  triggerTrace=0
  exitCount=0
  startTime=gettimeofday_s()
  printf ("hello world -- %d\n", startTime)
}


probe module("pm8001").function("*") {
  if ( triggerTrace == 10 ) {
    exitCount++
    printf ("%s -> %s\n", thread_indent(1), probefunc())
  }
}

probe module("pm8001").function("*").return {
  if ( triggerTrace == 10 ) {
    exitCount++
    printf ("%s <- %s\n", thread_indent(-1), probefunc())
  }
}

probe timer.s(1) {
  triggerTrace++
}


probe timer.ms(1) {
  if ( exitCount >= 1000 ) {
    printf ( "BYE NOW! %d \n", exitCount )
    exit ()
  }
}

Re: warning dump

[Josh Stone]

On 06/17/2011 12:22 PM, ersatz splatt wrote:
> When I run a script to trace activity of a loaded driver, I get a
> warning dump (below).  This is not really a big problem for me ...
> since it does drive a trace output.  I would like to understand the
> source of the problem more clearly though -- to better trust my
> results.

The two return codes shown are -22 (-EINVAL) and -84 (-EILSEQ).  These
are codes from kprobes internals, not systemtap itself.  There's not
much to go on to find out why, but you can peruse through:

  kernel/kprobes.c
  arch/x86/kernel/kprobes.c

EINVAL is all over the place, but EILSEQ only shows up in the arch code,
either from the test !can_probe() in arch_prepare_kprobe() or from
!can_optimize() in arch_prepare_optimized_kprobe().  The return value
from _optimized is not checked or reported (eek!), so it must be an
error of can_probe().  The comment of that function is:

  /* Check if paddr is at an instruction boundary */

Apparently it thinks some of your probes are not on instruction
boundaries.  This could be a kprobes bug or a systemtap placement bug,
but it's hard to say without looking at your actual module versus the
stap's probe addresses.

> I also see a pretty heavy load on the system when running this -- even
> when I comment the prints out.  Without systemtap, I'm getting about
> 70k IOPS per fio.  With the systemtap script running (see below the
> warning dump -- though the prints are not commented out) I get about
> 17K IOPS.  I know I can make a scripts that is not as heavy (by being
> more selective about which functions I'm probing) and I (think I) get
> the call trace I'm looking for anyhow.  Some other work I'm doing I
> still see a very heavy hit on I/O performance with only a few probe
> points ... but that is getting too deep into another discussion.

Even without prints, you're taking an INT3 debug trap for every probe
that's encountered.  The kprobe optimizer tries to turn these into
function calls instead, but it can't always do that.  So whatever you
can do to reduce the number of probes placed will probably help.

For instance:

> probe module("pm8001").function("*") {

> probe module("pm8001").function("*").return {

Your script looks like it wants balanced call/return.  You may not be
aware though, the first one actually covers both .call and .inline
function variants, and there's no .return to match .inline.  Your script
will correctly balanced if you use .call on the first probe, and then
you'll also save overhead where there were .inline probes before.


Josh

Re: warning dump

[ersatz splatt]

Thanks much Josh!

Adding .call to the function reference gets rid of all the warnings.
... and makes the trace much more readable.  It also boosts the IOPS
to about 23k.  Turning the prints back on will bump it back down.  It
is nice to have some clarity about the operation.


Regards,
David



On Fri, Jun 17, 2011 at 1:03 PM, Josh Stone <jistone@redhat.com> wrote:
> On 06/17/2011 12:22 PM, ersatz splatt wrote:
>> When I run a script to trace activity of a loaded driver, I get a
>> warning dump (below).  This is not really a big problem for me ...
>> since it does drive a trace output.  I would like to understand the
>> source of the problem more clearly though -- to better trust my
>> results.
>
> The two return codes shown are -22 (-EINVAL) and -84 (-EILSEQ).  These
> are codes from kprobes internals, not systemtap itself.  There's not
> much to go on to find out why, but you can peruse through:
>
>  kernel/kprobes.c
>  arch/x86/kernel/kprobes.c
>
> EINVAL is all over the place, but EILSEQ only shows up in the arch code,
> either from the test !can_probe() in arch_prepare_kprobe() or from
> !can_optimize() in arch_prepare_optimized_kprobe().  The return value
> from _optimized is not checked or reported (eek!), so it must be an
> error of can_probe().  The comment of that function is:
>
>  /* Check if paddr is at an instruction boundary */
>
> Apparently it thinks some of your probes are not on instruction
> boundaries.  This could be a kprobes bug or a systemtap placement bug,
> but it's hard to say without looking at your actual module versus the
> stap's probe addresses.
>
>> I also see a pretty heavy load on the system when running this -- even
>> when I comment the prints out.  Without systemtap, I'm getting about
>> 70k IOPS per fio.  With the systemtap script running (see below the
>> warning dump -- though the prints are not commented out) I get about
>> 17K IOPS.  I know I can make a scripts that is not as heavy (by being
>> more selective about which functions I'm probing) and I (think I) get
>> the call trace I'm looking for anyhow.  Some other work I'm doing I
>> still see a very heavy hit on I/O performance with only a few probe
>> points ... but that is getting too deep into another discussion.
>
> Even without prints, you're taking an INT3 debug trap for every probe
> that's encountered.  The kprobe optimizer tries to turn these into
> function calls instead, but it can't always do that.  So whatever you
> can do to reduce the number of probes placed will probably help.
>
> For instance:
>
>> probe module("pm8001").function("*") {
>
>> probe module("pm8001").function("*").return {
>
> Your script looks like it wants balanced call/return.  You may not be
> aware though, the first one actually covers both .call and .inline
> function variants, and there's no .return to match .inline.  Your script
> will correctly balanced if you use .call on the first probe, and then
> you'll also save overhead where there were .inline probes before.
>
>
> Josh
>