Ticket #765: Bug with milliseconds time resolution in WinCE/Windows Mobile targets (thanks Johan Lantz for the report)

 - backported changes in #764


git-svn-id: http://svn.pjsip.org/repos/pjproject/branches/1.0@2805 74dad513-b988-da41-8d7b-12977e46ad98

4 files changed, 211 insertions, 16 deletions

diff --git a/pjlib/include/pj/os.h b/pjlib/include/pj/os.h
index 4a5a77f8..38eb8ea6 100644
--- a/pjlib/include/pj/os.h
+++ b/pjlib/include/pj/os.h
@@ -1268,6 +1268,12 @@ PJ_DECL(pj_uint32_t) pj_elapsed_msec( const pj_timestamp *start,
                                       const pj_timestamp *stop );
 
 /**
+ * Variant of #pj_elapsed_msec() which returns 64bit value.
+ */
+PJ_DECL(pj_uint64_t) pj_elapsed_msec64(const pj_timestamp *start,
+                                       const pj_timestamp *stop );
+
+/**
  * Calculate the elapsed time in 32-bit microseconds.
  * This function calculates the elapsed time using highest precision
  * calculation that is available for current platform, considering
diff --git a/pjlib/src/pj/os_time_win32.c b/pjlib/src/pj/os_time_win32.c
index 0f28359a..6da3c23d 100644
--- a/pjlib/src/pj/os_time_win32.c
+++ b/pjlib/src/pj/os_time_win32.c
@@ -19,6 +19,7 @@
  */
 #include <pj/os.h>
 #include <pj/string.h>
+#include <pj/log.h>
 #include <windows.h>
 
 ///////////////////////////////////////////////////////////////////////////////
@@ -27,11 +28,133 @@
 
 static LARGE_INTEGER base_time;
 
+#if defined(PJ_WIN32_WINCE) && PJ_WIN32_WINCE
+#   define WINCE_TIME
+#endif
+
+#ifdef WINCE_TIME
+/* Note:
+ *  In Windows CE/Windows Mobile platforms, the availability of milliseconds
+ *  time resolution in SYSTEMTIME.wMilliseconds depends on the OEM, and most
+ *  likely it won't be available. When it's not available, the 
+ *  SYSTEMTIME.wMilliseconds will contain a constant arbitrary value.
+ *
+ *  Because of that, we need to emulate the milliseconds time resolution
+ *  using QueryPerformanceCounter() (via pj_get_timestamp() API). However 
+ *  there is limitation on using this, i.e. the time returned by 
+ *  pj_gettimeofday() may be off by up to plus/minus 999 msec (the second
+ *  part will be correct, however the msec part may be off), because we're 
+ *  not synchronizing the msec field with the change of value of the "second"
+ *  field of the system time.
+ *
+ *  Also there is other caveat which need to be handled (and they are 
+ *  handled by this implementation):
+ *   - user may change system time, so pj_gettimeofday() needs to periodically
+ *     checks if system time has changed. The period on which system time is
+ *     checked is controlled by PJ_WINCE_TIME_CHECK_INTERVAL macro.
+ */
+static LARGE_INTEGER g_start_time;  /* Time gettimeofday() is first called  */
+static pj_timestamp  g_start_tick;  /* TS gettimeofday() is first called  */
+static pj_timestamp  g_last_update; /* Last time check_system_time() is 
+				       called, to periodically synchronize
+				       with up-to-date system time (in case
+				       user changes system time).	    */
+static pj_uint64_t   g_update_period; /* Period (in TS) check_system_time()
+				         should be called.		    */
+
+/* Period on which check_system_time() is called, in seconds		    */
+#ifndef PJ_WINCE_TIME_CHECK_INTERVAL
+#   define PJ_WINCE_TIME_CHECK_INTERVAL (10)
+#endif
+
+#endif
+
+#ifdef WINCE_TIME
+static pj_status_t init_start_time(void)
+{
+    SYSTEMTIME st;
+    FILETIME ft;
+    pj_timestamp freq;
+    pj_status_t status;
+
+    GetLocalTime(&st);
+    SystemTimeToFileTime(&st, &ft);
+
+    g_start_time.LowPart = ft.dwLowDateTime;
+    g_start_time.HighPart = ft.dwHighDateTime;
+    g_start_time.QuadPart /= SECS_TO_FT_MULT;
+    g_start_time.QuadPart -= base_time.QuadPart;
+
+    status = pj_get_timestamp(&g_start_tick);
+    if (status != PJ_SUCCESS)
+	return status;
+
+    g_last_update.u64 = g_start_tick.u64;
+
+    status = pj_get_timestamp_freq(&freq);
+    if (status != PJ_SUCCESS)
+	return status;
+
+    g_update_period = PJ_WINCE_TIME_CHECK_INTERVAL * freq.u64;
+
+    PJ_LOG(4,("os_time_win32.c", "WinCE time (re)started"));
+
+    return PJ_SUCCESS;
+}
+
+static pj_status_t check_system_time(pj_uint64_t ts_elapsed)
+{
+    enum { MIS = 5 };
+    SYSTEMTIME st;
+    FILETIME ft;
+    LARGE_INTEGER cur, calc;
+    DWORD diff;
+    pj_timestamp freq;
+    pj_status_t status;
+
+    /* Get system's current time */
+    GetLocalTime(&st);
+    SystemTimeToFileTime(&st, &ft);
+    
+    cur.LowPart = ft.dwLowDateTime;
+    cur.HighPart = ft.dwHighDateTime;
+    cur.QuadPart /= SECS_TO_FT_MULT;
+    cur.QuadPart -= base_time.QuadPart;
+
+    /* Get our calculated system time */
+    status = pj_get_timestamp_freq(&freq);
+    if (status != PJ_SUCCESS)
+	return status;
+
+    calc.QuadPart = g_start_time.QuadPart + ts_elapsed / freq.u64;
+
+    /* See the difference between calculated and actual system time */
+    if (calc.QuadPart >= cur.QuadPart) {
+	diff = (DWORD)(calc.QuadPart - cur.QuadPart);
+    } else {
+	diff = (DWORD)(cur.QuadPart - calc.QuadPart);
+    }
+
+    if (diff > MIS) {
+	/* System time has changed */
+	PJ_LOG(3,("os_time_win32.c", "WinCE system time changed detected "
+				      "(diff=%u)", diff));
+	status = init_start_time();
+    } else {
+	status = PJ_SUCCESS;
+    }
+
+    return status;
+}
+
+#endif
+
 // Find 1st Jan 1970 as a FILETIME 
