View Issue Details

IDProjectCategoryView StatusLast Update
0004465The Dark ModTweakingpublic08.12.2022 15:55
ReporterHamlet Assigned To 
PrioritylowSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
PlatformIntel i7OSGentoo Linux (GCC 6.3.0)OS VersionKernel: 4.8.13
Product VersionSVN 
Fixed in VersionTDM 2.08 
Summary0004465: Profiling timer gives bogus times
DescriptionThe 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 Reproduce1. 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 InformationI 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 .
TagsNo tags attached.

Relationships

child of 0005324 resolvedstgatilov Refactor times and clocks 

Activities

Hamlet

Hamlet

15.01.2017 23:24

reporter  

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
 }
 
 /*
RDTSC_for_clock.patch (2,687 bytes)   
nbohr1more

nbohr1more

08.12.2022 15:54

developer   ~0015525

A different fix should have addressed this in 2.08

https://github.com/stgatilov/darkmod_src/commit/3d5b0cb45501e2c7b2c3d943e3d05ce87d25e3b9

Issue History

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