FS-3782 --resolve soft timer

diff --git a/src/include/private/switch_core_pvt.h b/src/include/private/switch_core_pvt.h
index ff0a6189b907c90eaa68ed52cc07c102276358e2..68376c273c937e263bcaa1c4cb73b912c688f6fc 100644 (file)
--- a/src/include/private/switch_core_pvt.h
+++ b/src/include/private/switch_core_pvt.h
@@ -260,6 +260,7 @@ struct switch_runtime {
        uint32_t max_db_handles;
        uint32_t db_handle_timeout;
        int cpu_count;
+       uint32_t time_sync;
 };
 
 extern struct switch_runtime runtime;

diff --git a/src/mod/applications/mod_commands/mod_commands.c b/src/mod/applications/mod_commands/mod_commands.c
index 41db0f191b38d3ff24723eb6b3d33d4591e3c74b..3e34f0a80d03e7e7188a58d9985795b789b6d23e 100644 (file)
--- a/src/mod/applications/mod_commands/mod_commands.c
+++ b/src/mod/applications/mod_commands/mod_commands.c
@@ -546,24 +546,19 @@ SWITCH_STANDARD_API(timer_test_function)
                goto end;
        }
 
-       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Timer Test: samplecount after init: %d\n", timer.samplecount);
+       switch_core_timer_next(&timer); /* Step timer once before testing results below, to get first timestamp as accurate as possible */
 
-       /* Step timer once before testing results below, to get first timestamp as accurate as possible */
-       switch_core_timer_next(&timer);
+       start = then = switch_time_ref();
 
-       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Timer Test: samplecount after first step: %d\n", timer.samplecount);
-
-       start = switch_time_ref();
        for (x = 1; x <= max; x++) {
-               then = switch_time_ref();
                switch_core_timer_next(&timer);
                now = switch_time_ref();
                diff = (int) (now - then);
-               //stream->write_function(stream, "test %d sleep %ld %d\n", x, mss, diff);
-               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Timer Test: %d sleep %d %d\n", x, mss, diff);
                total += diff;
+               then = now;
+               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Timer Test: %d sleep %d %d\n", x, mss, diff);
        }
-       end = switch_time_ref();
+       end = then;
 
        switch_yield(250000);
 

diff --git a/src/switch_time.c b/src/switch_time.c
index 2f111efa26bdbe6677328c7fc60df106e81dbefe..7199edf9cc3e457698db2cc4d2cac4321ee7da2e 100644 (file)
--- a/src/switch_time.c
+++ b/src/switch_time.c
@@ -59,9 +59,10 @@
 #define MAX_ELEMENTS 3600
 #define IDLE_SPEED 100
 
-/* In Windows, enable the montonic timer for better timer accuracy on Windows 2003 Server, XP and older */
-/* GetSystemTimeAsFileTime does not update on timeBeginPeriod on these OS. */
-/* Flag SCF_USE_WIN32_MONOTONIC must be enabled to activate it (start parameter -monotonic-clock) */
+/* In Windows, enable the montonic timer for better timer accuracy,
+ * GetSystemTimeAsFileTime does not update on timeBeginPeriod on these OS.
+ * Flag SCF_USE_WIN32_MONOTONIC must be enabled to activate it (start parameter -monotonic-clock).
+ */
 
 #if defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_MONOTONIC)
 static int MONO = 1;
@@ -91,9 +92,12 @@ static int COND = 1;
 static int MATRIX = 1;
 
 #ifdef WIN32
+static CRITICAL_SECTION timer_section;
 static switch_time_t win32_tick_time_since_start = -1;
 static DWORD win32_last_get_time_tick = 0;
-CRITICAL_SECTION  timer_section;
+
+static uint8_t win32_use_qpc = 0;
+static uint64_t win32_qpc_freq = 0;
 #endif
 
 static switch_memory_pool_t *module_pool = NULL;
