[PATCH weston v2 2/2] compositor: Implement JSON-timeline logging

[Pekka Paalanen]

On Thu, 04 Dec 2014 12:46:33 +0100
sardemff7+wayland at sardemff7.net wrote:

> On 2014-12-04 12:23, Pekka Paalanen wrote:
> > On Tue, 02 Dec 2014 12:12:28 -0800
> > Bill Spitzak <spitzak at gmail.com> wrote:
> >> I think you should make an emit(FILE*, const char*) function that prints
> >> a quoted string or null, instead of doing this repeatedly. Such a
> >> function could also convert non-printable characters to escape sequences.
> >
> > Yeah, not a bad idea.
> 
> I think you better use a streaming JSON library (yajl is quite good at 
> that). If this feature is for debugging, there is no harm making it 
> optional with a little dependency. Even better, could it be a private 
> debug protocol (always there) with a demo client outputting JSON? This 
> way, we could see graphical clients providing graphs in real time, which 
> would be nice too.

I'm not going to add a library dependency for something this simple.
The main work is to gather the data, after that it's just printf(). I
can't see what a library would help there by replacing a few printf
calls. Stdio already does caching, too, so if the caching is off, I
think we should just adjust stdio parameters.

I'm also not going put this debug stream through Wayland, because it is
on a performance-critical path, may (in the future) produce huge loads
of data, and so clog a socket before the Weston event loop spins again.

For real-time inspection, we need a different transport completely, and
that is out of scope at the moment. Sure, we can convert this JSON
logging to that later if it seems good. Real-time inspection also has
another issue: you don't want to view it on the same machine where you
run Weston, otherwise the viewing will affect the results.

While this is a debugging feature, it is also something that I imagine
is nice to build in in all cases. When not active, the impact should be
totally insignificant. But when a user hits a performance problem, we
could tell him to hit a magic key or change weston.ini or something,
and get a clue on what is the culprit.

Ideally, we would not have this as JSON like this at all, but integrated
with some system-wide profiling tool like perf with custom well-known
events defined in Weston sources, ready to be enabled at runtime. I
just could not find how to do that, so I decided to start with this.

My personal goal with these patches is just to be able to demonstrate
the effects of changing Weston's repaint loop scheduling in later
patches. This is just prerequisite work to justify further work.

> >> I think also you should ignore strict JSON and not put quotes around the
> >> keywords. It makes the output a lot easier to read and most libraries
> >> handle it.
> >
> > Oh, I did hate those quotes, but assumed they were necessary as per
> > <http://www.json.org/>.
> 
> They are necessary. The fact that the format is stricter than parsers is 
> just for robustness (and for JavaScript too probably, where these quotes 
> are optional). If you want to output JSON, please output real JSON.

Very well.

>  > OTOH, I'm not so sure my outmost JSON structure
> > is that valid either, since I'm emitting multiple separate objects
> > instead of a huge array enclosing it or something.
> 
> You can define that you are printing objects one after another, without 
> any relation between them. In this case, you can use a parser with 
> “ignore trailing garbage” option (think of it as e.g. the endptr of strtol).
> If you want to be able to parse the whole thing in one go, you should 
> put them in a big array. You can end your array with an empty object so 
> that you can always put a comma after each object. You will get 
> something like this (using "{…}" for complete objects):
> 
> [
> {…},
> {…},
> {…},
> {}]
> 
> Or you can use a JSON library that will manage it for you.

I prefer individual objects, since I meant this as streamed data. A log
could be hundreds of megabytes or more, in which case I'm wary of
requiring to read it all in at once and parse it all into memory.

OTOH, this format does require reading everything starting from the
beginning to the event of interest, to get all the information about an
object like weston_surface. It's not nice for random access, but I
chose that over repeating the same info over and over again, to make
the logs smaller and avoid needing to cache that data in Weston (e.g.
the surface labels which are not costless to get).


Thanks,
pq