gstreamer/docs/design/part-tracing.txt

Tracing
=======

This subsystem will provide a mechanism to get structured tracing info from
GStreamer applications. This can be used for post-run analysis as well as for
live introspection.

Use cases
---------
* I'd like to get statistics from a running application.

* I'd like to to understand which parts of my pipeline use how many resources.

* I'd like to know which parts of the pipeline use how much memory.

* I'd like to know about ref-counts of parts in the pipeline to find ref-count
  issues.

Non use-cases
-------------
* Some element in the pipeline does not play along the rules, find out which
  one. This could be done with generic tests.

Design
------

The system brings the following new items:
core hooks: probes in the core api, that will expose internal state when tracing
  is in use
tracers: plugin features that can process data from the hooks and emit a log
tracing front-ends: applications that consume logs from tracers

Like the logging, the tracer hooks can be compiled out and if not use a local
condition to check if active.

Certain GStreamer core function (such as gst_pad_push or gst_element_add_pad)
will call into the tracer subsystem to dispatch into active tracing modules.
Developers will be able to select a list of plugins by setting an environment
variable, such as GST_TRACERS="meminfo;dbus". One can also pass parameters to
plugins:  GST_TRACERS="log(events,buffers);stats(all)".
When then plugins are loaded, we'll add them to certain hooks according to which
they are interested in.

Right now tracing info is logged as GstStructures to the TRACE level.
Idea: Another env var GST_TRACE_CHANNEL could be used to send the tracing to a
file or a socket. See https://bugzilla.gnome.org/show_bug.cgi?id=733188 for
discussion on these environment variables.

Hook api
--------
We'll wrap interesting api calls with two macros, e.g. gst_pad_push():

GstFlowReturn
gst_pad_push (GstPad * pad, GstBuffer * buffer)
{
  GstFlowReturn res;

  g_return_val_if_fail (GST_IS_PAD (pad), GST_FLOW_ERROR);
  g_return_val_if_fail (GST_PAD_IS_SRC (pad), GST_FLOW_ERROR);
  g_return_val_if_fail (GST_IS_BUFFER (buffer), GST_FLOW_ERROR);

  GST_TRACER_PAD_PUSH_PRE (pad, buffer);
  res = gst_pad_push_data (pad,
      GST_PAD_PROBE_TYPE_BUFFER | GST_PAD_PROBE_TYPE_PUSH, buffer);
  GST_TRACER_PAD_PUSH_POST (pad, res);
  return res;
}

TODO(ensonic): gcc has some magic for wrapping functions
- http://gcc.gnu.org/onlinedocs/gcc/Constructing-Calls.html
- http://www.clifford.at/cfun/gccfeat/#gccfeat05.c

TODO(ensonic): we should eval if we can use something like jump_label in the kernel
- http://lwn.net/Articles/412072/ + http://lwn.net/Articles/435215/
- http://lxr.free-electrons.com/source/kernel/jump_label.c
- http://lxr.free-electrons.com/source/include/linux/jump_label.h
- http://lxr.free-electrons.com/source/arch/x86/kernel/jump_label.c
TODO(ensonic): liblttng-ust provides such a mechanism for user-space
- but this is mostly about logging traces
- it is linux specific :/

In addition to api hooks we should also provide timer hooks. Interval timers are
useful to get e.g. resource usage snapshots. Also absolute timers might make
sense. All this could be implemented with a clock thread. We can use another
env-var GST_TRACE_TIMERS="100ms,75ms" to configure timers and then pass them to
the tracers like, GST_TRACERS="rusage(timer=100ms);meminfo(timer=75ms)". Maybe
we can create them ad-hoc and avoid the GST_TRACE_TIMERS var.

Hooks (* already implemented)
-----
* gst_bin_add
* gst_bin_remove
* gst_element_add_pad
* gst_element_post_message
* gst_element_query
* gst_element_remove_pad
* gst_element_factory_make
* gst_pad_link
* gst_pad_pull_range
* gst_pad_push
* gst_pad_push_list
* gst_pad_push_event
* gst_pad_unlink

Tracer api
----------
Tracers are plugin features. They have a simple api:

class init
Here the tracers describe the data the will emit.

instance init
Tracers attach handlers to one or more hooks using gst_tracing_register_hook().
In case the are configurable, they can read the options from the 'params'
property. This is the extra detail from the environment var.

hook functions
Hooks marshal the parameters given to a trace hook into varargs and also
add some extra into such as a timestamp. Hooks will be called from misc threads.
The trace plugins should only consume (=read) the provided data. Expensive
computation should be avoided to not affect the execution too much.
Most trace plugins will log data to a trace channel.

