[Bug 772936] tracer: Allow outputting logs (in particular tracer logs) in Common Trace Format (ctf)

[GStreamer (GNOME Bugzilla)]

https://bugzilla.gnome.org/show_bug.cgi?id=772936

--- Comment #11 from Thibault Saunier <tsaunier at gnome.org> ---
My goals of outputting our traces and logs in CTF where (somehow ordered by
importance):

  * Output traces with minimal overhead
  * Enable reusing existing tools to mine the traces
  * Have smaller trace files size
  * Allow mining to be fast

I tested and benchmarked 2 implementations using the following tools:

  * babel[0], it was designed mostly to do trace format conversion,
    and thus is not MT safe, meaning I needed a dedicated thread to
    work with it. Its API fits pretty well in our current design.
  * lttng-ust[1] which is more linked to the linux kernel and is not
    very portable at this time (works on mac afaict, no windows support).
    Also the API does not fit well at all with our current design.

The benchmarking consists on outputting the GStreamer debug logs using
those format and compare the performances with our current implementation,
and when no debug is enabled.

An example result for the following pipeline:

The `stats.` tests are running the `stats` tracer and checking the logs for it.

Results with audiotestsrc num-buffers=500000 ! fakesink:

╒═════════════════════════════════════════════════════╤══════════╤════════════╕
│ Test name                                           │ size     │ duration   │
╞═════════════════════════════════════════════════════╪══════════╪════════════╡
│ stats.audiotestsrc.1_runs.500000_buffers.gstdebug   │ 200.0MiB │ 28.335s    │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ stats.audiotestsrc.1_runs.500000_buffers.babeltrace │ 39.9MiB  │ 24.661s    │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ stats.audiotestsrc.1_runs.500000_buffers.no_logs    │ 0.0B     │ 23.396s    │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ audiotestsrc.1_runs.500000_buffers.babeltrace       │ 1.7GiB   │ 156.701s   │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ audiotestsrc.1_runs.500000_buffers.gstdebug         │ 2.1GiB   │ 62.773s    │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ audiotestsrc.1_runs.500000_buffers.no_logs          │ 0.0B     │ 23.183s    │
├─────────────────────────────────────────────────────┼──────────┼────────────┤
│ audiotestsrc.1_runs.500000_buffers.ust              │ 1.7GiB   │ 45.460s    │
╘═════════════════════════════════════════════════════╧══════════╧════════════╛

We can see that for tracer logs (properly formatted) babeltrace is being
more efficient, in term of speed and disk usage (overhead is actually pretty
low).

For debug logs, it is being much slower for still unknown reasons.

I think using babeltrace makes quite some sense for tracer logs, but we will
need to check why it is so inefficient for standard debug logs.

I have done some more benchmarking in other conditions and results look quite
coherent
with that small example.


[0] diamon.org/babel/
[1] http://lttng.org/man/3/lttng-ust/v2.7/

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.