Can't set statement probe in self-built linux-4.4

Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

Hi,

I can't seem to set statement probes in a self-built linux-4.4. What can
be going wrong?

I'm using stap 3.1, gcc 4.9.2, and have SYSTEMTAP_RELEASE set to my build
dir:

----------------------------------------------------------------------
$ stap --version
Systemtap translator/driver (version 3.1/0.159, commit release-3.0-133-g42b97387ed3f + changes)
Copyright (C) 2005-2016 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
tested kernel versions: 2.6.18 ... 4.6-rc
enabled features: AVAHI BOOST_STRING_REF LIBSQLITE3 LIBXML2 NLS NSS READLINE

$ gcc --version
gcc (Debian 4.9.2-10) 4.9.2
Copyright (C) 2014 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

$ env | grep SYSTEMTAP_RELEASE
SYSTEMTAP_RELEASE=/home/chris/git/linux-build/4.4.14-otn-00011-g7bcaa67
----------------------------------------------------------------------

The kernel is configued with CONFIG options per:

https://sourceware.org/systemtap/wiki/SystemTapWithSelfBuiltKernel

...with the addition of CONFIG_DEBUG_INFO_DWARF if that matters:

----------------------------------------------------------------------
$ egrep '^CONFIG_(DEBUG_INFO|KPROBES|RELAY|DEBUG_FS|MODULES|MODULE_UNLOAD|UPROBES|DEBUG_INFO_DWARF4)=' .config
CONFIG_RELAY=y
CONFIG_KPROBES=y
CONFIG_UPROBES=y
CONFIG_MODULES=y
CONFIG_MODULE_UNLOAD=y
CONFIG_DEBUG_INFO=y
CONFIG_DEBUG_INFO_DWARF4=y
CONFIG_DEBUG_FS=y 
----------------------------------------------------------------------

I can set a kernel function probe, e.g.:

----------------------------------------------------------------------
$ stap -p2 -e 'probe kernel.function("register_shrinker") { printf("foo\n"); }' 
# probes
kernel.function("register_shrinker") /* pc=_stext+0x1421b0 */ /* <- kernel.function("register_shrinker") */
----------------------------------------------------------------------

But I can't set a kernel statement probe using either a function offset or
explicit line number, e.g.:

