From ceee662cf0bdb1f8452ece299dbfe8bba5fe035b Mon Sep 17 00:00:00 2001 From: Boram Park Date: Tue, 21 Nov 2017 16:56:58 +0900 Subject: [PATCH] correct ttrace debug information for vblank Change-Id: Ie465ef620bc2f91b23c85a7321e7ba39de777c02 --- client/tdm_client.c | 17 +++++++++++------ src/tdm.c | 11 +++++------ src/tdm_private.h | 16 ++++++++++------ src/tdm_server.c | 16 ++++++++++------ src/tdm_vblank.c | 8 ++++++++ 5 files changed, 44 insertions(+), 24 deletions(-) diff --git a/client/tdm_client.c b/client/tdm_client.c index cd74513..267854b 100644 --- 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 --- 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 --- a/src/tdm_private.h +++ b/src/tdm_private.h @@ -91,15 +91,19 @@ extern int tdm_debug_dump; #ifdef HAVE_TTRACE #include -#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 --- 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 --- 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); -- 2.7.4