kernel read fault when accessing context variables

kernel read fault when accessing context variables

[tonyg362]

systemtap version 0.0.20090613-1
Ubuntu 9.10 x86_64 kernel 2.6.31-22-generic
debug kernel installed using 2.6.31-22 according to the instructions here:
http://sourceware.org/systemtap/wiki/SystemtapOnUbuntu

I'm trying to access the prev/next task structs within the scheduler e.g.

probe kernel.statement("schedule@kernel/sched.c:line#") {
    ppid = $prev->tgid
    npid = $npid->tgid

    printf("ppid:%d, npid:%d\n", ppid, npid)
}

I am able access $npid->tgid just fine and it prints the correct npid,
however whenever I try to access $prev->tgid the entire probe is skipped and
I get a kernel read fault:

SystemTap translator/driver (version 0.9.8/0.141 non-git sources)
Copyright (C) 2005-2009 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
Session arch: x86_64 release: 2.6.31-22-generic
Created temporary directory "/tmp/stapmQJ4zq"
Searched '/usr/share/systemtap/tapset/x86_64/*.stp', found 3
Searched '/usr/share/systemtap/tapset/*.stp', found 51
Pass 1: parsed user script and 54 library script(s) in 350usr/50sys/443real
ms.
blacklist regexps:
blfn:
^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|.*raw_.*lock.*|.*read_.*lock.*|.*write_.*lock.*|.*spin_.*lock.*|.*rwlock_.*lock.*|.*rwsem_.*lock.*|.*mutex_.*lock.*|raw_.*|.*seq_.*lock.*|atomic_.*|atomic64_.*|get_bh|put_bh|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to)$
blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
blfile:
^(kernel/kprobes.c|arch/.*/kernel/kprobes.c|include/asm/io.h|include/asm/bitops.h|arch/.*/include/asm/io.h|arch/.*/include/asm/bitops.h|drivers/ide/ide-iops.c)$
parsed 'schedule@kernel/sched.c:5364' -> func 'schedule', file
'kernel/sched.c', line 0x7fff7a68e9d4
focused on module 'kernel = [0xffffffff81000000-0xffffffff81a0c000, bias
0x0] file /usr/lib/debug/boot/vmlinux-2.6.31-22-generic ELF machine |x86_64
(code 62)
focused on module 'kernel'
selected source file '/build/buildd/linux-2.6.31/kernel/sched.c'
selected function schedule
probe schedule@/build/buildd/linux-2.6.31/kernel/sched.c:5365 kernel
reloc=.dynamic section=.text pc=0xffffffff8152bc4e
finding location for local 'prev' near address 0xffffffff8152bc4e, module
bias 0x0
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 embed(s), 0 global(s)
in 620usr/390sys/1030real ms.
Pass 3: using cached
/home/tony/.systemtap/cache/37/stapconf_372e45b50185996104fc41217631e5f5_364.h
Pass 3: using cached
/home/tony/.systemtap/cache/f4/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.c
Pass 4: using cached
/home/tony/.systemtap/cache/f4/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko
Pass 5: starting run.
Running /usr/bin/staprun -v -v -c '/usr/bin/gedit'
/tmp/stapmQJ4zq/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko
staprun:main:269
modpath="/tmp/stapmQJ4zq/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko",
modname="stap_f43d8fd5008d00d09fc93292d18a3a6d_1120"
staprun:check_signature:224 checking signature for
/tmp/stapmQJ4zq/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko
staprun:check_signature:241 verify_module returns 0
staprun:init_staprun:207 init_staprun
staprun:insert_module:53 inserting module
staprun:insert_module:72 module options: _stp_bufsize=0
staprun:init_ctl_channel:30 Opening
/sys/kernel/debug/systemtap/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120/.cmd
execing: /usr/lib/systemtap/stapio -v -v -c /usr/bin/gedit
/tmp/stapmQJ4zq/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko 
stapio:main:37
modpath="/tmp/stapmQJ4zq/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120.ko",
modname="stap_f43d8fd5008d00d09fc93292d18a3a6d_1120"
stapio:init_stapio:290 init_stapio
stapio:init_ctl_channel:30 Opening
/sys/kernel/debug/systemtap/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120/.cmd
stapio:stp_main_loop:471 in main loop
stapio:stp_main_loop:478 nb=4
stapio:init_relayfs:234 initializing relayfs
stapio:init_relayfs:258 attempting to open
/sys/kernel/debug/systemtap/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120/trace0
stapio:init_relayfs:258 attempting to open
/sys/kernel/debug/systemtap/stap_f43d8fd5008d00d09fc93292d18a3a6d_1120/trace1
stapio:init_relayfs:264 ncpus=1, bulkmode = 0
stapio:init_relayfs:335 starting threads
stapio:stp_main_loop:478 nb=12
stapio:stp_main_loop:519 probe_start() returned 0
stapio:stp_main_loop:525 detaching pid 22717
stapio:stp_main_loop:478 nb=99
ERROR: kernel read fault at 0x000000000000029d (addr) near identifier
'$prev' at test.stp:2:9
stapio:stp_main_loop:478 nb=4
stapio:stp_main_loop:511 got STP_REQUEST_EXIT
stapio:chld_proc:54 chld_proc 17 (Child exited)
stapio:stp_main_loop:478 nb=53
WARNING: Number of errors: 1, skipped probes: 1
stapio:stp_main_loop:478 nb=4
stapio:stp_main_loop:504 got STP_EXIT
stapio:cleanup_and_exit:371 detach=0
stapio:close_relayfs:352 closing
stapio:close_relayfs:371 done
stapio:cleanup_and_exit:388 closing control channel
stapio:cleanup_and_exit:413 removing
stap_f43d8fd5008d00d09fc93292d18a3a6d_1120
Pass 5: run completed in 10usr/50sys/231real ms.
Running rm -rf /tmp/stapmQJ4zq
tony@tonys-laptop:~/Desktop$ stap -V
SystemTap translator/driver (version 0.9.8/0.141 non-git sources)
Copyright (C) 2005-2009 Red Hat, Inc. and others
This is free software; see the source for copying conditions.

