On Tue, Feb 28, 2017 at 2:31 PM, Brendan Gregg
<[email protected]> wrote:
> G'Day Ravi,
>
[...]
> Now retrying perf:
>
> # ./perf record -e sdt_node:http__server__request -a
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.446 MB perf.data (3 samples) ]
> # ./perf script
> node 7646 [002] 361.012364:
> sdt_node:http__server__request: (dc2e69)
> node 7646 [002] 361.204718:
> sdt_node:http__server__request: (dc2e69)
> node 7646 [002] 361.363043:
> sdt_node:http__server__request: (dc2e69)
>
> Now perf works.
>
> If I restart the node process, it goes back to the broken state.
>
Oh sorry, I forgot about that these Node.js probes are behind an
is-enabled semaphore.
$ readelf -n `which node`
[...]
stapsdt 0x00000089 NT_STAPSDT (SystemTap probe descriptors)
Provider: node
Name: http__server__request
Location: 0x0000000000dc2e69, Base: 0x000000000112e064, Semaphore:
0x0000000001470954
Arguments: 8@%r14 8@%rax 8@-4344(%rbp) -4@-4348(%rbp)
8@-4304(%rbp) 8@-4312(%rbp) -4@-4352(%rbp)
# dd if=/proc/31695/mem bs=1 count=1 skip=$(( 0x0000000001470954 ))
2>/dev/null | xxd
00000000: 00 .
# printf "\x1" | dd of=/proc/31695/mem bs=1 count=1 seek=$((
0x0000000001470954 )) 2>/dev/null
# dd if=/proc/31695/mem bs=1 count=1 skip=$(( 0x0000000001470954 ))
2>/dev/null | xxd
00000000: 01 .
# ./perf record -e sdt_node:http__server__request -a
Matching event(s) from uprobe_events:
sdt_node:http__server__request 0x9c2e69@/usr/local/bin/node
Use 'perf probe -d <event>' to delete event(s).
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.280 MB perf.data (3 samples) ]
# ./perf script
node 31695 [003] 24947.168761:
sdt_node:http__server__request: (dc2e69)
node 31695 [003] 24947.476143:
sdt_node:http__server__request: (dc2e69)
node 31695 [003] 24947.679090:
sdt_node:http__server__request: (dc2e69)
So setting that to 1 made the probe work from perf. I guess this is
not a problem with this patch set, but rather a feature request for
the next one: is-enabled SDT support.
Were probe arguments supposed to work? I don't notice them in the perf
script output.
PS, if it's helpful, here's the commands to build node with these SDT probes:
$ sudo apt-get install systemtap-sdt-dev # adds "dtrace", used
by node build
$ wget https://nodejs.org/dist/v4.4.1/node-v4.4.1.tar.gz
$ tar xvf node-v4.4.1.tar.gz
$ cd node-v4.4.1
$ ./configure --with-dtrace
$ make -j 8
Brendan
Thank you Brendan for reviewing,
On Wednesday 01 March 2017 10:34 AM, Brendan Gregg wrote:
> On Tue, Feb 28, 2017 at 2:31 PM, Brendan Gregg
> <[email protected]> wrote:
>> G'Day Ravi,
>>
> [...]
>> Now retrying perf:
>>
>> # ./perf record -e sdt_node:http__server__request -a
>> ^C[ perf record: Woken up 1 times to write data ]
>> [ perf record: Captured and wrote 0.446 MB perf.data (3 samples) ]
>> # ./perf script
>> node 7646 [002] 361.012364:
>> sdt_node:http__server__request: (dc2e69)
>> node 7646 [002] 361.204718:
>> sdt_node:http__server__request: (dc2e69)
>> node 7646 [002] 361.363043:
>> sdt_node:http__server__request: (dc2e69)
>>
>> Now perf works.
>>
>> If I restart the node process, it goes back to the broken state.
>>
> Oh sorry, I forgot about that these Node.js probes are behind an
> is-enabled semaphore.
Yes. Perf does not support "is-enabled" markers yet.
> $ readelf -n `which node`
> [...]
> stapsdt 0x00000089 NT_STAPSDT (SystemTap probe descriptors)
> Provider: node
> Name: http__server__request
> Location: 0x0000000000dc2e69, Base: 0x000000000112e064, Semaphore:
> 0x0000000001470954
> Arguments: 8@%r14 8@%rax 8@-4344(%rbp) -4@-4348(%rbp)
> 8@-4304(%rbp) 8@-4312(%rbp) -4@-4352(%rbp)
> # dd if=/proc/31695/mem bs=1 count=1 skip=$(( 0x0000000001470954 ))
> 2>/dev/null | xxd
> 00000000: 00 .
> # printf "\x1" | dd of=/proc/31695/mem bs=1 count=1 seek=$((
> 0x0000000001470954 )) 2>/dev/null
> # dd if=/proc/31695/mem bs=1 count=1 skip=$(( 0x0000000001470954 ))
> 2>/dev/null | xxd
> 00000000: 01 .
> # ./perf record -e sdt_node:http__server__request -a
> Matching event(s) from uprobe_events:
> sdt_node:http__server__request 0x9c2e69@/usr/local/bin/node
> Use 'perf probe -d <event>' to delete event(s).
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.280 MB perf.data (3 samples) ]
> # ./perf script
> node 31695 [003] 24947.168761:
> sdt_node:http__server__request: (dc2e69)
> node 31695 [003] 24947.476143:
> sdt_node:http__server__request: (dc2e69)
> node 31695 [003] 24947.679090:
> sdt_node:http__server__request: (dc2e69)
>
> So setting that to 1 made the probe work from perf. I guess this is
> not a problem with this patch set, but rather a feature request for
> the next one: is-enabled SDT support.
Yes. Actually I'm thinking about how this can be accomplished. Perf is a userspace
tool and, unlike systemtap, it cannot change semaphore value easily. This is what
I was thinking:
'perf record', at the start of session will increments semaphore in /proc/<pid>/mem.
and at the end of session, perf will decrement it (same as bcc). This does not require
any support from kernel infrastructure. But there are challenges with this approach:
1. What if user starts workload after starting 'perf record'. How perf will be able
to increment semaphore value.
2. Systemwide record. We have to loop over all pids and check if any process is
using SDT with semaphore that is being recorded.
3. Dynamic library loading. How to handle SDT probes in library that is not loaded
at the time of 'perf record'?
Please let me know your thoughts.
> Were probe arguments supposed to work? I don't notice them in the perf
> script output.
Not yet. Alexis[1] (and followed by me[2]) had sent patches for that. Please
have a look at them.
[1] https://lkml.org/lkml/2016/12/13/784
[2] https://lkml.org/lkml/2017/2/2/145
So, why perf is able to record data after recording them with bcc?
Ideally, bcc should increment semaphore value at the start of session and
it should decrement at the end of the session. So after bcc process exits,
semaphore value should be zero. But actually it's not happening.
I've seen this when I was experimenting bcc with is-enabled markers.
See this example,
$ readelf -n /usr/bin/node | grep -A2 Provider
Provider: node
Name: http__server__request
Location: 0x0000000000e5f484, Base: 0x00000000011a0bc4, Semaphore: 0x0000000001558cf2
$ sudo cat /proc/1426/maps
00400000-01306000 r-xp 00000000 08:02 1083365 /usr/bin/node
01506000-01551000 r--p 00f06000 08:02 1083365 /usr/bin/node
01551000-01559000 rw-p 00f51000 08:02 1083365 /usr/bin/node
...
[TERMINAL-1]$ gdb 1426
(gdb) x/1 0x1558cf2
0x1558cf2: 0
[TERMINAL-2]$ sudo ./trace.py -p 1426 'u:node:http__server__request'
PID TID COMM FUNC
/* Do not exit yet. */
[TERMINAL-1]
(gdb) x/1 0x1558cf2
0x1558cf2: 2
[TERMINAL-2]
^C /* Exit bcc trace.py */
[TERMINAL-1]
(gdb) x/1 0x1558cf2
0x1558cf2: 2
Here it's maintaining value 2 as it is. it should be 0. I suspect this is a bug in
bcc. Please let me know if I'm understanding it wrong.
>
> PS, if it's helpful, here's the commands to build node with these SDT probes:
>
> $ sudo apt-get install systemtap-sdt-dev # adds "dtrace", used
> by node build
> $ wget https://nodejs.org/dist/v4.4.1/node-v4.4.1.tar.gz
> $ tar xvf node-v4.4.1.tar.gz
> $ cd node-v4.4.1
> $ ./configure --with-dtrace
> $ make -j 8
Thanks for this. :)
-Ravi