add debugging logs

Change-Id: I3aae4e23b3d6b24f8638ea58673a63e844acb5fa

diff --git a/src/tdm_server.c b/src/tdm_server.c
index ca994ce..a8f7175 100644 (file)
--- a/src/tdm_server.c
+++ b/src/tdm_server.c
@@ -176,7 +176,7 @@ _tdm_server_send_done(tdm_server_wait_info *wait_info, tdm_error error,
        }
 
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               TDM_INFO("req_id(%d) done", wait_info->req_id);
+               TDM_DBG("req_id(%d) done", wait_info->req_id);
 
        TDM_TRACE_COUNT(ServerDoneVBlank, wait_info->req_id);
 
@@ -317,7 +317,7 @@ _tdm_server_vblank_cb_wait_vblank(struct wl_client *client, struct wl_resource *
        wait_info->req_id = req_id;
 
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               TDM_INFO("req_id(%d) wait", req_id);
+               TDM_DBG("req_id(%d) wait", req_id);
 
        ret = tdm_vblank_wait(vblank_info->vblank, req_sec, req_usec, interval, _tdm_server_cb_vblank, wait_info);
 
@@ -359,7 +359,7 @@ _tdm_server_vblank_cb_wait_vblank_seq(struct wl_client *client, struct wl_resour
        wait_info->req_id = req_id;
 
        if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               TDM_INFO("req_id(%d) wait", req_id);
+               TDM_DBG("req_id(%d) wait", req_id);
 
        ret = tdm_vblank_wait_seq(vblank_info->vblank, req_sec, req_usec, sequence, _tdm_server_cb_vblank, wait_info);
 

diff --git a/src/tdm_vblank.c b/src/tdm_vblank.c
index 337e7cf..2c5eca4 100644 (file)
--- a/src/tdm_vblank.c
+++ b/src/tdm_vblank.c
@@ -71,8 +71,8 @@
 
 #define VER(fmt, arg...)   TDM_ERR("[%p] "fmt, private_vblank, ##arg)
 #define VWR(fmt, arg...)   TDM_WRN("[%p] "fmt, private_vblank, ##arg)
-#define VIN(fmt, arg...)   TDM_INFO("[%p] "fmt, private_vblank, ##arg)
-#define VDB(fmt, arg...)   TDM_DBG("[%p] "fmt, private_vblank, ##arg)
+#define VIN(fmt, arg...)   do { if (tdm_debug_module & TDM_DEBUG_VBLANK) TDM_INFO("[%p] "fmt, private_vblank, ##arg); } while (0)
+#define VDB(fmt, arg...)   do { if (tdm_debug_module & TDM_DEBUG_VBLANK) TDM_DBG("[%p] "fmt, private_vblank, ##arg); } while (0)
 
 typedef enum {
        VBLANK_TYPE_SW,
@@ -81,6 +81,12 @@ typedef enum {
        VBLANK_TYPE_HW_SW,
 } tdm_vblank_wait_type;
 
+typedef enum {
+       VBLANK_EVENT_TYPE_NONE,
+       VBLANK_EVENT_TYPE_SW,
+       VBLANK_EVENT_TYPE_HW,
+} tdm_vblank_event_type;
+
 typedef struct _tdm_vblank_wait_info tdm_vblank_wait_info;
 
 typedef struct _tdm_private_vblank {
@@ -95,6 +101,7 @@ typedef struct _tdm_private_vblank {
        tdm_output_dpms dpms;
        unsigned int vrefresh;
 
+       tdm_vblank_event_type last_type;
        unsigned int check_HW_or_SW;
        char name[TDM_NAME_LEN];
        unsigned int fps;
@@ -324,12 +331,17 @@ _tdm_vblank_update_output_info(tdm_private_vblank *private_vblank)
        if (connection != TDM_OUTPUT_CONN_STATUS_DISCONNECTED) {
                const tdm_output_mode *mode = NULL;
                tdm_output_get_mode(output, &mode);
-               vrefresh = (mode) ? mode->vrefresh : 0;
+               if (mode)
+                       vrefresh = mode->vrefresh;
+               else
+                       VWR("mode not setted!!!");
                tdm_output_get_dpms(output, &dpms);
        }
 
-       if (vrefresh == 0)
+       if (vrefresh == 0) {
+               VWR("vrefresh can't be zero !!!");
                vrefresh = TDM_VBLANK_DEFAULT_VREFRESH;
+       }
 
        private_vblank->dpms = dpms;
        private_vblank->connection = connection;
@@ -339,9 +351,9 @@ _tdm_vblank_update_output_info(tdm_private_vblank *private_vblank)
        if (private_vblank->fps_changeable)
                private_vblank->fps = vrefresh;
 
-       VDB("dpms(%d) connection(%d) vrefresh(%d) fps(%d)",
+       VIN("dpms(%d) connection(%d) vrefresh(%d) fps(%d) fps_changeable(%d)",
                private_vblank->dpms, private_vblank->connection,
-               private_vblank->vrefresh, private_vblank->fps);
+               private_vblank->vrefresh, private_vblank->fps, private_vblank->fps_changeable);
 }
 
 static void
@@ -356,7 +368,7 @@ _tdm_vblank_cb_output_change(tdm_output *output, tdm_output_change_type type,
        case TDM_OUTPUT_CHANGE_DPMS:
                if (private_vblank->dpms == value.u32)
                        break;
-               VDB("dpms %s", tdm_dpms_str(value.u32));
+               VIN("dpms %s", tdm_dpms_str(value.u32));
                _tdm_vblank_update_output_info(private_vblank);
                private_vblank->check_HW_or_SW = 1;
                if (private_vblank->dpms != TDM_OUTPUT_DPMS_ON) {
@@ -369,7 +381,7 @@ _tdm_vblank_cb_output_change(tdm_output *output, tdm_output_change_type type,
        case TDM_OUTPUT_CHANGE_CONNECTION:
                if (private_vblank->connection == value.u32)
                        break;
-               VDB("output %s", tdm_status_str(value.u32));
+               VIN("output %s", tdm_status_str(value.u32));
                _tdm_vblank_update_output_info(private_vblank);
                private_vblank->check_HW_or_SW = 1;
                if (private_vblank->connection == TDM_OUTPUT_CONN_STATUS_DISCONNECTED) {
@@ -502,9 +514,8 @@ tdm_vblank_create(tdm_display *dpy, tdm_output *output, tdm_error *error)
 
        _tdm_vblank_valid_list_add(&private_vblank->valid_link, &valid_vblank_list);
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("created. vrefresh(%d) dpms(%d) connection(%d)",
-                       private_vblank->vrefresh, private_vblank->dpms, private_vblank->connection);
+       VIN("created. vrefresh(%d) dpms(%d) connection(%d)",
+               private_vblank->vrefresh, private_vblank->dpms, private_vblank->connection);
 
        return (tdm_vblank *)private_vblank;
 }
@@ -537,8 +548,7 @@ tdm_vblank_destroy(tdm_vblank *vblank)
                free(w);
        }
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("destroyed");
+       VIN("destroyed");
 
        free(private_vblank);
 }
@@ -556,8 +566,7 @@ tdm_vblank_set_name(tdm_vblank *vblank, const char *name)
        strncpy(private_vblank->name, name, TDM_NAME_LEN - 1);
        private_vblank->name[TDM_NAME_LEN - 1] = '\0';
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("name(%s)", name);
+       VIN("name(%s)", name);
 
        return TDM_ERROR_NONE;
 }
@@ -583,16 +592,17 @@ tdm_vblank_set_fps(tdm_vblank *vblank, unsigned int fps)
        TDM_RETURN_VAL_IF_FAIL(private_vblank != NULL, TDM_ERROR_INVALID_PARAMETER);
        TDM_RETURN_VAL_IF_FAIL(fps > 0, TDM_ERROR_INVALID_PARAMETER);
 
+       if (private_vblank->fps != fps || private_vblank->fps_changeable)
+               VIN("fps(%d) fps_changeable(0)", fps);
+
+       private_vblank->fps_changeable = 0;
+
        if (private_vblank->fps == fps)
                return TDM_ERROR_NONE;
 
        private_vblank->fps = fps;
-       private_vblank->fps_changeable = 0;
        private_vblank->check_HW_or_SW = 1;
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("fps(%d)", private_vblank->fps);
-
        return TDM_ERROR_NONE;
 }
 
@@ -622,8 +632,7 @@ tdm_vblank_ignore_global_fps(tdm_vblank *vblank, unsigned int ignore)
        private_vblank->ignore_global_fps = ignore;
        private_vblank->check_HW_or_SW = 1;
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("ignore_global_fps(%d)", private_vblank->ignore_global_fps);
+       VIN("ignore_global_fps(%d)", private_vblank->ignore_global_fps);
 
        return TDM_ERROR_NONE;
 }
@@ -641,8 +650,7 @@ tdm_vblank_set_offset(tdm_vblank *vblank, int offset)
        private_vblank->offset = offset;
        private_vblank->check_HW_or_SW = 1;
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("offset(%d)", private_vblank->offset);
+       VIN("offset(%d)", private_vblank->offset);
 
        return TDM_ERROR_NONE;
 }
@@ -672,8 +680,7 @@ tdm_vblank_set_enable_fake(tdm_vblank *vblank, unsigned int enable_fake)
 
        private_vblank->enable_fake = enable_fake;
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("enable_fake(%d)", private_vblank->enable_fake);
+       VIN("enable_fake(%d)", private_vblank->enable_fake);
 
        return TDM_ERROR_NONE;
 }