instance destruction
Tracers can output results and release data. This would ideally be done at the
end of the applications, but gst_deinit() is not mandatory. gst_tracelib was
using a gcc_destructor. Ideally tracer modules log data as they have them and
leave aggregation to a tool that processes the log.

tracer event classes
--------------------
Most tracers will log some kind of 'events' : a data transfer, an event,
a message, a query or a measurement. Every tracers should describe the data
format. This way tools that process tracer logs can show the data in a
meaningful way without having to know about the tracer plugin.

One way would be to introspect the data from the plugin. This has the
disadvantage that the postprocessing app needs to load the plugins or talk to
the gstreamer registry. An alternative is to also log the format description
into the log. Right now we're logging several nested GstStructure from the
_tracer_class_init() function (except in the log tracer).

// the name is the value name + ".class"
// the content describes a single log record
gst_tracer_record_new ("thread-rusage.class",
    // value in the log record (order does not matter)
    // 'thread-id' is a 'key' to related the record to something as indicated
    // by 'scope' substructure
    "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
        "type", G_TYPE_GTYPE, G_TYPE_GUINT64,
        "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_THREAD,
        NULL),
    // next value in the record
    // 'average-cpuload' is a measurement as indicated by the 'value'
    // substructure
    "average-cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
        // value type
        "type", G_TYPE_GTYPE, G_TYPE_UINT,
        // human readable description, that can be used as a graph label
        "description", G_TYPE_STRING, "average cpu usage per thread",
        // flags that help to use the right graph type
        // flags { aggregated, windowed, cumulative, ... }
        "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
        // value range
        "min", G_TYPE_UINT, 0,
        "max", G_TYPE_UINT, 100,
        NULL),
    ...
    NULL);

A few ideas that are not yet in the above spec:
- it would be nice to describe the unit of values
  - putting it into the description is not flexible though, e.g. time would be
    a guint64 but a ui would reformat it to e.g. h:m:s.ms
  - other units are e.g.: percent, per-mille, or kbit/s
- we'd like to have some metadata on scopes
  - e.g. we'd like to log the thread-names, so that a UI can show that instead
    of thread-ids
  - the stats tracer logs 'new-element' and 'new-pad' messages
    - they add a unique 'ix' to each instance as the memory ptr can be reused
      for new instances, the data is attached to the objects as qdata
    - the latency tracer would like to also reference this metadata
- right now we log the classes as structures
  - this is important so that the log is self contained
  - it would be nice to add them to the registry, so that gst-inspect can show
    them

We could also consider to add each value as a READABLE gobject property. The
property has name/description. We could use qdata for scope and flags (or have
some new property flags).
We would also need a new "notify" signal, so that value-change notifications
would include a time-stamp. This way the tracers would not needs to be aware of
the logging. The core tracer would register the notify handlers and emit the
log.
Or we just add a gst_tracer_class_install_event() and that mimics the
g_object_class_install_property().

Frontends can:
- do an events over time histogram
- plot curves of values over time or deltas
- show gauges
- collect statistics (min, max, avg, ...)

Plugins ideas
=============

We can have some under gstreamer/plugins/tracers/

latency
-------
- register to buffer and event flow
- send custom event on buffer flow at source elements
- catch events on event transfer at sink elements

meminfo (not yet implemented)
-------
- register to an interval-timer hook.
- call mallinfo() and log memory usage

rusage
------
- register to an interval-timer hook.
- call getrusage() and log resource usage

dbus (not yet implemented)
----
- provide a dbus iface to announce applications that are traced
- tracing UIs can use the dbus iface to find the channels where logging and
  tracing is getting logged to
- one would start the tracing UI first and when the application is started with
  tracing activated, the dbus plugin will announce the new application,
  upon which the tracing UI can start reading from the log channels, this avoid
  missing some data

topology (not yet implemented)
--------
- register to pipeline topology hooks
- tracing UIs can show a live pipeline graph

stats
-----
- register to buffer, event, message and query flow
- tracing apps can do e.g. statistics

refcounts (not yet implemented)
---------
- log ref-counts of objects
- just logging them outside of glib/gobject would still make it hard to detect
  issues though

opengl (not yet implemented)
------
- upload/download times
- there is not hardware agnostic way to get e.g. memory usage info
  (gl extensions)

memory (not yet implemented)
------
- trace live instance (and pointer to the memory)
- use an atexit handler to dump leaked instance
https://bugzilla.gnome.org/show_bug.cgi?id=756760#c6

