From f55348fd9b90335ae39669c77de493954fb763ce Mon Sep 17 00:00:00 2001
From: Nicolas LeQuec <nicolas.lequec@gmail.com>
Date: Mon, 19 Jul 2021 16:53:00 +0200
Subject: [PATCH] logs: fit trace messages with the new trace API

Use of the previouly created trace API to collect data from demuxer, decoder and video_output.
Fields "type", "id", and "stream" are then used by a script to identify data and name curves to
display.
Here is the link of the script project: https://gitlab.com/videolabs/public/vlc-pa
---
 include/vlc_tracer.h | 37 +++++++++++++++++++++++++++++++++++++
 src/clock/clock.c    |  7 +++++++
 src/input/decoder.c  | 27 +++++++++++++++++++++++++++
 src/input/es_out.c   | 13 +++++++++++++
 4 files changed, 84 insertions(+)

diff --git a/include/vlc_tracer.h b/include/vlc_tracer.h
index ed7e4f48cf32..7797796faec8 100644
--- a/include/vlc_tracer.h
+++ b/include/vlc_tracer.h
@@ -142,6 +142,43 @@ static inline struct vlc_tracer_entry VLC_TRACE(const char *key, const char *val
 }
 #endif
 
+/*
+ * Helper trace functions
+ */
+
+static inline void vlc_tracer_TraceStreamPTS(struct vlc_tracer *tracer, const char *type,
+                                const char *id, const char* stream,
+                                vlc_tick_t pts)
+{
+    vlc_tracer_Trace(tracer, VLC_TRACE("type", type), VLC_TRACE("id", id),
+                     VLC_TRACE("stream", stream), VLC_TRACE("pts", NS_FROM_VLC_TICK(pts)),
+                     VLC_TRACE_END);
+}
+
+static inline void vlc_tracer_TraceStreamDTS(struct vlc_tracer *tracer, const char *type,
+                                const char *id, const char* stream,
+                                vlc_tick_t pts, vlc_tick_t dts)
+{
+    vlc_tracer_Trace(tracer, VLC_TRACE("type", type), VLC_TRACE("id", id),
+                     VLC_TRACE("stream", stream), VLC_TRACE("pts", NS_FROM_VLC_TICK(pts)),
+                     VLC_TRACE("dts", NS_FROM_VLC_TICK(dts)), VLC_TRACE_END);
+}
+
+static inline void vlc_tracer_TraceRender(struct vlc_tracer *tracer, const char *type,
+                                const char *id, vlc_tick_t pts, vlc_tick_t now)
+{
+    vlc_tracer_Trace(tracer, VLC_TRACE("type", type), VLC_TRACE("id", id),
+                     VLC_TRACE("pts", NS_FROM_VLC_TICK(pts)),
+                     VLC_TRACE("render_ts", NS_FROM_VLC_TICK(now)), VLC_TRACE_END);
+}
+
+static inline void vlc_tracer_TracePCR( struct vlc_tracer *tracer, const char *type,
+                                    const char *id, vlc_tick_t pcr)
+{
+    vlc_tracer_Trace(tracer, VLC_TRACE("type", type), VLC_TRACE("id", id),
+                     VLC_TRACE("pcr", NS_FROM_VLC_TICK(pcr)), VLC_TRACE_END);
+}
+
 /**
  * @}
  */
diff --git a/src/clock/clock.c b/src/clock/clock.c
index c3535e84cf56..034829be76c9 100644
--- a/src/clock/clock.c
+++ b/src/clock/clock.c
@@ -25,6 +25,7 @@
 #include <vlc_aout.h>
 #include <assert.h>
 #include <limits.h>
+#include <vlc_tracer.h>
 #include "clock.h"
 #include "clock_internal.h"
 