@@ -719,8 +726,8 @@ _tdm_vblank_sw_timer_update(tdm_private_vblank *private_vblank)
 
        if (ms_delay > 5000)
                VER("wait(%p) curr(%.6f) target(%.6f) ms_delay(%d)", first_wait_info, curr, target, ms_delay);
-       else if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("wait(%p) curr(%.6f) target(%.6f) ms_delay(%d)", first_wait_info, curr, target, ms_delay);
+       else
+               VDB("wait(%p) curr(%.6f) target(%.6f) ms_delay(%d)", first_wait_info, curr, target, ms_delay);
 
        tdm_display_lock(private_vblank->dpy);
 
@@ -735,7 +742,7 @@ _tdm_vblank_sw_timer_update(tdm_private_vblank *private_vblank)
                        VER("couldn't add timer");
                        return ret;
                }
-               VIN("Use SW vblank");
+               VIN("Create SW timer");
        }
 
        ret = tdm_event_loop_source_timer_update(private_vblank->SW_timer, ms_delay);
@@ -788,8 +795,7 @@ _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) {
-                       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-                               VIN("wait(%p) SW timer", wait_info);
+                       VDB("wait(%p) SW timer", wait_info);
                        return;
                }
 
@@ -810,8 +816,7 @@ _tdm_vblank_cb_vblank_HW(tdm_output *output, unsigned int sequence,
        private_vblank->last_seq = wait_info->target_seq;
        private_vblank->last_time = TDM_TIME(tv_sec, tv_usec);
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("wait(%p) last(%.6f) sequence(%u) done", wait_info, private_vblank->last_time, wait_info->target_seq);
+       VDB("wait(%p) last(%.6f) sequence(%u) done", wait_info, private_vblank->last_time, wait_info->target_seq);
 
        if (wait_info->func)
                wait_info->func(private_vblank, TDM_ERROR_NONE, wait_info->target_seq,
@@ -829,6 +834,11 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
        int hw_interval;
        tdm_error ret;
 
+       if (private_vblank->last_type != VBLANK_EVENT_TYPE_HW) {
+               VIN("Use HW vblank");
+               private_vblank->last_type = VBLANK_EVENT_TYPE_HW;
+       }
+
        _tdm_vblank_insert_wait(wait_info, &private_vblank->HW_wait_list);
 
        hw_interval = wait_info->interval * private_vblank->quotient;
@@ -840,9 +850,9 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
 
                /* +1 ms to call the handler ASAP at the first. no matter for SW timer. */
                wait_info->target_seq = 1;
-               if (tdm_debug_module & TDM_DEBUG_VBLANK)
-                       VIN("wait(%p) last(%.6f) hw_itvl(%d) targ_seq(%u)",
-                               wait_info, private_vblank->last_time, hw_interval, wait_info->target_seq);
+
+               VDB("wait(%p) last(%.6f) hw_itvl(%d) targ_seq(%u)",
+                       wait_info, private_vblank->last_time, hw_interval, wait_info->target_seq);
        } else {
                double last, prev, req, curr, target;
                unsigned int skip;
@@ -871,8 +881,8 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
                        VER("wait(%p) last(%.6f) req(%.6f) prev(%.6f) curr(%.6f) targ(%.6f,%.6f) skip(%u) hw_itvl(%d) targ_seq(%u)",
                                wait_info, last, req - last, prev - last, curr - last, target, target - last,
                                skip, hw_interval, wait_info->target_seq);
-               else if (tdm_debug_module & TDM_DEBUG_VBLANK)
-                       VIN("wait(%p) last(%.6f) req(%.6f) prev(%.6f) curr(%.6f) targ(%.6f,%.6f) skip(%u) hw_itvl(%d) targ_seq(%u)",
+               else
+                       VDB("wait(%p) last(%.6f) req(%.6f) prev(%.6f) curr(%.6f) targ(%.6f,%.6f) skip(%u) hw_itvl(%d) targ_seq(%u)",
                                wait_info, last, req - last, prev - last, curr - last, target, target - last,
                                skip, hw_interval, wait_info->target_seq);
        }
@@ -889,8 +899,7 @@ _tdm_vblank_wait_HW(tdm_vblank_wait_info *wait_info)
                return ret;
        }
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("wait(%p) waiting", wait_info);
+       VDB("wait(%p) waiting", wait_info);
 
        return TDM_ERROR_NONE;
 }
