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 |