Re: [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN

[Zhao Liu]

Hi Stefan,

> QEMU uses clock_gettime(CLOCK_MONOTONIC) on Linux hosts. The man page
> says:
> 
>   All CLOCK_MONOTONIC variants guarantee that the time returned by
>   consecutive  calls  will  not go backwards, but successive calls
>   may—depending  on  the  architecture—return  identical  (not-in‐
>   creased) time values.
> 
> trace_record_start() calls clock_gettime(CLOCK_MONOTONIC) so trace events
> should have monotonically increasing timestamps.
> 
> I don't see a scenario where trace record A's timestamp is greater than
> trace record B's timestamp unless the clock is non-monotonic.
> 
> Which host CPU architecture and operating system are you running?

I tested on these 2 machines:
* CML (intel 10th) with Ubuntu 22.04 + kernel v6.5.0-28
* MTL (intel 14th) with Ubuntu 22.04.2 + kernel v6.9.0

> Please attach to the QEMU process with gdb and print out the value of
> the use_rt_clock variable or add a printf in init_get_clock(). The value
> should be 1.

Thanks, on both above machines, use_rt_clock is 1 and there're both
timestamp reversal issues with the following debug print:

diff --git a/include/qemu/timer.h b/include/qemu/timer.h
index 9a366e551fb3..7657785c27dc 100644
--- a/include/qemu/timer.h
+++ b/include/qemu/timer.h
@@ -831,10 +831,17 @@ extern int use_rt_clock;

 static inline int64_t get_clock(void)
 {
+    static int64_t clock = 0;
     if (use_rt_clock) {
         struct timespec ts;
         clock_gettime(CLOCK_MONOTONIC, &ts);
-        return ts.tv_sec * 1000000000LL + ts.tv_nsec;
+        int64_t tmp = ts.tv_sec * 1000000000LL + ts.tv_nsec;
+        if (tmp <= clock) {
+            printf("get_clock: strange, clock: %ld, tmp: %ld\n", clock, tmp);
+        }
+        assert(tmp > clock);
+        clock = tmp;
+        return clock;
     } else {
         /* XXX: using gettimeofday leads to problems if the date
            changes, so it should be avoided. */
diff --git a/util/qemu-timer-common.c b/util/qemu-timer-common.c
index cc1326f72646..3bf06eb4a4ce 100644
--- a/util/qemu-timer-common.c
+++ b/util/qemu-timer-common.c
@@ -59,5 +59,6 @@ static void __attribute__((constructor)) init_get_clock(void)
         use_rt_clock = 1;
     }
     clock_start = get_clock();
+    printf("init_get_clock: use_rt_clock: %d\n", use_rt_clock);
 }
 #endif

---
The timestamp interval is very small, for example:
get_clock: strange, clock: 3302130503505, tmp: 3302130503503

or

get_clock: strange, clock: 2761577819846455, tmp: 2761577819846395

I also tried to use CLOCK_MONOTONIC_RAW, but there's still the reversal
issue.

Thanks,
Zhao