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 <joonbum.ko@samsung.com>

diff --git a/src/tpl_wl_egl_thread.c b/src/tpl_wl_egl_thread.c
index 1ff7076044d808e5239585620e161f217ef8619d..276e26601a25adba1b1329f4c933d187b0c85957 100755 (executable)
--- 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)