From 1ffce54c172b921bb35fb965f7e60ba074a711f7 Mon Sep 17 00:00:00 2001 From: "Wang, Shaofei" Date: Thu, 30 May 2019 07:16:28 -0400 Subject: [PATCH] [PATCH] refine, total fps without init(filter) and add decode/encode profiling for decode, only sw profiling are supported now. Signed-off-by: Wang, Shaofei Signed-off-by: Hu, Yuan Change-Id: I02083c4354eec4d82f4c844d90f801d538195f93 --- fftools/ffmpeg.c | 71 +++++++++++++++++++++++++++++++++++++++++++++- fftools/ffmpeg.h | 1 + fftools/ffmpeg_opt.c | 7 +++++ libavcodec/avcodec.h | 2 ++ libavcodec/decode.c | 5 ++++ libavcodec/encode.c | 6 ++++ libavcodec/pthread_frame.c | 13 +++++++++ libavcodec/utils.c | 1 + libavfilter/avfilter.c | 15 ++++++++++ libavfilter/avfilter.h | 2 ++ libavutil/log.c | 11 +++++++ libavutil/log.h | 3 ++ 12 files changed, 136 insertions(+), 1 deletion(-) diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c index 2752652..ab52b92 100644 --- a/fftools/ffmpeg.c +++ b/fftools/ffmpeg.c @@ -151,6 +151,7 @@ int nb_input_files = 0; OutputStream **output_streams = NULL; int nb_output_streams = 0; +int total_frames_num = 0; OutputFile **output_files = NULL; int nb_output_files = 0; @@ -1765,6 +1766,7 @@ static void print_report(int is_last_report, int64_t timer_start, int64_t cur_ti double speed; int64_t pts = INT64_MIN + 1; static int64_t last_time = -1; + static int64_t init_time = 0; static int qp_histogram[52]; int hours, mins, secs, us; const char *hours_sign; @@ -1786,6 +1788,18 @@ static void print_report(int is_last_report, int64_t timer_start, int64_t cur_ti t = (cur_time-timer_start) / 1000000.0; + if (init_time == 0 && do_profiling_all) { + for (i = 0; i < nb_filtergraphs; i++) { + FilterGraph *fg = filtergraphs[i]; + int j; + for (j = 0; j < fg->graph->nb_filters; j++) { + AVFilterContext *ft = fg->graph->filters[j]; + if (!ft) + continue; + init_time += ft->init_working_time; + } + } + } oc = output_files[0]->ctx; @@ -1808,7 +1822,7 @@ static void print_report(int is_last_report, int64_t timer_start, int64_t cur_ti av_bprintf(&buf_script, "stream_%d_%d_q=%.1f\n", ost->file_index, ost->index, q); } - if (!vid && enc->codec_type == AVMEDIA_TYPE_VIDEO) { + if (!vid && enc->codec_type == AVMEDIA_TYPE_VIDEO && !do_profiling_all) { float fps; frame_number = ost->frame_number; @@ -1868,6 +1882,19 @@ static void print_report(int is_last_report, int64_t timer_start, int64_t cur_ti if (is_last_report) nb_frames_drop += ost->last_dropped; } + if (do_profiling_all) { + total_frames_num = 0; + for (i = 0; i < nb_output_streams; i++) { + ost = output_streams[i]; + total_frames_num += ost->frame_number; + } + float total_fps; + total_fps = t > 1 ? total_frames_num / t : 0; + av_bprintf(&buf, "| profiling | total frame=%d ", total_frames_num); + av_bprintf(&buf, "fps=%.2f |", total_fps); + total_fps = t > 1 ? total_frames_num / (t - init_time / 1000000.0 ): 0; + av_bprintf(&buf, ", fps without filter init=%.2f |", total_fps); + } secs = FFABS(pts) / AV_TIME_BASE; us = FFABS(pts) % AV_TIME_BASE; @@ -4952,6 +4979,13 @@ static int transcode(void) for (i = 0; i < nb_output_streams; i++) { ost = output_streams[i]; if (ost->encoding_needed) { + if (do_profiling_all) { + if (ost->enc_ctx->frame_number > 1 && ost->enc_ctx->sum_working_time > 1) { + double fps = (double)(ost->enc_ctx->frame_number * 1000000) / ost->enc_ctx->sum_working_time; + printf("| encode profiling | name=%s, frame=%d, fps=%.2f\n", + ost->enc_ctx->codec->name, ost->enc_ctx->frame_number, fps); + } + } av_freep(&ost->enc_ctx->stats_in); } total_packets_written += ost->packets_written; @@ -4966,12 +5000,47 @@ static int transcode(void) for (i = 0; i < nb_input_streams; i++) { ist = input_streams[i]; if (ist->decoding_needed) { + if (do_profiling_all && !ist->dec_ctx->hwaccel) { + if (ist->dec_ctx->frame_number > 1 && ist->dec_ctx->sum_working_time > 1) { + double fps = (double)(ist->dec_ctx->frame_number * 1000000) / ist->dec_ctx->sum_working_time; + printf("| sw decode profiling | name=%s, frame=%d, fps=%.2f\n", + ist->dec_ctx->codec->name, ist->dec_ctx->frame_number, fps); + } + } avcodec_close(ist->dec_ctx); if (ist->hwaccel_uninit) ist->hwaccel_uninit(ist->dec_ctx); } } + if (do_profiling_all) { //for filters + for (i = 0; i < nb_filtergraphs; i++) { + FilterGraph *fg = filtergraphs[i]; + int j; + for (j = 0; j < fg->graph->nb_filters; j++) { + AVFilterContext *ft = fg->graph->filters[j]; + int64_t frame_cnt = 0; + int k; + + if (!ft) + continue; + for (k = 0; k < ft->nb_outputs; k++) { + if (ft->outputs[k]) + frame_cnt += ft->outputs[k]->frame_count_out; + } + if (frame_cnt == 0) + continue; + if (ft->sum_working_time > 1) { + double fps = (double)(frame_cnt * 1000000) / ft->sum_working_time; + if (fps < 10000) { //some filter delivered too big fps is not we focused + printf("| filter profiling | name=%s, init=%.2f ms, frame=%d, fps=%.2f\n", + ft->filter->name, (double)ft->init_working_time / 1000, frame_cnt, fps); + } + } + } + } + } + av_buffer_unref(&hw_device_ctx); hw_device_free_all(); diff --git a/fftools/ffmpeg.h b/fftools/ffmpeg.h index 436e428..7142873 100644 --- a/fftools/ffmpeg.h +++ b/fftools/ffmpeg.h @@ -601,6 +601,7 @@ extern int video_sync_method; extern float frame_drop_threshold; extern int do_benchmark; extern int do_benchmark_all; +extern int do_profiling_all; extern int do_deinterlace; extern int do_hex_dump; extern int do_pkt_dump; diff --git a/fftools/ffmpeg_opt.c b/fftools/ffmpeg_opt.c index fa5a556..bf71423 100644 --- a/fftools/ffmpeg_opt.c +++ b/fftools/ffmpeg_opt.c @@ -94,6 +94,7 @@ float frame_drop_threshold = 0; int do_deinterlace = 0; int do_benchmark = 0; int do_benchmark_all = 0; +int do_profiling_all = 0; int do_hex_dump = 0; int do_pkt_dump = 0; int copy_ts = 0; @@ -3295,6 +3296,10 @@ int ffmpeg_parse_options(int argc, char **argv) check_filter_outputs(); + if (do_profiling_all) { + av_profiling_set(do_profiling_all); + } + fail: uninit_parse_context(&octx); if (ret < 0) { @@ -3397,6 +3402,8 @@ const OptionDef options[] = { "add timings for benchmarking" }, { "benchmark_all", OPT_BOOL | OPT_EXPERT, { &do_benchmark_all }, "add timings for each task" }, + { "profiling_all", OPT_BOOL | OPT_EXPERT, { &do_profiling_all }, + "print performance info based on all running pipelines" }, { "progress", HAS_ARG | OPT_EXPERT, { .func_arg = opt_progress }, "write program-readable progress information", "url" }, { "stdin", OPT_BOOL | OPT_EXPERT, { &stdin_interaction }, diff --git a/libavcodec/avcodec.h b/libavcodec/avcodec.h index 84ccd8d..6d3ab2e 100644 --- a/libavcodec/avcodec.h +++ b/libavcodec/avcodec.h @@ -3339,6 +3339,8 @@ typedef struct AVCodecContext { * used as reference pictures). */ int extra_hw_frames; + + unsigned long long int last_tm, sum_working_time; } AVCodecContext; #if FF_API_CODEC_GET_SET diff --git a/libavcodec/decode.c b/libavcodec/decode.c index b18ad02..4ded2f6 100644 --- a/libavcodec/decode.c +++ b/libavcodec/decode.c @@ -399,6 +399,7 @@ static int64_t guess_correct_pts(AVCodecContext *ctx, * returning any output, so this function needs to be called in a loop until it * returns EAGAIN. **/ + #include "libavutil/time.h" static int decode_simple_internal(AVCodecContext *avctx, AVFrame *frame) { AVCodecInternal *avci = avctx->internal; @@ -430,7 +431,11 @@ static int decode_simple_internal(AVCodecContext *avctx, AVFrame *frame) if (HAVE_THREADS && avctx->active_thread_type & FF_THREAD_FRAME) { ret = ff_thread_decode_frame(avctx, frame, &got_frame, pkt); } else { + if (av_profiling_get()) + avctx->last_tm = av_gettime(); ret = avctx->codec->decode(avctx, frame, &got_frame, pkt); + if (av_profiling_get()) + avctx->sum_working_time += av_gettime() - avctx->last_tm; if (!(avctx->codec->caps_internal & FF_CODEC_CAP_SETS_PKT_DTS)) frame->pkt_dts = pkt->dts; diff --git a/libavcodec/encode.c b/libavcodec/encode.c index d12c425..0f71426 100644 --- a/libavcodec/encode.c +++ b/libavcodec/encode.c @@ -28,6 +28,7 @@ #include "avcodec.h" #include "frame_thread_encoder.h" #include "internal.h" +#include "libavutil/time.h" int ff_alloc_packet2(AVCodecContext *avctx, AVPacket *avpkt, int64_t size, int64_t min_size) { @@ -293,7 +294,12 @@ int attribute_align_arg avcodec_encode_video2(AVCodecContext *avctx, av_assert0(avctx->codec->encode2); + if (av_profiling_get()) + avctx->last_tm = av_gettime(); ret = avctx->codec->encode2(avctx, avpkt, frame, got_packet_ptr); + if (av_profiling_get()) + avctx->sum_working_time += av_gettime() - avctx->last_tm; + av_assert0(ret <= 0); emms_c(); diff --git a/libavcodec/pthread_frame.c b/libavcodec/pthread_frame.c index 36ac0ac..caa49f6 100644 --- a/libavcodec/pthread_frame.c +++ b/libavcodec/pthread_frame.c @@ -44,6 +44,7 @@ #include "libavutil/mem.h" #include "libavutil/opt.h" #include "libavutil/thread.h" +#include "libavutil/time.h" enum { ///< Set when the thread is awaiting a packet. @@ -198,7 +199,11 @@ static attribute_align_arg void *frame_worker_thread(void *arg) av_frame_unref(p->frame); p->got_frame = 0; + if (av_profiling_get()) + avctx->last_tm = av_gettime(); p->result = codec->decode(avctx, p->frame, &p->got_frame, &p->avpkt); + if (av_profiling_get() && !avctx->hwaccel) + avctx->sum_working_time += av_gettime() - avctx->last_tm; if ((p->result < 0 || !p->got_frame) && p->frame->buf[0]) { if (avctx->internal->allocate_progress) @@ -283,6 +288,10 @@ static int update_context_from_thread(AVCodecContext *dst, AVCodecContext *src, dst->sample_fmt = src->sample_fmt; dst->channel_layout = src->channel_layout; dst->internal->hwaccel_priv_data = src->internal->hwaccel_priv_data; + if (av_profiling_get()) { + dst->last_tm = src->last_tm; + dst->sum_working_time = src->sum_working_time; + } if (!!dst->hw_frames_ctx != !!src->hw_frames_ctx || (dst->hw_frames_ctx && dst->hw_frames_ctx->data != src->hw_frames_ctx->data)) { @@ -340,6 +349,10 @@ static int update_context_from_user(AVCodecContext *dst, AVCodecContext *src) dst->frame_number = src->frame_number; dst->reordered_opaque = src->reordered_opaque; dst->thread_safe_callbacks = src->thread_safe_callbacks; + if (av_profiling_get()) { + dst->last_tm = src->last_tm; + dst->sum_working_time = src->sum_working_time; + } if (src->slice_count && src->slice_offset) { if (dst->slice_count < src->slice_count) { diff --git a/libavcodec/utils.c b/libavcodec/utils.c index 1661d48..8b6d6e4 100644 --- a/libavcodec/utils.c +++ b/libavcodec/utils.c @@ -692,6 +692,7 @@ int attribute_align_arg avcodec_open2(AVCodecContext *avctx, const AVCodec *code goto free_and_end; } avctx->frame_number = 0; + avctx->sum_working_time = 0; avctx->codec_descriptor = avcodec_descriptor_get(avctx->codec_id); if ((avctx->codec->capabilities & AV_CODEC_CAP_EXPERIMENTAL) && diff --git a/libavfilter/avfilter.c b/libavfilter/avfilter.c index 93e866b..2951bc4 100644 --- a/libavfilter/avfilter.c +++ b/libavfilter/avfilter.c @@ -44,6 +44,7 @@ #include "internal.h" #include "libavutil/ffversion.h" +#include "libavutil/time.h" const char av_filter_ffversion[] = "FFmpeg version " FFMPEG_VERSION; void ff_tlog_ref(void *ctx, AVFrame *ref, int end) @@ -760,6 +761,7 @@ static void free_link(AVFilterLink *link) void avfilter_free(AVFilterContext *filter) { int i; + int64_t frame_cnt = 0; if (!filter) return; @@ -925,6 +927,7 @@ int avfilter_init_str(AVFilterContext *filter, const char *args) { AVDictionary *options = NULL; AVDictionaryEntry *e; + int64_t tm_init; int ret = 0; if (args && *args) { @@ -1015,7 +1018,12 @@ int avfilter_init_str(AVFilterContext *filter, const char *args) } } + if (av_profiling_get()) + tm_init = av_gettime(); ret = avfilter_init_dict(filter, &options); + if (av_profiling_get()) + filter->init_working_time = av_gettime() - tm_init; + if (ret < 0) goto fail; @@ -1422,12 +1430,19 @@ int ff_filter_activate(AVFilterContext *filter) { int ret; + if (av_profiling_get()) + filter->last_tm = av_gettime(); + /* Generic timeline support is not yet implemented but should be easy */ av_assert1(!(filter->filter->flags & AVFILTER_FLAG_SUPPORT_TIMELINE_GENERIC && filter->filter->activate)); filter->ready = 0; ret = filter->filter->activate ? filter->filter->activate(filter) : ff_filter_activate_default(filter); + + if (av_profiling_get()) + filter->sum_working_time += av_gettime() - filter->last_tm; + if (ret == FFERROR_NOT_READY) ret = 0; return ret; diff --git a/libavfilter/avfilter.h b/libavfilter/avfilter.h index 9d70e71..e70142e 100644 --- a/libavfilter/avfilter.h +++ b/libavfilter/avfilter.h @@ -422,6 +422,8 @@ struct AVFilterContext { * configured. */ int extra_hw_frames; + + int64_t last_tm, init_working_time, sum_working_time; }; /** diff --git a/libavutil/log.c b/libavutil/log.c index 93a156b..84d0282 100644 --- a/libavutil/log.c +++ b/libavutil/log.c @@ -52,6 +52,7 @@ static AVMutex mutex = AV_MUTEX_INITIALIZER; #endif static int av_log_level = AV_LOG_INFO; +static int av_profiling = 0; static int flags; #define NB_LEVELS 8 @@ -402,6 +403,16 @@ void av_log_set_callback(void (*callback)(void*, int, const char*, va_list)) av_log_callback = callback; } +int av_profiling_get(void) +{ + return av_profiling; +} + +void av_profiling_set(int arg) +{ + av_profiling = arg; +} + static void missing_feature_sample(int sample, void *avc, const char *msg, va_list argument_list) { diff --git a/libavutil/log.h b/libavutil/log.h index d9554e6..0fb29dd 100644 --- a/libavutil/log.h +++ b/libavutil/log.h @@ -297,6 +297,9 @@ void av_log_set_callback(void (*callback)(void*, int, const char*, va_list)); void av_log_default_callback(void *avcl, int level, const char *fmt, va_list vl); +int av_profiling_get(void); +void av_profiling_set(int arg); + /** * Return the context name * -- 1.8.3.1