On Tue, Aug 29, 2017 at 10:07:03AM +0200, Vincent Bernat wrote:
Feedback appreciated! (Better ideas also appreciated. :D)
Using USDT probes? You can attach arbitrary strings to them. I know perf supports them (with a recent kernel) but I don't know how exactly. However, with systemtap, it's dead easy to see them:
stap -e 'probe bird.* { print($$vars) }'
For implementation, see: https://github.com/vincentbernat/lldpd/commit/bdfe419389075af3cdfeadc78008a1... https://github.com/vincentbernat/lldpd/commit/140e34f057462d5ff7818ab4af368f...
As far as I can see, these are tracepoints, but they wouldn't let me do profiling? What I need is profiling, as I want to know what's consuming the most CPU, so I want to be able to fire an event N times per second to tell me what bird is doing right at that specific moment, and listing or counting tracepoint invocations won't necessarily tell me what's using up the most CPU.
I didn't look at your patch, but from my understanding, when you see a CPU pike, you sent USR2 and it started "tracing". Use of tracepoints would do the same thing without having to send a signal.
The patch outputs a single location (config file + line number) sample every time you send a SIGUSR2, so you have to send SIGUSR2 signals in a loop to collect enough samples (and then aggregate those samples somehow). Sample output while running 'while true; killall -USR2 bird; done' while having bird receive 1M /32 routes from a remote test peer is as follows (where each line corresponds to one SIGUSR2 signal): # ./bird -c test.conf -s test.sock -f test.conf:55 200.6.170.145/32 test.conf:30 200.7.98.189/32 test.conf:37 200.14.187.67/32 test.conf:47 200.7.183.137/32 test.conf:28 200.15.56.225/32 test.conf:44 200.5.53.104/32 test.conf:33 200.1.38.168/32 test.conf:25 200.12.74.254/32 test.conf:26 200.1.111.250/32 test.conf:42 200.9.63.39/32 test.conf:37 200.15.180.68/32 test.conf:44 200.11.188.128/32 test.conf:36 200.9.193.157/32 test.conf:32 200.13.155.79/32 test.conf:32 200.6.171.136/32 test.conf:38 200.3.169.76/32 test.conf:31 200.6.189.140/32 test.conf:36 200.14.178.7/32 test.conf:49 200.13.55.165/32 test.conf:33 200.6.83.248/32 test.conf:51 200.4.150.202/32 test.conf:39 200.3.215.221/32 test.conf:26 200.11.220.20/32 test.conf:31 200.10.166.139/32 test.conf:32 200.4.250.210/32 test.conf:54 200.6.3.46/32 test.conf:30 200.9.48.108/32 test.conf:38 200.11.118.191/32 test.conf:39 200.10.199.82/32 test.conf:47 200.0.168.132/32 [...]
You could also have a tracepoint for "begin", a tracepoint for "end", you record the current filter by intercepting "begin", remove it on "end" and you can profile on CPU to know which is the current filter if BIRD is currently running on a CPU.
Right, my patch does something like that, but it unconditionally does the "begin" and "end" actions, because each of them is only two global variable assignments, the cost of which is likely negligible, so you don't really need to conditionalize those with tracepoints -- and you'd do the heavy lifting from a timer anyway. Ideally, I would like to be able to use a timer-based profiling mode (e.g. perf record -F) with stack trace collection, but then instead of collecting bird stack traces, which would just show many stacks of nested interpret() calls, I'd like it to collect traces of f_inst call stacks. (Right now, my patch only prints the top 'stack frame' when receiving SIGUSR2, but there's no reason you wouldn't be able to instrument interpret() to thread the stack 'frames', so that you'd be able to get a full config language stack trace when a profiling event is triggered.) That and JITting filter statements... Thanks! Lennert