----------------------------------------------------------------------
$ grep -n -A5 '^int register_shrinker' mm/vmscan.c 
226:int register_shrinker(struct shrinker *shrinker)
227-{
228-    size_t size = sizeof(*shrinker->nr_deferred);
229-
230-    /* 
231-     * If we only have one possible node in the system anyway, save

$ stap -v -p2 -e 'probe kernel.statement("register_shinker@mm/vmscan.c+3") { printf("foo\n"); }'
Pass 1: parsed user script and 116 library scripts using 93372virt/31136res/2988shr/28456data kb, in 180usr/20sys/205real ms.
semantic error: resolution failed in DWARF builder

semantic error: while resolving probe point: identifier 'kernel' at <input>:1:7
        source: probe kernel.statement("register_shinker@mm/vmscan.c+3") { printf("foo\n"); }
                      ^

semantic error: no match

Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 112444virt/50900res/3736shr/47528data kb, in 330usr/40sys/362real ms.
Pass 2: analysis failed.  [man error::pass2]

$ stap -v -p2 -e 'probe kernel.statement("*@*/vmscan.c:229") { printf("foo\n"); }'
Pass 1: parsed user script and 116 library scripts using 93372virt/31132res/2988shr/28456data kb, in 190usr/30sys/204real ms.
semantic error: resolution failed in DWARF builder

semantic error: while resolving probe point: identifier 'kernel' at <input>:1:7
        source: probe kernel.statement("*@*/vmscan.c:229") { printf("foo\n"); }
                      ^

semantic error: no match

Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 108076virt/46716res/3736shr/43160data kb, in 380usr/30sys/427real ms.
Pass 2: analysis failed.  [man error::pass2]

$ stap -vvvvv -p2 -e 'probe kernel.statement("*@*/vmscan.c:229") { printf("foo\n"); }' >& /tmp/stap.out
----------------------------------------------------------------------

The full -vvvvvv output from above is available at:

https://www.dropbox.com/s/dfepzebixd7yb36/stap.out.gz?dl=0

From here I'm pretty lost, but the image looks to contain line numbers,
e.g.:

----------------------------------------------------------------------
$ readelf --debug-dump=line $SYSTEMTAP_RELEASE/vmlinux | head -45
Raw dump of debug contents of section .debug_line:

  Offset:                      0x0
  Length:                      375
  DWARF Version:               2
  Prologue Length:             86
  Minimum Instruction Length:  1
  Initial value of 'is_stmt':  1
  Line Base:                   -5
  Line Range:                  14
  Opcode Base:                 13

 Opcodes:
  Opcode 1 has 0 args
  Opcode 2 has 1 args
  Opcode 3 has 1 args
  Opcode 4 has 1 args
  Opcode 5 has 1 args
  Opcode 6 has 0 args
  Opcode 7 has 0 args
  Opcode 8 has 0 args
  Opcode 9 has 1 args
  Opcode 10 has 0 args
  Opcode 11 has 0 args
  Opcode 12 has 1 args

 The Directory Table (offset 0x1b):
  1     /home/chris/git/linux/arch/x86/kernel

 The File Name Table (offset 0x42):
  Entry Dir     Time    Size    Name
  1     1       0       0       head_64.S
  2     1       0       0       verify_cpu.S

 Line Number Statements:
  [0x00000060]  Extended opcode 2: set Address to 0xffffffff81000000
  [0x0000006b]  Advance Line by 68 to 69
  [0x0000006e]  Copy
  [0x0000006f]  Special opcode 81: advance Address by 5 to 0xffffffff81000005 and Line by 6 to 75
  [0x00000070]  Special opcode 104: advance Address by 7 to 0xffffffff8100000c and Line by 1 to 76
  [0x00000071]  Special opcode 106: advance Address by 7 to 0xffffffff81000013 and Line by 3 to 79
  [0x00000072]  Special opcode 48: advance Address by 3 to 0xffffffff81000016 and Line by 1 to 80
  [0x00000073]  Special opcode 76: advance Address by 5 to 0xffffffff8100001b and Line by 1 to 81
  [0x00000074]  Special opcode 34: advance Address by 2 to 0xffffffff8100001d and Line by 1 to 82
  [0x00000075]  Special opcode 94: advance Address by 6 to 0xffffffff81000023 and Line by 5 to 87
----------------------------------------------------------------------

...and files seem to be in the right places, e.g.:

----------------------------------------------------------------------
$ readelf --debug-dump=info $SYSTEMTAP_RELEASE/vmlinux | less
Contents of the .debug_info section:
...
  Compilation Unit @ offset 0x4ed2:
   Length:        0x30 (32-bit)
   Version:       4
   Abbrev Offset: 0x2904
   Pointer Size:  8
 <0><4edd>: Abbrev Number: 1 (DW_TAG_compile_unit)
    <4ede>   DW_AT_ranges      : 0xcc400
    <4ee2>   DW_AT_low_pc      : 0x0
    <4eea>   DW_AT_stmt_list   : 0x141ef1
    <4eee>   DW_AT_GNU_dwo_name: (indirect string, offset: 0x2cb1): mm/.tmp_vmscan.dwo
    <4ef2>   DW_AT_comp_dir    : (indirect string, offset: 0x20): /home/chris/git/linux-build/4.4.14-otn-00011-g7bcaa67
    <4ef6>   DW_AT_GNU_pubnames: 1
    <4ef6>   DW_AT_GNU_addr_base: 0x11fc98
    <4efa>   DW_AT_GNU_dwo_id  : 0xac451f4dafc46631
    <4f02>   DW_AT_GNU_ranges_base: 0xc88d0

$ readelf --debug-dump=info /home/chris/git/linux-build/4.4.14-otn-00011-g7bcaa67/mm/.tmp_vmscan.dwo | less
Contents of the .debug_info.dwo section:
        
  Compilation Unit @ offset 0x0:
   Length:        0x1fbe1 (32-bit)
   Version:       4
   Abbrev Offset: 0x0
   Pointer Size:  8
 <0><b>: Abbrev Number: 1 (DW_TAG_compile_unit)
    <c>   DW_AT_producer    : (indexed string: 0x37): GNU C 4.9.2 -mno-sse -mno-mmx -mno-sse2 -mno-3dnow -mno-avx -m64 -mno-80387 -mno-fp-ret-in-387 -mpreferred-stack-boundary=3 -mtune=generic -mno-red-zone -mcmodel=kernel -maccumulate-outgoing-args -mfentry -march=x86-64 -gsplit-dwarf -gdwarf-4 -O2 -std=gnu90 -p -fno-strict-aliasing -fno-common -falign-jumps=1 -falign-loops=1 -funit-at-a-time -fno-asynchronous-unwind-tables -fno-delete-null-pointer-checks -fno-stack-protector -fno-omit-frame-pointer -fno-optimize-sibling-calls -fno-var-tracking-assignments -fno-strict-overflow -fconserve-stack --param allow-store-data-races=0
    <d>   DW_AT_language    : 1 (ANSI C)
    <e>   DW_AT_name        : (indexed string: 0xd05): /home/chris/git/linux/mm/vmscan.c
    <10>   DW_AT_comp_dir    : (indexed string: 0x4d9): /home/chris/git/linux-build/4.4.14-otn-00011-g7bcaa67
    <12>   DW_AT_GNU_dwo_id  : 0xac451f4dafc46631

$ ls -l /home/chris/git/linux/mm/vmscan.c
-rw-r--r-- 1 chris chris 113618 Jun 24 01:22 /home/chris/git/linux/mm/vmscan.c
----------------------------------------------------------------------


Where to from here?

Cheers,

Chris

Re: Can't set statement probe in self-built linux-4.4

[Frank Ch. Eigler]

Hi -

chris wrote:

> [...]
> I can't seem to set statement probes in a self-built linux-4.4. What can
> be going wrong? [...]

It sounds like you're setting up everything all right, good job.


> I can set a kernel function probe, e.g.:
>
> $ stap -p2 -e 'probe kernel.function("register_shrinker") { printf("foo\n"); }' 
> [...]
> But I can't set a kernel statement probe using either a function offset or
> explicit line number [...]
> $ stap -v -p2 -e 'probe kernel.statement("register_shinker@mm/vmscan.c+3") { printf("foo\n"); }'
> [...]

Have you tried:

    $ stap -L 'kernel.statement("register_shrinker@*:*")'

to get the list of line numbers that systemtap recognizes?


> The full -vvvvvv output from above is available at:
> https://www.dropbox.com/s/dfepzebixd7yb36/stap.out.gz?dl=0

Will look at that shortly.


> ----------------------------------------------------------------------
> $ readelf --debug-dump=line $SYSTEMTAP_RELEASE/vmlinux | head -45
> Raw dump of debug contents of section .debug_line:
> [...]
>   [0x0000006e]  Copy
>   [0x0000006f]  Special opcode 81: advance Address by 5 to 0xffffffff81000005 and Line by 6 to 75
>   [0x00000070]  Special opcode 104: advance Address by 7 to 0xffffffff8100000c and Line by 1 to 76
>   [0x00000071]  Special opcode 106: advance Address by 7 to 0xffffffff81000013 and Line by 3 to 79
>   [0x00000072]  Special opcode 48: advance Address by 3 to 0xffffffff81000016 and Line by 1 to 80
>   [0x00000073]  Special opcode 76: advance Address by 5 to 0xffffffff8100001b and Line by 1 to 81
>   [0x00000074]  Special opcode 34: advance Address by 2 to 0xffffffff8100001d and Line by 1 to 82
>   [0x00000075]  Special opcode 94: advance Address by 6 to 0xffffffff81000023 and Line by 5 to 87
> ----------------------------------------------------------------------

This too looks OK.  Keep in mind though that systemtap does filter out
line numbers that are not uniquely mappable to a single PC address.
Highly optimized code can smear statements from a single line to
multiple locations, and stap doesn't want to guess wrong from ambiguous
alternatives.

- FChE

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

Hi Frank,

On Thu, Jun 30, 2016 at 10:58:47AM -0400, Frank Ch. Eigler wrote:
>> [...]
>> I can't seem to set statement probes in a self-built linux-4.4. What can
>> be going wrong? [...]

[...]

> Have you tried:
> 
>     $ stap -L 'kernel.statement("register_shrinker@*:*")'
> 
> to get the list of line numbers that systemtap recognizes?

No, I hadn't come across that option in my travels - that's useful!
Unfortunately it doesn't come back with anything:

$ stap -v -L 'kernel.statement("register_shrinker@*:*")'
Pass 1: parsed user script and 116 library scripts using 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 131260virt/69116res/3764shr/66344data kb, in 310usr/40sys/354real ms.
$

Re: Can't set statement probe in self-built linux-4.4

[David Smith]

On 06/30/2016 05:34 PM, Chris Dunlop wrote:
> Hi Frank,
> 
> On Thu, Jun 30, 2016 at 10:58:47AM -0400, Frank Ch. Eigler wrote:
>>> [...]
>>> I can't seem to set statement probes in a self-built linux-4.4. What can
>>> be going wrong? [...]
> 
> [...]
> 
>> Have you tried:
>>
>>     $ stap -L 'kernel.statement("register_shrinker@*:*")'
>>
>> to get the list of line numbers that systemtap recognizes?
> 
> No, I hadn't come across that option in my travels - that's useful!
> Unfortunately it doesn't come back with anything:
> 
> $ stap -v -L 'kernel.statement("register_shrinker@*:*")'
> Pass 1: parsed user script and 116 library scripts using 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 131260virt/69116res/3764shr/66344data kb, in 310usr/40sys/354real ms.

Hmm. Please try the following:

# stap -L 'kernel.function("register_shrinker").*'

That should let us know if 'register_shrinker' is only inlined in your
kernel.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

On Fri, Jul 01, 2016 at 11:11:54AM -0500, David Smith wrote:
> On 06/30/2016 05:34 PM, Chris Dunlop wrote:
>> 
>> $ stap -v -L 'kernel.statement("register_shrinker@*:*")'
>> Pass 1: parsed user script and 116 library scripts using 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
>> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 131260virt/69116res/3764shr/66344data kb, in 310usr/40sys/354real ms.
> 
> Hmm. Please try the following:
> 
> # stap -L 'kernel.function("register_shrinker").*'

$ stap -L 'kernel.function("register_shrinker").*'
kernel.function("register_shrinker").call
kernel.function("register_shrinker").exported
kernel.function("register_shrinker").return

> That should let us know if 'register_shrinker' is only inlined in your
> kernel.

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

On Thu, Jun 30, 2016 at 05:57:44PM +1000, Chris Dunlop wrote:
> Hi,
> 
> I can't seem to set statement probes in a self-built linux-4.4. What can
> be going wrong?

Apologies for being a pest, but any ideas?

Chris

On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
> On Thu, Jun 30, 2016 at 08:57:38PM -0400, Frank Ch. Eigler wrote:
>> Something's weird about your -vvvvv trace too; a similar command
>> that works here gives a lot more "function cache ...." type lines.
>> 
>> Any chance you could tar.xz up the whole vmlinux build tree?
> 
> Of course: https://www.dropbox.com/s/l7cvs773mw8jqga/build.tar.xz?dl=0 (193M)
> 
> Chris

On Sat, Jul 02, 2016 at 06:44:28AM +1000, Chris Dunlop wrote:
> On Fri, Jul 01, 2016 at 11:11:54AM -0500, David Smith wrote:
>> On 06/30/2016 05:34 PM, Chris Dunlop wrote:
>>> 
>>> $ stap -v -L 'kernel.statement("register_shrinker@*:*")'
>>> Pass 1: parsed user script and 116 library scripts using 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
>>> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 131260virt/69116res/3764shr/66344data kb, in 310usr/40sys/354real ms.
>> 
>> Hmm. Please try the following:
>> 
>> # stap -L 'kernel.function("register_shrinker").*'
> 
> $ stap -L 'kernel.function("register_shrinker").*'
> kernel.function("register_shrinker").call
> kernel.function("register_shrinker").exported
> kernel.function("register_shrinker").return
> 
>> That should let us know if 'register_shrinker' is only inlined in your
>> kernel.

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

Hi Frank,

On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
> On Thu, Jun 30, 2016 at 08:57:38PM -0400, Frank Ch. Eigler wrote:
>> Something's weird about your -vvvvv trace too; a similar command
>> that works here gives a lot more "function cache ...." type lines.
>> 
>> Any chance you could tar.xz up the whole vmlinux build tree?
> 
> Of course: https://www.dropbox.com/s/l7cvs773mw8jqga/build.tar.xz?dl=0 (193M)

Any ideas?

Thanks,

Chris

Re: Can't set statement probe in self-built linux-4.4

[David Smith]

On 07/14/2016 11:08 AM, Chris Dunlop wrote:
> Hi Frank,
> 
> On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
>> On Thu, Jun 30, 2016 at 08:57:38PM -0400, Frank Ch. Eigler wrote:
>>> Something's weird about your -vvvvv trace too; a similar command
>>> that works here gives a lot more "function cache ...." type lines.
>>>
>>> Any chance you could tar.xz up the whole vmlinux build tree?
>>
>> Of course: https://www.dropbox.com/s/l7cvs773mw8jqga/build.tar.xz?dl=0 (193M)
> 
> Any ideas?

I haven't had a chance to look at your tree, but since stap can find
register_shrinker() itself:

> $ stap -L 'kernel.function("register_shrinker").*'
> kernel.function("register_shrinker").call
> kernel.function("register_shrinker").exported
> kernel.function("register_shrinker").return

But not any lines from it:

> $ stap -v -L 'kernel.statement("register_shrinker@*:*")'
> Pass 1: parsed user script and 116 library scripts using
> 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals
> using 131260virt/69116res/3764shr/66344data kb, in
310usr/40sys/354real ms.

I'd say that the compiler has optimized and reorganized things to the
point where systemtap can't recognize a single line number in that function.

So, what to do about it? Off the top of my head, you've got a few options:

1) One option would be to probe at a different spot, say either in the
functions that call register_shrinker() or in the functions that
register_shrinker() calls.

