mirror of
https://gitlab.freedesktop.org/gstreamer/gstreamer.git
synced 2024-10-02 16:52:42 +00:00
db3686c14d
Add new tracer idea.
280 lines
9.7 KiB
Text
280 lines
9.7 KiB
Text
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_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.
|
|
|
|
Right now tracing info is logged as structures 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
|
|
--------
|
|
e.g. gst_pad_push() would become:
|
|
|
|
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.
|
|
|
|
Hooks
|
|
-----
|
|
- gst_bin_add
|
|
- gst_bin_remove
|
|
- gst_element_add_pad
|
|
* gst_element_post_message
|
|
* gst_element_query
|
|
- gst_element_remove_pad
|
|
- gst_pad_link
|
|
* gst_pad_pull_range
|
|
* gst_pad_push
|
|
* gst_pad_push_list
|
|
* gst_pad_push_event
|
|
- gst_pad_unlink
|
|
|
|
Plugin api
|
|
----------
|
|
|
|
TracerPlugins are plugin features. They have a simple api:
|
|
|
|
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.
|
|
|
|
void invoke(GstTracerHookId id, GstStructure *s);
|
|
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.
|
|
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
|
|
end of the applications, but gst_deinit() is not mandatory. gst_tracelib was
|
|
using a gcc_destructor
|
|
|
|
tracer factory
|
|
--------------
|
|
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.
|
|
|
|
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, ...)
|
|
|
|
Gst??? type; // some kind of hierarchical event type? or make name a 'path'
|
|
// event.eos, event.seek.flushing, measurement.cpu.load, ...
|
|
|
|
GstTraceEventClassFlags flags; // cummulative, ...
|
|
}
|
|
|
|
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 ?
|
|
}
|
|
|
|
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".
|
|
|
|
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().
|
|
|
|
The log would have a bunch of streams. A stream has a reference to the
|
|
GstTraceEventClass.
|
|
|
|
Frontends can:
|
|
- do a 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
|
|
-------
|
|
- 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
|
|
----
|
|
- 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
|
|
--------
|
|
- 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
|
|
|
|
UI
|
|
==
|
|
|
|
gst-debug-viewer
|
|
----------------
|
|
gst-debug-viewer could be given the trace log in addition to the debug 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.
|
|
|
|
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?
|
|
- 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)
|
|
- 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
|
|
- 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
|
|
|
|
- when hooking into a timer, should we just have some predefined intervals?
|
|
- 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 stored
|
|
|
|
Try it
|
|
======
|
|
GST_DEBUG="GST_TRACER:7,GST_BUFFER*:7,GST_EVENT:7,GST_MESSAGE:7" GST_TRACE=log gst-launch-1.0 fakesrc num-buffers=10 ! fakesink
|
|
- traces for buffer flow in TRACE level
|
|
|
|
GST_DEBUG="GST_TRACER:7" GST_TRACE="stats;rusage" gst-launch-1.0 2>trace.log 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_TRACE=latency gst-launch-1.0 audiotestsrc num-buffers=10 ! audioconvert ! volume volume=0.7 ! autoaudiosink
|
|
- print processing latencies
|