Re: perf user SDT markers

[Brendan Gregg <brendan.d.gregg@gmail.com>]

G'Day Hemant,

Thanks for testing; here's how I compiled node.js:

# apt-get install -y systemtap-sdt-dev            # provides "dtrace"
# git clone --depth 1 https://github.com/joyent/node
# cd node
# ./configure --with-dtrace
# make

node readelf:

# readelf -n node

Notes at offset 0x00000254 with length 0x00000020:
  Owner                 Data size    Description
  GNU                  0x00000010    NT_GNU_ABI_TAG (ABI version tag)
    OS: Linux, ABI: 2.6.24

Notes at offset 0x00000274 with length 0x00000024:
  Owner                 Data size    Description
  GNU                  0x00000014    NT_GNU_BUILD_ID (unique build ID bitstring)
    Build ID: 85dd5ef00ffde124f220b94c8a2b552d9274a89f

Notes at offset 0x00c45fd8 with length 0x000004e4:
  Owner                 Data size    Description
  stapsdt              0x0000003c    NT_STAPSDT (SystemTap probe descriptors)
    Provider: node
    Name: gc__start
    Location: 0x0000000000bf7894, Base: 0x0000000000f252de, Semaphore:
0x0000000001245fa8
    Arguments: 4@%esi 4@%edx 8@%rdi
  stapsdt              0x0000003a    NT_STAPSDT (SystemTap probe descriptors)
    Provider: node
    Name: gcstart
    Location: 0x0000000000bf7895, Base: 0x0000000000f252de, Semaphore:
0x0000000001245faa
    Arguments: 4@%esi 4@%edx 8@%rdi
  stapsdt              0x0000003b    NT_STAPSDT (SystemTap probe descriptors)
    Provider: node
    Name: gc__done
    Location: 0x0000000000bf78a4, Base: 0x0000000000f252de, Semaphore:
0x0000000001245fac
    Arguments: 4@%esi 4@%edx 8@%rdi
  stapsdt              0x0000005c    NT_STAPSDT (SystemTap probe descriptors)
[...etc...]

(the "gcstart" probe is one I added to test the underscore theory.)

Here's also the event files:

# ls /sys/kernel/debug/tracing/events/node/
enable        gc__start_11  gc__start_2  gcstart_5    http__server__request
filter        gcstart_1_1   gcstart_2    gc__start_6  http__server__request_1
gcstart       gc__start_12  gc__start_3  gcstart_6    http__server__request_2
gc__start     gc__start_13  gcstart_3    gc__start_7  http__server__request_3
gc__start_1   gc__start_14  gc__start_4  gcstart_7    http__server__request_4
gcstart_1     gc__start_15  gcstart_4    gc__start_8  net__server__connection
gc__start_10  gc__start_16  gc__start_5  gc__start_9  net__server__connection_1

This is after several iterations of --add and --del. Something seems
to be going wrong there. Thanks,

Brendan



On Mon, Apr 13, 2015 at 2:27 AM, Hemant Kumar <hemant@linux.vnet.ibm.com> wrote:
> Hi Brendan,
>
>
> On 04/13/2015 01:35 AM, Brendan Gregg wrote:
>>
>> On Sat, Apr 11, 2015 at 7:13 PM, Brendan Gregg
>> <brendan.d.gregg@gmail.com> wrote:
>>>
>>> G'Day,
>>>
>>> I was just trying Hemant Kumar's user SDT patch
>>> (http://lwn.net/Articles/618956/); anyone else tried it recently? I
>>> applied it to 4.0.0-rc6, and it creates instrumentation, but doesn't
>>> record the probes.
>>>
>>> This works (it finds the Node.js probes):
>>>
>>> # ./perf sdt-cache --dump
>>> /home/bgregg-testtest/node-standard/out/Release/node:
>>>     %node:net__server__connection
>>>     %node:net__stream__end
>>>     %node:net__socket__read
>>>     %node:net__socket__write
>>>     %node:http__server__request
>>>     %node:http__server__response
>>>     %node:http__client__request
>>>     %node:http__client__response
>>>     %node:gc__done
>>>     %node:gc__start
>>>
>>> But I can't "perf list" or record them:
>>>
>>> # ./perf record -e '%node:http__server__request' -aR
>>> invalid or unsupported event: '%node:http__server__request'
>>> Run 'perf list' for a list of valid events
>>> [...]
>>>
>>> stap works:
>>>
>>> # /root/systemtap-2.8/bin/stap -e 'probe
>>>
>>> process("/home/bgregg-testtest/node-standard/out/Release/node").mark("http__server__request")
>>> { println("hit"); }'
>>> hit
>>> hit
>>>
>>> Brendan
>>
>> Some more digging... So a simple C program with a DTRACE_PROBE1()
>> works, where the marker ends up being "%tick:loop":
>>
>> # ./perf record -e '%tick:loop' -a -g
>> [...]
>> ^C
>> [ perf record: Woken up 1 times to write data ]
>> [ perf record: Captured and wrote 0.334 MB perf.data (2 samples) ]
>>
>> But the %node markers don't work (eg, "%node:gc__start"). Maybe the
>> presence of underscores is breaking it? By adding some debug
>> statements, I dug this message out of yyparse(), which was failing:
>>
>> yyparse() yymsgbuf: syntax error, unexpected PE_NAME, expecting $end
>
>
> I rebased and tried the patches with perf for the latest tip:
>
> # ./perf sdt-cache --add /lib64/libc.so.6
>    8 events added for /lib64/libc.so.6
>
> # ./perf sdt-cache --dump
> /usr/lib64/libc-2.16.so:
>    %libc:setjmp
>    %libc:longjmp
>    %libc:longjmp_target
>    %libc:lll_futex_wake
>    %libc:lll_lock_wait_private
>    %libc:longjmp
>    %libc:longjmp_target
>    %libc:lll_futex_wake
>
>
> # ./perf record -e %libc:longjmp_target -aR sleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.286 MB perf.data ]
>
> Its able to probe and record on %libc:longjmp_target with an underscore.
>
> Also, can you please point me to the node.js with SDT markers you are using
> and can you dump me the readelf -n /path/to/node.js o/p?
>
> --
> Thanks,
> Hemant Kumar
>