RE: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF
From: Doug Smythies
Date: Sat Jan 18 2025 - 19:09:13 EST
Hi Peter,
An update.
On 2025.01.14 02:59 Peter Zijlstra wrote:
> On Mon, Jan 13, 2025 at 12:03:12PM +0100, Peter Zijlstra wrote:
>> On Sun, Jan 12, 2025 at 03:14:17PM -0800, Doug Smythies wrote:
>>> means that there were 19 occurrences of turbostat interval times
>>> between 1.016 and 1.016999 seconds.
>>
>> OK, let me lower my threshold to 10ms and change the turbostat
>> invocation -- see if I can catch me some wabbits :-)
>
> I've had it run overnight and have not caught a single >10ms event :-(
Okay, so both you and I have many many hours of testing and
never see >= 10ms in that area of the turbostat code anymore.
The lingering >= 10ms (but I have never seen more than 25 ms)
is outside of that timing. As previously reported, I thought it might
be in the sampling interval sleep step, but I did a bunch of testing
and it doesn't appear to be there. That leaves:
delta_platform(&platform_counters_even, &platform_counters_odd);
compute_average(ODD_COUNTERS);
format_all_counters(ODD_COUNTERS);
flush_output_stdout();
I modified your tracing trigger thing in turbostat to this:
doug@s19:~/kernel/linux/tools/power/x86/turbostat$ git diff turbostat.c
diff --git a/tools/power/x86/turbostat/turbostat.c b/tools/power/x86/turbostat/turbostat.c
index 58a487c225a7..777efb64a754 100644
--- a/tools/power/x86/turbostat/turbostat.c
+++ b/tools/power/x86/turbostat/turbostat.c
@@ -67,6 +67,7 @@
#include <stdbool.h>
#include <assert.h>
#include <linux/kernel.h>
+#include <sys/syscall.h>
#define UNUSED(x) (void)(x)
@@ -2704,7 +2705,7 @@ int format_counters(struct thread_data *t, struct core_data *c, struct pkg_data
struct timeval tv;
timersub(&t->tv_end, &t->tv_begin, &tv);
- outp += sprintf(outp, "%5ld\t", tv.tv_sec * 1000000 + tv.tv_usec);
+ outp += sprintf(outp, "%7ld\t", tv.tv_sec * 1000000 + tv.tv_usec);
}
/* Time_Of_Day_Seconds: on each row, print sec.usec last timestamp taken */
@@ -2713,6 +2714,11 @@ int format_counters(struct thread_data *t, struct core_data *c, struct pkg_data
interval_float = t->tv_delta.tv_sec + t->tv_delta.tv_usec / 1000000.0;
+ double requested_interval = (double) interval_tv.tv_sec + (double) interval_tv.tv_usec / 1000000.0;
+
+ if(interval_float >= (requested_interval + 0.01)) /* was the last interval over by more than 10 mSec? */
+ syscall(__NR_gettimeofday, &tv_delta, (void*)1);
+
tsc = t->tsc * tsc_tweak;
/* topo columns, print blanks on 1st (average) line */
@@ -4570,12 +4576,14 @@ int get_counters(struct thread_data *t, struct core_data *c, struct pkg_data *p)
int i;
int status;
+ gettimeofday(&t->tv_begin, (struct timezone *)NULL); /* doug test */
+
if (cpu_migrate(cpu)) {
fprintf(outf, "%s: Could not migrate to CPU %d\n", __func__, cpu);
return -1;
}
- gettimeofday(&t->tv_begin, (struct timezone *)NULL);
+// gettimeofday(&t->tv_begin, (struct timezone *)NULL);
if (first_counter_read)
get_apic_id(t);
And so that I could prove a correlation with the trace times
and to my graph times I also did not turn off tracing upon a hit:
doug@s19:~/kernel/linux$ git diff kernel/time/time.c
diff --git a/kernel/time/time.c b/kernel/time/time.c
index 1b69caa87480..fb84915159cc 100644
--- a/kernel/time/time.c
+++ b/kernel/time/time.c
@@ -149,6 +149,12 @@ SYSCALL_DEFINE2(gettimeofday, struct __kernel_old_timeval __user *, tv,
return -EFAULT;
}
if (unlikely(tz != NULL)) {
+ if (tz == (void*)1) {
+ trace_printk("WHOOPSIE!\n");
+// tracing_off();
+ return 0;
+ }
+
if (copy_to_user(tz, &sys_tz, sizeof(sys_tz)))
return -EFAULT;
}
I ran a test for about 1 hour and 28 minutes.
The data in the trace correlates with turbostat line by line
TOD differentials. Trace got:
turbostat-1370 [011] ..... 751.738151: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 760.763184: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1362.788298: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1365.815332: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1366.836340: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1367.856355: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1368.867365: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1373.893423: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1374.910439: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1377.928469: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1378.941483: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1379.959490: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1382.982525: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1385.005548: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1386.019561: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1387.030572: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1398.097683: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1620.752963: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1621.772969: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1622.788972: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1697.022098: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1703.071104: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1704.088103: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1705.105107: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1706.116106: __x64_sys_gettimeofday: WHOOPSIE!
turbostat-1370 [011] ..... 1707.126107: __x64_sys_gettimeofday: WHOOPSIE!
Going back to some old test data from when the CPU migration in turbostat
often took up to 6 seconds. If I subtract that migration time from the measured
interval time, I get a lot of samples between 10 and 23 ms.
I am saying there were 2 different issues. The 2nd was hidden by the 1st
because its magnitude was about 260 times less.
I do not know if my trace is any use. I'll compress it and send it to you only, off list.
My trace is as per this older email:
https://lore.kernel.org/all/20240727105030.226163742@xxxxxxxxxxxxx/T/#m453062b267551ff4786d33a2eb5f326f92241e96