Re: [patch] trace: Add user-space event tracing/injection

[Pekka Enberg]

Hi Ingo,

On 11/17/10 2:07 PM, Ingo Molnar wrote:
> * Pekka Enberg<penberg@xxxxxxxxxx>  wrote:
>
> > (Trimming CC for sanity.)
> [ Added back Linus (in case he wants to object to the new prctl()) and lkml. ]
>
> > On 11/16/10 11:04 PM, Thomas Gleixner wrote:
> > > 'trace' is our shot at improving the situation: it aims at providing a
> > > simple to use and straightforward tracing tool based on the perf
> > > infrastructure and on the well-known perf profiling workflow:
> > >
> > >     trace record firefox          # trace firefox and all child tasks,
> > >                                     put it into trace.data
> > >
> > >     trace summary                 # show quick overview of the trace,
> > >                                     based on trace.data
> > >
> > >     trace report                  # detailed traces, based on trace.data
> > Nice work guys!
> >
> > Does this concept lend itself to tracing latencies in userspace applications that
> > run in virtual machines (e.g. the Java kind)? I'm of course interested in this
> > because of Jato [1] where bunch of interesting things can cause jitter: JIT
> > compilation, GC, kernel, and the actual application doing something (in either
> > native code or JIT'd code). It's important to be able to measure where "slowness"
> > to desktop applications and certain class of server applications comes from to be
> > able to improve things.
> Makes quite a bit of sense.
>
> How about the attached patch? It works fine with the simple testcase included in the
> changelog. There's a common-sense limit on the message size - but otherwise it adds
> support for apps to generate a free-form string trace event.
>
> Thanks,
>
> 	Ingo
>
> ---------------------------------->
> Subject: trace: Add user-space event tracing/injection
> From: Ingo Molnar<mingo@xxxxxxx>
> Date: Wed Nov 17 10:11:53 CET 2010
>
> This feature (suggested by Darren Hart and Pekka Engberg) allows user-space
> programs to print trace events in a very simple and self-contained way:
>
>   #include<sys/prctl.h>
>   #include<string.h>
>
>   #define PR_TASK_PERF_USER_TRACE 35
>
>   int main(void)
>   {
>           char *msg = "Hello World!\n";
>
>           prctl(PR_TASK_PERF_USER_TRACE, msg, strlen(msg));
>
>           return 0;
>   }
>
> These show up in 'trace' output as:
>
>   $ trace report
>   #
>   # trace events of 'sleep 1':
>   #
>          testit/ 6006 ( 0.002 ms):<"Hello World!">
>          testit/ 6006 ( 0.002 ms):<"Hello World!">

Wow! This looks really nice!

What does the duration in milliseconds mean there? For things like GC 
and JIT, I want something like:

void gc(void)
{
        prctl(PR_TASK_PERF_USER_TRACE_START, ...)

        collect();

        prctl(PR_TASK_PERF_USER_TRACE_END, ...)
}

So that it's clear from the tracing output that the VM was busy doing GC 
for n milliseconds. Barring background JIT'ing and pauseless GC, I'd 
also be interested in showing how much time the VM was actually 
_blocking_ the running application (which can happen with signals too, 
btw, for things like accessing data that's lazily initialized).

            Pekka
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/