@@ -952,8 +961,7 @@ tdm_vblank_cb_vblank_SW(tdm_vblank *vblank, double vblank_stamp)
        private_vblank->last_seq = first_wait_info->target_seq;
        private_vblank->last_time = first_wait_info->target_time;
 
-       if (tdm_debug_module & TDM_DEBUG_VBLANK)
-               VIN("wait(%p) last(%.6f) sequence(%u) done", first_wait_info, private_vblank->last_time, first_wait_info->target_seq);
+       VDB("wait(%p) last(%.6f) sequence(%u) done", first_wait_info, private_vblank->last_time, first_wait_info->target_seq);
 
        LIST_FOR_EACH_ENTRY_SAFE(w, ww, &private_vblank->SW_wait_list, link) {
                if (w->target_time != first_wait_info->target_time)
@@ -982,6 +990,11 @@ _tdm_vblank_wait_SW(tdm_vblank_wait_info *wait_info)
        tdm_private_vblank *private_vblank = wait_info->private_vblank;
        tdm_error ret;
 
+       if (private_vblank->last_type != VBLANK_EVENT_TYPE_SW) {
+               VIN("Use SW vblank");
+               private_vblank->last_type = VBLANK_EVENT_TYPE_SW;
+       }
+
        if (private_vblank->last_time == 0) {
                /* SW vblank starts from now. SW vblank doesn't need to be aligned with HW vblank. */
                private_vblank->last_seq = 0;
@@ -991,9 +1004,8 @@ _tdm_vblank_wait_SW(tdm_vblank_wait_info *wait_info)
                wait_info->target_seq = 1;
                wait_info->target_time = private_vblank->last_time + 0.001;
 
-               if (tdm_debug_module & TDM_DEBUG_VBLANK)
-                       VIN("wait(%p) last(%.6f) target(%.6f) target sequence(%u)",
-                               wait_info, private_vblank->last_time, wait_info->target_time, wait_info->target_seq);
+               VDB("wait(%p) last(%.6f) target(%.6f) target sequence(%u)",
+                       wait_info, private_vblank->last_time, wait_info->target_time, wait_info->target_seq);
        } else {
                double last, prev, req, curr, target;
                unsigned int skip;
@@ -1019,10 +1031,9 @@ _tdm_vblank_wait_SW(tdm_vblank_wait_info *wait_info)
 
                wait_info->target_time = target;
 
-               if (tdm_debug_module & TDM_DEBUG_VBLANK)
-                       VIN("wait(%p) last(%.6f) req(%.6f) prev(%.6f) curr(%.6f) targ(%.6f,%.6f) skip(%u) targ_seq(%u)",
-                               wait_info, last, req - last, prev - last, curr - last,
-                               target, target - last, skip, wait_info->target_seq);
+               VDB("wait(%p) last(%.6f) req(%.6f) prev(%.6f) curr(%.6f) targ(%.6f,%.6f) skip(%u) targ_seq(%u)",
+                       wait_info, last, req - last, prev - last, curr - last,
+                       target, target - last, skip, wait_info->target_seq);
        }
 
        _tdm_vblank_insert_wait(wait_info, &private_vblank->SW_wait_list);
@@ -1056,11 +1067,11 @@ tdm_vblank_wait(tdm_vblank *vblank, unsigned int req_sec, unsigned int req_usec,
 
        if (!private_vblank->enable_fake) {
                if (private_vblank->connection == TDM_OUTPUT_CONN_STATUS_DISCONNECTED) {
-                       VIN("can't wait a vblank: output disconnected");
+                       VER("can't wait a vblank: output disconnected");
                        return TDM_ERROR_OUTPUT_DISCONNECTED;
                }
                if (private_vblank->dpms != TDM_OUTPUT_DPMS_ON) {
-                       VIN("can't wait a vblank: DPMS off");
+                       VER("can't wait a vblank: DPMS off");
                        return TDM_ERROR_DPMS_OFF;
                }
        }