2) Another option would be to try to lower the gcc's optimization level
for that source file.

3) Since you are building your own kernel, you could add a tracepoint(s)
to that function that contains the info you need at the point(s) you are
interested in, then hook up systemtap to that tracepoint(s).

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: Can't set statement probe in self-built linux-4.4

[Josh Stone]

On 07/14/2016 09:08 AM, Chris Dunlop wrote:
> Hi Frank,
> 
> On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
>> On Thu, Jun 30, 2016 at 08:57:38PM -0400, Frank Ch. Eigler wrote:
>>> Something's weird about your -vvvvv trace too; a similar command
>>> that works here gives a lot more "function cache ...." type lines.
>>>
>>> Any chance you could tar.xz up the whole vmlinux build tree?
>>
>> Of course: https://www.dropbox.com/s/l7cvs773mw8jqga/build.tar.xz?dl=0 (193M)
> 
> Any ideas?

$ grep DEBUG_INFO .config
CONFIG_DEBUG_INFO=y
# CONFIG_DEBUG_INFO_REDUCED is not set
CONFIG_DEBUG_INFO_SPLIT=y
CONFIG_DEBUG_INFO_DWARF4=y

I think SPLIT is the problem.  This puts all debuginfo into separate
.dwo objects, and then vmlinux itself only contains DW_AT_GNU_dwo_name
references from each CU.