leaks
-----
- track creation/destruction of GstObject and GstMiniObject
- log those which are still alive when app is exiting and raise an error if any
- Can also log alive object when receiving the SIGUSR1 signal if the
  GST_LEAKS_TRACER_SIG env variable is defined.

User interfaces
===============

gst-debug-viewer
----------------
gst-debug-viewer could be given the trace log in addition to the debug log (or a
combined log). Alternatively it would show a dialog that shows all local apps
(if the dbus plugin is loaded) and read the log streams from the sockets/files
that are configured for the app.

gst-tracer
----------
Counterpart of gst-tracelib-ui.

gst-stats
---------
A terminal app that shows summary/running stats like the summary gst-tracelib
shows at the end of a run. Currently only shows an aggregated status.

live-graphers
-------------
Maybe we can even feed the log into existing live graphers, with a little driver
* https://github.com/dkogan/feedgnuplot


Problems / Open items
=====================
- should tracers log into the debug.log or into a separate log?
  - separate log
    - use a binary format?
    - worse performance (we're writing two logs at the same time)
    - need to be careful when people to GST_DEBUG_CHANNEL=stderr and
      GST_TRACE_CHANNEL=stderr (use a shared channel, but what about the
      formats?)
  - debug log
    - the tracer subsystem would need to log the GST_TRACE at a level that is
      active
    - should the tracer call gst_debug_category_set_threshold() to ensure things
      work, even though the levels don't make a lot of sense here
  - make logging a tracer (a hook in gst_debug_log_valist, move
    gst_debug_log_default() to the tracer module)
    - log all debug log to the tracer log, some of the current logging
      statements can be replaced by generic logging as shown in the log-tracer
    - add tools/gst-debug to extract a human readable debug log from the trace
      log
  - we could maintain a list of log functions, where gst_tracer_log_trace() is
    the default one. This way e.g. gst-validate could consume the traces
    directly.

- when hooking into a timer, should we just have some predefined intervals?
  - can we add a tracer module that registers the timer hook? then we could do
      GST_TRACER="timer(10ms);rusage"
    right now the tracer hooks are defined as an enum though.

- when connecting to a running app, we can't easily get the 'current' state if
  logging is using a socket, as past events are not explicitly stored, we could
  determine the current topology and emit events with GST_CLOCK_TIME_NONE as ts
  to indicate that the events are synthetic.

- we need stable ids for scopes (threads, elements, pads)
  - the address can be reused
  - we can use gst_util_seqnum_next()
  - something like gst_object_get_path_string() won't work as objects are
    initially without parent

- right now the tracing-hooks are enabled/disabled from configure with
  --{enable,disable}-gst-tracer-hooks
  The tracer code and the plugins are still built though. We should add a
  --{enable,disable}-gst-tracer to disabled the whole system, allthough this
  is a bit confusing with the --{enable,disable}-trace option we have already.

Try it
======
GST_DEBUG="GST_TRACER:7,GST_BUFFER*:7,GST_EVENT:7,GST_MESSAGE:7" GST_TRACERS=log gst-launch-1.0 fakesrc num-buffers=10 ! fakesink
- traces for buffer flow in TRACE level

GST_DEBUG="GST_TRACER:7" GST_TRACERS="stats;rusage" GST_DEBUG_FILE=trace.log gst-launch-1.0 fakesrc num-buffers=10 sizetype=fixed ! queue ! fakesink
gst-stats-1.0 trace.log
- print some pipeline stats on exit

GST_DEBUG="GST_TRACER:7" GST_TRACERS="stats;rusage" GST_DEBUG_FILE=trace.log /usr/bin/gst-play-1.0 --interactive $HOME/Videos/movie.mp4
./scripts/gst-plot-traces.sh --format=png | gnuplot
eog trace.log.*.png
- get ts, average-cpuload, current-cpuload, time and plot

GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency gst-launch-1.0 audiotestsrc num-buffers=10 ! audioconvert ! volume volume=0.7 ! autoaudiosink
- print processing latencies

GST_TRACERS="leaks" gst-launch-1.0 videotestsrc num-buffers=10 ! fakesink
- Raise a warning if a leak is detected

GST_DEBUG="GST_TRACER:7" GST_TRACERS="leaks(GstEvent,GstMessage)" gst-launch-1.0 videotestsrc num-buffers=10 ! fakesink
- check if any GstEvent or GstMessage is leaked and raise a warning

Performance
===========
run ./tests/benchmarks/tracing.sh <tracer(s)> <media>

egrep -c "(proc|thread)-rusage" trace.log
658618
grep -c "gst_tracer_log_trace" trace.log
823351

- we can optimize most of it by using quarks in structures or eventually avoid structures totally