[FFmpeg-devel] [PATCH 07/11] doc/examples/transcode: introduce timestamp logging

[Stefano Sabatini]

Aid timestamp debugging.
---
 doc/examples/transcode.c | 43 +++++++++++++++++++++++++++++++---------
 1 file changed, 34 insertions(+), 9 deletions(-)

diff --git a/doc/examples/transcode.c b/doc/examples/transcode.c
index 21ea14b614..5671c6664b 100644
--- a/doc/examples/transcode.c
+++ b/doc/examples/transcode.c
@@ -37,6 +37,7 @@
 #include <libavutil/channel_layout.h>
 #include <libavutil/opt.h>
 #include <libavutil/pixdesc.h>
+#include <libavutil/timestamp.h>
 
 static AVFormatContext *ifmt_ctx;
 static AVFormatContext *ofmt_ctx;
@@ -435,6 +436,26 @@ static int init_filters(void)
     return 0;
 }
 
+static void log_packet(AVPacket *pkt, const AVFormatContext *fmt_ctx, const char *tag)
+{
+    AVRational *time_base = &fmt_ctx->streams[pkt->stream_index]->time_base;
+
+    av_log(NULL, AV_LOG_INFO,
+           "%s [pkt] stream:%d tb:%d/%d pts_time:%s\n",
+           tag, pkt->stream_index, time_base->num, time_base->den,
+           av_ts2timestr(pkt->pts, time_base));
+}
+
+static void log_frame(AVFrame *frame, int stream_index, const char *tag)
+{
+    AVRational *time_base = &frame->time_base;
+
+    av_log(NULL, AV_LOG_INFO,
+           "%s [frame] stream:%d tb:%d/%d pts_time:%s\n",
+           tag, stream_index, time_base->num, time_base->den,
+           av_ts2timestr(frame->pts, time_base));
+}
+
 static int encode_write_frame(unsigned int stream_index, int flush)
 {
     StreamContext *stream = &stream_ctx[stream_index];
@@ -443,16 +464,16 @@ static int encode_write_frame(unsigned int stream_index, int flush)
     AVPacket *enc_pkt = filter->enc_pkt;
     int ret;
 
-    av_log(NULL, AV_LOG_INFO, "Encoding frame\n");
     /* encode filtered frame */
     av_packet_unref(enc_pkt);
 
-    if (filt_frame && filt_frame->pts != AV_NOPTS_VALUE)
+    if (filt_frame && filt_frame->pts != AV_NOPTS_VALUE) {
         filt_frame->pts = av_rescale_q(filt_frame->pts, filt_frame->time_base,
                                        stream->enc_ctx->time_base);
+        log_frame(filt_frame, stream_index, "encoder <-");
+    }
 
     ret = avcodec_send_frame(stream->enc_ctx, filt_frame);
-
     if (ret < 0)
         return ret;
 
@@ -468,8 +489,8 @@ static int encode_write_frame(unsigned int stream_index, int flush)
                              stream->enc_ctx->time_base,
                              ofmt_ctx->streams[stream_index]->time_base);
 
-        av_log(NULL, AV_LOG_DEBUG, "Muxing frame\n");
         /* mux encoded frame */
+        log_packet(enc_pkt, ofmt_ctx, "muxer <-");
         ret = av_interleaved_write_frame(ofmt_ctx, enc_pkt);
     }
 
@@ -481,8 +502,11 @@ static int filter_encode_write_frame(AVFrame *frame, unsigned int stream_index)
     FilteringContext *filter = &filter_ctx[stream_index];
     int ret;
 
-    av_log(NULL, AV_LOG_INFO, "Pushing decoded frame to filters\n");
     /* push the decoded frame into the filtergraph */
+    if (frame) {
+        log_frame(frame, stream_index, "filters <-");
+    }
+
     ret = av_buffersrc_add_frame(filter->buffersrc_ctx, frame);
     if (ret < 0) {
         av_log(NULL, AV_LOG_ERROR, "Error while feeding the filtergraph\n");
@@ -491,7 +515,6 @@ static int filter_encode_write_frame(AVFrame *frame, unsigned int stream_index)
 
     /* pull filtered frames from the filtergraph */
     while (1) {
-        av_log(NULL, AV_LOG_INFO, "Pulling filtered frame from filters\n");
         ret = av_buffersink_get_frame(filter->buffersink_ctx, filter->filtered_frame);
         if (ret < 0) {
             /* if no more frames for output - returns AVERROR(EAGAIN)
@@ -505,6 +528,8 @@ static int filter_encode_write_frame(AVFrame *frame, unsigned int stream_index)
 
         filter->filtered_frame->time_base = av_buffersink_get_time_base(filter->buffersink_ctx);
         filter->filtered_frame->pict_type = AV_PICTURE_TYPE_NONE;
+
+        log_frame(filter->filtered_frame, stream_index, "filters ->");
         ret = encode_write_frame(stream_index, 0);
         av_frame_unref(filter->filtered_frame);
         if (ret < 0)
@@ -549,13 +574,11 @@ int main(int argc, char **argv)
         if ((ret = av_read_frame(ifmt_ctx, packet)) < 0)
             break;
         stream_index = packet->stream_index;
-        av_log(NULL, AV_LOG_DEBUG, "Demuxer gave frame of stream_index %u\n", stream_index);
+        log_packet(packet, ifmt_ctx, "demuxer ->");
 
         if (filter_ctx[stream_index].filter_graph) {
             StreamContext *stream = &stream_ctx[stream_index];
 
-            av_log(NULL, AV_LOG_DEBUG, "Going to reencode&filter the frame\n");
-
             ret = avcodec_send_packet(stream->dec_ctx, packet);
             if (ret < 0) {
                 av_log(NULL, AV_LOG_ERROR, "Decoding failed\n");
@@ -569,6 +592,7 @@ int main(int argc, char **argv)
                 else if (ret < 0)
                     goto end;
 
+                log_frame(stream->dec_frame, stream_index, "decoder ->");
                 stream->dec_frame->pts = stream->dec_frame->best_effort_timestamp;
                 ret = filter_encode_write_frame(stream->dec_frame, stream_index);
                 if (ret < 0)
@@ -580,6 +604,7 @@ int main(int argc, char **argv)
                                  ifmt_ctx->streams[stream_index]->time_base,
                                  ofmt_ctx->streams[stream_index]->time_base);
 
+            log_packet(packet, ofmt_ctx, "muxer <-");
             ret = av_interleaved_write_frame(ofmt_ctx, packet);
             if (ret < 0)
                 goto end;
-- 
2.34.1