View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0004465 | The Dark Mod | Tweaking | public | 15.01.2017 23:24 | 08.12.2022 15:55 |
| Reporter | Hamlet | Assigned To | |||
| Priority | low | Severity | minor | Reproducibility | always |
| Status | resolved | Resolution | fixed | ||
| Platform | Intel i7 | OS | Gentoo Linux (GCC 6.3.0) | OS Version | Kernel: 4.8.13 |
| Product Version | SVN | ||||
| Fixed in Version | TDM 2.08 | ||||
| Summary | 0004465: Profiling timer gives bogus times | ||||
| Description | The times returned by idTimer are bogus. I am not aware of any consequence on gameplay. This is, as far as I can tell, a Linux-specific problem on multicore platforms. In short, the clock ticks returned by Sys_GetClockTicks() (sys/linux/main.cpp) are not steady. The code goes assembly and tries to ReaD the TimeStamp Counter (RDTSC instruction). As far as I can tell, there is one such a counter for each code (or hyper-thread?), and Linux likes to move threads from a core to another. Since each core has its own timestamp count, which depends on power saving policies and whatnot, the counters are inconsistent between cores. The usage of idTimer implies a call to a "Start()" method and then a "Stop()" method. If the O.S. has in the meanwhile relocated the thread, the two tick counts will be unrelated and their difference, which idTimer returns as elapsed time, will be bogus. | ||||
| Steps To Reproduce | 1. Start TDM 2. parse the console log (e.g. for keyword "Compiled") 3. notice how the number of milliseconds is nonsense. An example of what I read while loading the training mission (the correct value is around 30 milliseconds): Initializing scripts /proc/cpuinfo CPU frequency: 3400 MHz Compiled 'tdm_ai_lanternbot::startAlarmWhistle': 450601688549.4 ms ---------- Compile stats ---------- | ||||
| Additional Information | I propose a patch for your evaluation. It might need adaptation since my branch has quite some customisation. It uses a POSIX standard system call to interrogate the system clock. I choose a system clock that is Linux-specific and requires at least Linux 2.6.12 ("CLOCK_THREAD_CPUTIME_ID"), which is ancient (2005); but less restrictive one can be used instead. (in fact, I have just noticed that the problem reported here is also described in the page of the manual on clock_gettime: `man 2 clock_gettime`). This patch still allows to restore the old implementation by defining the preprocessor symbol USE_RDTSC . | ||||
| Tags | No tags attached. | ||||
| Attached Files | RDTSC_for_clock.patch (2,687 bytes)
commit 34cd5bd02930630a98b6a71abe11c2b105f24e05
Author: Hamlet <_hamlet@libero.it>
Date: Sun Jan 15 16:41:42 2017 -0600
Don't use timestamp counter as timer.
Linux-specific: the old implementation using CPU timestamp counters to
estimate the time elapsed is incompatible with multi-core systems.
diff --git a/sys/linux/main.cpp b/sys/linux/main.cpp
index dbb72d5d5..cfe9da78a 100644
--- a/sys/linux/main.cpp
+++ b/sys/linux/main.cpp
@@ -16,6 +16,17 @@
$Author$ (Author of last commit)
******************************************************************************/
+
+// define DO_USE_RDTSC only if we want AND we can use the timestamp counter
+#if (USE_RDTSC) and defined( __i386__ )
+# define DO_USE_RDTSC 1
+#else
+# define DO_USE_RDTSC 0
+// # define LINUX_CLOCK CLOCK_REALTIME // which clock to use for timing
+// CLOCK_THREAD_CPUTIME_ID is Linux-specific (2.6.12+); see `man 2 clock_gettime`
+# define LINUX_CLOCK CLOCK_THREAD_CPUTIME_ID // which clock to use for timing
+#endif
+
#include "../../idlib/precompiled.h"
#include "../posix/posix_public.h"
#include "../sys_local.h"
@@ -27,6 +38,8 @@
#include <sys/stat.h>
#include <sys/types.h>
#include <fcntl.h>
+#include <cstring> // strerror()
+#include <ctime> // clock_gettime()
#ifdef ID_MCHECK
#include <mcheck.h>
@@ -285,7 +298,13 @@ Sys_GetClockticks
===============
*/
double Sys_GetClockTicks( void ) {
-#if defined( __i386__ )
+#if (DO_USE_RDTSC)
+ // it appears like every core has its own timestamp counter,
+ // and they (may?) count different cycles;
+ // so if the thread jumps from one core to another between the
+ // "start = Sys_GetClockTicks();" and the "end = Sys_GetClockTicks();",
+ // the "stop - start" number is nonsense.
+ // Even `MeasureClockTicks()` might be affected.
unsigned long lo, hi;
__asm__ __volatile__ (
@@ -298,8 +317,12 @@ double Sys_GetClockTicks( void ) {
"pop %%ebx\n"
: "=r" (lo), "=r" (hi) );
return (double) lo + (double) 0xFFFFFFFF * hi;
-#else
-#error unsupported CPU
+#else // do not use the timestamp counter
+ // this is poors' magic inspired from GNU implementation of the standard
+ // library std::chrono::system_clock::now():
+ timespec timePoint;
+ clock_gettime(LINUX_CLOCK, &timePoint);
+ return ((double) timePoint.tv_sec) * 1e9 + (double) timePoint.tv_nsec;
#endif
}
@@ -309,12 +332,16 @@ MeasureClockTicks
===============
*/
double MeasureClockTicks( void ) {
+#if (DO_USE_RDTSC)
double t0, t1;
t0 = Sys_GetClockTicks( );
Sys_Sleep( 1000 );
t1 = Sys_GetClockTicks( );
return t1 - t0;
+#else
+ return 1e9; // the value returned by Sys_GetClockTicks() is nanoseconds
+#endif
}
/*
| ||||
|
A different fix should have addressed this in 2.08 https://github.com/stgatilov/darkmod_src/commit/3d5b0cb45501e2c7b2c3d943e3d05ce87d25e3b9 |
|
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 15.01.2017 23:24 | Hamlet | New Issue | |
| 15.01.2017 23:24 | Hamlet | File Added: RDTSC_for_clock.patch | |
| 08.12.2022 15:44 | nbohr1more | Relationship added | child of 0005324 |
| 08.12.2022 15:54 | nbohr1more | Note Added: 0015525 | |
| 08.12.2022 15:55 | nbohr1more | Status | new => resolved |
| 08.12.2022 15:55 | nbohr1more | Resolution | open => fixed |
| 08.12.2022 15:55 | nbohr1more | Fixed in Version | => TDM 2.08 |