From: Joonbum Ko Date: Fri, 12 Apr 2024 03:59:10 +0000 (+0900) Subject: wl_egl: add logs to print elapsed time X-Git-Tag: accepted/tizen/8.0/unified/20240415.141904~2 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=b1b40a1f61b72299b25d48ce8ca65db1e7cfe306;p=platform%2Fcore%2Fuifw%2Flibtpl-egl.git wl_egl: add logs to print elapsed time Change-Id: Ie910e39d5ec15800dd04db1d7198a40361dd9e8f Signed-off-by: Joonbum Ko --- diff --git a/src/tpl_utils.h b/src/tpl_utils.h index 08d7ab6..dc35956 100644 --- a/src/tpl_utils.h +++ b/src/tpl_utils.h @@ -47,6 +47,7 @@ #include #include #include +#include #include #include @@ -738,4 +739,5 @@ __tpl_util_image_dump(void *data, int width, int height) tbm_surface_internal_dump_buffer((tbm_surface_h)data, "png"); tbm_surface_internal_dump_end(); } + #endif /* TPL_UTILS_H */ diff --git a/src/tpl_wl_egl_thread.c b/src/tpl_wl_egl_thread.c index 5d5b263..11d7dda 100755 --- a/src/tpl_wl_egl_thread.c +++ b/src/tpl_wl_egl_thread.c @@ -155,6 +155,11 @@ struct _tpl_wl_egl_surface { /* To make sure that tpl_gsource has been successfully finalized. */ tpl_bool_t gsource_finalized; + + struct timespec last_commit; + int last_commit_bo; + struct timespec last_release; + int last_release_bo; }; struct _surface_vblank { @@ -242,6 +247,9 @@ struct _tpl_wl_egl_buffer { tpl_gcond cond; tpl_wl_egl_surface_t *wl_egl_surface; + + struct timespec begin; + buffer_status_t begin_status; }; #if TIZEN_FEATURE_ENABLE @@ -281,6 +289,89 @@ _thread_wl_surface_commit(tpl_wl_egl_surface_t *wl_egl_surface, static void __cb_surface_vblank_free(void *data); +#define REL_TO_DEQ 30 +#define DEQ_TO_ENQ 20 +#define DEQ_TO_CAN 20 +#define ENQ_TO_ACQ 20 +#define ACQ_TO_SIG 10 +#define ACQ_TO_VBL 10 +#define SIG_TO_VBL 30 +#define VBL_TO_CMT 20 +#define CMT_TO_REL 50 + +#define RELEASE_FROM_LAST_COMMIT 20 +#define DEQUEUE_FROM_LAST_RELEASE 20 + +static long +_cal_time_gap(struct timespec begin, struct timespec end) +{ + long gap_ms = 1000 * (end.tv_sec - begin.tv_sec); + gap_ms = gap_ms + ((end.tv_nsec/1000000) - (begin.tv_nsec/1000000)); + return gap_ms; +} + +static void +_elapsed_between_status(tpl_wl_egl_buffer_t *wl_egl_buffer, long threshold) +{ + struct timespec end; + clock_gettime(CLOCK_MONOTONIC, &end); + long gap = _cal_time_gap(wl_egl_buffer->begin, end); + if (wl_egl_buffer->begin_status != COMMITTED && gap > threshold) { + TPL_ERR("bo_name(%d) | %s ~ %s | takes too long time %ld > %ld", + wl_egl_buffer->bo_name, + status_to_string[wl_egl_buffer->begin_status], + status_to_string[wl_egl_buffer->status], + gap, threshold); + } + wl_egl_buffer->begin.tv_sec = end.tv_sec; + wl_egl_buffer->begin.tv_nsec = end.tv_nsec; + wl_egl_buffer->begin_status = wl_egl_buffer->status; +} + +static void +_elapsed_from_last_commit(tpl_wl_egl_surface_t *wl_egl_surface, int bo_name) +{ + struct timespec release; + clock_gettime(CLOCK_MONOTONIC, &release); + long gap = _cal_time_gap(wl_egl_surface->last_commit, release); + if (gap > RELEASE_FROM_LAST_COMMIT) { + TPL_ERR("last COMMIT(%d) ~ RELEASE(%d) | takes too long time %ld > %d", + wl_egl_surface->last_commit_bo, bo_name, + gap, RELEASE_FROM_LAST_COMMIT); + } +} + +static void +_update_last_commit_time(tpl_wl_egl_surface_t *wl_egl_surface) +{ + struct timespec commit; + clock_gettime(CLOCK_MONOTONIC, &commit); + wl_egl_surface->last_commit.tv_sec = commit.tv_sec; + wl_egl_surface->last_commit.tv_nsec = commit.tv_nsec; +} + +static void +_elapsed_from_last_release(tpl_wl_egl_surface_t *wl_egl_surface, int bo_name) +{ + struct timespec dequeue; + clock_gettime(CLOCK_MONOTONIC, &dequeue); + long gap = _cal_time_gap(wl_egl_surface->last_release, dequeue); + if (gap > RELEASE_FROM_LAST_COMMIT) { + TPL_ERR("last RELEASE(%d) ~ DEQUEUE(%d) | takes too long time %ld > %d", + wl_egl_surface->last_release_bo, bo_name, + gap, DEQUEUE_FROM_LAST_RELEASE); + } +} + +static void +_update_last_release_time(tpl_wl_egl_surface_t *wl_egl_surface) +{ + struct timespec release; + clock_gettime(CLOCK_MONOTONIC, &release); + wl_egl_surface->last_release.tv_sec = release.tv_sec; + wl_egl_surface->last_release.tv_nsec = release.tv_nsec; +} + static struct tizen_private * tizen_private_create() { @@ -1819,6 +1910,9 @@ __tpl_wl_egl_surface_init(tpl_surface_t *surface) wl_egl_surface->buffers = __tpl_list_alloc(); + _update_last_release_time(wl_egl_surface); + wl_egl_surface->last_release_bo = -1; + { struct tizen_private *tizen_private = NULL; @@ -2489,6 +2583,8 @@ _wl_egl_buffer_create(tpl_wl_egl_surface_t *wl_egl_surface, wl_egl_buffer->wl_egl_surface = wl_egl_surface; wl_egl_buffer->status = RELEASED; + wl_egl_buffer->begin_status = wl_egl_buffer->status; + clock_gettime(CLOCK_MONOTONIC, &wl_egl_buffer->begin); wl_egl_buffer->acquire_fence_fd = -1; wl_egl_buffer->commit_sync_fd = -1; @@ -2699,6 +2795,8 @@ __tpl_wl_egl_surface_dequeue_buffer(tpl_surface_t *surface, uint64_t timeout_ns, tpl_gmutex_lock(&wl_egl_buffer->mutex); wl_egl_buffer->status = DEQUEUED; + _elapsed_between_status(wl_egl_buffer, REL_TO_DEQ); + _elapsed_from_last_release(wl_egl_surface, wl_egl_buffer->bo_name); /* If wl_egl_buffer->release_fence_fd is -1, * the tbm_surface can be used immediately. @@ -2764,6 +2862,7 @@ __tpl_wl_egl_surface_cancel_buffer(tpl_surface_t *surface, if (wl_egl_buffer) { tpl_gmutex_lock(&wl_egl_buffer->mutex); wl_egl_buffer->status = RELEASED; + _elapsed_between_status(wl_egl_buffer, DEQ_TO_ENQ); tpl_gmutex_unlock(&wl_egl_buffer->mutex); } @@ -2888,6 +2987,7 @@ __tpl_wl_egl_surface_enqueue_buffer(tpl_surface_t *surface, tpl_gmutex_unlock(&wl_egl_surface->commit_sync.mutex); wl_egl_buffer->status = ENQUEUED; + _elapsed_between_status(wl_egl_buffer, DEQ_TO_ENQ); TPL_LOG_T("WL_EGL", "[ENQ] wl_egl_buffer(%p) tbm_surface(%p) bo(%d) fence(%d)", wl_egl_buffer, tbm_surface, bo_name, acquire_fence); @@ -2939,6 +3039,7 @@ __thread_func_waiting_source_dispatch(tpl_gsource *gsource, uint64_t message) tpl_gmutex_lock(&wl_egl_buffer->mutex); wl_egl_buffer->status = WAITING_VBLANK; + _elapsed_between_status(wl_egl_buffer, SIG_TO_VBL); TPL_LOG_D("[FINALIZE]", "wl_egl_surface(%p) wl_egl_buffer(%p) wait_source(%p) fence_fd(%d)", wl_egl_surface, wl_egl_buffer, wl_egl_buffer->waiting_source, @@ -2976,6 +3077,8 @@ static tpl_gsource_functions buffer_funcs = { .finalize = __thread_func_waiting_source_finalize, }; + + static tpl_result_t _thread_surface_queue_acquire(tpl_wl_egl_surface_t *wl_egl_surface) { @@ -3003,6 +3106,7 @@ _thread_surface_queue_acquire(tpl_wl_egl_surface_t *wl_egl_surface) tpl_gmutex_lock(&wl_egl_buffer->mutex); wl_egl_buffer->status = ACQUIRED; + _elapsed_between_status(wl_egl_buffer, ENQ_TO_ACQ); TPL_LOG_T("WL_EGL", "[ACQ] wl_egl_buffer(%p) tbm_surface(%p) bo(%d)", wl_egl_buffer, tbm_surface, @@ -3026,6 +3130,7 @@ _thread_surface_queue_acquire(tpl_wl_egl_surface_t *wl_egl_surface) FD_TYPE_FENCE, &buffer_funcs, SOURCE_TYPE_DISPOSABLE); wl_egl_buffer->status = WAITING_SIGNALED; + _elapsed_between_status(wl_egl_buffer, ACQ_TO_SIG); TRACE_ASYNC_BEGIN(wl_egl_buffer->acquire_fence_fd, "FENCE WAIT fd(%d)", wl_egl_buffer->acquire_fence_fd); @@ -3041,6 +3146,7 @@ _thread_surface_queue_acquire(tpl_wl_egl_surface_t *wl_egl_surface) ready_to_commit = TPL_TRUE; else { wl_egl_buffer->status = WAITING_VBLANK; + _elapsed_between_status(wl_egl_buffer, ACQ_TO_VBL); tpl_gmutex_lock(&wl_egl_surface->vblank->mutex); __tpl_list_push_back(wl_egl_surface->vblank->waiting_buffers, wl_egl_buffer); tpl_gmutex_unlock(&wl_egl_surface->vblank->mutex); @@ -3130,6 +3236,10 @@ __cb_buffer_fenced_release(void *data, wl_egl_buffer->release_fence_fd = fence; wl_egl_buffer->status = RELEASED; + _elapsed_between_status(wl_egl_buffer, CMT_TO_REL); + wl_egl_surface->last_release_bo = wl_egl_buffer->bo_name; + _elapsed_from_last_commit(wl_egl_surface, wl_egl_buffer->bo_name); + _update_last_release_time(wl_egl_surface); TRACE_MARK("[FENCED_RELEASE] BO(%d) fence(%d)", _get_tbm_surface_bo_name(tbm_surface), @@ -3182,6 +3292,10 @@ __cb_buffer_immediate_release(void *data, wl_egl_buffer->release_fence_fd = -1; wl_egl_buffer->status = RELEASED; + _elapsed_between_status(wl_egl_buffer, CMT_TO_REL); + wl_egl_surface->last_release_bo = wl_egl_buffer->bo_name; + _elapsed_from_last_commit(wl_egl_surface, wl_egl_buffer->bo_name); + _update_last_release_time(wl_egl_surface); TRACE_MARK("[IMMEDIATE_RELEASE] BO(%d)", _get_tbm_surface_bo_name(tbm_surface)); @@ -3239,6 +3353,10 @@ __cb_wl_buffer_release(void *data, struct wl_proxy *wl_buffer) TPL_ERR("tbm_surface(%p) tsq_err(%d)", tbm_surface, tsq_err); wl_egl_buffer->status = RELEASED; + _elapsed_between_status(wl_egl_buffer, CMT_TO_REL); + wl_egl_surface->last_release_bo = wl_egl_buffer->bo_name; + _elapsed_from_last_commit(wl_egl_surface, wl_egl_buffer->bo_name); + _update_last_release_time(wl_egl_surface); TRACE_MARK("[RELEASE] BO(%d)", _get_tbm_surface_bo_name(tbm_surface)); TRACE_ASYNC_END((intptr_t)tbm_surface, "[COMMIT ~ RELEASE] BO(%d)", @@ -3572,6 +3690,10 @@ _thread_wl_surface_commit(tpl_wl_egl_surface_t *wl_egl_surface, wl_egl_buffer->need_to_commit = TPL_FALSE; wl_egl_buffer->status = COMMITTED; + _elapsed_between_status(wl_egl_buffer, VBL_TO_CMT); + _update_last_commit_time(wl_egl_surface); + wl_egl_surface->last_commit_bo = wl_egl_buffer->bo_name; + if (wl_egl_surface->last_enq_buffer == wl_egl_buffer->tbm_surface) wl_egl_surface->last_enq_buffer = NULL;