I've tried building my own kernel, I've tried version 2.6.28, this error
seems to persist no matter what I try. I've even tried systemtap 1.2 same
problem.
-- 
View this message in context: http://old.nabble.com/kernel-read-fault-when-accessing-context-variables-tp29099754p29099754.html
Sent from the Sourceware - systemtap mailing list archive at Nabble.com.

Re: kernel read fault when accessing context variables

[Mark Wielaard]

Hi Tony,

On Wed, 2010-07-07 at 11:41 -0700, tonyg362 wrote:
> I'm trying to access the prev/next task structs within the scheduler e.g.
> 
> probe kernel.statement("schedule@kernel/sched.c:line#") {
>     ppid = $prev->tgid
>     npid = $npid->tgid
> 
>     printf("ppid:%d, npid:%d\n", ppid, npid)
> }
> 
> I am able access $npid->tgid just fine and it prints the correct npid,
> however whenever I try to access $prev->tgid the entire probe is skipped and
> I get a kernel read fault:
> 
> focused on module 'kernel'
> selected source file '/build/buildd/linux-2.6.31/kernel/sched.c'
> selected function schedule
> probe schedule@/build/buildd/linux-2.6.31/kernel/sched.c:5365 kernel
> reloc=.dynamic section=.text pc=0xffffffff8152bc4e
> finding location for local 'prev' near address 0xffffffff8152bc4e, module
> bias 0x0
> [...]
> ERROR: kernel read fault at 0x000000000000029d (addr) near identifier
> '$prev' at test.stp:2:9
>
> I've tried building my own kernel, I've tried version 2.6.28, this error
> seems to persist no matter what I try. I've even tried systemtap 1.2 same
> problem.

I am not seeing the same thing as you, but I do also have trouble trying
to grab $prev and $npid from schedule().

semantic error: not accessible at this address (0xffffffff814d7b30):
identifier '$prev' at <input>:2:12
        source:     ppid = $prev->tgid
                           ^
semantic error: unable to find local 'npid' near pc 0xffffffff814d7b30
in schedule(kernel/sched.c) (alternatives: $prev $next $switch_count $rq
$cpu): identifier '$npid' at :3:12
        source:     npid = $npid->tgid
                           ^

It is correct about $npid, there is no argument or local variable with
that name in my kernel/sched.c(schedule) function. It might be correct
about $prev, it might not yet be available at the start of the function.

I haven't inspected the dwarf output yet, but I assume gcc got somewhat
confused here. I do notice schedule is marked with asmlinkage
http://kernelnewbies.org/FAQ/asmlinkage maybe that gets gcc confused?

What compiler did you use to build your kernel?

Thanks,

Mark

Re: kernel read fault when accessing context variables

[Frank Ch. Eigler]

tonyg362 <tonyg3622@yahoo.com> writes:

