From 77fd81376028ceae9c14ca06193046de06114252 Mon Sep 17 00:00:00 2001 From: Stefan Sauer Date: Wed, 10 Sep 2014 08:33:38 +0200 Subject: [PATCH] design: update tracer design Update the tracer event classes section. Add a performance section. --- docs/design/draft-tracing.txt | 156 ++++++++++++++++++++++------------ 1 file changed, 103 insertions(+), 53 deletions(-) diff --git a/docs/design/draft-tracing.txt b/docs/design/draft-tracing.txt index 753364c1d2..34ba4bff3e 100644 --- a/docs/design/draft-tracing.txt +++ b/docs/design/draft-tracing.txt @@ -36,7 +36,7 @@ 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_TRACE="meminfo,dbus". One can also pass parameters to +variable, such as GST_TRACE="meminfo;dbus". One can also pass parameters to plugins: GST_TRACE="log(events,buffers);stats(all)". When then plugins are loaded, we'll add them to certain hooks according to which they are interested in. @@ -81,7 +81,10 @@ TODO(ensonic): liblttng-ust provides such a mechanism for user-space 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. +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_TRACE="rusage(timer=100ms);meminfo(timer=75ms)". Maybe +we can create them ad-hoc and avoid the GST_TRACE_TIMERS var. Hooks (* already implemented) ----- @@ -98,64 +101,89 @@ Hooks (* already implemented) * gst_pad_push_event - gst_pad_unlink -Plugin api +Tracer api ---------- +Tracers are plugin features. They have a simple api: -TracerPlugins are plugin features. They have a simple api: +class init +Here the tracers describe the data the will emit. -instance creation -Plugins can attach handlers to one or more hooks. They use a HookMask to tell -which events they are interested in. The params are the extra detail from the -environment var. +instance init +Tracers attach handlers to one or more hooks using gst_tracer_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. -void invoke(GstTracerHookId id, GstStructure *s); +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. +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 -Plugins can output results and release data. This would ideally be done at the +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 it and -leave aggregation to a tool that processed the log. +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 (not implemented yet) +tracer event classes -------------------- -tracers will describe the data the log here (gst_tracer_class_add_event_class). Most tracers will log some kind of 'events' : a data transfer, an event, -a message, a query or a measurement. +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. -GstTraceEventClass { // meta data for events, can be printed from gst-inspect - gchar *name; // something that front ends can use as a label for a graph - // should ideally contain a unit - gchar *description; // something that front ends can use as a tooltip - - GstTraceEventScope scope; // a way to associate the event - // enum(per process, thread, element, pad, ...) +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). - Gst??? type; // some kind of hierarchical event type? or make name a 'path' - // event.eos, event.seek.flushing, measurement.cpu.load, ... - - GstTraceEventClassFlags flags; // cummulative, ... -} +// the name is the value name + ".class" +// the content describes a single log record +gst_structure_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", + // enum { process, thread, element, pad, context?, ... } + "related-to", G_TYPE_STRING, "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", G_TYPE_STRING, "aggregated", + // value range + "min", G_TYPE_UINT, 0, + "max", G_TYPE_UINT, 100, + NULL), + ... + NULL); -GstTraceEvent { - GstClockTime ts; // when did it happen - gpointer owner; // GThread, GObject, ... - // payloads: - // - array of unions - // - GstStructure - // - we can just serialize this for logging and easily deserialize it in - // the front-ends using gst_structure_{from,to}_string() - // - we would have 'ts' and 'owner' in the structure - // - the structure 'name-id' can be used to lookup the GstTraceEventClass - // - GVariant ? -} +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 ref this metadata +- right now we log the classes as structures, it would be nice to add them to + the registry, so that gst-inspect can show them -instead of "gpointer owner", we could send a trace-events that register new -owners with an id (atomic int) and unregister them at the end of their -live-time. Then we can reference the owner as "guint owner". +In addition to the above spec, each log event will contain a "ts" field as a +G_TYPE_UINT64 to specify the time of the event. 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 @@ -167,9 +195,6 @@ log. Or we just add a gst_tracer_class_install_event() and that mimics the g_object_class_install_property(). -The log would have a bunch of streams. A stream has a reference to the -GstTraceEventClass. - Frontends can: - do an events over time histogram - plot curves of values over time or deltas @@ -217,6 +242,12 @@ 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 + User interfaces =============== @@ -245,9 +276,6 @@ Maybe we can even feed the log into existing live graphers, with a little driver Problems / Open items ===================== - should tracers log into the debug.log or into a separate log? - - in the log we need a bit of protocol: - - log the GST_TRACE var, so that front-ends can understand what tracers - where active and what parameters where passed. - separate log - use a binary format? - worse performance (we're writing two logs at the same time) @@ -271,8 +299,8 @@ Problems / Open items 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 + 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. Try it @@ -284,8 +312,30 @@ GST_DEBUG="GST_TRACER:7" GST_TRACE="stats;rusage" gst-launch-1.0 2>trace.log fak gst-stats-1.0 trace.log - print some pipeline stats on exit -grep "proc-rusage" trace.log | cut -c154- | sed -e 's#ts=(guint64)##' -e 's#cpuload=(uint)##' -e 's#time=(guint64)##' -e 's#;##' - +GST_DEBUG="GST_TRACER:7" GST_TRACE="stats;rusage" /usr/bin/gst-play-1.0 2>trace.log --interactive $HOME/Videos/movie.mp4 +./tools/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_TRACE=latency gst-launch-1.0 audiotestsrc num-buffers=10 ! audioconvert ! volume volume=0.7 ! autoaudiosink - print processing latencies + +Performance +=========== +GST_DEBUG="GST_TRACER:7" GST_TRACE="stats;rusage" /usr/bin/gst-launch-1.0 2>trace.log playbin uri=file:///home/ensonic/Music/1.mp3 audio-sink="fakesink sync=false" +0:00:42.531147106 (GList) +0:00:09.273174008 (GQueue)! + +GST_DEBUG="GST_TRACER:7" GST_TRACE="rusage" /usr/bin/gst-launch-1.0 2>trace.log playbin uri=file:///home/ensonic/Music/1.mp3 audio-sink="fakesink sync=false" +0:00:07.388375834 + +GST_TRACE="rusage" /usr/bin/gst-launch-1.0 2>trace.log playbin uri=file:///home/ensonic/Music/1.mp3 audio-sink="fakesink sync=false" +0:00:01.691596186 + +/usr/bin/gst-launch-1.0 playbin uri=file:///home/ensonic/Music/1.mp3 audio-sink="fakesink sync=false" +0:00:00.788497775 + +egrep -c "(proc|thread)-rusage" trace.log +658618 + +- we can optimize most with using quarks in structures or eventually avoid structures totally