Re: Q: perf log mode?

[Kirill Smelkov]

On Wed, Jan 12, 2011 at 01:21:12PM -0200, Arnaldo Carvalho de Melo wrote:
> Em Wed, Jan 12, 2011 at 05:06:13PM +0300, Kirill Smelkov escreveu:
> > I'm trying to use perf together with e.g. kprobes as a tool to show what
> > is happening with my system in "live-log" mode. The problem is, for
> > seldom events, actual info output is largely delayed because perf reads
> > sample data in whole pages. Could something be done with it or am I'm
> > missing something? Here is detailed description:
> 
> <SNIP>
> > 
> > Judging from timestamps, the events were coming with 1-2 seconds period
> > (ping <host> running) and for e.g. first event we got 96-43=53 seconds
> > delay (which is happening already at `perf record` stage -- I've
> > monitored it's raw output).
> > 
> > Is it somehow possible to display events instantly as they are coming?
> 
> Look at how perf top works:
> 
>         while (1) {
>                 int hits = samples;
> 
>                 perf_session__mmap_read(session);
> 
>                 if (hits == samples)
>                         ret = poll(evsel_list->pollfd, evsel_list->nr_fds, 100);
>         }
> 
> It will only call poll if no events were found so there
> should be no delays.
  ^^^^^^^^^^^^^^^^^^^

Hmm, if I understand it correctly, initially right after start,
perf-record sees no events, goes to poll, and then we are sleeping there
until the kernel will wake up us. As Peter pointed it, there are
parameters which control wakeup rule, and for "wakeup immediately" we
have to tune them.

I'm maybe wrong here, since I have only brief picture about how things
work, but anyway...

> perf script instead uses perf_session__process_events() and that, as
> requested by 'perf script' queues events to make sure they are ordered,
> so probably the problem is related to this latency, probably we'll need
> to use some timer to flush this queue more often.
> 
> Try tweaking:
> 
>         .ordering_requires_timestamps = true,
>         .ordered_samples = true,
> 
> in builtin-script.c, if you disable those there should be no queueing
> and we'll test this theory.
> 
> Also try checking if there isn't any buffering in action because it uses
> pipes to connect the record with the python script by printing the event
> as it comes in the record part.

As I wrote in my first mail, maybe a bit not explicitly (sorry then), the
latency is introduced in perf-record. I'm telling this because I've
visually monitored perf-record output to console (yes, binary output,
but it does not matter) to see whether there is output progress at all.

After initial startup there was no progress for long time and then bunch
of data after 30-40 seconds.


And with the patch posted inline within reply-to-Peter mail, the delay
goes away, so could you please consider applying it?


Thanks,
Kirill
--
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/