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 |