@@ -107,9 +108,15 @@ static inline void vlc_clock_on_update(vlc_clock_t *clock,
                                        unsigned frame_rate,
                                        unsigned frame_rate_base)
 {
+    vlc_clock_main_t *main_clock = clock->owner;
     if (clock->cbs)
         clock->cbs->on_update(system_now, ts, rate, frame_rate, frame_rate_base,
                               clock->cbs_data);
+
+    if (main_clock->tracer != NULL && clock->track_str_id)
+    {
+        vlc_tracer_TraceRender(main_clock->tracer, "RENDER", clock->track_str_id, ts, system_now);
+    }
 }
 
 static vlc_tick_t vlc_clock_master_update(vlc_clock_t *clock,
diff --git a/src/input/decoder.c b/src/input/decoder.c
index cafb9f1cc34c..9253366b8f33 100644
--- a/src/input/decoder.c
+++ b/src/input/decoder.c
@@ -43,6 +43,7 @@
 #include <vlc_modules.h>
 #include <vlc_decoder.h>
 #include <vlc_picture_pool.h>
+#include <vlc_tracer.h>
 
 #include "audio_output/aout_internal.h"
 #include "stream_output/stream_output.h"
@@ -1114,7 +1115,13 @@ static void ModuleThread_QueueVideo( decoder_t *p_dec, picture_t *p_pic )
 {
     assert( p_pic );
     vlc_input_decoder_t *p_owner = dec_get_owner( p_dec );
+    struct vlc_tracer *tracer = vlc_object_get_tracer( &p_dec->obj );
 
+    if ( tracer != NULL )
+    {
+        vlc_tracer_TraceStreamPTS( tracer, "DEC", p_owner->psz_id,
+                            "OUT", p_pic->date );
+    }
     int success = ModuleThread_PlayVideo( p_owner, p_pic );
 
     ModuleThread_UpdateStatVideo( p_owner, success != VLC_SUCCESS );
@@ -1243,7 +1250,13 @@ static void ModuleThread_UpdateStatAudio( vlc_input_decoder_t *p_owner,
 static void ModuleThread_QueueAudio( decoder_t *p_dec, block_t *p_aout_buf )
 {
     vlc_input_decoder_t *p_owner = dec_get_owner( p_dec );
+    struct vlc_tracer *tracer = vlc_object_get_tracer( &p_dec->obj );
 
+    if ( tracer != NULL && p_aout_buf != NULL )
+    {
+        vlc_tracer_TraceStreamDTS( tracer, "DEC", p_owner->psz_id, "OUT",
+                            p_aout_buf->i_pts, p_aout_buf->i_dts );
+    }
     int success = ModuleThread_PlayAudio( p_owner, p_aout_buf );
 
     ModuleThread_UpdateStatAudio( p_owner, success != VLC_SUCCESS );
@@ -1281,6 +1294,13 @@ static void ModuleThread_QueueSpu( decoder_t *p_dec, subpicture_t *p_spu )
 {
     assert( p_spu );
     vlc_input_decoder_t *p_owner = dec_get_owner( p_dec );
+    struct vlc_tracer *tracer = vlc_object_get_tracer( &p_dec->obj );
+
+    if ( tracer != NULL && p_spu != NULL )
+    {
+        vlc_tracer_TraceStreamPTS( tracer, "DEC", p_owner->psz_id,
+                            "OUT", p_spu->i_start );
+    }
 
     /* The vout must be created from a previous decoder_NewSubpicture call. */
     assert( p_owner->p_vout );
@@ -1305,6 +1325,13 @@ static void DecoderThread_ProcessInput( vlc_input_decoder_t *p_owner, block_t *p
 static void DecoderThread_DecodeBlock( vlc_input_decoder_t *p_owner, block_t *p_block )
 {
     decoder_t *p_dec = &p_owner->dec;
+    struct vlc_tracer *tracer = vlc_object_get_tracer( &p_dec->obj );
+
+    if ( tracer != NULL && p_block != NULL )
+    {
+        vlc_tracer_TraceStreamDTS( tracer, "DEC", p_owner->psz_id, "IN",
+                            p_block->i_pts, p_block->i_dts );
+    }
 
     int ret = p_dec->pf_decode( p_dec, p_block );
     switch( ret )
diff --git a/src/input/es_out.c b/src/input/es_out.c
index f1781f508f8f..a1fac4428228 100644
--- a/src/input/es_out.c
+++ b/src/input/es_out.c
@@ -40,6 +40,7 @@
 #include <vlc_list.h>
 #include <vlc_decoder.h>
 #include <vlc_memstream.h>
+#include <vlc_tracer.h>
 
 #include "input_internal.h"
 #include "../clock/input_clock.h"
@@ -2901,6 +2902,13 @@ static int EsOutSend( es_out_t *out, es_out_id_t *es, block_t *p_block )
     input_thread_t *p_input = p_sys->p_input;
 
     assert( p_block->p_next == NULL );
+    struct vlc_tracer *tracer = vlc_object_get_tracer( &p_input->obj );
+
+    if ( tracer != NULL )
+    {
+        vlc_tracer_TraceStreamDTS( tracer, "DEMUX", es->id.str_id, "OUT",
+                            p_block->i_pts, p_block->i_dts);
+    }
 
     struct input_stats *stats = input_priv(p_input)->stats;
     if( stats != NULL )
@@ -3348,6 +3356,11 @@ static int EsOutVaControlLocked( es_out_t *out, input_source_t *source,
 
         p_pgrm->i_last_pcr = i_pcr;
 
+        struct vlc_tracer *tracer = vlc_object_get_tracer( &p_sys->p_input->obj );
+        if ( tracer != NULL )
+        {
+            vlc_tracer_TracePCR(tracer, "DEMUX", "PCR", i_pcr);
+        }
         input_thread_private_t *priv = input_priv(p_sys->p_input);
 
         /* TODO do not use vlc_tick_now() but proper stream acquisition date */
-- 
GitLab