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
> <brendan.d.gr...@gmail.com> 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