There's no dwo_name support at all in elfutils yet, thus stap doesn't
support it either.

The function probe that you are getting is based only on the symbol
table, which is why you're not seeing any arguments either.  And
statement probes aren't available at all without working debuginfo.

For comparision, I get this on Fedora 24:

> $ stap -L 'kernel.function("register_shrinker").*' 
> kernel.function("register_shrinker@mm/vmscan.c:227").call $shrinker:struct shrinker* $size:size_t
> kernel.function("register_shrinker@mm/vmscan.c:227").callee("down_write@kernel/locking/rwsem.c:46") $sem:struct rw_semaphore*
> kernel.function("register_shrinker@mm/vmscan.c:227").callee("up_write@kernel/locking/rwsem.c:89") $sem:struct rw_semaphore*
> kernel.function("register_shrinker@mm/vmscan.c:227").exported $shrinker:struct shrinker* $size:size_t
> kernel.function("register_shrinker@mm/vmscan.c:227").return $return:int $shrinker:struct shrinker* $size:size_t

> $ stap -L 'kernel.statement("register_shrinker@*:*")'                                                                                                                                                                                            
> kernel.statement("register_shrinker@mm/vmscan.c:228") $shrinker:struct shrinker* $size:size_t
> kernel.statement("register_shrinker@mm/vmscan.c:231") $shrinker:struct shrinker* $size:size_t
> kernel.statement("register_shrinker@mm/vmscan.c:232") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:234") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:235") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:236") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:238") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:239") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:240") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:241") $shrinker:struct shrinker*
> kernel.statement("register_shrinker@mm/vmscan.c:242") $shrinker:struct shrinker*

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

