Re: [PATCH v2] ftrace: record command lines at more appropriate moment

Frederic Weisbecker
2010-07-29T03:04:56Z

On Thu, Jul 29, 2010 at 11:01:53AM +0800, Li Zefan wrote:
> Ian Munsie wrote:
> > From: Ian Munsie <imunsie@au1.ibm.com>
> >
> > Previously, when tracing was activated through debugfs, regardless of
> > which tracing plugin (if any) were activated, the probe_sched_switch and
> > probe_sched_wakeup probes from the sched_switch plugin would be
> > activated. This appears to have been a hack to use them to record the
> > command lines of active processes as they were scheduled.
> >
> > That approach would suffer if many processes were being scheduled that
> > were not generating events as they would consume entries in the
> > saved_cmdlines buffer that could otherwise have been used by other
> > processes that were actually generating events.
> >
> > It also had the problem that events could be mis-attributed - in the
> > common situation of a process forking then execing a new process, the
> > change of the process command would not be noticed for some time after
> > the exec until the process was next scheduled.
> >
> > If the trace was read after the fact this would generally go unnoticed
> > because at some point the process would be scheduled and the entry in
> > the saved_cmdlines buffer would be updated so that the new command would
> > be reported when the trace was eventually read. However, if the events
> > were being read live (e.g. through trace_pipe), the events just after
> > the exec and before the process was next scheduled would show the
> > incorrect command (though the PID would be correct).
> >
> > This patch removes the sched_switch hack altogether and instead records
> > the commands at a more appropriate moment - when a new trace event is
> > committed onto the ftrace ring buffer. This means that the recorded
> > command line is much more likely to be correct when the trace is read,
> > either live or after the fact, so long as the command line still resides
> > in the saved_cmdlines buffer.
> >
> > It is still not guaranteed to be correct in all situations. For instance
> > if the trace is read after the fact rather than live (consider events
> > generated by a process before an exec - in the below example they would
> > be attributed to sleep rather than stealpid since the entry in
> > saved_cmdlines would have changed before the event was read), but this
> > is no different to the current situation and the alternative would be to
> > store the command line with each and every event.
> >
> > terminal 1: grep '\-12345' /sys/kernel/debug/tracing/trace_pipe
> > terminal 2: ./stealpid 12345 `which sleep` 0.1
> >
> > Before:
> > stealpid-12345 [003] 86.001826: sys_clone -> 0x0
> > stealpid-12345 [003] 86.002013: compat_sys_execve(ufilename: ffaaabef, argv: ffaaa7ec, envp: ffaaa7f8)
> > stealpid-12345 [002] 86.002292: sys_restart_syscall -> 0x0
> > stealpid-12345 [002] 86.002336: sys_brk(brk: 0)
> > stealpid-12345 [002] 86.002338: sys_brk -> 0x1007a000
> > ...
> > stealpid-12345 [002] 86.002582: sys_mmap(addr: 0, len: 1000, prot: 3, flags: 22, fd: ffffffff, offset: 0)
> > stealpid-12345 [002] 86.002586: sys_mmap -> 0xf7c21000
> > sleep-12345 [002] 86.002771: sys_mprotect(start: ffe8000, len: 4000, prot: 1)
> > sleep-12345 [002] 86.002780: sys_mprotect -> 0x0
> > ...
> >
> > After:
> > stealpid-12345 [003] 1368.823626: sys_clone -> 0x0
> > stealpid-12345 [003] 1368.823820: compat_sys_execve(ufilename: fffa6bef, argv: fffa5afc, envp: fffa5b08)
> > sleep-12345 [002] 1368.824125: sys_restart_syscall -> 0x0
> > sleep-12345 [002] 1368.824173: sys_brk(brk: 0)
> > sleep-12345 [002] 1368.824175: sys_brk -> 0x104ae000
> > ...
> >
> > Signed-off-by: Ian Munsie <imunsie@au1.ibm.com>
>
> I've tested your patch using lmbench(ctx):
>
> Context switching - times in microseconds - smaller is better
> -------------------------------------------------------------------------
> Host OS 2p/0K 2p/16K 2p/64K 8p/16K 8p/64K 16p/16K 16p/64K
> ctxsw ctxsw ctxsw ctxsw ctxsw ctxsw ctxsw
> --------- ------------- ------ ------ ------ ------ ------ ------- -------
> (trace-off)
> Linux 2.6.35- 2.1300 2.2100 2.0800 2.5900 2.1400 2.59000 2.19000
> Linux 2.6.35- 2.1400 2.2000 2.0800 2.6000 2.0900 2.56000 2.15000
>
> (all events on)
> Linux 2.6.35- 2.8000 2.9600 2.7200 3.2500 2.8200 3.24000 2.98000
> Linux 2.6.35- 2.7100 2.6900 2.7300 3.2200 2.8500 3.25000 2.79000
>
> (all events on without cmdline-recording)
> Linux 2.6.35- 2.6100 2.6900 2.5800 3.0300 2.5800 3.04000 2.67000
> Linux 2.6.35- 2.5800 2.5900 2.5600 3.0300 2.6600 3.04000 2.61000
>
> (your patch applied)
> Linux 2.6.35- 2.7100 2.8000 2.7200 3.2100 2.8400 3.24000 2.82000
> Linux 2.6.35- 2.6600 2.8400 2.6900 3.1900 2.7600 3.27000 2.78000
>
> So with your patch applied, the performance is still worse than just disabling
> cmdline-recording.
>
> The performance may be worse if I choose some other benchmarks.
>
> I'd suggest another approch, that we add a tracepiont in set_task_comm()
> to record cmdname, and that's how perf does.

That works for tasks that exec() after tracing get enabled, but not for the others.
We need to first walk the tasklist to catch up with running tasks, and then
hook on the exec and fork tracepoints.

I think this would be welcome.