Perf trace event parse errors for KVM events
in [Kernel]
|
Prev: [PATCH] dynamic_debug: allow to set dynamic debug flags right at module load time
Next: [PATCH] writeback: fix non-integrity write-back
From: Steven Rostedt on 30 May 2010 11:40 On Sun, 2010-05-30 at 17:07 +0300, Avi Kivity wrote: > On 05/30/2010 05:03 PM, Steven Rostedt wrote: > > > >> Right. The tools can fall back to %x/%s based on the structure > >> descriptor if they can't parse the format string. > >> > >> > > trace-cmd has plugin support to override how to read the format and > > print it out. It now has the ability to write those plugins in python. > > > > Cool. May make sense to use simpler formatting in the kernel, and use > trace-cmd plugins for the complicated cases. > > It does raise issues with ABIs. Can trace-cmd read plugins from > /lib/modules/*? We can then distribute the plugins with the kernel. > We probably could do that. Perhaps if we can port the python code to perf, then it would work for both. Then the plugins could be just python scripts, (or binary .so modules) and have a tools/plugins dir? The python part probably would be easier to port, since the .so modules are a bit more specific to trace-cmd. -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Avi Kivity on 1 Jun 2010 04:40 On 05/30/2010 06:34 PM, Steven Rostedt wrote: > >> Cool. May make sense to use simpler formatting in the kernel, and use >> trace-cmd plugins for the complicated cases. >> >> It does raise issues with ABIs. Can trace-cmd read plugins from >> /lib/modules/*? We can then distribute the plugins with the kernel. >> >> > We probably could do that. Perhaps if we can port the python code to > perf, then it would work for both. Then the plugins could be just python > scripts, (or binary .so modules) and have a tools/plugins dir? > > The python part probably would be easier to port, since the .so modules > are a bit more specific to trace-cmd. > One concern is performance. Traces tend to be long, and running python code on each line will be slow. If trace-cmd integrates a pager and a search mechanism that looks at the binary data instead of the text, we could format only the lines that are displayed. But that is going to be a lot of work and I don't think it's worth the effort. -- error compiling committee.c: too many arguments to function -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Steven Rostedt on 1 Jun 2010 08:00 On Tue, 2010-06-01 at 11:39 +0300, Avi Kivity wrote: > On 05/30/2010 06:34 PM, Steven Rostedt wrote: > > > >> Cool. May make sense to use simpler formatting in the kernel, and use > >> trace-cmd plugins for the complicated cases. > >> > >> It does raise issues with ABIs. Can trace-cmd read plugins from > >> /lib/modules/*? We can then distribute the plugins with the kernel. > >> > >> > > We probably could do that. Perhaps if we can port the python code to > > perf, then it would work for both. Then the plugins could be just python > > scripts, (or binary .so modules) and have a tools/plugins dir? > > > > The python part probably would be easier to port, since the .so modules > > are a bit more specific to trace-cmd. > > > > One concern is performance. Traces tend to be long, and running python > code on each line will be slow. > > If trace-cmd integrates a pager and a search mechanism that looks at the > binary data instead of the text, we could format only the lines that are > displayed. But that is going to be a lot of work and I don't think it's > worth the effort. > Every event gets its own ID. The plugin registers a callback to that ID. When the ID is hit, the plugin is executed on that event to display its binary format. This is done after the data has been saved in binary format to a file. It may slow down the executing of reading a data file, but it does not affect the running of the trace one bit. -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Avi Kivity on 1 Jun 2010 08:40 On 06/01/2010 02:59 PM, Steven Rostedt wrote: > >> One concern is performance. Traces tend to be long, and running python >> code on each line will be slow. >> >> If trace-cmd integrates a pager and a search mechanism that looks at the >> binary data instead of the text, we could format only the lines that are >> displayed. But that is going to be a lot of work and I don't think it's >> worth the effort. >> >> > Every event gets its own ID. The plugin registers a callback to that ID. > When the ID is hit, the plugin is executed on that event to display its > binary format. > > This is done after the data has been saved in binary format to a file. > It may slow down the executing of reading a data file, but it does not > affect the running of the trace one bit. > I meant that viewing would be slowed down. It's an important part of using ftrace! How long does the Python formatter take to process 100k or 1M events? -- error compiling committee.c: too many arguments to function -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Steven Rostedt on 3 Jun 2010 18:00
On Tue, 2010-06-01 at 15:39 +0300, Avi Kivity wrote: > On 06/01/2010 02:59 PM, Steven Rostedt wrote: > I meant that viewing would be slowed down. It's an important part of > using ftrace! > > How long does the Python formatter take to process 100k or 1M events? > I finally got around to testing this. I ran a trace on lock_acquire, and traced 1,253,296 events. I then created a python plugin to analyze the trace: ---- def lock_acquire(trace_seq, event): t = '' r = '' if int(event['flags']) & 1: t = 'try' if int(event['flags']) & 2: r = 'read' trace_seq.puts('t %x %s%s%s' % ( event['lockdep_addr'], t, r, event['name'])) def register(pevent): pevent.register_event_handler("lock", "lock_acquire", lock_acquire) ---- Disclaimer, I'm not a python expert, and I'm sure the above python code sucks. [root(a)ixf9 trace-cmd.git]# time ./trace-cmd report -N >/dev/null 2>&1 real 0m4.653s user 0m4.234s sys 0m0.419s * -N keeps trace-cmd from loading any plugins. [root(a)ixf9 trace-cmd.git]# time PYTHONPATH=`pwd` ./trace-cmd report >/dev/null 2>&1 real 0m53.916s user 0m53.047s sys 0m0.859s Yes, running a python interpreter is a bit more expensive. It took 4 seconds to read the million events with plain C, but 53 seconds to read it in python. That said... This would only affect you if you were writing this to a file. I doubt that you would notice this if you were scanning the trace with less. Also, I kicked this off in kernelshark, and it made no difference that I can see. This is because kernelshark only evaluates the viewable area of the screen. -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/ |