On Thu, Jul 14, 2016 at 11:54:56AM -0500, David Smith wrote:
> On 07/14/2016 11:08 AM, Chris Dunlop wrote:
>> On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
>>> On Thu, Jun 30, 2016 at 08:57:38PM -0400, Frank Ch. Eigler wrote:
>>>> Something's weird about your -vvvvv trace too; a similar command
>>>> that works here gives a lot more "function cache ...." type lines.
>>>>
>>>> Any chance you could tar.xz up the whole vmlinux build tree?
>>>
>>> Of course: https://www.dropbox.com/s/l7cvs773mw8jqga/build.tar.xz?dl=0 (193M)
>> 
>> Any ideas?
> 
> I haven't had a chance to look at your tree, but since stap can find
> register_shrinker() itself:
> 
>> $ stap -L 'kernel.function("register_shrinker").*'
>> kernel.function("register_shrinker").call
>> kernel.function("register_shrinker").exported
>> kernel.function("register_shrinker").return
> 
> But not any lines from it:
> 
>> $ stap -v -L 'kernel.statement("register_shrinker@*:*")'
>> Pass 1: parsed user script and 116 library scripts using
>> 93372virt/31140res/3000shr/28456data kb, in 190usr/20sys/206real ms.
>> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals
>> using 131260virt/69116res/3764shr/66344data kb, in
> 310usr/40sys/354real ms.
> 
> I'd say that the compiler has optimized and reorganized things to the
> point where systemtap can't recognize a single line number in that function.

