wl_egl: add logs to print elapsed time

Change-Id: Ie910e39d5ec15800dd04db1d7198a40361dd9e8f
Signed-off-by: Joonbum Ko <joonbum.ko@samsung.com>

diff --git a/src/tpl_utils.h b/src/tpl_utils.h
index 08d7ab6046f3539640eb07de5f6ba8bcd9d4bf66..dc35956c00ef565940e9ea1abecc0fc43edff2a9 100644 (file)
--- a/src/tpl_utils.h
+++ b/src/tpl_utils.h
@@ -47,6 +47,7 @@
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <signal.h>
+#include <time.h>
 
 #include <tbm_surface.h>
 #include <tbm_surface_internal.h>
@@ -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 5d5b263131dac20f81ea52b07517828b3d9c29ce..11d7dda43eeb1561fe156c516812e1c7cea4a286 100755 (executable)
--- 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;