@@ -321,7 +325,7 @@ SWITCH_DECLARE(time_t) switch_epoch_time_now(time_t *t)
 
 SWITCH_DECLARE(void) switch_time_set_monotonic(switch_bool_t enable)
 {
-#if defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_MONOTONIC)
+#if (defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_MONOTONIC)) || defined(WIN32)
        MONO = enable ? 1 : 0;
        switch_time_sync();
 #else
@@ -375,24 +379,32 @@ static switch_time_t time_now(int64_t offset)
                clock_gettime(CLOCK_MONOTONIC, &ts);
                now = ts.tv_sec * APR_USEC_PER_SEC + (ts.tv_nsec / 1000) + offset;
 #else
-               DWORD tick_now;
-               DWORD tick_diff;
-
-               tick_now = timeGetTime();
-               if (win32_tick_time_since_start != -1) {
-                       EnterCriticalSection(&timer_section);
-                       /* just add diff (to make it work more than 50 days). */
-                       tick_diff = tick_now - win32_last_get_time_tick;
-                       win32_tick_time_since_start += tick_diff;
-
-                       win32_last_get_time_tick = tick_now;
-                       now = (win32_tick_time_since_start * 1000) + offset;
-                       LeaveCriticalSection(&timer_section);
+               if (win32_use_qpc) {
+                       /* Use QueryPerformanceCounter */
+                       uint64_t count = 0;
+                       QueryPerformanceCounter((LARGE_INTEGER*)&count);
+                       now = ((count * 1000000) / win32_qpc_freq) + offset;
                } else {
-                       /* If someone is calling us before timer is initialized,
-                        * return the current tick + offset
-                        */
-                       now = (tick_now * 1000) + offset;
+                       /* Use good old timeGetTime() */
+                       DWORD tick_now;
+                       DWORD tick_diff;
+
+                       tick_now = timeGetTime();
+                       if (win32_tick_time_since_start != -1) {
+                               EnterCriticalSection(&timer_section);
+                               /* just add diff (to make it work more than 50 days). */
+                               tick_diff = tick_now - win32_last_get_time_tick;
+                               win32_tick_time_since_start += tick_diff;
+
+                               win32_last_get_time_tick = tick_now;
+                               now = (win32_tick_time_since_start * 1000) + offset;
+                               LeaveCriticalSection(&timer_section);
+                       } else {
+                               /* If someone is calling us before timer is initialized,
+                                * return the current tick + offset
+                                */
+                               now = (tick_now * 1000) + offset;
+                       }
                }
 #endif
        } else {
@@ -415,6 +427,8 @@ static switch_time_t last_time = 0;
 
 SWITCH_DECLARE(void) switch_time_sync(void)
 {
+       runtime.time_sync++; /* Indicate that we are syncing time right now */
+
        runtime.reference = switch_time_now();
 
        runtime.offset = runtime.reference - time_now(0);
@@ -423,6 +437,8 @@ SWITCH_DECLARE(void) switch_time_sync(void)
                switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_INFO, "Clock synchronized to system time.\n");
        }
        last_time = runtime.reference;
+
+       runtime.time_sync++; /* Indicate that we are finished syncing time */
 }
 
 SWITCH_DECLARE(void) switch_micro_sleep(switch_interval_time_t t)
@@ -546,6 +562,7 @@ static switch_status_t timer_init(switch_timer_t *timer)
 #define check_roll() if (private_info->roll < TIMER_MATRIX[timer->interval].roll) {    \
                private_info->roll++;                                                                                   \
                private_info->reference = private_info->start = TIMER_MATRIX[timer->interval].tick;     \
+               private_info->start--; /* Must have a diff */                                   \
        }                                                                                                                                       \
 
 
@@ -562,7 +579,7 @@ static switch_status_t timer_step(switch_timer_t *timer)
        samples = timer->samples * (private_info->reference - private_info->start);
 
        if (samples > UINT32_MAX) {
-               private_info->start = private_info->reference;
+               private_info->start = private_info->reference - 1; /* Must have a diff */
                samples = timer->samples;
        }
 
@@ -691,6 +708,55 @@ static switch_status_t timer_destroy(switch_timer_t *timer)
        return SWITCH_STATUS_SUCCESS;
 }
 
