add timeout logs (1000ms)

Change-Id: Ie9bbcba3d1b109d5c80734a8c55cd8959b6cdef7

diff --git a/src/tdm.c b/src/tdm.c
index e20e7dd..de6c179 100644 (file)
--- a/src/tdm.c
+++ b/src/tdm.c
@@ -161,6 +161,9 @@ _tdm_display_destroy_private_output(tdm_private_output *private_output)
 
        free(private_output->layers_ptr);
 
+       if (private_output->vblank_timeout_timer)
+               tdm_event_loop_source_remove(private_output->vblank_timeout_timer);
+
        LIST_FOR_EACH_ENTRY_SAFE(v, vv, &private_output->vblank_handler_list, link) {
                LIST_DEL(&v->link);
                free(v);

diff --git a/src/tdm_output.c b/src/tdm_output.c
index c9fba68..4105ced 100644 (file)
--- a/src/tdm_output.c
+++ b/src/tdm_output.c
@@ -57,6 +57,69 @@
        private_output = (tdm_private_output*)output; \
        private_display = private_output->private_display
 
+static void
+_tdm_output_vblank_timeout_update(tdm_private_output *private_output, int ms_delay);
+
+static tdm_error
+_tdm_output_vblank_timeout_cb(void *user_data)
+{
+       tdm_private_output *private_output = user_data;
+       tdm_private_vblank_handler *v = NULL;
+
+       TDM_RETURN_VAL_IF_FAIL(private_output != NULL, TDM_ERROR_OPERATION_FAILED);
+
+       TDM_ERR("TDM output(%d) vblank TIMEOUT!!", private_output->pipe);
+
+       LIST_FOR_EACH_ENTRY(v, &private_output->vblank_handler_list, link) {
+               TDM_ERR("vblank_handler(%p) interval(%d) sync(%d) sent_to_frontend(%u) owner_tid(%d)",
+                               v, v->interval, v->sync, v->sent_to_frontend, v->owner_tid);
+       }
+
+       return TDM_ERROR_NONE;
+}
+
+INTERN void
+tdm_output_vblank_print_wait_information(tdm_private_output *private_output, void *user_data)
+{
+       tdm_private_vblank_handler *v = NULL;
+
+       TDM_RETURN_IF_FAIL(private_output != NULL);
+       TDM_RETURN_IF_FAIL(user_data != NULL);
+
+       TDM_ERR("TDM output(%d) vblank user_data(%p) info!!", private_output->pipe, user_data);
+
+       LIST_FOR_EACH_ENTRY(v, &private_output->vblank_handler_list, link) {
+               if (v->user_data != user_data)
+                       continue;
+               TDM_ERR("vblank_handler(%p) interval(%d) sync(%d) sent_to_frontend(%u) owner_tid(%d)",
+                               v, v->interval, v->sync, v->sent_to_frontend, v->owner_tid);
+       }
+}
+
+static void
+_tdm_output_vblank_timeout_update(tdm_private_output *private_output, int ms_delay)
+{
+       tdm_error ret;
+
+       if (!private_output->vblank_timeout_timer) {
+               private_output->vblank_timeout_timer =
+                       tdm_event_loop_add_timer_handler(private_output->private_display,
+                                                                                        _tdm_output_vblank_timeout_cb,
+                                                                                        private_output,
+                                                                                        &ret);
+               if (!private_output->vblank_timeout_timer) {
+                       TDM_ERR("output(%d) couldn't add timer", private_output->pipe);
+                       return;
+               }
+               TDM_INFO("output(%d) create vblank timeout timer", private_output->pipe);
+       }
+
+       ret = tdm_event_loop_source_timer_update(private_output->vblank_timeout_timer, ms_delay);
+       if (ret != TDM_ERROR_NONE) {
+               TDM_ERR("output(%d) couldn't update timer", private_output->pipe);
+               return;
+       }
+}
 
 static tdm_private_hwc_window *
 _tdm_output_find_private_hwc_window(tdm_private_output *private_output,
@@ -602,6 +665,8 @@ tdm_output_cb_vblank(tdm_output *output_backend, unsigned int sequence,
                tdm_thread_cb_output_vblank output_vblank;
                tdm_error ret;
 
+               vblank_handler->sent_to_frontend = 1;
+
                output_vblank.base.type = TDM_THREAD_CB_OUTPUT_VBLANK;
                output_vblank.base.length = sizeof output_vblank;
                output_vblank.output_stamp = vblank_handler->private_output->stamp;
@@ -616,6 +681,10 @@ tdm_output_cb_vblank(tdm_output *output_backend, unsigned int sequence,
                return;
        }
 
+       vblank_handler->sent_to_frontend = 0;
+
+       _tdm_output_vblank_timeout_update(private_output, 0);
+
        if (vblank_handler->owner_tid != tid)
                TDM_NEVER_GET_HERE();
 
@@ -787,6 +856,8 @@ _tdm_output_wait_vblank(tdm_output *output, int interval, int sync,
                                                                                          sync, vblank_handler);
                TDM_GOTO_IF_FAIL(ret == TDM_ERROR_NONE, wait_failed);
 
+               _tdm_output_vblank_timeout_update(private_output, 1000);
+
                if (tdm_debug_module & TDM_DEBUG_COMMIT)
                        TDM_INFO("output(%d) backend wait_vblank", private_output->pipe);
        }

diff --git a/src/tdm_private.h b/src/tdm_private.h
index 058c228..6cf2a6d 100644 (file)
--- a/src/tdm_private.h
+++ b/src/tdm_private.h
@@ -113,6 +113,8 @@ tdm_output_cb_dpms(tdm_output *output_backend, tdm_output_dpms dpms,
 tdm_error
 tdm_output_cb_need_validate(tdm_private_output *private_output);
 
+void
+tdm_output_vblank_print_wait_information(tdm_private_output *private_output, void *user_data);
 tdm_error
 tdm_output_wait_vblank_add_front(tdm_output *output, int interval, int sync,
                                                                 tdm_output_vblank_handler func, void *user_data);

diff --git a/src/tdm_private_types.h b/src/tdm_private_types.h
index a406ecd..8f7fb7d 100644 (file)
--- a/src/tdm_private_types.h
+++ b/src/tdm_private_types.h
@@ -186,6 +186,8 @@ struct _tdm_private_output {
        tdm_vblank *vblank;
        int layer_waiting_vblank;
 
+       tdm_event_loop_source *vblank_timeout_timer;
+
        /* seperate list for multi-thread*/
        struct list_head change_handler_list_main;
        struct list_head change_handler_list_sub;
@@ -341,6 +343,8 @@ struct _tdm_private_vblank_handler {
        tdm_output_vblank_handler func;
        void *user_data;
 
+       unsigned int sent_to_frontend;
+
        pid_t owner_tid;
 };
 

diff --git a/src/tdm_server.c b/src/tdm_server.c
index c1b1359..8fc2336 100644 (file)
--- a/src/tdm_server.c
+++ b/src/tdm_server.c
@@ -168,13 +168,12 @@ _tdm_server_send_done(tdm_server_wait_info *wait_info, tdm_error error,
        tdm_server_wait_info *found;
        tdm_server_vblank_info *vblank_info;
 
-       if (!keep_private_server)
-               return;
+       TDM_RETURN_IF_FAIL(keep_private_server != NULL);
 
        LIST_FIND_ITEM(wait_info, &keep_private_server->wait_list,
                                   tdm_server_wait_info, link, found);
        if (!found) {
-               TDM_DBG("wait_info(%p) is destroyed", wait_info);
+               TDM_ERR("wait_info(%p) is destroyed", wait_info);
                return;
        }
 

diff --git a/src/tdm_vblank.c b/src/tdm_vblank.c
index 16c1838..d9738fb 100644 (file)
--- a/src/tdm_vblank.c
+++ b/src/tdm_vblank.c
@@ -126,6 +126,9 @@ typedef struct _tdm_private_vblank {
        /* for SW */
        tdm_event_loop_source *SW_timer;
        struct list_head SW_wait_list;
+
+       /* for timeout */
+       tdm_event_loop_source *timeout_timer;
 } tdm_private_vblank;
 
 struct _tdm_vblank_wait_info {
@@ -136,6 +139,7 @@ struct _tdm_vblank_wait_info {
 
        double req_time;
        unsigned int interval;
+       int hw_interval;
 
        tdm_vblank_handler func;
        void *user_data;
@@ -170,6 +174,9 @@ static tdm_error _tdm_vblank_wait_SW(tdm_vblank_wait_info *wait_info);
 static void _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
                                                                         unsigned int tv_sec, unsigned int tv_usec,
                                                                         void *user_data);
+static void _tdm_vblank_timeout_timer_update(tdm_private_vblank *private_vblank, int ms_delay);
+static void _tdm_vblank_get_client_information(tdm_private_vblank *private_vblank,
+                                                                                          pid_t *pid, const char **name);
 
 #if 0
 static void
@@ -330,6 +337,13 @@ _tdm_vblank_free_HW_wait(tdm_private_vblank *private_vblank, tdm_error error, un
 {
        tdm_vblank_wait_info *w = NULL, *ww = NULL;
 
+       if (!LIST_IS_EMPTY(&private_vblank->HW_wait_list)) {
+               pid_t pid;
+               const char *proc_name;
+               _tdm_vblank_get_client_information(private_vblank, &pid, &proc_name);
+               VER("TDM HW vblank destroyed forcely!! (pid: %u, name: %s)", pid, proc_name);
+       }
+
        LIST_FOR_EACH_ENTRY_SAFE(w, ww, &private_vblank->HW_wait_list, link) {
                LIST_DEL(&w->link);
                _tdm_vblank_valid_list_del(&w->valid_link);
@@ -401,8 +415,13 @@ _tdm_vblank_cb_output_change(tdm_output *output, tdm_output_change_type type,
                if (TDM_OUTPUT_DPMS_VSYNC_IS_OFF(value.u32)) {
                        if (private_vblank->enable_fake)
                                _tdm_vblank_change_to_SW(private_vblank);
-                       else
+                       else {
+                               tdm_display_lock(private_vblank->dpy);
+                               _tdm_vblank_timeout_timer_update(private_vblank, 0);
+                               tdm_display_unlock(private_vblank->dpy);
+
                                _tdm_vblank_free_HW_wait(private_vblank, TDM_ERROR_DPMS_OFF, 1);
+                       }
                }
                break;
        case TDM_OUTPUT_CHANGE_CONNECTION:
@@ -414,8 +433,13 @@ _tdm_vblank_cb_output_change(tdm_output *output, tdm_output_change_type type,
                if (private_vblank->connection == TDM_OUTPUT_CONN_STATUS_DISCONNECTED) {
                        if (private_vblank->enable_fake)
                                _tdm_vblank_change_to_SW(private_vblank);
-                       else
+                       else {
+                               tdm_display_lock(private_vblank->dpy);
+                               _tdm_vblank_timeout_timer_update(private_vblank, 0);
+                               tdm_display_unlock(private_vblank->dpy);
+
                                _tdm_vblank_free_HW_wait(private_vblank, TDM_ERROR_OUTPUT_DISCONNECTED, 1);
+                       }
                }
                break;
        default:
@@ -645,7 +669,7 @@ tdm_vblank_create(tdm_display *dpy, tdm_output *output, tdm_error *error)
                /* LCOV_EXCL_START */
                if (error)
                        *error = TDM_ERROR_OUT_OF_MEMORY;
-               VER("alloc failed");
+               TDM_ERR("alloc failed");
                return NULL;
                /* LCOV_EXCL_STOP */
        }
@@ -706,12 +730,25 @@ tdm_vblank_destroy(tdm_vblank *vblank)
 
        _tdm_vblank_free_HW_wait(private_vblank, 0, 0);
 
+       if (!LIST_IS_EMPTY(&private_vblank->SW_wait_list)) {
+               pid_t pid;
+               const char *proc_name;
+               _tdm_vblank_get_client_information(private_vblank, &pid, &proc_name);
+               VER("TDM SW vblank destroyed forcely!! (pid: %u, name: %s)", pid, proc_name);
+       }
+
        LIST_FOR_EACH_ENTRY_SAFE(w, ww, &private_vblank->SW_wait_list, link) {
                LIST_DEL(&w->link);
                _tdm_vblank_valid_list_del(&w->valid_link);
                free(w);
        }
 
+       if (private_vblank->timeout_timer) {
+               tdm_display_lock(private_vblank->dpy);
+               tdm_event_loop_source_remove(private_vblank->timeout_timer);
+               tdm_display_unlock(private_vblank->dpy);
+       }
+
        VIN("destroyed");
 
        free(private_vblank);
@@ -914,6 +951,65 @@ tdm_vblank_get_enable_fake(tdm_vblank *vblank, unsigned int *enable_fake)
 }
 
 static tdm_error
+_tdm_vblank_timeout_timer_cb(void *user_data)
+{
+       tdm_private_vblank *private_vblank = user_data;
+       tdm_vblank_wait_info *w = NULL;
+       pid_t pid;
+       const char *proc_name;
+
+       TDM_RETURN_VAL_IF_FAIL(private_vblank != NULL, TDM_ERROR_OPERATION_FAILED);
+
+       _tdm_vblank_get_client_information(private_vblank, &pid, &proc_name);
+
+       VER("TDM vblank TIMEOUT!! (pid: %u, name: %s)", pid, proc_name);
+       VER("quotient(%u) last_seq(%u) last_time(%.6f)", private_vblank->quotient, private_vblank->last_seq, private_vblank->last_time);
+
+       LIST_FOR_EACH_ENTRY(w, &private_vblank->HW_wait_list, link) {
+               VER("wait_info(%p) req_time(%.6f) target_seq(%u) interval(%u) hw_interval(%d)",
+                       w, w->req_time, w->target_seq, w->interval, w->hw_interval);
+               tdm_output_vblank_print_wait_information(private_vblank->output, w);
+       }
+
+       LIST_FOR_EACH_ENTRY(w, &private_vblank->SW_wait_list, link) {
+               VER("wait_info(%p) req_time(%.6f) target_time(%.6f) target_seq(%u) interval(%u)",
+                       w, w->req_time, w->target_time, w->target_seq, w->interval);
+       }
+
+       return TDM_ERROR_NONE;
+}
+
+static void
+_tdm_vblank_timeout_timer_update(tdm_private_vblank *private_vblank, int ms_delay)
+{
+       tdm_error ret;
+
+       if (!private_vblank->timeout_timer) {
+               private_vblank->timeout_timer =
+                       tdm_event_loop_add_timer_handler(private_vblank->dpy,
+                                                                                        _tdm_vblank_timeout_timer_cb,
+                                                                                        private_vblank,
+                                                                                        &ret);
+               if (!private_vblank->timeout_timer) {
+                       VER("couldn't add timer");
+                       return;
+               }
+               VIN("Create Timeout timer");
+       }
+
+       ret = tdm_event_loop_source_timer_update(private_vblank->timeout_timer, ms_delay);
+       if (ret != TDM_ERROR_NONE) {
+               VER("couldn't update timer");
+               return;
+       }
+
+       if (ms_delay != 0)
+               VDB("timeout timer updated");
+       else
+               VDB("timeout timer disabled");
+}
+
+static tdm_error
 _tdm_vblank_sw_timer_update(tdm_private_vblank *private_vblank)
 {
        tdm_vblank_wait_info *first_wait_info = NULL;
@@ -985,7 +1081,7 @@ _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
        tdm_private_vblank *private_vblank;
 
        if (!_tdm_vblank_check_valid_wait(wait_info)) {
-               TDM_DBG("can't find wait(%p) from valid_wait_list", wait_info);
+               TDM_ERR("can't find wait(%p) from valid_wait_list", wait_info);
                return;
        }
 
@@ -993,7 +1089,7 @@ _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
        TDM_RETURN_IF_FAIL(tdm_vblank_is_valid(private_vblank));
 
        if (!_tdm_vblank_find_wait(wait_info, &private_vblank->HW_wait_list)) {
-               VDB("can't find wait(%p)", wait_info);
+               VER("can't find wait(%p)", wait_info);
                return;
        }
 
@@ -1014,13 +1110,17 @@ _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
 
                /* wait_info will be freed in _tdm_vblank_cb_vblank_SW() */
                if (ret == TDM_ERROR_NONE) {
-                       VDB("wait(%p) SW timer", wait_info);
+                       VIN("wait(%p) SW timer", wait_info);
                        return;
                }
 
-               VWR("couldn't update sw timer");
+               VER("couldn't update sw timer");
        }
 
+       tdm_display_lock(private_vblank->dpy);
+       _tdm_vblank_timeout_timer_update(private_vblank, 0);
+       tdm_display_unlock(private_vblank->dpy);
+
        LIST_DEL(&wait_info->link);
        _tdm_vblank_valid_list_del(&wait_info->valid_link);
 
@@ -1064,9 +1164,9 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
 
        _tdm_vblank_insert_wait(wait_info, &private_vblank->HW_wait_list);
 
-       hw_interval = wait_info->interval * private_vblank->quotient;
-
        if (private_vblank->last_time == 0) {
+               hw_interval = wait_info->interval * private_vblank->quotient;
+
                /* SW vblank starts from now. SW vblank doesn't need to be aligned with HW vblank. */
                private_vblank->last_seq = 0;
                private_vblank->last_time = tdm_helper_get_time();
@@ -1111,6 +1211,7 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
        }
 
        private_vblank->last_interval = hw_interval;
+       wait_info->hw_interval = hw_interval;
 
        if (tdm_ttrace_module & TDM_TTRACE_VBLANK)
                TDM_TRACE_ASYNC_BEGIN((int)wait_info->req_time, "TDM_Vblank:%u", (unsigned int)private_vblank->stamp);
@@ -1155,7 +1256,7 @@ tdm_vblank_cb_vblank_SW(tdm_vblank *vblank, double vblank_stamp)
        else {
                private_vblank = _tdm_vblank_find(vblank_stamp);
                if (!private_vblank) {
-                       TDM_DBG("can't find vblank(%.0f) from valid_list", vblank_stamp);
+                       TDM_ERR("can't find vblank(%.0f) from valid_list", vblank_stamp);
                        return TDM_ERROR_NONE;
                }
        }
@@ -1180,9 +1281,14 @@ tdm_vblank_cb_vblank_SW(tdm_vblank *vblank, double vblank_stamp)
                return TDM_ERROR_OPERATION_FAILED;
        }
 
+       if (!LIST_IS_EMPTY(&private_vblank->HW_wait_list))
+               TDM_NEVER_GET_HERE();
+
        first_wait_info = container_of(private_vblank->SW_wait_list.next, first_wait_info, link);
        TDM_RETURN_VAL_IF_FAIL(first_wait_info != NULL, TDM_ERROR_OPERATION_FAILED);
 
+       _tdm_vblank_timeout_timer_update(private_vblank, 0);
+
        if (private_vblank->last_seq >= first_wait_info->target_seq)
                TDM_ERR("last_seq(%u) target_seq(%u)", private_vblank->last_seq, first_wait_info->target_seq);
 
@@ -1399,6 +1505,10 @@ tdm_vblank_wait(tdm_vblank *vblank, unsigned int req_sec, unsigned int req_usec,
                /* LCOV_EXCL_STOP */
        }
 
+       tdm_display_lock(private_vblank->dpy);
+       _tdm_vblank_timeout_timer_update(private_vblank, 1000);
+       tdm_display_unlock(private_vblank->dpy);
+
        return TDM_ERROR_NONE;
 }
 
@@ -1415,7 +1525,7 @@ tdm_vblank_wait_seq(tdm_vblank *vblank, unsigned int req_sec, unsigned int req_u
        /* if the sequence of vblank reaches the max value, sequence can be 0. */
 
        if (private_vblank->last_seq == 0) {
-               TDM_WRN("can't calculate interval with sequence(%u)", sequence);
+               VWR("can't calculate interval with sequence(%u)", sequence);
                interval = 1;
        } else if (sequence > private_vblank->last_seq ||
                           TDM_VBLANK_SEQ_REACHED_MAX(sequence, private_vblank->last_seq)) {
@@ -1443,7 +1553,7 @@ tdm_vblank_wait_seq(tdm_vblank *vblank, unsigned int req_sec, unsigned int req_u
                interval = (unsigned int)((seq_target - curr) / private_vblank->vblank_gap + TDM_TIME_MARGIN) + 1;
        } else {
                /* this seems error. But we handle this like normal to avoid the unexpected error in cliend side */
-               TDM_WRN("sequence(%u) should be over the last sequence(%u)", sequence, private_vblank->last_seq);
+               VER("sequence(%u) should be over the last sequence(%u)", sequence, private_vblank->last_seq);
                func(vblank, TDM_ERROR_NONE, private_vblank->last_seq,
                         TDM_TIME_SEC(private_vblank->last_time), TDM_TIME_USEC(private_vblank->last_time),
                         user_data);
@@ -1512,6 +1622,29 @@ _tdm_vblank_get_waiting_count(tdm_private_vblank *private_vblank)
        return count;
 }
 
+static void
+_tdm_vblank_get_client_information(tdm_private_vblank *private_vblank, pid_t *pid, const char **name)
+{
+       struct wl_client *client;
+
+       if (!private_vblank->resource)
+               goto no_client;
+
+       client = wl_resource_get_client(private_vblank->resource);
+       if (!client)
+               goto no_client;
+
+       wl_client_get_credentials(client, pid, NULL, NULL);
+       *name = tdm_server_get_client_name(*pid);
+
+       return;
+
+no_client:
+       *pid = 0;
+       *name = NULL;
+       return;
+}
+
 /* LCOV_EXCL_START */
 INTERN void
 tdm_vblank_get_vblank_list_information(tdm_display *dpy, char *reply, int *len)
@@ -1536,13 +1669,7 @@ tdm_vblank_get_vblank_list_information(tdm_display *dpy, char *reply, int *len)
                pid_t pid = 0;
                unsigned int count;
 
-               if (v->resource) {
-                       struct wl_client *client = wl_resource_get_client(v->resource);
-                       if (client) {
-                               wl_client_get_credentials(client, &pid, NULL, NULL);
-                               proc_name = tdm_server_get_client_name(pid);
-                       }
-               }
+               _tdm_vblank_get_client_information(v, &pid, &proc_name);
 
                count = _tdm_vblank_get_waiting_count(v);