From: Joonbum Ko Date: Tue, 8 Oct 2024 00:50:19 +0000 (+0900) Subject: wl_egl: add surf_trace_begin/end X-Git-Tag: accepted/tizen/unified/20241011.010650~1 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=refs%2Fchanges%2F54%2F318754%2F1;p=platform%2Fcore%2Fuifw%2Flibtpl-egl.git wl_egl: add surf_trace_begin/end - By using the surface, it was possible to measure what was ambiguous to be measured using the change in buffer state (like below) LAST_COMMIT ~ RELEASE : Delay in buffer release event from server LAST_RELEASE ~ DEQUEUE : Delay in rendering job from EGL caller - enum surface_trace_period has been added INITIALIZING - to check the total elapsed time until surface_init done LAST_REL_TO_DEQ_REQUESTED - the period from when last buffer release to when dequeue is requested - to check if there is a delay in rendering requests between frames DEQ_REQUEST_TO_DEQ_DONE - The period from when can_dequeue is called to when dequeue is completed WAIT_VBL_TO_VBL_DONE - The period from when wait_vblank to when vblank done callback is called - to check if there is a delay in client vblank event processing LAST_COMMIT_TO_REL - The period from when the last surface commit to when buffer release event processed - to check if there is a delay in server or thread's event processing - For each trace_period, even if _surf_trace_begin is called multiple times, only the last call will be recorded and calling _surf_trace_end calculates the elapsed time for that period. Change-Id: I62fb3617faa3c823d56404414b9dc68fd2a84f91 Signed-off-by: Joonbum Ko --- diff --git a/src/tpl_wl_egl_thread.c b/src/tpl_wl_egl_thread.c index 1ff7076..276e266 100755 --- a/src/tpl_wl_egl_thread.c +++ b/src/tpl_wl_egl_thread.c @@ -162,10 +162,10 @@ struct _tpl_wl_egl_surface { /* To make sure that tpl_gsource has been successfully finalized. */ tpl_bool_t gsource_finalized; - double last_commit_time; - int last_commit_bo; - double last_release_time; - int last_release_bo; + struct { + tpl_gmutex mutex; + double begin_time[5]; + } perf_trace; }; struct _surface_vblank { @@ -175,6 +175,25 @@ struct _surface_vblank { tpl_gmutex mutex; }; +typedef enum surface_trace_period { + INITIALIZING = 0, + LAST_REL_TO_DEQ_REQUESTED, // The period from when last buffer release to when dequeue is requested + DEQ_REQUEST_TO_DEQ_DONE, // The period from when can_dequeue is called to when dequeue is completed + WAIT_VBL_TO_VBL_DONE, // The period from when wait_vblank to when vblank done callback is called + LAST_COMMIT_TO_REL, // The period from when the last surface commit to when buffer release event processed +} surface_trace_period; + +static struct surface_trace_info { + const char str[20]; + uint32_t threshold_ms; // The time limit for processing each section +} surface_trace_info[5] = { + { "INITIALIZING", 30 }, // INITIALIZING + { "RENDER DELAYED", 20 }, // LAST_REL_TO_DEQ_REQUESTED + { "DEQUEUE", 30 }, // DEQ_REQUEST_TO_DEQ_DONE + { "VBLANK", 20 }, // WAIT_VBL_TO_VBL_DONE + { "RELEASE", 20 } // LAST_COMMIT_TO_REL +}; + typedef enum buffer_status { CREATED = 0, // 0 RELEASED, // 1 @@ -342,7 +361,7 @@ _cal_time_gap_ms(double begin, double end) } static void -_elapsed_between_status(tpl_wl_egl_buffer_t *wl_egl_buffer, +_check_buffer_elapsed(tpl_wl_egl_buffer_t *wl_egl_buffer, buffer_status cur_status, double cur_time) { @@ -364,71 +383,21 @@ _elapsed_between_status(tpl_wl_egl_buffer_t *wl_egl_buffer, } } -static void -_elapsed_since_last_commit(tpl_wl_egl_surface_t *wl_egl_surface, - int bo_name, - double cur_time) -{ - uint32_t gap_ms = _cal_time_gap_ms(wl_egl_surface->last_commit_time, cur_time); - if (gap_ms > RELEASE_FROM_LAST_COMMIT) { - TPL_ERR("LAST_COMMIT(%d)~RELEASE(%d)|takes too long time|%u>%u", - wl_egl_surface->last_commit_bo, bo_name, - gap_ms, RELEASE_FROM_LAST_COMMIT); - TPL_ERR("%s(%.3lf) ~ %s(%.3lf)", - "L_COMMIT", wl_egl_surface->last_commit_time, - "RELEASE", cur_time); - } -} - -static void -_elapsed_since_last_release(tpl_wl_egl_surface_t *wl_egl_surface, - int bo_name, - double cur_time) -{ - uint32_t gap_ms = _cal_time_gap_ms(wl_egl_surface->last_release_time, cur_time); - if (gap_ms > DEQUEUE_FROM_LAST_RELEASE) { - TPL_ERR("LAST_RELEASE(%d)~DEQUEUE(%d)|takes too long time|%u>%u", - wl_egl_surface->last_release_bo, bo_name, - gap_ms, DEQUEUE_FROM_LAST_RELEASE); - TPL_ERR("%s(%.3lf) ~ %s(%.3lf)", - "L_RELEASE", wl_egl_surface->last_release_time, - "DEQUEUE", cur_time); - } -} - static void _update_buffer_status(tpl_wl_egl_buffer_t *wl_egl_buffer, buffer_status status) { - tpl_wl_egl_surface_t *wl_egl_surface = wl_egl_buffer->wl_egl_surface; double current_time = _get_current_time(); switch (status) { case CREATED: - /* do nothing */ - break; - case RELEASED: - _elapsed_since_last_commit(wl_egl_surface, wl_egl_buffer->bo_name, current_time); - wl_egl_surface->last_release_time = current_time; - wl_egl_surface->last_release_bo = wl_egl_buffer->bo_name; - break; - case DEQUEUED: - /* calculate the time elapsed since the last release - * only if it is not a newly created buffer */ - if (wl_egl_buffer->wl_buffer != NULL) - _elapsed_since_last_release(wl_egl_surface, wl_egl_buffer->bo_name, current_time); - break; - - case COMMITTED: - _elapsed_between_status(wl_egl_buffer, status, current_time); - wl_egl_surface->last_commit_time = current_time; - wl_egl_surface->last_commit_bo = wl_egl_buffer->bo_name; + /* do nothing */ break; default: - _elapsed_between_status(wl_egl_buffer, status, current_time); + _check_buffer_elapsed(wl_egl_buffer, status, current_time); break; } @@ -436,6 +405,55 @@ _update_buffer_status(tpl_wl_egl_buffer_t *wl_egl_buffer, buffer_status status) wl_egl_buffer->changed_time = current_time; } +static void +_check_surf_elapsed(tpl_wl_egl_surface_t *wl_egl_surface, + surface_trace_period period, + double cur_time) +{ + if (wl_egl_surface->perf_trace.begin_time[period] == 0.0f) + return; + + uint32_t gap_ms = _cal_time_gap_ms(wl_egl_surface->perf_trace.begin_time[period], + cur_time); + + uint32_t threshold = surface_trace_info[period].threshold_ms; + + if (gap_ms > threshold) { + TPL_ERR("%s|takes too long time %.3lf~%.3lf|%u>%u", + surface_trace_info[period].str, + wl_egl_surface->perf_trace.begin_time[period], cur_time, + gap_ms, threshold); + } +} + +static void +_surf_trace_init(tpl_wl_egl_surface_t *wl_egl_surface, surface_trace_period period) +{ + tpl_gmutex_lock(&wl_egl_surface->perf_trace.mutex); + wl_egl_surface->perf_trace.begin_time[period] = 0.0f; + tpl_gmutex_unlock(&wl_egl_surface->perf_trace.mutex); +} + +static void +_surf_trace_begin(tpl_wl_egl_surface_t *wl_egl_surface, surface_trace_period period) +{ + double current_time = _get_current_time(); + + tpl_gmutex_lock(&wl_egl_surface->perf_trace.mutex); + wl_egl_surface->perf_trace.begin_time[period] = current_time; + tpl_gmutex_unlock(&wl_egl_surface->perf_trace.mutex); +} + +static void +_surf_trace_end(tpl_wl_egl_surface_t *wl_egl_surface, surface_trace_period period) +{ + double current_time = _get_current_time(); + + tpl_gmutex_lock(&wl_egl_surface->perf_trace.mutex); + _check_surf_elapsed(wl_egl_surface, period, current_time); + tpl_gmutex_unlock(&wl_egl_surface->perf_trace.mutex); +} + static struct tizen_private * tizen_private_create() { @@ -1903,6 +1921,10 @@ __tpl_wl_egl_surface_init(tpl_surface_t *surface) goto surf_source_create_fail; } + tpl_gmutex_init(&wl_egl_surface->perf_trace.mutex); + _surf_trace_init(wl_egl_surface, LAST_REL_TO_DEQ_REQUESTED); + _surf_trace_begin(wl_egl_surface, INITIALIZING); + surface->backend.data = (void *)wl_egl_surface; surface->width = wl_egl_window->width; surface->height = wl_egl_window->height; @@ -1952,9 +1974,6 @@ __tpl_wl_egl_surface_init(tpl_surface_t *surface) wl_egl_surface->buffers = __tpl_list_alloc(); - wl_egl_surface->last_release_bo = -1; - wl_egl_surface->last_release_time = 0.0; - { struct tizen_private *tizen_private = wl_egl_tizen_get_tizen_private(wl_egl_window); @@ -2005,6 +2024,8 @@ __tpl_wl_egl_surface_init(tpl_surface_t *surface) "tpl_surface(%p) wl_egl_surface(%p) gsource(%p)", surface, wl_egl_surface, wl_egl_surface->surf_source); + _surf_trace_end(wl_egl_surface, INITIALIZING); + return TPL_ERROR_NONE; surf_source_create_fail: @@ -2517,18 +2538,12 @@ __tpl_wl_egl_surface_fini(tpl_surface_t *surface) tpl_gmutex_rec_unlock(&wl_egl_surface->buffers_mutex); tpl_gmutex_rec_clear(&wl_egl_surface->buffers_mutex); - tpl_gmutex_lock(&wl_egl_surface->commit_sync.mutex); - tpl_gmutex_unlock(&wl_egl_surface->commit_sync.mutex); tpl_gmutex_clear(&wl_egl_surface->commit_sync.mutex); - - tpl_gmutex_lock(&wl_egl_surface->presentation_sync.mutex); - tpl_gmutex_unlock(&wl_egl_surface->presentation_sync.mutex); tpl_gmutex_clear(&wl_egl_surface->presentation_sync.mutex); + tpl_gmutex_clear(&wl_egl_surface->perf_trace.mutex); - tpl_gmutex_lock(&wl_egl_surface->surf_mutex); - tpl_gmutex_unlock(&wl_egl_surface->surf_mutex); - tpl_gmutex_clear(&wl_egl_surface->surf_mutex); tpl_gcond_clear(&wl_egl_surface->surf_cond); + tpl_gmutex_clear(&wl_egl_surface->surf_mutex); TPL_INFO("[SURFACE_FINI][END]", "wl_egl_surface(%p)", wl_egl_surface); @@ -2843,6 +2858,9 @@ __tpl_wl_egl_surface_dequeue_buffer(tpl_surface_t *surface, uint64_t timeout_ns, int bo_name = 0; tbm_surface_h tbm_surface = NULL; + _surf_trace_end(wl_egl_surface, LAST_REL_TO_DEQ_REQUESTED); + _surf_trace_begin(wl_egl_surface, DEQ_REQUEST_TO_DEQ_DONE); + TPL_OBJECT_UNLOCK(surface); tpl_gmutex_lock(&wl_egl_surface->surf_mutex); if (wl_egl_surface->reset == TPL_TRUE) { @@ -3038,6 +3056,8 @@ __tpl_wl_egl_surface_dequeue_buffer(tpl_surface_t *surface, uint64_t timeout_ns, tpl_gmutex_unlock(&wl_egl_buffer->mutex); tpl_gmutex_unlock(&wl_egl_display->wl_event_mutex); + _surf_trace_end(wl_egl_surface, DEQ_REQUEST_TO_DEQ_DONE); + return tbm_surface; } @@ -3378,6 +3398,8 @@ __cb_tdm_client_vblank(tdm_client_vblank *vblank, tdm_error error, tpl_wl_egl_surface_t wl_egl_surface(user_data); TRACE_ASYNC_END((intptr_t)wl_egl_surface, "WAIT_VBLANK"); + _surf_trace_end(wl_egl_surface, WAIT_VBL_TO_VBL_DONE); + TPL_LOG_D("[VBLANK_DONE]", "wl_egl_surface(%p)", wl_egl_surface); if (error == TDM_ERROR_TIMEOUT) @@ -3441,6 +3463,8 @@ __cb_buffer_fenced_release(void *data, wl_egl_buffer->release_fence_fd = fence; _update_buffer_status(wl_egl_buffer, RELEASED); + _surf_trace_end(wl_egl_surface, LAST_COMMIT_TO_REL); + _surf_trace_begin(wl_egl_surface, LAST_REL_TO_DEQ_REQUESTED); TRACE_MARK("[FENCED_RELEASE] BO(%d) fence(%d)", _get_tbm_surface_bo_name(tbm_surface), @@ -3493,6 +3517,8 @@ __cb_buffer_immediate_release(void *data, wl_egl_buffer->release_fence_fd = -1; _update_buffer_status(wl_egl_buffer, RELEASED); + _surf_trace_end(wl_egl_surface, LAST_COMMIT_TO_REL); + _surf_trace_begin(wl_egl_surface, LAST_REL_TO_DEQ_REQUESTED); TRACE_MARK("[IMMEDIATE_RELEASE] BO(%d)", _get_tbm_surface_bo_name(tbm_surface)); @@ -3550,6 +3576,8 @@ __cb_wl_buffer_release(void *data, struct wl_proxy *wl_buffer) TPL_ERR("tbm_surface(%p) tsq_err(%d)", tbm_surface, tsq_err); _update_buffer_status(wl_egl_buffer, RELEASED); + _surf_trace_end(wl_egl_surface, LAST_COMMIT_TO_REL); + _surf_trace_begin(wl_egl_surface, LAST_REL_TO_DEQ_REQUESTED); 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 +3600,7 @@ __cb_wl_buffer_release(void *data, struct wl_proxy *wl_buffer) static const struct wl_buffer_listener wl_buffer_release_listener = { (void *)__cb_wl_buffer_release, }; + #if TIZEN_FEATURE_ENABLE static void __cb_presentation_feedback_sync_output(void *data, @@ -3687,6 +3716,7 @@ _thread_surface_vblank_wait(tpl_wl_egl_surface_t *wl_egl_surface) if (tdm_err == TDM_ERROR_NONE) { wl_egl_surface->vblank_done = TPL_FALSE; + _surf_trace_begin(wl_egl_surface, WAIT_VBL_TO_VBL_DONE); TRACE_ASYNC_BEGIN((intptr_t)wl_egl_surface, "WAIT_VBLANK"); } else { TPL_ERR("Failed to tdm_client_vblank_wait. tdm_err(%d)", tdm_err); @@ -3892,6 +3922,8 @@ _thread_wl_surface_commit(tpl_wl_egl_surface_t *wl_egl_surface, wl_egl_buffer, wl_egl_buffer->wl_buffer, wl_egl_buffer->tbm_surface, wl_egl_buffer->bo_name); + _surf_trace_begin(wl_egl_surface, LAST_COMMIT_TO_REL); + if (wl_egl_surface->post_interval > 0 && wl_egl_surface->vblank != NULL) { wl_egl_surface->vblank_enable = TPL_TRUE; if (_thread_surface_vblank_wait(wl_egl_surface) != TPL_ERROR_NONE)