Ticket #764: Bug with milliseconds time resolution in WinCE/Windows Mobile targets (thanks Johan Lantz for the report)
- use QueryPerformanceCounter() (via pj_get_timestamp() API) to emulate the msec precision)
- more strict tests in pjlib-test
git-svn-id: https://svn.pjsip.org/repos/pjproject/trunk@2560 74dad513-b988-da41-8d7b-12977e46ad98
diff --git a/pjlib/src/pj/os_time_win32.c b/pjlib/src/pj/os_time_win32.c
index 0f28359..6da3c23 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;
-// Find 1st Jan 1970 as a FILETIME
-static void get_base_time(void)
+#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 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 @@
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)
- get_base_time();
+ 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);
+
+ 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 @@
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 3384baf..293f616 100644
--- a/pjlib/src/pj/os_timestamp_common.c
+++ b/pjlib/src/pj/os_timestamp_common.c
@@ -152,6 +152,12 @@
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 1c4986f..eaaac88 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 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 @@
}
/* 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 @@
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 @@
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 @@
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 "