-static void get_base_time(void)
+static pj_status_t get_base_time(void)
 {
     SYSTEMTIME st;
     FILETIME ft;
+    pj_status_t status = PJ_SUCCESS;
 
     memset(&st,0,sizeof(st));
     st.wYear=1970;
@@ -42,17 +165,58 @@ static void get_base_time(void)
     base_time.LowPart = ft.dwLowDateTime;
     base_time.HighPart = ft.dwHighDateTime;
     base_time.QuadPart /= SECS_TO_FT_MULT;
+
+#ifdef WINCE_TIME
+    pj_enter_critical_section();
+    status = init_start_time();
+    pj_leave_critical_section();
+#endif
+
+    return status;
 }
 
 PJ_DEF(pj_status_t) pj_gettimeofday(pj_time_val *tv)
 {
+#ifdef WINCE_TIME
+    pj_timestamp tick;
+    pj_uint64_t msec_elapsed;
+#else
     SYSTEMTIME st;
     FILETIME ft;
     LARGE_INTEGER li;
+#endif
+    pj_status_t status;
+
+    if (base_time.QuadPart == 0) {
+	status = get_base_time();
+	if (status != PJ_SUCCESS)
+	    return status;
+    }
+
+#ifdef WINCE_TIME
+    do {
+	status = pj_get_timestamp(&tick);
+	if (status != PJ_SUCCESS)
+	    return status;
+
+	if (tick.u64 - g_last_update.u64 >= g_update_period) {
+	    pj_enter_critical_section();
+	    if (tick.u64 - g_last_update.u64 >= g_update_period) {
+		g_last_update.u64 = tick.u64;
+		check_system_time(tick.u64 - g_start_tick.u64);
+	    }
+	    pj_leave_critical_section();
+	} else {
+	    break;
+	}
+    } while (1);
 
-    if (base_time.QuadPart == 0)
-	get_base_time();
+    msec_elapsed = pj_elapsed_msec64(&g_start_tick, &tick);
 
+    tv->sec = (long)(g_start_time.QuadPart + msec_elapsed/1000);
+    tv->msec = (long)(msec_elapsed % 1000);
+#else
+    /* Standard Win32 GetLocalTime */
     GetLocalTime(&st);
     SystemTimeToFileTime(&st, &ft);
 
@@ -63,6 +227,7 @@ PJ_DEF(pj_status_t) pj_gettimeofday(pj_time_val *tv)
 
     tv->sec = li.LowPart;
     tv->msec = st.wMilliseconds;
+#endif	/* WINCE_TIME */
 
     return PJ_SUCCESS;
 }
diff --git a/pjlib/src/pj/os_timestamp_common.c b/pjlib/src/pj/os_timestamp_common.c
index 3384baf7..293f6162 100644
--- a/pjlib/src/pj/os_timestamp_common.c
+++ b/pjlib/src/pj/os_timestamp_common.c
@@ -152,6 +152,12 @@ PJ_DEF(pj_uint32_t) pj_elapsed_msec( const pj_timestamp *start,
     return (pj_uint32_t)elapsed_msec(start, stop);
 }
 