> [...]
> I am able access $npid->tgid just fine and it prints the correct npid,
> however whenever I try to access $prev->tgid the entire probe is skipped and
> I get a kernel read fault:
>
> SystemTap translator/driver (version 0.9.8/0.141 non-git sources)
> [...]
> ERROR: kernel read fault at 0x000000000000029d (addr) near identifier
> '$prev' at test.stp:2:9

There are a couple of possible workarounds and fixes for the cause,
most likely incorrect debugging data.

1) run your script with --skip-badvars
2) with modern systemtap, wrap your $var accessing code in try {} catch {}
3) try building your kernel with gcc 4.5 or Red Hat's 4.4.4
   VTA-enabled backports

- FChE

Re: kernel read fault when accessing context variables

[tonyg362]

I'm sorry that was a typo, npid is the name of the local variable I use in my
script. There is no local variable named npid in the scheduler. It should've
read npid = $next->tgid. As for the semantic errors, npid is not found
because as you pointed out it does not exist. And $prev isn't being found
because you probably aren't specifying a line number near enough to it. I
used 5364 or 5365 because that worked for my kernel version. You would need
to look at your sched.c file and find the correct line number, generally any
place where prev is used will work for me (making sure it's already been set
though). But, I also went line by line through the entire schedule function
and I would either get a semantic error (when it couldn't be found), or I
would get a kernel read fault (it's been found but there is some kind of
fault in reading it).

Could you tell me if it works for you if you look at a line in sched.c where
prev is set (or near it), and not just at the beginning of the function? In
the meantime I will try using a gcc version as suggested by Frank. As for my
compiler I used 4.4.1 which I guess is the latest version available through
apt-get on Ubuntu 9.10. I would like to know if anybody can get this working
on Ubuntu 9.10 so I can know their setup.


Mark Wielaard-4 wrote:
> 
> Hi Tony,
> 
> On Wed, 2010-07-07 at 11:41 -0700, tonyg362 wrote:
>> I'm trying to access the prev/next task structs within the scheduler e.g.
>> 
>> probe kernel.statement("schedule@kernel/sched.c:line#") {
>>     ppid = $prev->tgid
>>     npid = $npid->tgid
>> 
>>     printf("ppid:%d, npid:%d\n", ppid, npid)
>> }
>> 
>> I am able access $npid->tgid just fine and it prints the correct npid,
>> however whenever I try to access $prev->tgid the entire probe is skipped
>> and
>> I get a kernel read fault:
>> 
>> focused on module 'kernel'
>> selected source file '/build/buildd/linux-2.6.31/kernel/sched.c'
>> selected function schedule
>> probe schedule@/build/buildd/linux-2.6.31/kernel/sched.c:5365 kernel
>> reloc=.dynamic section=.text pc=0xffffffff8152bc4e
>> finding location for local 'prev' near address 0xffffffff8152bc4e, module
>> bias 0x0
>> [...]
>> ERROR: kernel read fault at 0x000000000000029d (addr) near identifier
>> '$prev' at test.stp:2:9
>>
>> I've tried building my own kernel, I've tried version 2.6.28, this error
>> seems to persist no matter what I try. I've even tried systemtap 1.2 same
>> problem.
> 
> I am not seeing the same thing as you, but I do also have trouble trying
> to grab $prev and $npid from schedule().
> 
> semantic error: not accessible at this address (0xffffffff814d7b30):
> identifier '$prev' at <input>:2:12
>         source:     ppid = $prev->tgid
>                            ^
> semantic error: unable to find local 'npid' near pc 0xffffffff814d7b30
> in schedule(kernel/sched.c) (alternatives: $prev $next $switch_count $rq
> $cpu): identifier '$npid' at :3:12
>         source:     npid = $npid->tgid
>                            ^
> 
> It is correct about $npid, there is no argument or local variable with
> that name in my kernel/sched.c(schedule) function. It might be correct
> about $prev, it might not yet be available at the start of the function.
> 
> I haven't inspected the dwarf output yet, but I assume gcc got somewhat
> confused here. I do notice schedule is marked with asmlinkage
> http://kernelnewbies.org/FAQ/asmlinkage maybe that gets gcc confused?
> 
> What compiler did you use to build your kernel?
> 
> Thanks,
> 
> Mark
> 
> 
> 

-- 
View this message in context: http://old.nabble.com/kernel-read-fault-when-accessing-context-variables-tp29099754p29108946.html
Sent from the Sourceware - systemtap mailing list archive at Nabble.com.

Re: kernel read fault when accessing context variables

[Mark Wielaard]

On Thu, 2010-07-08 at 09:15 -0700, tonyg362 wrote:
> Could you tell me if it works for you if you look at a line in sched.c where
> prev is set (or near it), and not just at the beginning of the function? In
> the meantime I will try using a gcc version as suggested by Frank. As for my
> compiler I used 4.4.1 which I guess is the latest version available through
> apt-get on Ubuntu 9.10. I would like to know if anybody can get this working
> on Ubuntu 9.10 so I can know their setup.

I looked a bit at the sources, and when I set the probe at line 42 of
the function (if (likely(prev != next))) it seems to work fine:

$ stap -e 'probe kernel.statement("schedule@kernel/sched.c+42")
  { ppid = $prev->tgid; npid = $next->tgid;
    printf("ppid:%d, npid:%d\n", ppid, npid) }'
ppid:24737, npid:0
ppid:0, npid:21431
ppid:21431, npid:23130
ppid:23130, npid:22989
ppid:22989, npid:21431
[...]

If I set the probe earlier next isn't assigned yet in the function and I
see what you are seeing:

$ stap -e 'probe kernel.statement("schedule@kernel/sched.c+16")
  { ppid = $prev->tgid; npid = $next->tgid;
    printf("ppid:%d, npid:%d\n", ppid, npid) }'
ERROR: kernel read fault at 0x0000129c29e10ec5 (addr) near identifier
'$next' at <input>:1:83

So it might actually be that in your case the probe is at a point where
next isn't initialized yet?

Cheers,

Mark

Re: kernel read fault when accessing context variables

[Mark Wielaard]

On Thu, 2010-07-08 at 22:42 +0200, Mark Wielaard wrote:
> On Thu, 2010-07-08 at 09:15 -0700, tonyg362 wrote:
> > Could you tell me if it works for you if you look at a line in sched.c where
> > prev is set (or near it), and not just at the beginning of the function? In
> > the meantime I will try using a gcc version as suggested by Frank. As for my
> > compiler I used 4.4.1 which I guess is the latest version available through
> > apt-get on Ubuntu 9.10. I would like to know if anybody can get this working
> > on Ubuntu 9.10 so I can know their setup.
> 
> I looked a bit at the sources, and when I set the probe at line 42 of
> the function (if (likely(prev != next))) it seems to work fine:
> 
> $ stap -e 'probe kernel.statement("schedule@kernel/sched.c+42")
>   { ppid = $prev->tgid; npid = $next->tgid;
>     printf("ppid:%d, npid:%d\n", ppid, npid) }'
> ppid:24737, npid:0
> ppid:0, npid:21431
> ppid:21431, npid:23130
> ppid:23130, npid:22989
> ppid:22989, npid:21431
> [...]
> 
> If I set the probe earlier next isn't assigned yet in the function and I
> see what you are seeing:
> 
> $ stap -e 'probe kernel.statement("schedule@kernel/sched.c+16")
>   { ppid = $prev->tgid; npid = $next->tgid;
>     printf("ppid:%d, npid:%d\n", ppid, npid) }'
> ERROR: kernel read fault at 0x0000129c29e10ec5 (addr) near identifier
> '$next' at <input>:1:83
> 
> So it might actually be that in your case the probe is at a point where
> next isn't initialized yet?

Looking a bit more I see right after that line (+42) there is a call
into context_switch, which has a trace point "sched_switch" in it:

$ stap -L 'kernel.trace("sched_switch")'
kernel.trace("sched_switch") $rq:struct rq* $prev:struct task_struct*
$next:struct task_struct*

So, if you are interested in scheduler switches, then maybe this is more
robust:

$ stap -e 'probe kernel.trace("sched_switch")
  { ppid = $prev->tgid; npid = $next->tgid;
    printf("ppid:%d, npid:%d\n", ppid, npid) }'

Cheers,

Mark

Re: kernel read fault when accessing context variables

[tonyg362]

That's strange, I have tried probing at every line in the scheduler and get a
semantic error or a kernel read fault. Can you tell me your setup and how
you built your debug kernel?


Mark Wielaard-4 wrote:
> 
> On Thu, 2010-07-08 at 22:42 +0200, Mark Wielaard wrote:
>> On Thu, 2010-07-08 at 09:15 -0700, tonyg362 wrote:
>> > Could you tell me if it works for you if you look at a line in sched.c
>> where
>> > prev is set (or near it), and not just at the beginning of the
>> function? In
>> > the meantime I will try using a gcc version as suggested by Frank. As
>> for my
>> > compiler I used 4.4.1 which I guess is the latest version available
>> through
>> > apt-get on Ubuntu 9.10. I would like to know if anybody can get this
>> working
>> > on Ubuntu 9.10 so I can know their setup.
>> 
>> I looked a bit at the sources, and when I set the probe at line 42 of
>> the function (if (likely(prev != next))) it seems to work fine:
>> 
>> $ stap -e 'probe kernel.statement("schedule@kernel/sched.c+42")
>>   { ppid = $prev->tgid; npid = $next->tgid;
>>     printf("ppid:%d, npid:%d\n", ppid, npid) }'
>> ppid:24737, npid:0
>> ppid:0, npid:21431
>> ppid:21431, npid:23130
>> ppid:23130, npid:22989
>> ppid:22989, npid:21431
>> [...]
>> 
>> If I set the probe earlier next isn't assigned yet in the function and I
>> see what you are seeing:
>> 
>> $ stap -e 'probe kernel.statement("schedule@kernel/sched.c+16")
>>   { ppid = $prev->tgid; npid = $next->tgid;
>>     printf("ppid:%d, npid:%d\n", ppid, npid) }'
>> ERROR: kernel read fault at 0x0000129c29e10ec5 (addr) near identifier
>> '$next' at <input>:1:83
>> 
>> So it might actually be that in your case the probe is at a point where
>> next isn't initialized yet?
> 
> Looking a bit more I see right after that line (+42) there is a call
> into context_switch, which has a trace point "sched_switch" in it:
> 
> $ stap -L 'kernel.trace("sched_switch")'
> kernel.trace("sched_switch") $rq:struct rq* $prev:struct task_struct*
> $next:struct task_struct*
> 
> So, if you are interested in scheduler switches, then maybe this is more
> robust:
> 
> $ stap -e 'probe kernel.trace("sched_switch")
>   { ppid = $prev->tgid; npid = $next->tgid;
>     printf("ppid:%d, npid:%d\n", ppid, npid) }'
> 
> Cheers,
> 
> Mark
> 
> 
> 

-- 
View this message in context: http://old.nabble.com/kernel-read-fault-when-accessing-context-variables-tp29099754p29114046.html
Sent from the Sourceware - systemtap mailing list archive at Nabble.com.

Re: kernel read fault when accessing context variables

[Mark Wielaard]

On Thu, 2010-07-08 at 21:11 -0700, tonyg362 wrote:
> That's strange, I have tried probing at every line in the scheduler and get a
> semantic error or a kernel read fault. Can you tell me your setup and how
> you built your debug kernel?

That result was against the rhel6 beta kernel on x86_64:
http://www.redhat.com/rhel/beta/

But the same work on i686 against the fedora 13 (2.6.33.5-124.fc13.i686)
kernel. The source line moved a bit, so I had to use +44 here for
kernel.statement("schedule@kernel/sched.c+44") also the trace point just
works out of the box kernel.trace("sched_switch").

Cheers,

Mark

Re: kernel read fault when accessing context variables

[tonyg362]

Thanks for your help, the sched_switch trace point seems like a good option
and works fine on my machine. I just really wanted to get it to work the
other way if for no other reason than I spent so much time trying to get it
to work, I may keep trying. Funny thing is that I can get my original script
working on an embedded ARM 9 running Ubuntu 9.10 but I can't get it on my
PC. :-/

-Tony


Mark Wielaard-4 wrote:
> 
> On Thu, 2010-07-08 at 21:11 -0700, tonyg362 wrote:
>> That's strange, I have tried probing at every line in the scheduler and
>> get a
>> semantic error or a kernel read fault. Can you tell me your setup and how
>> you built your debug kernel?
> 
> That result was against the rhel6 beta kernel on x86_64:
> http://www.redhat.com/rhel/beta/
> 
> But the same work on i686 against the fedora 13 (2.6.33.5-124.fc13.i686)
> kernel. The source line moved a bit, so I had to use +44 here for
> kernel.statement("schedule@kernel/sched.c+44") also the trace point just
> works out of the box kernel.trace("sched_switch").
> 
> Cheers,
> 
> Mark
> 
> 
> 

-- 
View this message in context: http://old.nabble.com/kernel-read-fault-when-accessing-context-variables-tp29099754p29117808.html
Sent from the Sourceware - systemtap mailing list archive at Nabble.com.