static void
log_new_element_stats (GstElementStats * stats, GstElement * element,
GstClockTime elapsed)
{
gst_tracer_record_log (tr_new_element, (guint64) (guintptr) g_thread_self (),
elapsed, stats->index, stats->parent_ix, GST_OBJECT_NAME (element),
G_OBJECT_TYPE_NAME (element), GST_IS_BIN (element));
}
static void
log_new_pad_stats (GstPadStats * stats, GstPad * pad)
{
gst_tracer_record_log (tr_new_pad, (guint64) (guintptr) g_thread_self (),
stats->index, stats->parent_ix, GST_OBJECT_NAME (pad),
G_OBJECT_TYPE_NAME (pad), GST_IS_GHOST_PAD (pad),
GST_PAD_DIRECTION (pad));
}
static void
do_element_query_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
GstQuery * qry)
{
GstElementStats *stats = get_element_stats (self, elem);
stats->last_ts = ts;
gst_tracer_record_log (tr_element_query,
(guint64) (guintptr) g_thread_self (), ts, stats->index,
GST_QUERY_TYPE_NAME (qry));
}
static void
do_push_event_pre (GstStatsTracer * self, guint64 ts, GstPad * pad,
GstEvent * ev)
{
GstElement *elem = get_real_pad_parent (pad);
GstElementStats *elem_stats = get_element_stats (self, elem);
GstPadStats *pad_stats = get_pad_stats (self, pad);
elem_stats->last_ts = ts;
gst_tracer_record_log (tr_event, (guint64) (guintptr) g_thread_self (), ts,
pad_stats->index, elem_stats->index, GST_EVENT_TYPE_NAME (ev));
}
static void
do_post_message_pre (GstStatsTracer * self, guint64 ts, GstElement * elem,
GstMessage * msg)
{
GstElementStats *stats = get_element_stats (self, elem);
const GstStructure *msg_s = gst_message_get_structure (msg);
GstStructure *s =
msg_s ? (GstStructure *) msg_s : gst_structure_new_empty ("dummy");
stats->last_ts = ts;
/* FIXME: work out whether using NULL instead of a dummy struct would work */
gst_tracer_record_log (tr_message, (guint64) (guintptr) g_thread_self (), ts,
stats->index, GST_MESSAGE_TYPE_NAME (msg), s);
if (s != msg_s)
gst_structure_free (s);
}
static void
do_query_stats (GstStatsTracer * self, GstPad * this_pad,
GstPadStats * this_pad_stats, GstPad * that_pad,
GstPadStats * that_pad_stats, GstQuery * qry, GstClockTime elapsed,
gboolean have_res, gboolean res)
{
GstElement *this_elem = get_real_pad_parent (this_pad);
GstElementStats *this_elem_stats = get_element_stats (self, this_elem);
GstElement *that_elem = get_real_pad_parent (that_pad);
GstElementStats *that_elem_stats = get_element_stats (self, that_elem);
gst_tracer_record_log (tr_query, (guint64) (guintptr) g_thread_self (),
elapsed, this_pad_stats->index, this_elem_stats->index,
that_pad_stats->index, that_elem_stats->index, GST_QUERY_TYPE_NAME (qry),
gst_query_get_structure (qry), have_res, res);
}
static void
log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
{
GstPad *src_pad;
guint64 src_ts;
gchar *src, *sink;
gst_structure_id_get (data,
latency_probe_pad, GST_TYPE_PAD, &src_pad,
latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL);
src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad));
sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad));
gst_tracer_record_log (tr_latency, src, sink,
GST_CLOCK_DIFF (src_ts, sink_ts));
g_free (src);
g_free (sink);
}
static void
do_buffer_stats (GstStatsTracer * self, GstPad * this_pad,
GstPadStats * this_pad_stats, GstPad * that_pad,
GstPadStats * that_pad_stats, GstBuffer * buf, GstClockTime elapsed)
{
GstElement *this_elem = get_real_pad_parent (this_pad);
GstElementStats *this_elem_stats = get_element_stats (self, this_elem);
GstElement *that_elem = get_real_pad_parent (that_pad);
GstElementStats *that_elem_stats = get_element_stats (self, that_elem);
GstClockTime pts = GST_BUFFER_PTS (buf);
GstClockTime dts = GST_BUFFER_DTS (buf);
GstClockTime dur = GST_BUFFER_DURATION (buf);
gst_tracer_record_log (tr_buffer, (guint64) (guintptr) g_thread_self (),
elapsed, this_pad_stats->index, this_elem_stats->index,
that_pad_stats->index, that_elem_stats->index, gst_buffer_get_size (buf),
GST_CLOCK_TIME_IS_VALID (pts), pts, GST_CLOCK_TIME_IS_VALID (dts), dts,
GST_CLOCK_TIME_IS_VALID (dur), dur, GST_BUFFER_FLAGS (buf));
}
static void
do_stats (GstTracer * obj, guint64 ts)
{
GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj);
GstThreadStats *stats;
gpointer thread_id = g_thread_self ();
guint avg_cpuload, cur_cpuload;
struct rusage ru;
GstClockTime tproc = G_GUINT64_CONSTANT (0);
GstClockTime tthread = G_GUINT64_CONSTANT (0);
GstClockTime dts, dtproc;
#ifdef HAVE_CLOCK_GETTIME
{
struct timespec now;
if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) {
tproc = GST_TIMESPEC_TO_TIME (now);
} else {
GST_WARNING_OBJECT (obj,
"clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed: %s",
g_strerror (errno));
getrusage (RUSAGE_SELF, &ru);
tproc =
GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
}
/* cpu time per thread */
if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) {
tthread = GST_TIMESPEC_TO_TIME (now);
} else {
GST_WARNING_OBJECT (obj,
"clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed: %s",
g_strerror (errno));
#ifdef RUSAGE_THREAD
getrusage (RUSAGE_THREAD, &ru);
tthread =
GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
#endif
}
}
#else
getrusage (RUSAGE_SELF, &ru);
tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
#ifdef RUSAGE_THREAD
getrusage (RUSAGE_THREAD, &ru);
tthread =
GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
#endif
#endif
/* get stats record for current thread */
if (!(stats = g_hash_table_lookup (self->threads, thread_id))) {
stats = g_slice_new0 (GstThreadStats);
stats->tvs_thread = make_trace_values (GST_SECOND);
g_hash_table_insert (self->threads, thread_id, stats);
}
stats->tthread = tthread;
/* Calibrate ts for the process and main thread. For tthread[main] and tproc
* the time is larger than ts, as our base-ts is taken after the process has
* started.
*/
if (G_UNLIKELY (thread_id == self->main_thread_id)) {
self->main_thread_id = NULL;
/* when the registry gets updated, the tproc is less than the debug time ? */
/* TODO(ensonic): we still see cases where tproc overtakes ts, especially
* when with sync=false, can this be due to multiple cores in use? */
if (tproc > ts) {
self->tproc_base = tproc - ts;
GST_DEBUG ("rusage: calibrating by %" G_GUINT64_FORMAT ", thread: %"
G_GUINT64_FORMAT ", proc: %" G_GUINT64_FORMAT,
self->tproc_base, stats->tthread, tproc);
stats->tthread -= self->tproc_base;
}
}
/* we always need to correct proc time */
tproc -= self->tproc_base;
/* FIXME: how can we take cpu-frequency scaling into account?
* - looking at /sys/devices/system/cpu/cpu0/cpufreq/
* scale_factor=scaling_max_freq/scaling_cur_freq
* - as a workaround we can switch it via /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
* cpufreq-selector -g performance
* cpufreq-selector -g ondemand
*/
/* *INDENT-OFF* */
avg_cpuload = (guint) gst_util_uint64_scale (stats->tthread,
G_GINT64_CONSTANT (1000), ts);
update_trace_value (stats->tvs_thread, ts, stats->tthread, &dts, &dtproc);
cur_cpuload = (guint) gst_util_uint64_scale (dtproc,
G_GINT64_CONSTANT (1000), dts);
gst_tracer_record_log (tr_thread, (guint64) (guintptr) thread_id, ts,
MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), stats->tthread);
avg_cpuload = (guint) gst_util_uint64_scale (tproc / num_cpus,
G_GINT64_CONSTANT (1000), ts);
G_LOCK (_proc);
update_trace_value (self->tvs_proc, ts, tproc, &dts, &dtproc);
G_UNLOCK (_proc);
cur_cpuload = (guint) gst_util_uint64_scale (dtproc / num_cpus,
G_GINT64_CONSTANT (1000), dts);
gst_tracer_record_log (tr_proc, (guint64) getpid (), ts,
MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), tproc);
/* *INDENT-ON* */
}