+static void win32_init_timers(void)
+{
+#ifdef WIN32
+       OSVERSIONINFOEX version_info; /* Used to fetch current OS version from Windows */
+
+       EnterCriticalSection(&timer_section);
+
+       ZeroMemory(&version_info, sizeof(OSVERSIONINFOEX));
+       version_info.dwOSVersionInfoSize = sizeof(OSVERSIONINFOEX);
+
+       /* Check if we should use timeGetTime() (pre-Vista) or QueryPerformanceCounter() (Vista and later) */
+
+       if (GetVersionEx((OSVERSIONINFO*) &version_info)) {
+               if (version_info.dwPlatformId == VER_PLATFORM_WIN32_NT && version_info.dwMajorVersion >= 6) {
+                       if (QueryPerformanceFrequency((LARGE_INTEGER*)&win32_qpc_freq) && win32_qpc_freq > 0) {
+                               /* At least Vista, and QueryPerformanceFrequency() suceeded, enable qpc */
+                               win32_use_qpc = 1;
+                       } else {
+                               /* At least Vista, but QueryPerformanceFrequency() failed, disable qpc */
+                               win32_use_qpc = 0;
+                       }
+               } else {
+                       /* Older then Vista, disable qpc */
+                       win32_use_qpc = 0;
+               }
+       } else {
+               /* Unknown version - we want at least Vista, disable qpc */
+               win32_use_qpc = 0;
+       }
+
+       if (win32_use_qpc) {
+               uint64_t count = 0;
+
+               if (!QueryPerformanceCounter((LARGE_INTEGER*)&count) || count == 0) {
+                       /* Call to QueryPerformanceCounter() failed, disable qpc again */
+                       win32_use_qpc = 0;
+               }
+       }
+
+       if (!win32_use_qpc) {
+               /* This will enable timeGetTime() instead, qpc init failed */
+               win32_last_get_time_tick = timeGetTime();
+               win32_tick_time_since_start = win32_last_get_time_tick;
+       }
+
+       LeaveCriticalSection(&timer_section);
+#endif
+}
+
 SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
 {
        switch_time_t too_late = runtime.microseconds_per_tick * 1000;
@@ -700,6 +766,7 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
        int fwd_errs = 0, rev_errs = 0;
        int profile_tick = 0;
        int tfd = -1;
+       uint32_t time_sync = runtime.time_sync;
 
 #ifdef HAVE_TIMERFD_CREATE
        int last_MICROSECONDS_PER_TICK = runtime.microseconds_per_tick;
@@ -738,6 +805,7 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
 #endif
 
        switch_time_sync();
+       time_sync = runtime.time_sync;
 
        globals.STARTED = globals.RUNNING = 1;
        switch_mutex_lock(runtime.throttle_mutex);
@@ -775,6 +843,7 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
 
 
        switch_time_sync();
+       time_sync = runtime.time_sync;
 
        globals.use_cond_yield = COND;
        globals.RUNNING = 1;
@@ -795,8 +864,12 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
                while (((ts = time_now(runtime.offset)) + 100) < runtime.reference) {
                        if (ts < last) {
                                if (MONO) {
-                                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Virtual Migration Detected! Syncing Clock\n");
-                                       switch_time_sync();
+                                       if (time_sync == runtime.time_sync) { /* Only resync if not in the middle of switch_time_sync() already */
+                                               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Virtual Migration Detected! Syncing Clock\n");
+                                               win32_init_timers(); /* Make sure to reinit timers on WIN32 */
+                                               switch_time_sync();
+                                               time_sync = runtime.time_sync;
+                                       }
                                } else {
                                        int64_t diff = (int64_t) (ts - last);
                                        switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Reverse Clock Skew Detected!\n");
@@ -807,9 +880,10 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
                                        rev_errs++;
                                }
 
-                               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, 
-                                                                 "If you see this message many times try setting the param enable-clock-nanosleep to true in switch.conf.xml or consider a nicer machine to run me on. I AM *FREE* afterall.\n");
-
+                               if (!MONO || time_sync == runtime.time_sync) {
+                                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT,
+                                                                         "If you see this message many times try setting the param enable-clock-nanosleep to true in switch.conf.xml or consider a nicer machine to run me on. I AM *FREE* afterall.\n");
+                               }
                        } else {
                                rev_errs = 0;
                        }
@@ -823,7 +897,19 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
                                        r = read(tfd, &exp, sizeof(exp));
                                        r++;
                                } else {
-                                       do_sleep(runtime.microseconds_per_tick);
+                                       switch_time_t timediff = runtime.reference - ts;
+
+                                       if (runtime.microseconds_per_tick < timediff) {
+                                               /* Only sleep for runtime.microseconds_per_tick if this value is lower then the actual time diff we need to sleep */
+                                               do_sleep(runtime.microseconds_per_tick);
+                                       } else {
+#ifdef WIN32
+                                               /* Windows only sleeps in ms precision, try to round the usec value as good as possible */
+                                               do_sleep((switch_interval_time_t)floor((timediff / 1000.0) + 0.5) * 1000);
+#else
+                                               do_sleep(timediff);
+#endif
+                                       }
                                }
                        }
 
