[Development] QtCS 2017 logging/tracing session notes

[Arnaud Clère]

Hi Christian,

Thank you for your interest and your questions... 
Regarding the ParTraP language, currently, you need to parse, transform and classify unstructured traces in a JSON form to be able to use it. JSON will remain the pivot format between trace stores and tools so, if ETW or whatever native format is used to store traces, there must be a conversion tool... Stay tuned!

I will now try to answer the ones regarding modmed... and digress to explain what IMO we should examine and discuss regarding Qt tracing.

modmedLog was primarily designed to structure the data coming from existing qDebug() tracepoints. Performance requirements were present too but we do not know very well where we stand now. We have users logging structured devices data at GUI-like rates (say 60Hz) along with lots of other tracepoints. That is not much but at least performance is not an issue for them (I must say though that they use a commercial version with asynchronous logging). That is why our 1st priority was API "usability" vs raw performance.

Now, the key idea in modmedLog design was to avoid intermediate data structures like QVariantXxx and directly write structured data into the output buffer. That is the point of the Bind<T>::bind(Item<>, T& t) signature: it allows writing the structure of data in a serie of possibly stacked, possibly inlined, bind() calls directly able to read/write into the structure through the Item<> "iterator" without necessarily formatting and appending strings. But there are still things to do to reach the best performance using modmed's design:

1/ Avoid numeric and binary data formatting by offering a serializable binary format.
It is not clear to me whether ETW/LTTng/journald formats can handle any user data type such as an object tree or if it imposes limitations such as builtin numeric types, etc. Also, we have to find a way to write such formats without using macro APIs.
Otherwise, maybe QJsonDocument binary format is suitable to embed inside all these "native" log formats. The problem is that to read traces using tools like Python, the format should be documented and a basic Python reader would be the minimum to start doing interesting trace analysis. 
Other possibilities : sqlite, Binary JSON (CBOR RFC7049 as in CoAP ?)...

2/ Avoid memory allocations.
The initial idea when designing modmedLog's fluent interface was to only use stack-based local variables to track the current state of structured writing, but this is not entirely possible with C++ rules of temporary variables creation/destruction. 
So we currently allocate small structures. I think it is possible to optimize that with an allocator using a buffer on the stack.

3/ Limit indirection levels from tracepoint to output.
This is probably negligible compared to the points above and we are probably quite close to the minimum here if we want to keep the flexibility of choosing various formats for various outputs in a QtMessageHandler.
But ensuring compatibility with the existing handler requires to chain at least one structured logging handler with the existing one. 

Regarding your concerns about locks, there must be some mechanism to avoid mixing events from multiple threads but native APIs certainly provide very efficient solutions. 
On our side, if we avoid dynamic allocations, we should be able to avoid 99% of the locks by writing in a reasonably large buffer before sending the result to native APIs. Would that be enough?

Regards,
Arnaud Clère 

-----Original Message-----
From: Christian Gagneraud [mailto:chgans at gmail.com] 
Sent: mercredi 11 octobre 2017 10:21
To: Thiago Macieira <thiago.macieira at intel.com>
Cc: development at qt-project.org
Subject: Re: [Development] QtCS 2017 logging/tracing session notes

Hi,

Going through the wiki, the pdf and the codereview again, i see 3 different things:
- Qt: Logging framework
- ModMed: real-time dissection of organised/structured logs
- Ltt/ETW: event tracing/profiling

Different needs, different means, different reasons and different goals.

I like all 3! ;)

But i'm a bit worry of perf inpact on Ltt/ETW, if one wanted to integrate them into the "structured" logging framework.
I've never heard of ETW before, so i won't comment. Regarding Ltt, I would say that their primary design goal is stealthiness, the second one being efficiency.
In the kernel mode case, you access the events from /proc, which is backed by a kernel RCU list/buffer, i don't know how they have implemented their userspace solution, but i'm expecting something "pretty well done".

My point is that Ltt doesn't interfere (much) with the observed system, and it's I think a primary quality that cannot be thrown away.
Letting Ltt traces go though the whole qDebug stuff makes me feel nervous, traces shouldn't go though Qt locks.

Concerning the pending code review, what will happen next? Will this be merged somewhere?
What if I want to share some experiments about Qt event tracing on top of this review? (time permitting) Now that the framework is there, it should be quite easy to pollute Qt with new traces. I used pollute on purpose, b/c that's really the drawback with Ltt, you have to pollute your code with macros at key locations.

On the side: ModMed's ParTraP language looks very interesting, could this be made accessible to Ltt/ETW?

Chris