correct ttrace debug information for vblank

Change-Id: Ie465ef620bc2f91b23c85a7321e7ba39de777c02

diff --git a/client/tdm_client.c b/client/tdm_client.c
index cd74513..267854b 100644 (file)
--- a/client/tdm_client.c
+++ b/client/tdm_client.c
@@ -96,6 +96,7 @@ struct _tdm_private_client_vblank {
        unsigned int started;
        unsigned int stamp;
 
+       double req_time;
        double last_time;
 
        struct list_head link;
@@ -148,12 +149,12 @@ _tdm_client_vblank_cb_done(void *data, struct wl_tdm_vblank *wl_tdm_vblank,
        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;
 
+               TDM_TRACE_ASYNC_END((int)w->req_time, "TDM_Client_Vblank:%u", private_vblank->stamp);
+
                if (w->req_time >= private_vblank->last_time)
                        TDM_WRN("'req(%.6f) < last(%.6f)' failed", w->req_time, private_vblank->last_time);
 
@@ -888,10 +889,12 @@ tdm_client_vblank_wait(tdm_client_vblank *vblank, unsigned int interval, tdm_cli
 
        wl_tdm_vblank_wait_vblank(private_vblank->vblank, interval, w->req_id, req_sec, req_usec);
 
-       TDM_TRACE_COUNT(ClientWaitVBlank, w->req_id);
+       TDM_TRACE_ASYNC_BEGIN((int)w->req_time, "TDM_Client_Vblank:%u", private_vblank->stamp);
 
        TDM_DBG("vblank(%p) interval(%u) req_id(%d) req(%.6f)",
-                       vblank, interval, w->req_id, TDM_TIME(req_sec, req_usec));
+                       vblank, interval, w->req_id, w->req_time);
+
+       private_vblank->req_time = w->req_time;
 
        if (private_vblank->last_time >= w->req_time)
                TDM_ERR("'last(%.6f) < req(%.6f)' failed", private_vblank->last_time, w->req_time);
@@ -970,10 +973,12 @@ tdm_client_vblank_wait_seq(tdm_client_vblank *vblank, unsigned int sequence,
 
        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_TRACE_ASYNC_BEGIN((int)w->req_time, "TDM_Client_Vblank:%u", private_vblank->stamp);
 
        TDM_DBG("vblank(%p) sequence(%u) req_id(%d) req(%.6f)",
-                       vblank, sequence, w->req_id, TDM_TIME(req_sec, req_usec));
+                       vblank, sequence, w->req_id, w->req_time);
+
+       private_vblank->req_time = w->req_time;
 
        if (private_vblank->last_time >= w->req_time)
                TDM_ERR("'last(%.6f) < req(%.6f)' failed", private_vblank->last_time, w->req_time);

diff --git a/src/tdm.c b/src/tdm.c
index 2246fc4..53732ac 100644 (file)
--- a/src/tdm.c
+++ b/src/tdm.c
@@ -788,8 +788,8 @@ _tdm_display_load_module_with_file(tdm_private_display *private_display,
        };
 
        stamp = tdm_helper_get_time();
-       TDM_TRACE_BEGIN(Load_Backend);
 
+       TDM_TRACE_BEGIN("TDM_Load_Backend");
        module = dlopen(path, RTLD_LAZY);
        if (!module) {
                TDM_ERR("failed to load module: %s(%s)", dlerror(), file);
@@ -804,6 +804,7 @@ _tdm_display_load_module_with_file(tdm_private_display *private_display,
                TDM_TRACE_END();
                goto failed_load;
        }
+       TDM_TRACE_END();
 
        TDM_DBG("dlopen, dlsym time: %.3f ms", (tdm_helper_get_time() - stamp) * 1000.0);
 
@@ -815,10 +816,8 @@ _tdm_display_load_module_with_file(tdm_private_display *private_display,
        if (ret != TDM_ERROR_NONE)
                goto failed_load;
 
-       TDM_TRACE_END();
-
        /* We don't care if backend_data is NULL or not. It's up to backend. */
-       TDM_TRACE_BEGIN(Init_Backend);
+       TDM_TRACE_BEGIN("TDM_Init_Backend");
        stamp = tdm_helper_get_time();
        private_display->bdata = module_data->init((tdm_display *)private_display, &ret);
        TDM_DBG("backend init() time: %.3f ms", (tdm_helper_get_time() - stamp) * 1000.0);
@@ -989,7 +988,7 @@ tdm_display_init(tdm_error *error)
        }
 #endif
 
-       TDM_TRACE_BEGIN(Update_Display);
+       TDM_TRACE_BEGIN("TDM_Update_Display");
        ret = _tdm_display_update_internal(private_display, 0);
        TDM_TRACE_END();
        if (ret != TDM_ERROR_NONE)
@@ -1289,7 +1288,7 @@ _tdm_display_ttrace_vblank_cb(tdm_vblank *vblank, tdm_error error, unsigned int
 {
        tdm_error ret = TDM_ERROR_NONE;
 
-       TDM_TRACE_MARK(VBlank);
+       TDM_TRACE_MARK("TDM_DISPLAY_TTRACE_VBlank");
 
        ret = tdm_vblank_wait(vblank, 0, 0, 1, _tdm_display_ttrace_vblank_cb, NULL);
        TDM_RETURN_IF_FAIL(ret == TDM_ERROR_NONE);

diff --git a/src/tdm_private.h b/src/tdm_private.h
index 6853bfb..92bb4a1 100644 (file)
--- a/src/tdm_private.h
+++ b/src/tdm_private.h
@@ -91,15 +91,19 @@ extern int tdm_debug_dump;
 
 #ifdef HAVE_TTRACE
 #include <ttrace.h>
-#define TDM_TRACE_BEGIN(NAME) traceBegin(TTRACE_TAG_GRAPHICS, "TDM:"#NAME)
+#define TDM_TRACE_BEGIN(fmt, ...) traceBegin(TTRACE_TAG_GRAPHICS, fmt, ##__VA_ARGS__)
 #define TDM_TRACE_END() traceEnd(TTRACE_TAG_GRAPHICS)
-#define TDM_TRACE_COUNT(NAME, COUNT) traceCounter(TTRACE_TAG_GRAPHICS, COUNT, "TDM:"#NAME)
-#define TDM_TRACE_MARK(NAME) traceMark(TTRACE_TAG_GRAPHICS, "TDM:"#NAME)
+#define TDM_TRACE_ASYNC_BEGIN(key, name,...) traceAsyncBegin(TTRACE_TAG_GRAPHICS, key, name, ##__VA_ARGS__)
+#define TDM_TRACE_ASYNC_END(key, name,...) traceAsyncEnd(TTRACE_TAG_GRAPHICS, key, name, ##__VA_ARGS__)
+#define TDM_TRACE_COUNT(count, fmt, ...) traceCounter(TTRACE_TAG_GRAPHICS, count, fmt, ##__VA_ARGS__)
+#define TDM_TRACE_MARK(fmt, ...) traceMark(TTRACE_TAG_GRAPHICS, fmt, ##__VA_ARGS__)
 #else
-#define TDM_TRACE_BEGIN(NAME)
+#define TDM_TRACE_BEGIN(fmt, ...)
 #define TDM_TRACE_END()
-#define TDM_TRACE_COUNT(NAME, COUNT)
-#define TDM_TRACE_MARK(NAME)
+#define TDM_TRACE_ASYNC_BEGIN(key, name,...)
+#define TDM_TRACE_ASYNC_END(key, name,...)
+#define TDM_TRACE_COUNT(count, fmt, ...)
+#define TDM_TRACE_MARK(fmt, ...)
 #endif
 
 typedef enum {

diff --git a/src/tdm_server.c b/src/tdm_server.c
index 4da079d..b193ac6 100644 (file)
--- a/src/tdm_server.c
+++ b/src/tdm_server.c
@@ -80,6 +80,7 @@ typedef struct _tdm_server_wait_info {
        tdm_server_vblank_info *vblank_info;
 
        unsigned int req_id;
+       double req_time;
 } tdm_server_wait_info;
 
 typedef struct _tdm_server_client_info {
@@ -179,11 +180,12 @@ _tdm_server_send_done(tdm_server_wait_info *wait_info, tdm_error error,
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
                TDM_DBG("req_id(%d) done", wait_info->req_id);
 
-       TDM_TRACE_COUNT(ServerDoneVBlank, wait_info->req_id);
-
        vblank_info = wait_info->vblank_info;
        wl_tdm_vblank_send_done(vblank_info->resource, wait_info->req_id,
                                                        sequence, tv_sec, tv_usec, error);
+
+       TDM_TRACE_ASYNC_END((int)wait_info->req_time, "TDM_Server_Vblank:%u", vblank_info->stamp);
+
        destroy_wait(wait_info);
 }
 
@@ -305,8 +307,6 @@ _tdm_server_vblank_cb_wait_vblank(struct wl_client *client, struct wl_resource *
        unsigned int enable_fake = 0;
        tdm_error ret;
 
-       TDM_TRACE_COUNT(ServerWaitVBlank, req_id);
-
        wait_info = calloc(1, sizeof * wait_info);
        if (!wait_info) {
                TDM_ERR("alloc failed");
@@ -317,10 +317,13 @@ _tdm_server_vblank_cb_wait_vblank(struct wl_client *client, struct wl_resource *
        LIST_ADDTAIL(&wait_info->link, &private_server->wait_list);
        wait_info->vblank_info = vblank_info;
        wait_info->req_id = req_id;
+       wait_info->req_time = TDM_TIME(req_sec, req_usec);
 
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
                TDM_DBG("req_id(%d) wait", req_id);
 
+       TDM_TRACE_ASYNC_BEGIN((int)wait_info->req_time, "TDM_Server_Vblank:%u", vblank_info->stamp);
+
        ret = tdm_vblank_wait(vblank_info->vblank, req_sec, req_usec, interval, _tdm_server_cb_vblank, wait_info);
 
        tdm_vblank_get_enable_fake(vblank_info->vblank, &enable_fake);
@@ -347,8 +350,6 @@ _tdm_server_vblank_cb_wait_vblank_seq(struct wl_client *client, struct wl_resour
        unsigned int enable_fake = 0;
        tdm_error ret;
 
-       TDM_TRACE_COUNT(ServerWaitVBlank, req_id);
-
        wait_info = calloc(1, sizeof * wait_info);
        if (!wait_info) {
                TDM_ERR("alloc failed");
@@ -359,10 +360,13 @@ _tdm_server_vblank_cb_wait_vblank_seq(struct wl_client *client, struct wl_resour
        LIST_ADDTAIL(&wait_info->link, &private_server->wait_list);
        wait_info->vblank_info = vblank_info;
        wait_info->req_id = req_id;
+       wait_info->req_time = TDM_TIME(req_sec, req_usec);
 
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
                TDM_DBG("req_id(%d) wait", req_id);
 
+       TDM_TRACE_ASYNC_BEGIN((int)wait_info->req_time, "TDM_Server_Vblank:%u", vblank_info->stamp);
+
        ret = tdm_vblank_wait_seq(vblank_info->vblank, req_sec, req_usec, sequence, _tdm_server_cb_vblank, wait_info);
 
        tdm_vblank_get_enable_fake(vblank_info->vblank, &enable_fake);

diff --git a/src/tdm_vblank.c b/src/tdm_vblank.c
index 6861ec8..1a3f6b9 100644 (file)
--- a/src/tdm_vblank.c
+++ b/src/tdm_vblank.c
@@ -771,6 +771,8 @@ _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
                return;
        }
 
+       TDM_TRACE_ASYNC_END((int)wait_info->req_time, "TDM_HW_Vblank:%u", (unsigned int)private_vblank->stamp);
+
        if (wait_info->type == VBLANK_TYPE_HW_SW) {
                tdm_error ret;
 
@@ -881,6 +883,8 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
                                skip, hw_interval, wait_info->target_seq);
        }
 
+       TDM_TRACE_ASYNC_BEGIN((int)wait_info->req_time, "TDM_HW_Vblank:%u", (unsigned int)private_vblank->stamp);
+
        if (private_vblank->add_front)
                ret = tdm_output_wait_vblank_add_front(private_vblank->output, hw_interval, 0,
                                                                                           _tdm_vblank_cb_vblank_HW, wait_info);
@@ -961,6 +965,8 @@ tdm_vblank_cb_vblank_SW(tdm_vblank *vblank, double vblank_stamp)
                if (w->target_time != first_wait_info->target_time)
                        break;
 
+               TDM_TRACE_ASYNC_END((int)w->req_time, "TDM_SW_Vblank:%u", (unsigned int)private_vblank->stamp);
+
                LIST_DEL(&w->link);
                _tdm_vblank_valid_list_del(&w->valid_link);
 
@@ -1032,6 +1038,8 @@ _tdm_vblank_wait_SW(tdm_vblank_wait_info *wait_info)
 
        _tdm_vblank_insert_wait(wait_info, &private_vblank->SW_wait_list);
 
+       TDM_TRACE_ASYNC_BEGIN((int)wait_info->req_time, "TDM_SW_Vblank:%u", (unsigned int)private_vblank->stamp);
+
        ret = _tdm_vblank_sw_timer_update(private_vblank);
        if (ret != TDM_ERROR_NONE) {
                LIST_DEL(&wait_info->link);