@@ -832,13 +918,15 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
 
                if (ts > (runtime.reference + too_late)) {
                        if (MONO) {
-                               switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Virtual Migration Detected! Syncing Clock\n");
-                               switch_time_sync();
+                               if (time_sync == runtime.time_sync) { /* Only resync if not in the middle of switch_time_sync() already */
+                                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Virtual Migration Detected! Syncing Clock\n");
+                                       win32_init_timers(); /* Make sure to reinit timers on WIN32 */
+                                       switch_time_sync();
+                                       time_sync = runtime.time_sync;
+                               }
                        } else {
                                switch_time_t diff = ts - runtime.reference - runtime.microseconds_per_tick;
-#ifndef WIN32
                                switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Forward Clock Skew Detected!\n");
-#endif
                                fwd_errs++;
                                runtime.reference = switch_time_now();
                                current_ms = 0;
@@ -852,6 +940,7 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
                if (fwd_errs > 9 || rev_errs > 9) {
                        switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Auto Re-Syncing clock.\n");
                        switch_time_sync();
+                       time_sync = runtime.time_sync;
                        fwd_errs = rev_errs = 0;
                }
 
@@ -859,6 +948,10 @@ SWITCH_MODULE_RUNTIME_FUNCTION(softtimer_runtime)
                current_ms += (runtime.microseconds_per_tick / 1000);
                tick += (runtime.microseconds_per_tick / 1000);
 
+               if (time_sync < runtime.time_sync) {
+                       time_sync++; /* Only step once for each loop, we want to make sure to keep this thread safe */
+               }
+
                if (tick >= (1000000 / runtime.microseconds_per_tick)) {
                        if (++profile_tick == 1) {
                                switch_get_system_idle_time(runtime.profile_timer, &runtime.profile_time);
@@ -1117,11 +1210,12 @@ SWITCH_MODULE_LOAD_FUNCTION(softtimer_load)
        switch_timer_interface_t *timer_interface;
        module_pool = pool;
 
-#if defined(WIN32)
+#ifdef WIN32
        timeBeginPeriod(1);
+
        InitializeCriticalSection(&timer_section);
-       win32_last_get_time_tick = timeGetTime();
-       win32_tick_time_since_start = win32_last_get_time_tick;
+
+       win32_init_timers(); /* Init timers for Windows, if we should use timeGetTime() or QueryPerformanceCounters() */
 #endif
 
        memset(&globals, 0, sizeof(globals));
@@ -1155,6 +1249,21 @@ SWITCH_MODULE_LOAD_FUNCTION(softtimer_load)
                switch_clear_flag((&runtime), SCF_CALIBRATE_CLOCK);
        }
 
+#ifdef WIN32
+       if (switch_test_flag((&runtime), SCF_USE_WIN32_MONOTONIC)) {
+               MONO = 1;
+
+               if (win32_use_qpc) {
+                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_NOTICE, "Enabled Windows monotonic clock, using QueryPerformanceCounter()\n");
+               } else {
+                       switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_NOTICE, "Enabled Windows monotonic clock, using timeGetTime()\n");
+               }
+       }
+
+       /* No need to calibrate clock in Win32, we will only sleep ms anyway, it's just not accurate enough */
+       switch_clear_flag((&runtime), SCF_CALIBRATE_CLOCK);
+#endif
+
        if (switch_test_flag((&runtime), SCF_CALIBRATE_CLOCK)) {
                switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Calibrating timer, please wait...\n");
                switch_time_calibrate_clock();
@@ -1162,10 +1271,6 @@ SWITCH_MODULE_LOAD_FUNCTION(softtimer_load)
                switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "Clock calibration disabled.\n");
        }
 
-       if (switch_test_flag((&runtime), SCF_USE_WIN32_MONOTONIC)) {
-               MONO = 1;
-       }
-
        /* indicate that the module should continue to be loaded */
        return SWITCH_STATUS_SUCCESS;
 }