hwc: Check for correct screen state before enabling vsync

Sometimes vsync would not be disabled before the display is
blanked.
This was due to the vsync disable ioctl being kicked off in a
thread different from the event control which surfaceflinger
called. So, while the calls from surfaceflinger are in order, the
order of execution wasn't always the same. Hence, making sure
ioctls are called in the same context to ensure order.

Also
- Make blanking/unblanking logs show the operation as a string.
- Add a debug property to dump vsync timestamps (needs framework
reboot)
- Remove a log which showed delay in reading vsync. This log was
unreliable when vsync is disabled and we're still reading from
the sysfs node.

Change-Id: Ibec04e9ffebd0ac6e1d32b7031e3668abd9390ff
CRs-fixed: 443113
diff --git a/libhwcomposer/hwc_vsync.cpp b/libhwcomposer/hwc_vsync.cpp
index f83b6d7..559cd7d 100644
--- a/libhwcomposer/hwc_vsync.cpp
+++ b/libhwcomposer/hwc_vsync.cpp
@@ -18,9 +18,6 @@
  * limitations under the License.
  */
 
-// WARNING : Excessive logging, if VSYNC_DEBUG enabled
-#define VSYNC_DEBUG 0
-
 #include <cutils/properties.h>
 #include <utils/Log.h>
 #include <fcntl.h>
@@ -32,11 +29,23 @@
 #include "string.h"
 #include "external.h"
 
-using android::LogIfSlow;
 namespace qhwc {
 
 #define HWC_VSYNC_THREAD_NAME "hwcVsyncThread"
 
+int hwc_vsync_control(hwc_context_t* ctx, int dpy, int enable)
+{
+    int ret = 0;
+    if(!ctx->vstate.fakevsync &&
+       ioctl(ctx->dpyAttr[dpy].fd, MSMFB_OVERLAY_VSYNC_CTRL,
+             &enable) < 0) {
+        ALOGE("%s: vsync control failed. Dpy=%d, enable=%d : %s",
+              __FUNCTION__, dpy, enable, strerror(errno));
+        ret = -errno;
+    }
+    return ret;
+}
+
 static void *vsync_loop(void *param)
 {
     const char* vsync_timestamp_fb0 = "/sys/class/graphics/fb0/vsync_event";
@@ -59,14 +68,17 @@
     int fd_timestamp = -1;
     int ret = 0;
     bool fb1_vsync = false;
-    bool enabled = false;
-    bool fakevsync = false;
-    uint32_t log_threshold = ns2ms(ctx->dpyAttr[dpy].vsync_period)*2;
+    bool logvsync = false;
 
     char property[PROPERTY_VALUE_MAX];
     if(property_get("debug.hwc.fakevsync", property, NULL) > 0) {
         if(atoi(property) == 1)
-            fakevsync = true;
+            ctx->vstate.fakevsync = true;
+    }
+
+    if(property_get("debug.hwc.logvsync", property, 0) > 0) {
+        if(atoi(property) == 1)
+            logvsync = true;
     }
 
     /* Currently read vsync timestamp from drivers
@@ -77,42 +89,18 @@
         ALOGE ("FATAL:%s:not able to open file:%s, %s",  __FUNCTION__,
                (fb1_vsync) ? vsync_timestamp_fb1 : vsync_timestamp_fb0,
                strerror(errno));
-        fakevsync = true;
+        ctx->vstate.fakevsync = true;
     }
 
     do {
         pthread_mutex_lock(&ctx->vstate.lock);
         while (ctx->vstate.enable == false) {
-            if(enabled) {
-                int e = 0;
-                if(!fakevsync &&
-                   ioctl(ctx->dpyAttr[dpy].fd, MSMFB_OVERLAY_VSYNC_CTRL,
-                         &e) < 0) {
-                    ALOGE("%s: vsync control failed. Dpy=%d, enabled=%d : %s",
-                          __FUNCTION__, dpy, enabled, strerror(errno));
-                    ret = -errno;
-                }
-                enabled = false;
-            }
             pthread_cond_wait(&ctx->vstate.cond, &ctx->vstate.lock);
         }
         pthread_mutex_unlock(&ctx->vstate.lock);
 
-        if (!enabled) {
-            int e = 1;
-            if(!fakevsync &&
-               ioctl(ctx->dpyAttr[dpy].fd, MSMFB_OVERLAY_VSYNC_CTRL,
-                     &e) < 0) {
-                ALOGE("%s: vsync control failed. Dpy=%d, enabled=%d : %s",
-                      __FUNCTION__, dpy, enabled, strerror(errno));
-                ret = -errno;
-            }
-            enabled = true;
-        }
-
-        if(!fakevsync) {
+        if (!ctx->vstate.fakevsync) {
             for(int i = 0; i < MAX_RETRY_COUNT; i++) {
-                ALOGD_IF_SLOW(log_threshold, "Excessive delay reading vsync");
                 len = pread(fd_timestamp, vdata, MAX_DATA, 0);
                 if(len < 0 && (errno == EAGAIN ||
                                errno == EINTR  ||
@@ -129,7 +117,7 @@
                 ALOGE ("FATAL:%s:not able to read file:%s, %s", __FUNCTION__,
                        vsync_timestamp_fb0, strerror(errno));
                 close (fd_timestamp);
-                fakevsync = true;
+                ctx->vstate.fakevsync = true;
             }
 
             // extract timestamp
@@ -140,7 +128,7 @@
                 ALOGE ("FATAL: %s: vsync timestamp not in correct format: [%s]",
                        __FUNCTION__,
                        str);
-                fakevsync = true;
+                ctx->vstate.fakevsync = true;
             }
 
         } else {
@@ -148,7 +136,7 @@
             cur_timestamp = systemTime();
         }
         // send timestamp to HAL
-        ALOGD_IF (VSYNC_DEBUG, "%s: timestamp %llu sent to HWC for %s",
+        ALOGD_IF (logvsync, "%s: timestamp %llu sent to HWC for %s",
                   __FUNCTION__, cur_timestamp, "fb0");
         ctx->proc->vsync(ctx->proc, dpy, cur_timestamp);