+PJ_DEF(pj_uint64_t) pj_elapsed_msec64(const pj_timestamp *start,
+                                      const pj_timestamp *stop )
+{
+    return (pj_uint64_t)elapsed_msec(start, stop);
+}
+
 PJ_DEF(pj_time_val) pj_elapsed_time( const pj_timestamp *start,
                                      const pj_timestamp *stop )
 {
diff --git a/pjlib/src/pjlib-test/sleep.c b/pjlib/src/pjlib-test/sleep.c
index 1c4986f0..eaaac88c 100644
--- a/pjlib/src/pjlib-test/sleep.c
+++ b/pjlib/src/pjlib-test/sleep.c
@@ -55,19 +55,35 @@
 
 static int simple_sleep_test(void)
 {
-    enum { COUNT = 5 };
+    enum { COUNT = 10 };
     int i;
     pj_status_t rc;
     
     PJ_LOG(3,(THIS_FILE, "..will write messages every 1 second:"));
     
     for (i=0; i<COUNT; ++i) {
+	pj_time_val tv;
+	pj_parsed_time pt;
+
 	rc = pj_thread_sleep(1000);
 	if (rc != PJ_SUCCESS) {
 	    app_perror("...error: pj_thread_sleep()", rc);
 	    return -10;
 	}
-	PJ_LOG(3,(THIS_FILE, "...wake up.."));
+
+	rc = pj_gettimeofday(&tv);
+	if (rc != PJ_SUCCESS) {
+	    app_perror("...error: pj_gettimeofday()", rc);
+	    return -11;
+	}
+
+	pj_time_decode(&tv, &pt);
+
+	PJ_LOG(3,(THIS_FILE, 
+		  "...%04d-%02d-%02d %02d:%02d:%02d.%03d",
+		  pt.year, pt.mon, pt.day,
+		  pt.hour, pt.min, pt.sec, pt.msec));
+
     }
 
     return 0;
@@ -75,13 +91,15 @@ static int simple_sleep_test(void)
 
 static int sleep_duration_test(void)
 {
-    enum { MIS = 20, DURATION = 1000, DURATION2 = 500 };
+    enum { MIS = 20};
+    unsigned duration[] = { 2000, 1000, 500, 200, 100 };
+    unsigned i;
     pj_status_t rc;
 
     PJ_LOG(3,(THIS_FILE, "..running sleep duration test"));
 
     /* Test pj_thread_sleep() and pj_gettimeofday() */
-    {
+    for (i=0; i<PJ_ARRAY_SIZE(duration); ++i) {
         pj_time_val start, stop;
 	pj_uint32_t msec;
 
@@ -93,7 +111,7 @@ static int sleep_duration_test(void)
         }
 
         /* Sleep */
-        rc = pj_thread_sleep(DURATION);
+        rc = pj_thread_sleep(duration[i]);
         if (rc != PJ_SUCCESS) {
             app_perror("...error: pj_thread_sleep()", rc);
             return -20;
@@ -109,20 +127,20 @@ static int sleep_duration_test(void)
 	msec = PJ_TIME_VAL_MSEC(stop);
 
 	/* Check if it's within range. */
-	if (msec < DURATION * (100-MIS)/100 ||
-	    msec > DURATION * (100+MIS)/100)
+	if (msec < duration[i] * (100-MIS)/100 ||
+	    msec > duration[i] * (100+MIS)/100)
 	{
 	    PJ_LOG(3,(THIS_FILE, 
 		      "...error: slept for %d ms instead of %d ms "
 		      "(outside %d%% err window)",
-		      msec, DURATION, MIS));
+		      msec, duration[i], MIS));
 	    return -30;
 	}
     }
 
 
     /* Test pj_thread_sleep() and pj_get_timestamp() and friends */
-    {
+    for (i=0; i<PJ_ARRAY_SIZE(duration); ++i) {
 	pj_time_val t1, t2;
         pj_timestamp start, stop;
 	pj_uint32_t msec;
@@ -140,7 +158,7 @@ static int sleep_duration_test(void)
 	pj_gettimeofday(&t1);
 
         /* Sleep */
-        rc = pj_thread_sleep(DURATION2);
+        rc = pj_thread_sleep(duration[i]);
         if (rc != PJ_SUCCESS) {
             app_perror("...error: pj_thread_sleep()", rc);
             return -70;
@@ -162,13 +180,13 @@ static int sleep_duration_test(void)
         msec = pj_elapsed_msec(&start, &stop);
 
 	/* Check if it's within range. */
-	if (msec < DURATION2 * (100-MIS)/100 ||
-	    msec > DURATION2 * (100+MIS)/100)
+	if (msec < duration[i] * (100-MIS)/100 ||
+	    msec > duration[i] * (100+MIS)/100)
 	{
 	    PJ_LOG(3,(THIS_FILE, 
 		      "...error: slept for %d ms instead of %d ms "
 		      "(outside %d%% err window)",
-		      msec, DURATION2, MIS));
+		      msec, duration[i], MIS));
 	    PJ_TIME_VAL_SUB(t2, t1);
 	    PJ_LOG(3,(THIS_FILE, 
 		      "...info: gettimeofday() reported duration is "