Actually, register_shrinker was a random example: I was originally trying to
(and am still wanting to) set statement probes in an externally compiled
kernel module (zfsonlinux). That was (and is) failing the same way, so I
thought I'd try to go back to basics and ended up at register_shinker.

I haven't been able to set statement probes on anything I've tried: kernel,
modules, external modules.

For what it's worth, if this is expected to bring back all the line numbers
systemtap can find in the whole kernel, it's not finding any at all:

$ stap -v -L 'kernel.statement("*@*:*")'
Pass 1: parsed user script and 116 library scripts using 93372virt/31144res/3000shr/28456data kb, in 190usr/20sys/204real ms.
Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 132988virt/70760res/3764shr/68072data kb, in 300usr/40sys/351real ms.
$

> So, what to do about it? Off the top of my head, you've got a few options:
> 
> 1) One option would be to probe at a different spot, say either in the
> functions that call register_shrinker() or in the functions that
> register_shrinker() calls.

See above: I can't put statement probes in anywhere in any function.

> 2) Another option would be to try to lower the gcc's optimization level
> for that source file.

Surely shouldn't be required for the whole kernel? That would be a bloody
good optimiser! Or a really crap one. :-)

> 3) Since you are building your own kernel, you could add a tracepoint(s)
> to that function that contains the info you need at the point(s) you are
> interested in, then hook up systemtap to that tracepoint(s).

...or printks(). Yes, but that's what I'd like to avoid by using systemtap
statement probes.

Chris

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

On Thu, Jul 14, 2016 at 10:20:56AM -0700, Josh Stone wrote:
> On 07/14/2016 09:08 AM, Chris Dunlop wrote:
> > On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
> > Any ideas?
> 
> $ grep DEBUG_INFO .config
> CONFIG_DEBUG_INFO=y
> # CONFIG_DEBUG_INFO_REDUCED is not set
> CONFIG_DEBUG_INFO_SPLIT=y
> CONFIG_DEBUG_INFO_DWARF4=y
> 
> I think SPLIT is the problem.  This puts all debuginfo into separate
> .dwo objects, and then vmlinux itself only contains DW_AT_GNU_dwo_name
> references from each CU.
> 
> There's no dwo_name support at all in elfutils yet, thus stap doesn't
> support it either.
> 
> The function probe that you are getting is based only on the symbol
> table, which is why you're not seeing any arguments either.  And
> statement probes aren't available at all without working debuginfo.

OK, that sounds like it explains the problem.

I'll remove the SPLIT and let you know...

Thanks!

Chris

Re: Can't set statement probe in self-built linux-4.4

[David Smith]

On 07/14/2016 12:27 PM, Chris Dunlop wrote:
> On Thu, Jul 14, 2016 at 11:54:56AM -0500, David Smith wrote:
>> I'd say that the compiler has optimized and reorganized things to the
>> point where systemtap can't recognize a single line number in that function.
> 
> Actually, register_shrinker was a random example: I was originally trying to
> (and am still wanting to) set statement probes in an externally compiled
> kernel module (zfsonlinux). That was (and is) failing the same way, so I
> thought I'd try to go back to basics and ended up at register_shinker.

