From 473e46f0cc1b87bcfb6d2873b720dbe554fa95c7 Mon Sep 17 00:00:00 2001 From: Govindaraj Rajagopal Date: Wed, 20 Jul 2022 20:02:21 +0530 Subject: [PATCH] video: driver: add buffer statistics logic Added change to print etb, ebd, ftb, fbd, (ebd-etb), (fbd - etb), (etb-ftb) wallclock time in ms. It will help to debug perf issues. Change-Id: Ideaecb2d51763711d6628729aa0f9056d05f0d51 Signed-off-by: Govindaraj Rajagopal --- driver/vidc/inc/msm_vidc_debug.h | 5 + driver/vidc/inc/msm_vidc_driver.h | 5 + driver/vidc/inc/msm_vidc_inst.h | 2 + driver/vidc/inc/msm_vidc_internal.h | 20 ++++ driver/vidc/inc/msm_vidc_memory.h | 1 + driver/vidc/src/msm_vdec.c | 2 + driver/vidc/src/msm_vidc.c | 2 + driver/vidc/src/msm_vidc_driver.c | 160 ++++++++++++++++++++++++++- driver/vidc/src/msm_vidc_memory.c | 1 + driver/vidc/src/msm_vidc_vb2.c | 9 +- driver/vidc/src/venus_hfi_response.c | 6 + 11 files changed, 210 insertions(+), 3 deletions(-) diff --git a/driver/vidc/inc/msm_vidc_debug.h b/driver/vidc/inc/msm_vidc_debug.h index 85df5fe60b..2b07215df9 100644 --- a/driver/vidc/inc/msm_vidc_debug.h +++ b/driver/vidc/inc/msm_vidc_debug.h @@ -64,6 +64,7 @@ enum vidc_msg_prio { VIDC_PERF = 0x00000008, VIDC_PKT = 0x00000010, VIDC_BUS = 0x00000020, + VIDC_STAT = 0x00000040, VIDC_ENCODER = 0x00000100, VIDC_DECODER = 0x00000200, VIDC_PRINTK = 0x00001000, @@ -97,9 +98,12 @@ enum vidc_msg_prio { #define i_vpr_p(inst, __fmt, ...) dprintk_inst(VIDC_PERF, "perf", inst, __fmt, ##__VA_ARGS__) #define i_vpr_t(inst, __fmt, ...) dprintk_inst(VIDC_PKT, "pkt ", inst, __fmt, ##__VA_ARGS__) #define i_vpr_b(inst, __fmt, ...) dprintk_inst(VIDC_BUS, "bus ", inst, __fmt, ##__VA_ARGS__) +#define i_vpr_s(inst, __fmt, ...) dprintk_inst(VIDC_STAT, "stat", inst, __fmt, ##__VA_ARGS__) #define i_vpr_hp(inst, __fmt, ...) \ dprintk_inst(VIDC_HIGH | VIDC_PERF, "high", inst, __fmt, ##__VA_ARGS__) +#define i_vpr_hs(inst, __fmt, ...) \ + dprintk_inst(VIDC_HIGH | VIDC_STAT, "high", inst, __fmt, ##__VA_ARGS__) #define dprintk_core(__level, __level_str, __fmt, ...) \ do { \ @@ -118,6 +122,7 @@ enum vidc_msg_prio { #define d_vpr_p(__fmt, ...) dprintk_core(VIDC_PERF, "perf", __fmt, ##__VA_ARGS__) #define d_vpr_t(__fmt, ...) dprintk_core(VIDC_PKT, "pkt ", __fmt, ##__VA_ARGS__) #define d_vpr_b(__fmt, ...) dprintk_core(VIDC_BUS, "bus ", __fmt, ##__VA_ARGS__) +#define d_vpr_s(__fmt, ...) dprintk_core(VIDC_STAT, "stat", __fmt, ##__VA_ARGS__) #define dprintk_ratelimit(__level, __level_str, __fmt, ...) \ do { \ diff --git a/driver/vidc/inc/msm_vidc_driver.h b/driver/vidc/inc/msm_vidc_driver.h index 230ac8e052..0e9647e31f 100644 --- a/driver/vidc/inc/msm_vidc_driver.h +++ b/driver/vidc/inc/msm_vidc_driver.h @@ -585,6 +585,11 @@ int msm_vidc_get_properties(struct msm_vidc_inst *inst); int msm_vidc_create_input_metadata_buffer(struct msm_vidc_inst *inst, int buf_fd); int msm_vidc_update_input_meta_buffer_index(struct msm_vidc_inst *inst, struct vb2_buffer *vb2); int msm_vidc_update_input_rate(struct msm_vidc_inst *inst, u64 time_us); +int msm_vidc_add_buffer_stats(struct msm_vidc_inst *inst, + struct msm_vidc_buffer *buf); +int msm_vidc_remove_buffer_stats(struct msm_vidc_inst *inst, + struct msm_vidc_buffer *buf); +int msm_vidc_flush_buffer_stats(struct msm_vidc_inst *inst); int msm_vidc_get_input_rate(struct msm_vidc_inst *inst); int msm_vidc_get_frame_rate(struct msm_vidc_inst *inst); int msm_vidc_get_operating_rate(struct msm_vidc_inst *inst); diff --git a/driver/vidc/inc/msm_vidc_inst.h b/driver/vidc/inc/msm_vidc_inst.h index 954e519762..befd855b29 100644 --- a/driver/vidc/inc/msm_vidc_inst.h +++ b/driver/vidc/inc/msm_vidc_inst.h @@ -163,6 +163,7 @@ struct msm_vidc_inst { struct list_head firmware_list; /* struct msm_vidc_inst_cap_entry */ struct list_head pending_pkts; /* list of struct hfi_pending_packet */ struct list_head fence_list; /* list of struct msm_vidc_fence */ + struct list_head buffer_stats_list; /* struct msm_vidc_buffer_stats */ bool once_per_session_set; bool ipsc_properties_set; bool opsc_properties_set; @@ -175,6 +176,7 @@ struct msm_vidc_inst { struct msm_vidc_fence_context fence_context; bool active; u64 last_qbuf_time_ns; + u64 initial_time_us; bool vb2q_init; u32 max_input_data_size; u32 dpb_list_payload[MAX_DPB_LIST_ARRAY_SIZE]; diff --git a/driver/vidc/inc/msm_vidc_internal.h b/driver/vidc/inc/msm_vidc_internal.h index 1fd1841860..c4eeb7a4f0 100644 --- a/driver/vidc/inc/msm_vidc_internal.h +++ b/driver/vidc/inc/msm_vidc_internal.h @@ -903,6 +903,8 @@ struct msm_vidc_buffer { u64 timestamp; enum msm_vidc_buffer_attributes attr; u64 fence_id; + u32 start_time_ms; + u32 end_time_ms; }; struct msm_vidc_buffers { @@ -914,6 +916,24 @@ struct msm_vidc_buffers { bool reuse; }; +struct msm_vidc_buffer_stats { + struct list_head list; + u32 frame_num; + u64 timestamp; + u32 etb_time_ms; + u32 ebd_time_ms; + u32 ftb_time_ms; + u32 fbd_time_ms; + u32 data_size; + u32 flags; +}; + +enum msm_vidc_buffer_stats_flag { + MSM_VIDC_STATS_FLAG_CORRUPT = BIT(0), + MSM_VIDC_STATS_FLAG_OVERFLOW = BIT(1), + MSM_VIDC_STATS_FLAG_NO_OUTPUT = BIT(2), +}; + struct msm_vidc_sort { struct list_head list; s64 val; diff --git a/driver/vidc/inc/msm_vidc_memory.h b/driver/vidc/inc/msm_vidc_memory.h index cbaca724b4..11105260b6 100644 --- a/driver/vidc/inc/msm_vidc_memory.h +++ b/driver/vidc/inc/msm_vidc_memory.h @@ -27,6 +27,7 @@ enum msm_memory_pool_type { MSM_MEM_POOL_DMABUF, MSM_MEM_POOL_PACKET, MSM_MEM_POOL_BUF_TIMER, + MSM_MEM_POOL_BUF_STATS, MSM_MEM_POOL_MAX, }; diff --git a/driver/vidc/src/msm_vdec.c b/driver/vidc/src/msm_vdec.c index ea64f9cfa4..717c0ffeec 100644 --- a/driver/vidc/src/msm_vdec.c +++ b/driver/vidc/src/msm_vdec.c @@ -1881,6 +1881,8 @@ static int msm_vdec_qbuf_batch(struct msm_vidc_inst *inst, if (!buf) return -EINVAL; + msm_vidc_add_buffer_stats(inst, buf); + allow = msm_vidc_allow_qbuf(inst, vb2->type); if (allow == MSM_VIDC_DISALLOW) { i_vpr_e(inst, "%s: qbuf not allowed\n", __func__); diff --git a/driver/vidc/src/msm_vidc.c b/driver/vidc/src/msm_vidc.c index b61803b89b..08286853c9 100644 --- a/driver/vidc/src/msm_vidc.c +++ b/driver/vidc/src/msm_vidc.c @@ -897,6 +897,7 @@ void *msm_vidc_open(void *vidc_core, u32 session_type) inst->opsc_properties_set = false; inst->has_bframe = false; inst->auto_framerate = DEFAULT_FPS << 16; + inst->initial_time_us = ktime_get_ns() / 1000; kref_init(&inst->kref); mutex_init(&inst->lock); mutex_init(&inst->request_lock); @@ -957,6 +958,7 @@ void *msm_vidc_open(void *vidc_core, u32 session_type) INIT_LIST_HEAD(&inst->input_timer_list); INIT_LIST_HEAD(&inst->pending_pkts); INIT_LIST_HEAD(&inst->fence_list); + INIT_LIST_HEAD(&inst->buffer_stats_list); for (i = 0; i < MAX_SIGNAL; i++) init_completion(&inst->completions[i]); diff --git a/driver/vidc/src/msm_vidc_driver.c b/driver/vidc/src/msm_vidc_driver.c index 7ab506d026..c03c007bd5 100644 --- a/driver/vidc/src/msm_vidc_driver.c +++ b/driver/vidc/src/msm_vidc_driver.c @@ -481,6 +481,25 @@ void print_vb2_buffer(const char *str, struct msm_vidc_inst *inst, } } +static void print_buffer_stats(u32 tag, const char *tag_str, struct msm_vidc_inst *inst, + struct msm_vidc_buffer_stats *stats) +{ + if (!tag_str || !inst || !stats) + return; + + /* skip flushed buffer stats */ + if (!stats->etb_time_ms || !stats->ebd_time_ms || + !stats->ftb_time_ms || !stats->fbd_time_ms) + return; + + dprintk_inst(tag, tag_str, inst, + "f.no %4u ts %16llu (etb ebd ftb fbd)ms %6u %6u %6u %6u (ebd-etb fbd-etb etb-ftb)ms %4d %4d %4d size %8u attr %#x\n", + stats->frame_num, stats->timestamp, stats->etb_time_ms, stats->ebd_time_ms, + stats->ftb_time_ms, stats->fbd_time_ms, stats->ebd_time_ms - stats->etb_time_ms, + stats->fbd_time_ms - stats->etb_time_ms, stats->etb_time_ms - stats->ftb_time_ms, + stats->data_size, stats->flags); +} + static void __fatal_error(bool fatal) { WARN_ON(fatal); @@ -498,6 +517,135 @@ static int __strict_check(struct msm_vidc_core *core, const char *function) return fatal ? -EINVAL : 0; } +static u32 msm_vidc_get_buffer_stats_flag(struct msm_vidc_inst *inst) +{ + u32 flags = 0; + + if (inst->hfi_frame_info.data_corrupt) + flags |= MSM_VIDC_STATS_FLAG_CORRUPT; + + if (inst->hfi_frame_info.overflow) + flags |= MSM_VIDC_STATS_FLAG_OVERFLOW; + + if (inst->hfi_frame_info.no_output) + flags |= MSM_VIDC_STATS_FLAG_NO_OUTPUT; + + return flags; +} + +int msm_vidc_add_buffer_stats(struct msm_vidc_inst *inst, + struct msm_vidc_buffer *buf) +{ + struct msm_vidc_buffer_stats *stats = NULL; + + if (!inst || !buf) { + d_vpr_e("%s: invalid params\n", __func__); + return -EINVAL; + } + + /* stats applicable only to input & output buffers */ + if (buf->type != MSM_VIDC_BUF_INPUT && buf->type != MSM_VIDC_BUF_OUTPUT) + return -EINVAL; + + /* update start timestamp */ + buf->start_time_ms = (ktime_get_ns() / 1000 - inst->initial_time_us) / 1000; + + /* add buffer stats only in ETB path */ + if (buf->type != MSM_VIDC_BUF_INPUT) + return 0; + + stats = msm_memory_pool_alloc(inst, MSM_MEM_POOL_BUF_STATS); + if (!stats) + return -ENOMEM; + INIT_LIST_HEAD(&stats->list); + list_add_tail(&stats->list, &inst->buffer_stats_list); + + stats->frame_num = inst->debug_count.etb; + stats->timestamp = buf->timestamp; + stats->etb_time_ms = buf->start_time_ms; + if (is_decode_session(inst)) + stats->data_size = buf->data_size; + + return 0; +} + +int msm_vidc_remove_buffer_stats(struct msm_vidc_inst *inst, + struct msm_vidc_buffer *buf) +{ + struct msm_vidc_buffer_stats *stats = NULL, *dummy_stats = NULL; + + if (!inst || !buf) { + d_vpr_e("%s: invalid params\n", __func__); + return -EINVAL; + } + + /* stats applicable only to input & output buffers */ + if (buf->type != MSM_VIDC_BUF_INPUT && buf->type != MSM_VIDC_BUF_OUTPUT) + return -EINVAL; + + /* update end timestamp */ + buf->end_time_ms = (ktime_get_ns() / 1000 - inst->initial_time_us) / 1000; + + list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) { + if (stats->timestamp == buf->timestamp) { + if (buf->type == MSM_VIDC_BUF_INPUT) { + /* skip - already updated(multiple input - single output case) */ + if (stats->ebd_time_ms) + continue; + + /* ebd: update end ts and return */ + stats->ebd_time_ms = buf->end_time_ms; + stats->flags |= msm_vidc_get_buffer_stats_flag(inst); + + /* remove entry - no output attached */ + if (stats->flags & MSM_VIDC_STATS_FLAG_NO_OUTPUT) { + list_del_init(&stats->list); + msm_memory_pool_free(inst, stats); + } + } else if (buf->type == MSM_VIDC_BUF_OUTPUT) { + /* skip - ebd not arrived(single input - multiple output case) */ + if (!stats->ebd_time_ms) + continue; + + /* fbd: update end ts and remove entry */ + list_del_init(&stats->list); + stats->ftb_time_ms = buf->start_time_ms; + stats->fbd_time_ms = buf->end_time_ms; + stats->flags |= msm_vidc_get_buffer_stats_flag(inst); + if (is_encode_session(inst)) + stats->data_size = buf->data_size; + + print_buffer_stats(VIDC_STAT, "stat", inst, stats); + + msm_memory_pool_free(inst, stats); + } + } + } + + return 0; +} + +int msm_vidc_flush_buffer_stats(struct msm_vidc_inst *inst) +{ + struct msm_vidc_buffer_stats *stats, *dummy_stats; + + if (!inst) { + d_vpr_e("%s: invalid params\n", __func__); + return -EINVAL; + } + + i_vpr_l(inst, "%s: flush buffer_stats list\n", __func__); + list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) { + list_del_init(&stats->list); + msm_memory_pool_free(inst, stats); + } + + /* reset initial ts as well to avoid huge delta */ + inst->initial_time_us = ktime_get_ns() / 1000; + + return 0; +} + enum msm_vidc_buffer_type v4l2_type_to_driver(u32 type, const char *func) { enum msm_vidc_buffer_type buffer_type = 0; @@ -3465,7 +3613,7 @@ void msm_vidc_print_stats(struct msm_vidc_inst *inst) achieved_fps = (fbd * 1000) / dt_ms; bitrate_kbps = (inst->stats.data_size * 8 * 1000) / (dt_ms * 1024); - i_vpr_hp(inst, + i_vpr_hs(inst, "stats: counts (etb,ebd,ftb,fbd): %u %u %u %u (total %llu %llu %llu %llu), achieved bitrate %lldKbps fps %u/s, frame rate %u, operating rate %u, priority %u, dt %ums\n", etb, ebd, ftb, fbd, inst->debug_count.etb, inst->debug_count.ebd, inst->debug_count.ftb, inst->debug_count.fbd, @@ -3677,6 +3825,9 @@ int msm_vidc_queue_buffer_single(struct msm_vidc_inst *inst, struct vb2_buffer * if (!buf) return -EINVAL; + /* update start timestamp */ + msm_vidc_add_buffer_stats(inst, buf); + if (is_meta_rx_inp_enabled(inst, META_OUTBUF_FENCE) && is_output_buffer(buf->type)) { fence = msm_vidc_fence_create(inst); @@ -5641,6 +5792,7 @@ void msm_vidc_destroy_buffers(struct msm_vidc_inst *inst) struct msm_vidc_timestamp *ts, *dummy_ts; struct msm_memory_dmabuf *dbuf, *dummy_dbuf; struct msm_vidc_input_timer *timer, *dummy_timer; + struct msm_vidc_buffer_stats *stats, *dummy_stats; struct msm_vidc_inst_cap_entry *entry, *dummy_entry; struct msm_vidc_fence *fence, *dummy_fence; @@ -5731,6 +5883,12 @@ void msm_vidc_destroy_buffers(struct msm_vidc_inst *inst) msm_memory_pool_free(inst, timer); } + list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) { + print_buffer_stats(VIDC_ERR, "err ", inst, stats); + list_del(&stats->list); + msm_memory_pool_free(inst, stats); + } + list_for_each_entry_safe(dbuf, dummy_dbuf, &inst->dmabuf_tracker, list) { i_vpr_e(inst, "%s: removing dma_buf %#x, refcount %u\n", __func__, dbuf->dmabuf, dbuf->refcount); diff --git a/driver/vidc/src/msm_vidc_memory.c b/driver/vidc/src/msm_vidc_memory.c index 804817391f..aab13ccd6f 100644 --- a/driver/vidc/src/msm_vidc_memory.c +++ b/driver/vidc/src/msm_vidc_memory.c @@ -617,6 +617,7 @@ static const struct msm_vidc_type_size_name buftype_size_name_arr[] = { {MSM_MEM_POOL_PACKET, sizeof(struct hfi_pending_packet) + MSM_MEM_POOL_PACKET_SIZE, "MSM_MEM_POOL_PACKET"}, {MSM_MEM_POOL_BUF_TIMER, sizeof(struct msm_vidc_input_timer), "MSM_MEM_POOL_BUF_TIMER" }, + {MSM_MEM_POOL_BUF_STATS, sizeof(struct msm_vidc_buffer_stats), "MSM_MEM_POOL_BUF_STATS"}, }; int msm_memory_pools_init(struct msm_vidc_inst *inst) diff --git a/driver/vidc/src/msm_vidc_vb2.c b/driver/vidc/src/msm_vidc_vb2.c index 4b3378fe5d..9cf3a26af9 100644 --- a/driver/vidc/src/msm_vidc_vb2.c +++ b/driver/vidc/src/msm_vidc_vb2.c @@ -403,10 +403,15 @@ void msm_vidc_stop_streaming(struct vb2_queue *q) if (rc) goto unlock; - /* Input port streamoff - flush timestamps list*/ - if (q->type == INPUT_MPLANE) + /* Input port streamoff */ + if (q->type == INPUT_MPLANE) { + /* flush timestamps list */ msm_vidc_flush_ts(inst); + /* flush buffer_stats list */ + msm_vidc_flush_buffer_stats(inst); + } + i_vpr_h(inst, "Streamoff: %s successful\n", v4l2_type_name(q->type)); unlock: diff --git a/driver/vidc/src/venus_hfi_response.c b/driver/vidc/src/venus_hfi_response.c index 7ca06f3410..7b43bffc43 100644 --- a/driver/vidc/src/venus_hfi_response.c +++ b/driver/vidc/src/venus_hfi_response.c @@ -856,6 +856,9 @@ static int handle_input_buffer(struct msm_vidc_inst *inst, print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf); msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_EBD); + /* etd: update end timestamp and flags in stats entry */ + msm_vidc_remove_buffer_stats(inst, buf); + return rc; } @@ -1019,6 +1022,9 @@ static int handle_output_buffer(struct msm_vidc_inst *inst, print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf); msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_FBD); + /* fbd: print stats and remove entry */ + msm_vidc_remove_buffer_stats(inst, buf); + return rc; }