Re: Q: perf log mode?

[Arnaldo Carvalho de Melo <acme@infradead.org>]

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.

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.

- Arnaldo