client: enhance vblank logs

Change-Id: I6b12bc6aa56a1d4cdd2c319d7172dc46945fbd20

diff --git a/client/tdm_client.c b/client/tdm_client.c
index 4d8ba30..1604ca7 100644 (file)
--- a/client/tdm_client.c
+++ b/client/tdm_client.c
@@ -94,6 +94,8 @@ struct _tdm_private_client_vblank {
 
        unsigned int started;
 
+       double last_time;
+
        struct list_head link;
 };
 
@@ -113,8 +115,7 @@ typedef struct _tdm_client_wait_info {
        void *user_data;
 
        unsigned int req_id;
-       unsigned int req_sec;
-       unsigned int req_usec;
+       double req_time;
        int need_free;
 
        struct list_head link;
@@ -130,12 +131,20 @@ _tdm_client_vblank_cb_done(void *data, struct wl_tdm_vblank *wl_tdm_vblank,
 
        TDM_RETURN_IF_FAIL(private_vblank != NULL);
 
+       private_vblank->last_time = TDM_TIME(tv_sec, tv_usec);
+
+       TDM_DBG("vblank(%p) req_id(%u) sequence(%u) time(%.6f)",
+                       private_vblank, req_id, sequence, TDM_TIME(tv_sec, tv_usec));
+
        TDM_TRACE_COUNT(ClientDoneVBlank, req_id);
 
        LIST_FOR_EACH_ENTRY_SAFE(w, ww, &private_vblank->wait_list, link) {
                if (w->req_id != req_id)
                        continue;
 
+               if (w->req_time >= private_vblank->last_time)
+                       TDM_ERR("'req(%.6f) < last(%.6f)' failed", w->req_time, private_vblank->last_time);
+
                if (w->func)
                        w->func(private_vblank, error, sequence, tv_sec, tv_usec, w->user_data);
 
@@ -751,6 +760,7 @@ tdm_client_vblank_wait(tdm_client_vblank *vblank, unsigned int interval, tdm_cli
        tdm_private_client_vblank *private_vblank;
        tdm_client_wait_info *w;
        struct timespec tp;
+       unsigned int req_sec, req_usec;
        int ret = 0;
 
        TDM_RETURN_VAL_IF_FAIL(vblank != NULL, TDM_ERROR_INVALID_PARAMETER);
@@ -786,15 +796,23 @@ tdm_client_vblank_wait(tdm_client_vblank *vblank, unsigned int interval, tdm_cli
        LIST_ADDTAIL(&w->link, &private_vblank->wait_list);
 
        clock_gettime(CLOCK_MONOTONIC, &tp);
+       req_sec = (unsigned int)tp.tv_sec;
+       req_usec = (unsigned int)(tp.tv_nsec / 1000);
+
        w->req_id = ++private_output->req_id;
-       w->req_sec = (unsigned int)tp.tv_sec;
-       w->req_usec = (unsigned int)(tp.tv_nsec / 1000);
+       w->req_time = TDM_TIME(req_sec, req_usec);
        w->need_free = (private_vblank->sync) ? 0 : 1;
 
-       wl_tdm_vblank_wait_vblank(private_vblank->vblank, interval, w->req_id, w->req_sec, w->req_usec);
+       wl_tdm_vblank_wait_vblank(private_vblank->vblank, interval, w->req_id, req_sec, req_usec);
 
        TDM_TRACE_COUNT(ClientWaitVBlank, w->req_id);
 
+       TDM_DBG("vblank(%p) interval(%u) req_id(%d) req(%.6f)",
+                       vblank, interval, w->req_id, TDM_TIME(req_sec, req_usec));
+
+       if (private_vblank->last_time >= w->req_time)
+               TDM_ERR("'last(%.6f) < req(%.6f)' failed", private_vblank->last_time, w->req_time);
+
        if (!private_vblank->sync) {
                wl_display_flush(private_client->display);
                return TDM_ERROR_NONE;
@@ -806,7 +824,7 @@ tdm_client_vblank_wait(tdm_client_vblank *vblank, unsigned int interval, tdm_cli
        clock_gettime(CLOCK_MONOTONIC, &tp);
        TDM_DBG("block during %d us",
                        ((unsigned int)(tp.tv_sec * 1000000) + (unsigned int)(tp.tv_nsec / 1000))
-                       - (w->req_sec * 1000000 + w->req_usec));
+                       - (req_sec * 1000000 + req_usec));
 
        LIST_DEL(&w->link);
        free(w);
@@ -823,6 +841,7 @@ tdm_client_vblank_wait_seq(tdm_client_vblank *vblank, unsigned int sequence,
        tdm_private_client_vblank *private_vblank;
        tdm_client_wait_info *w;
        struct timespec tp;
+       unsigned int req_sec, req_usec;
        int ret = 0;
 
        TDM_RETURN_VAL_IF_FAIL(vblank != NULL, TDM_ERROR_INVALID_PARAMETER);
@@ -853,15 +872,23 @@ tdm_client_vblank_wait_seq(tdm_client_vblank *vblank, unsigned int sequence,
        LIST_ADDTAIL(&w->link, &private_vblank->wait_list);
 
        clock_gettime(CLOCK_MONOTONIC, &tp);
+       req_sec = (unsigned int)tp.tv_sec;
+       req_usec = (unsigned int)(tp.tv_nsec / 1000);
+
        w->req_id = ++private_output->req_id;
-       w->req_sec = (unsigned int)tp.tv_sec;
-       w->req_usec = (unsigned int)(tp.tv_nsec / 1000);
+       w->req_time = TDM_TIME(req_sec, req_usec);
        w->need_free = (private_vblank->sync) ? 0 : 1;
 
-       wl_tdm_vblank_wait_vblank_seq(private_vblank->vblank, sequence, w->req_id, w->req_sec, w->req_usec);
+       wl_tdm_vblank_wait_vblank_seq(private_vblank->vblank, sequence, w->req_id, req_sec, req_usec);
 
        TDM_TRACE_COUNT(ClientWaitVBlank, w->req_id);
 
+       TDM_DBG("vblank(%p) sequence(%u) req_id(%d) req(%.6f)",
+                       vblank, sequence, w->req_id, TDM_TIME(req_sec, req_usec));
+
+       if (private_vblank->last_time >= w->req_time)
+               TDM_ERR("'last(%.6f) < req(%.6f)' failed", private_vblank->last_time, w->req_time);
+
        if (!private_vblank->sync) {
                wl_display_flush(private_client->display);
                return TDM_ERROR_NONE;
@@ -873,7 +900,7 @@ tdm_client_vblank_wait_seq(tdm_client_vblank *vblank, unsigned int sequence,
        clock_gettime(CLOCK_MONOTONIC, &tp);
        TDM_DBG("block during %d us",
                        ((unsigned int)(tp.tv_sec * 1000000) + (unsigned int)(tp.tv_nsec / 1000))
-                       - (w->req_sec * 1000000 + w->req_usec));
+                       - (req_sec * 1000000 + req_usec));
 
        LIST_DEL(&w->link);
        free(w);