Ah, I didn't realize that.

> I haven't been able to set statement probes on anything I've tried: kernel,
> modules, external modules.

Hmm, so we've got a bigger problem than just register_shrinker().

> For what it's worth, if this is expected to bring back all the line numbers
> systemtap can find in the whole kernel, it's not finding any at all:
> 
> $ stap -v -L 'kernel.statement("*@*:*")'
> Pass 1: parsed user script and 116 library scripts using 93372virt/31144res/3000shr/28456data kb, in 190usr/20sys/204real ms.
> Pass 2: analyzed script: 0 probes, 0 functions, 0 embeds, 0 globals using 132988virt/70760res/3764shr/68072data kb, in 300usr/40sys/351real ms.
> $

OK, so I downloaded your kernel and looked at the build options. In your
config file, you've got:

CONFIG_DEBUG_INFO=y
# CONFIG_DEBUG_INFO_REDUCED is not set
CONFIG_DEBUG_INFO_SPLIT=y
CONFIG_DEBUG_INFO_DWARF4=y

In a Fedora 23 kernel, you'll see:

CONFIG_DEBUG_INFO=y
# CONFIG_DEBUG_INFO_REDUCED is not set
# CONFIG_DEBUG_INFO_SPLIT is not set
# CONFIG_DEBUG_INFO_DWARF4 is not set
CONFIG_DEBUG_INFO_VTA=y

My guess would be that systemtap is having trouble with either the
CONFIG_DEBUG_INFO_SPLIT option (which adds the '-gsplit-dwarf' gcc
option) or the CONFIG_DEBUG_INFO_DWARF4 option (which adds the
'-gdwarf-4' gcc option).

I'd suspect split debuginfo first. As far as I know, systemtap has never
been used with those individual .dwo files. Can you recompile without
CONFIG_DEBUG_INFO_SPLIT?

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: Can't set statement probe in self-built linux-4.4

[Chris Dunlop]

Hi Josh, Dave, Frank,

On Fri, Jul 15, 2016 at 03:29:54AM +1000, Chris Dunlop wrote:
> On Thu, Jul 14, 2016 at 10:20:56AM -0700, Josh Stone wrote:
> > On 07/14/2016 09:08 AM, Chris Dunlop wrote:
> > > On Fri, Jul 01, 2016 at 01:43:02PM +1000, Chris Dunlop wrote:
> > > Any ideas?
> > 
> > $ grep DEBUG_INFO .config
> > CONFIG_DEBUG_INFO=y
> > # CONFIG_DEBUG_INFO_REDUCED is not set
> > CONFIG_DEBUG_INFO_SPLIT=y
> > CONFIG_DEBUG_INFO_DWARF4=y
> > 
> > I think SPLIT is the problem.  This puts all debuginfo into separate
> > .dwo objects, and then vmlinux itself only contains DW_AT_GNU_dwo_name
> > references from each CU.
> > 
> > There's no dwo_name support at all in elfutils yet, thus stap doesn't
> > support it either.
> > 
> > The function probe that you are getting is based only on the symbol
> > table, which is why you're not seeing any arguments either.  And
> > statement probes aren't available at all without working debuginfo.
> 
> OK, that sounds like it explains the problem.
> 
> I'll remove the SPLIT and let you know...

Yup, that was it.

It's probably worth mentioning this on the "self built kernel" wiki page
until elfutils and therefore systemtap gain the support:

Using systemtap with self-built kernels
https://sourceware.org/systemtap/wiki/SystemTapWithSelfBuiltKernel

Thanks for your help!

Chris

Re: Can't set statement probe in self-built linux-4.4

[David Smith]

On 07/14/2016 06:18 PM, Chris Dunlop wrote:
>> I'll remove the SPLIT and let you know...
> 
> Yup, that was it.

Great!

> It's probably worth mentioning this on the "self built kernel" wiki page
> until elfutils and therefore systemtap gain the support:
> 
> Using systemtap with self-built kernels
> https://sourceware.org/systemtap/wiki/SystemTapWithSelfBuiltKernel

I added a sentence to that wiki page mentioning that split debuginfo
isn't supported.

> Thanks for your help!

I'm glad we were able to fix your problem so that systemtap is useful
for you.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)