Complete EEVDF

Hi Peter,

I have been having trouble with turbostat reporting processor package power levels that can not possibly be true. After eliminating the turbostat program itself as the source of the issue I bisected the kernel. An edited summary (actual log attached):

82e9d0456e06 sched/fair: Avoid re-setting virtual deadline on 'migrations'
b10 bad fc1892becd56 sched/eevdf: Fixup PELT vs DELAYED_DEQUEUE
b13 bad 54a58a787791 sched/fair: Implement DELAY_ZERO
skip 152e11f6df29 sched/fair: Implement delayed dequeue
skip e1459a50ba31 sched: Teach dequeue_task() about special task states
skip a1c446611e31 sched,freezer: Mark TASK_FROZEN special
skip 781773e3b680 sched/fair: Implement ENQUEUE_DELAYED
skip f12e148892ed sched/fair: Prepare pick_next_task() for delayed dequeue
skip 2e0199df252a sched/fair: Prepare exit/cleanup paths for delayed_dequeue
b12 good e28b5f8bda01 sched/fair: Assert {set_next,put_prev}_entity() are properly balanced
dfa0a574cbc4 sched/uclamg: Handle delayed dequeue
b11 good abc158c82ae5 sched: Prepare generic code for delayed dequeue
e8901061ca0c sched: Split DEQUEUE_SLEEP from deactivate_task()

Where "bN" is just my assigned kernel name for each bisection step.

In the linux-kernel email archives I found a thread that isolated these same commits. It was from late Novermebr / early December:

https://lore.kernel.org/all/[email protected]/T/#m9aeb4d897e029cf7546513bb09499c320457c174

An example of the turbostat manifestation of the issue:

doug@s19:~$ sudo ~/kernel/linux/tools/power/x86/turbostat/turbostat --quiet --Summary --show
Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1
[sudo] password for doug:
Busy%   Bzy_MHz TSC_MHz IRQ     PkgTmp  PkgWatt
99.76   4800    4104    12304   73      80.08
99.76   4800    4104    12047   73      80.23
99.76   4800    879     12157   73      11.40
99.76   4800    26667   84214   72      557.23
99.76   4800    4104    12036   72      79.39

Where TSC_MHz was reported as 879, there was a big gap in time. Like 4.7 seconds instead of 1.
Where TSC_MHz was reported as 26667, there was not a big gap in time.

It happens for about 5% of the samples + or - a lot. It only happens when the workload is almost exactly 100%. More load, it doesn't occur.
Less load, it doesn't occur. Although, I did get this once:

Busy%   Bzy_MHz TSC_MHz IRQ     PkgTmp  PkgWatt
91.46   4800    4104    11348   73      103.98
91.46   4800    4104    11353   73      103.89
91.50   4800    3903    11339   73      98.16
91.43   4800    4271    12001   73      108.52
91.45   4800    4148    11481   73      105.13
91.46   4800    4104    11341   73      103.96
91.46   4800    4104    11348   73      103.99

So, it might just be much less probable and less severe.

It happens over many different types of workload that I have tried.

Quoted 59 lines · Doug Smythies

Hi Peter,

I have been having trouble with turbostat reporting processor package power levels that can not possibly be true. After eliminating the turbostat program itself as the source of the issue I bisected the kernel. An edited summary (actual log attached):

82e9d0456e06 sched/fair: Avoid re-setting virtual deadline on 'migrations'
b10 bad fc1892becd56 sched/eevdf: Fixup PELT vs DELAYED_DEQUEUE
b13 bad 54a58a787791 sched/fair: Implement DELAY_ZERO
skip 152e11f6df29 sched/fair: Implement delayed dequeue
skip e1459a50ba31 sched: Teach dequeue_task() about special task states
skip a1c446611e31 sched,freezer: Mark TASK_FROZEN special
skip 781773e3b680 sched/fair: Implement ENQUEUE_DELAYED
skip f12e148892ed sched/fair: Prepare pick_next_task() for delayed dequeue
skip 2e0199df252a sched/fair: Prepare exit/cleanup paths for delayed_dequeue
b12 good e28b5f8bda01 sched/fair: Assert {set_next,put_prev}_entity() are properly balanced
dfa0a574cbc4 sched/uclamg: Handle delayed dequeue
b11 good abc158c82ae5 sched: Prepare generic code for delayed dequeue
e8901061ca0c sched: Split DEQUEUE_SLEEP from deactivate_task()

Where "bN" is just my assigned kernel name for each bisection step.

In the linux-kernel email archives I found a thread that isolated these same commits. It was from late Novermebr / early December:

https://lore.kernel.org/all/[email protected]/T/#m9aeb4d897e029cf7546513bb09499c320457c174

An example of the turbostat manifestation of the issue:

doug@s19:~$ sudo ~/kernel/linux/tools/power/x86/turbostat/turbostat --quiet --Summary --show
Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1
[sudo] password for doug:
Busy%   Bzy_MHz TSC_MHz IRQ     PkgTmp  PkgWatt
99.76   4800    4104    12304   73      80.08
99.76   4800    4104    12047   73      80.23
99.76   4800    879     12157   73      11.40
99.76   4800    26667   84214   72      557.23
99.76   4800    4104    12036   72      79.39

Where TSC_MHz was reported as 879, there was a big gap in time. Like 4.7 seconds instead of 1.
Where TSC_MHz was reported as 26667, there was not a big gap in time.

It happens for about 5% of the samples + or - a lot. It only happens when the workload is almost exactly 100%. More load, it doesn't occur.
Less load, it doesn't occur. Although, I did get this once:

Busy%   Bzy_MHz TSC_MHz IRQ     PkgTmp  PkgWatt
91.46   4800    4104    11348   73      103.98
91.46   4800    4104    11353   73      103.89
91.50   4800    3903    11339   73      98.16
91.43   4800    4271    12001   73      108.52
91.45   4800    4148    11481   73      105.13
91.46   4800    4104    11341   73      103.96
91.46   4800    4104    11348   73      103.99

So, it might just be much less probable and less severe.

Quoted 1 line

It happens over many different types of workload that I have tried.

In private email you've communicated it happens due to sched_setaffinity() sometimes taking multiple seconds.

I'm trying to reproduce by starting a bash 'while ;: do :; done' spinner for each CPU, but so far am not able to reproduce.

What is the easiest 100% load you're seeing this with?

Quoted 1 line

What is the easiest 100% load you're seeing this with?

Lately, and specifically to be able to tell others, I have been using:

yes > /dev/null &

On my Intel i5-10600K, with 6 cores and 2 threads per core, 12 CPUs, I run 12 of those work loads.

Quoted 8 lines · Doug Smythies

Quoted 1 line

What is the easiest 100% load you're seeing this with?

Lately, and specifically to be able to tell others, I have been using:

yes > /dev/null &

On my Intel i5-10600K, with 6 cores and 2 threads per core, 12 CPUs, I run 12 of those work loads.

On my headless ivb-ep 2 sockets, 10 cores each and 2 threads per core, I do:

for ((i=0; i<40; i++)) ; do yes > /dev/null & done
tools/power/x86/turbostat/turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1

But no so far, nada :-( I've tried with full preemption and voluntary, HZ=1000.

Quoted 11 lines · Peter Zijlstra

Quoted 8 lines · Doug Smythies

Quoted 1 line

What is the easiest 100% load you're seeing this with?

Lately, and specifically to be able to tell others, I have been using:

yes > /dev/null &

On my Intel i5-10600K, with 6 cores and 2 threads per core, 12 CPUs, I run 12 of those work loads.

Quoted 9 lines

On my headless ivb-ep 2 sockets, 10 cores each and 2 threads per core, I do:

for ((i=0; i<40; i++)) ; do yes > /dev/null & done
tools/power/x86/turbostat/turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1

But no so far, nada :-( I've tried with full preemption and voluntary, HZ=1000.

And just as I send this, I see these happen:

100.00  3100    2793    40302   71      195.22
100.00  3100    2618    40459   72      183.58
100.00  3100    2993    46215   71      209.21
100.00  3100    2789    40467   71      195.19
99.92   3100    2798    40589   71      195.76
100.00  3100    2793    40397   72      195.46
...
100.00  3100    2844    41906   71      199.43
100.00  3100    2779    40468   71      194.51
99.96   3100    2320    40933   71      163.23
100.00  3100    3529    61823   72      245.70
100.00  3100    2793    40493   72      195.45
100.00  3100    2793    40462   72      195.56

They look like funny little blips. Nowhere near as bad as you had though.

Quoted 38 lines · Peter Zijlstra

Quoted 11 lines · Peter Zijlstra

Quoted 8 lines · Doug Smythies

Quoted 1 line

What is the easiest 100% load you're seeing this with?

Lately, and specifically to be able to tell others, I have been using:

yes > /dev/null &

On my Intel i5-10600K, with 6 cores and 2 threads per core, 12 CPUs, I run 12 of those work loads.

Quoted 9 lines

On my headless ivb-ep 2 sockets, 10 cores each and 2 threads per core, I do:

for ((i=0; i<40; i++)) ; do yes > /dev/null & done
tools/power/x86/turbostat/turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1

But no so far, nada :-( I've tried with full preemption and voluntary, HZ=1000.

And just as I send this, I see these happen:

100.00  3100    2793    40302   71      195.22
100.00  3100    2618    40459   72      183.58
100.00  3100    2993    46215   71      209.21
100.00  3100    2789    40467   71      195.19
99.92   3100    2798    40589   71      195.76
100.00  3100    2793    40397   72      195.46
...
100.00  3100    2844    41906   71      199.43
100.00  3100    2779    40468   71      194.51
99.96   3100    2320    40933   71      163.23
100.00  3100    3529    61823   72      245.70
100.00  3100    2793    40493   72      195.45
100.00  3100    2793    40462   72      195.56

Quoted 2 lines

They look like funny little blips. Nowhere near as bad as you had though.

Anyway, given you've confirmed disabling DELAY_DEQUEUE fixes things, could you perhaps try the below hackery for me? Its a bit of a wild guess, but throw stuff at wall, see what sticks etc..

---

kernel/sched/core.c +22 -20

index 84902936a620..fa4b9891f93a 100644
@@ -3019,7 +3019,7 @@ static int affine_move_task(struct rq *rq, struct task_struct *p, struct rq_flag
      } else {
 
              if (!is_migration_disabled(p)) {
-                     if (task_on_rq_queued(p))
+                     if (task_on_rq_queued(p) && !p->se.sched_delayed)
                              rq = move_queued_task(rq, rf, p, dest_cpu);
 
                      if (!pending->stop_pending) {

@@ -3776,28 +3776,30 @@ ttwu_do_activate(struct rq *rq, struct task_struct *p, int wake_flags,
  */
 static int ttwu_runnable(struct task_struct *p, int wake_flags)
 {
-     struct rq_flags rf;
-     struct rq *rq;
-     int ret = 0;
+     CLASS(__task_rq_lock, rq_guard)(p);
+     struct rq *rq = rq_guard.rq;
 
-     rq = __task_rq_lock(p, &rf);
-     if (task_on_rq_queued(p)) {
-             update_rq_clock(rq);
-             if (p->se.sched_delayed)
-                     enqueue_task(rq, p, ENQUEUE_NOCLOCK | ENQUEUE_DELAYED);
-             if (!task_on_cpu(rq, p)) {
-                     /*
-                      * When on_rq && !on_cpu the task is preempted, see if
-                      * it should preempt the task that is current now.
-                      */
-                     wakeup_preempt(rq, p, wake_flags);
+     if (!task_on_rq_queued(p))
+             return 0;
+
+     update_rq_clock(rq);
+     if (p->se.sched_delayed) {
+             int queue_flags = ENQUEUE_NOCLOCK | ENQUEUE_DELAYED;
+             if (!is_cpu_allowed(p, cpu_of(rq))) {
+                     dequeue_task(rq, p, DEQUEUE_SLEEP | queue_flags);
+                     return 0;
              }
-             ttwu_do_wakeup(p);
-             ret = 1;
+             enqueue_task(rq, p, queue_flags);
      }
-     __task_rq_unlock(rq, &rf);
-
-     return ret;
+     if (!task_on_cpu(rq, p)) {
+             /*
+              * When on_rq && !on_cpu the task is preempted, see if
+              * it should preempt the task that is current now.
+              */
+             wakeup_preempt(rq, p, wake_flags);
+     }
+     ttwu_do_wakeup(p);
+     return 1;
 }
 
 #ifdef CONFIG_SMP

kernel/sched/sched.h +0 -0

index 65fa64845d9f..b4c1f6c06c18 100644
@@ -1793,6 +1793,11 @@ task_rq_unlock(struct rq *rq, struct task_struct *p, struct rq_flags *rf)
      raw_spin_unlock_irqrestore(&p->pi_lock, rf->flags);

I tried the patch on top of kernel 6.13-rc6.
It did not fix the issue.

Quoted 11 lines · Peter Zijlstra

Quoted 8 lines · Doug Smythies

Quoted 1 line

What is the easiest 100% load you're seeing this with?

Lately, and specifically to be able to tell others, I have been using:

yes > /dev/null &

On my Intel i5-10600K, with 6 cores and 2 threads per core, 12 CPUs, I run 12 of those work loads.

Quoted 8 lines

On my headless ivb-ep 2 sockets, 10 cores each and 2 threads per core, I do:

for ((i=0; i<40; i++)) ; do yes > /dev/null & done
tools/power/x86/turbostat/turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz --interval 1

But no so far, nada :-( I've tried with full preemption and voluntary, HZ=1000.

And just as I send this, I see these happen:

100.00  3100    2793    40302   71      195.22
100.00  3100    2618    40459   72      183.58
100.00  3100    2993    46215   71      209.21
100.00  3100    2789    40467   71      195.19
99.92   3100    2798    40589   71      195.76
100.00  3100    2793    40397   72      195.46
...
100.00  3100    2844    41906   71      199.43
100.00  3100    2779    40468   71      194.51
99.96   3100    2320    40933   71      163.23
100.00  3100    3529    61823   72      245.70
100.00  3100    2793    40493   72      195.45
100.00  3100    2793    40462   72      195.56

They look like funny little blips. Nowhere near as bad as you had though.

Which will show when a CPU migration took over 10 milliseconds. If you want to go further, for example to only display ones that took over a second and to include the target CPU, then patch turbostat:

doug@s19:~/kernel/linux/tools/power/x86/turbostat$ git diff

tools/power/x86/turbostat/turbostat.c +3 -1

index 58a487c225a7..f8a73cc8fbfc 100644
@@ -2704,7 +2704,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 */

@@ -4570,12 +4570,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 */
+

In this short example all captures were for the CPU 5 to 11 migration. 2 at 6 seconds, 1 at 1.33 seconds and 1 at 2 seconds.

Quoted 26 lines · Doug Smythies

Which will show when a CPU migration took over 10 milliseconds. If you want to go further, for example to only display ones that took over a second and to include the target CPU, then patch turbostat:

doug@s19:~/kernel/linux/tools/power/x86/turbostat$ git diff

tools/power/x86/turbostat/turbostat.c +3 -1

index 58a487c225a7..f8a73cc8fbfc 100644
@@ -2704,7 +2704,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 */

@@ -4570,12 +4570,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 */
+

tools/power/x86/turbostat/turbostat.c int get_counters(struct thread_data *t, struct core_data *c, struct pkg_data *p) · line 4583

Quoted 10 lines

tools/power/x86/turbostat/turbostat.c +1 -1

        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);

So I've taken the second node offline, running with 10 cores (20 threads) now.

usec Time_Of_Day_Seconds CPU Busy% IRQ

106783 1736248404.951438       -       100.00  20119
    46 1736248404.844701       0       100.00  1005
    41 1736248404.844742       20      100.00  1007
    42 1736248404.844784       1       100.00  1005
    40 1736248404.844824       21      100.00  1006
    41 1736248404.844865       2       100.00  1005
    40 1736248404.844905       22      100.00  1006
    41 1736248404.844946       3       100.00  1006
    40 1736248404.844986       23      100.00  1005
    41 1736248404.845027       4       100.00  1005
    40 1736248404.845067       24      100.00  1006
    41 1736248404.845108       5       100.00  1011
    40 1736248404.845149       25      100.00  1005
    41 1736248404.845190       6       100.00  1005
    40 1736248404.845230       26      100.00  1005
    42 1736248404.845272       7       100.00  1007
    41 1736248404.845313       27      100.00  1005
    41 1736248404.845355       8       100.00  1005
    42 1736248404.845397       28      100.00  1006
    46 1736248404.845443       9       100.00  1009
105995 1736248404.951438       29      100.00  1005

Is by far the worst I've had in the past few minutes playing with this.

If I get a blimp (>10000) then it is always on the last CPU, are you seeing the same thing?

Quoted 3 lines

In this short example all captures were for the CPU 5 to 11 migration. 2 at 6 seconds, 1 at 1.33 seconds and 1 at 2 seconds.

This seems to suggest you are, always on CPU 11.

Weird!

Anyway, let me see if I can capture a trace of this..

Quoted 4 lines · On 2025.01.07 03:26 Peter Zijlstra wrote:

On Mon, Jan 06, 2025 at 02:28:40PM -0800, Doug Smythies wrote:

If I get a blimp (>10000) then it is always on the last CPU, are you seeing the same thing?

More or less, yes. The very long migrations are dominated by the CPU 5 to CPU 11 migration.

Quoted 7 lines

Quoted 3 lines

In this short example all captures were for the CPU 5 to 11 migration. 2 at 6 seconds, 1 at 1.33 seconds and 1 at 2 seconds.

This seems to suggest you are, always on CPU 11.

Weird!

Yes, weird. I think, but am not certain, the CPU sequence in turbostat per interval loop is:

Wake on highest numbered CPU (11 in my case)
Do a bunch of work that can be done without MSR reads.
For each CPU in topological order (0,6,1,7,2,8,3,9,4,10,5,11 in my case)
Do the CPU specific work
Finish the intervals work and printing and such on CPU 11. Sleep for the interval time (we have been using 1 second)

Without any proof, I was thinking the CPU 11 dominance for the long migration issue was due to the other bits of work done on that CPU.

So I've taken the second node offline, running with 10 cores (20 threads) now.

usec    Time_Of_Day_Seconds     CPU     Busy%   IRQ
 106783 1736248404.951438       -       100.00  20119
     46 1736248404.844701       0       100.00  1005
     41 1736248404.844742       20      100.00  1007
     42 1736248404.844784       1       100.00  1005
     40 1736248404.844824       21      100.00  1006
     41 1736248404.844865       2       100.00  1005
     40 1736248404.844905       22      100.00  1006
     41 1736248404.844946       3       100.00  1006
     40 1736248404.844986       23      100.00  1005
     41 1736248404.845027       4       100.00  1005
     40 1736248404.845067       24      100.00  1006
     41 1736248404.845108       5       100.00  1011
     40 1736248404.845149       25      100.00  1005
     41 1736248404.845190       6       100.00  1005
     40 1736248404.845230       26      100.00  1005
     42 1736248404.845272       7       100.00  1007
     41 1736248404.845313       27      100.00  1005
     41 1736248404.845355       8       100.00  1005
     42 1736248404.845397       28      100.00  1006
     46 1736248404.845443       9       100.00  1009
 105995 1736248404.951438       29      100.00  1005

Is by far the worst I've had in the past few minutes playing with this.

Quoted 26 lines · Peter Zijlstra

So I've taken the second node offline, running with 10 cores (20 threads) now.

usec    Time_Of_Day_Seconds     CPU     Busy%   IRQ
 106783 1736248404.951438       -       100.00  20119
     46 1736248404.844701       0       100.00  1005
     41 1736248404.844742       20      100.00  1007
     42 1736248404.844784       1       100.00  1005
     40 1736248404.844824       21      100.00  1006
     41 1736248404.844865       2       100.00  1005
     40 1736248404.844905       22      100.00  1006
     41 1736248404.844946       3       100.00  1006
     40 1736248404.844986       23      100.00  1005
     41 1736248404.845027       4       100.00  1005
     40 1736248404.845067       24      100.00  1006
     41 1736248404.845108       5       100.00  1011
     40 1736248404.845149       25      100.00  1005
     41 1736248404.845190       6       100.00  1005
     40 1736248404.845230       26      100.00  1005
     42 1736248404.845272       7       100.00  1007
     41 1736248404.845313       27      100.00  1005
     41 1736248404.845355       8       100.00  1005
     42 1736248404.845397       28      100.00  1006
     46 1736248404.845443       9       100.00  1009
 105995 1736248404.951438       29      100.00  1005

Quoted 1 line

Is by far the worst I've had in the past few minutes playing with this.

Much also depends on how much (or if at all) cgroups are used.

What exact cgroup config are you having? /sys/kernel/debug/sched/debug should be able to tell you.

Quoted 2 lines · On 2025.07.11:24 Peter Zijlstra wrote:

What exact cgroup config are you having? /sys/kernel/debug/sched/debug should be able to tell you.

I do not know.
I'll capture the above output, compress it, and send it to you.

I did also boot with systemd.unified_cgroup_hierarchy=0 and it made no difference.

Quoted 10 lines · Doug Smythies

Quoted 2 lines · On 2025.07.11:24 Peter Zijlstra wrote:

What exact cgroup config are you having? /sys/kernel/debug/sched/debug should be able to tell you.

I do not know.
I'll capture the above output, compress it, and send it to you.

I did also boot with systemd.unified_cgroup_hierarchy=0 and it made no difference.

I think you need: "cgroup_disable=cpu noautogroup" to fully disable all the cpu-cgroup muck. Anyway:

$ zcat cgroup2.txt.gz | grep -e yes -e turbo | awk '{print $2 "\t" $16}'
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
turbostat       /autogroup-286
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
yes     /user.slice/user-1000.slice/session-1.scope
turbostat       /autogroup-286

That matches the scenario where I could reproduce, two competing groups.

I'm seeing wild vruntime divergence when this happens -- this is definitely wonky. Basically the turbostat groups gets starved for a while while the yes group catches up.

It looks like reweight_entity() is shooting out the cgroup entity to the right.

So it builds up some negative lag (received surplus service) and then because turbostat goes sleep for a second, it's cgroup's share gets truncated to 2 and it shoots the cgroup entity out waaaaaaaay far.

Thing is, waking up *should* fix that up again, but that doesn't appear to happen, leaving us up a creek.

/me noodles a bit....

Does this help?

kernel/sched/fair.c +7 -0

index c0e58e51801f..daa62cfa3092 100644
@@ -7000,6 +7063,13 @@ enqueue_task_fair(struct rq *rq, struct task_struct *p, int flags)
 
      if (flags & ENQUEUE_DELAYED) {
              requeue_delayed_entity(se);
+             se = se->parent;
+             for_each_sched_entity(se) {
+                     cfs_rq = cfs_rq_of(se);
+                     update_load_avg(cfs_rq, se, UPDATE_TG);
+                     se_update_runnable(se);
+                     update_cfs_group(se);
+             }
              return;
      }

Quoted 1 line

Does this help?

Sorry, but no it did not help.

Hi Peter,

after this change, we are seeing big latencies when trying to execute a simple command per SSH on a Fedora 41 s390x remote system which is under stress.

I was able to bisect the problem to this commit.

The problem is easy to reproduce with stress-ng executed on the remote system which is otherwise unoccupied and concurrent SSH connect attempts from a local system to the remote one.

stress-ng (on remote system)
----------------------------

$ cpus=$(nproc)
$ stress-ng --cpu $((cpus * 2)) --matrix 50 --mq 50 --aggressive --brk 2
           --stack 2 --bigheap 2 --userfaultfd 0 --perf -t 5m

That is a very very stressful test. It crashes within a few seconds on my test computer, with a " Segmentation fault (core dumped)" message.

Hi all,

Quoted 2 lines

That is a very very stressful test. It crashes within a few seconds on my test computer, with a " Segmentation fault (core dumped)" message.

Yes, this is an artificial test i came up with to demonstrate the problem we have with another realistic test which i can hardly use here for the sake of demonstration. But it reveals the exact same problem we have with our CI test on s390x test systems.

Let me explain shortly how it happens.

Basically, we have a test system where we execute a test suite and simultaneously monitor this system on another system via simple SSH logins (approximately invoked every 15 seconds) whether the test system is still online and dump automatically if it remains unresponsive for 5m straight. We limit every such SSH login to 10 seconds because we had situations where SSH sometimes hanged for a long time due to various problems with networking, test system itself etc., just to make our monitoring robust.

And since the commit "sched/fair: Fix EEVDF entity placement bug causing scheduling lag" we regularly see SSH logins (limited to 10s) failing for 5m straight, not a single SSH login succeeds. This happens regularly with test suites which compile software with GCC and use all CPUs at 100%. Before the commit, a SSH login required under 1 second. I cannot judge whether the problem really in this commit, or it is just an accumulated effect after multiple ones.

FYI:
One such system where it happens regularly has 7 cores (5.2Ghz SMT 2x, 14 cpus) and 8G of main memory with 20G of swap.

Thanks
Regards
Alex

This made me have a very hard look at reweight_entity(), and specifically the ->on_rq case, which is more prominent with DELAY_DEQUEUE.

And indeed, it is all sorts of broken. While the computation of the new lag is correct, the computation for the new vruntime, using the new lag is broken for it does not consider the logic set out in place_entity().

With the below patch, I now see things like:

   migration/12-55      [012] d..3.   309.006650: reweight_entity: (ffff8881e0e6f600-ffff88885f235f40-12)
                              { weight: 977582 avg_vruntime: 4860513347366 vruntime: 4860513347908 (-542) deadline: 4860516552475

                              { weight: 2 avg_vruntime: 4860528915984 vruntime: 4860793840706 (-264924722) deadline: 6427157349203

   migration/14-62      [014] d..3.   309.006698: reweight_entity: (ffff8881e0e6cc00-ffff88885f3b5f40-15)
                              { weight: 2 avg_vruntime: 4874472992283 vruntime: 4939833828823 (-65360836540) deadline:

                              { weight: 967149 avg_vruntime: 4874217684324 vruntime: 4874217688559 (-4235) deadline: 4874220535650

Which isn't perfect yet, but much closer.

Fixes eab03c23c2a1 ("sched/eevdf: Fix vruntime adjustment on reweight")

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

Hi Peter,

Thanks for all your hard work on this.

On 2025.01.09 03:00 Peter Zijlstra wrote:

...

Quoted 4 lines

This made me have a very hard look at reweight_entity(), and specifically the ->on_rq case, which is more prominent with DELAY_DEQUEUE.

Quoted 8 lines

And indeed, it is all sorts of broken. While the computation of the new lag is correct, the computation for the new vruntime, using the new lag is broken for it does not consider the logic set out in place_entity().

With the below patch, I now see things like:

   migration/12-55      [012] d..3.   309.006650: reweight_entity: (ffff8881e0e6f600-ffff88885f235f40-12)
                              { weight: 977582 avg_vruntime: 4860513347366 vruntime: 4860513347908 (-542) deadline: 4860516552475

} ->

Quoted 1 line

                              { weight: 2 avg_vruntime: 4860528915984 vruntime: 4860793840706 (-264924722) deadline: 6427157349203

}

Quoted 2 lines

   migration/14-62      [014] d..3.   309.006698: reweight_entity: (ffff8881e0e6cc00-ffff88885f3b5f40-15)
                              { weight: 2 avg_vruntime: 4874472992283 vruntime: 4939833828823 (-65360836540) deadline:

6316614641111 } ->

Quoted 1 line

                              { weight: 967149 avg_vruntime: 4874217684324 vruntime: 4874217688559 (-4235) deadline: 4874220535650

}

Quoted 1 line

Quoted 1 line

Which isn't perfect yet, but much closer.

Agreed.
I tested the patch. Attached is a repeat of a graph I had sent before, with different y axis scale and old data deleted. It still compares to the "b12" kernel (the last good one in the kernel bisection).
It was a 2 hour and 31 minute duration test, and the maximum CPU migration time was 24 milliseconds, verses 6 seconds without the patch.

I left things running for many hours and will let it continue overnight. There seems to have been an issue at one spot in time:

Quoted 8 lines · Doug Smythies

On 2025.01.09 03:00 Peter Zijlstra wrote:

...

Quoted 4 lines

This made me have a very hard look at reweight_entity(), and specifically the ->on_rq case, which is more prominent with DELAY_DEQUEUE.

Quoted 8 lines

Quoted 8 lines

And indeed, it is all sorts of broken. While the computation of the new lag is correct, the computation for the new vruntime, using the new lag is broken for it does not consider the logic set out in place_entity().

With the below patch, I now see things like:

   migration/12-55      [012] d..3.   309.006650: reweight_entity: (ffff8881e0e6f600-ffff88885f235f40-12)
                              { weight: 977582 avg_vruntime: 4860513347366 vruntime: 4860513347908 (-542) deadline:

Quoted 2 lines

} ->

Quoted 1 line

                              { weight: 2 avg_vruntime: 4860528915984 vruntime: 4860793840706 (-264924722) deadline:

Quoted 5 lines

}

Quoted 2 lines

   migration/14-62      [014] d..3.   309.006698: reweight_entity: (ffff8881e0e6cc00-ffff88885f3b5f40-15)
                              { weight: 2 avg_vruntime: 4874472992283 vruntime: 4939833828823 (-65360836540) deadline:

6316614641111 } ->

Quoted 1 line

                              { weight: 967149 avg_vruntime: 4874217684324 vruntime: 4874217688559 (-4235) deadline:

Quoted 9 lines

}

Quoted 2 lines

Which isn't perfect yet, but much closer.

Agreed.
I tested the patch. Attached is a repeat of a graph I had sent before, with different y axis scale and old data deleted. It still compares to the "b12" kernel (the last good one in the kernel bisection).
It was a 2 hour and 31 minute duration test, and the maximum CPU migration time was 24 milliseconds, verses 6 seconds without the patch.

Progress!

Quoted 2 lines

I left things running for many hours and will let it continue overnight. There seems to have been an issue at one spot in time:

Right, so by happy accident I also left mine running overnight and I think I caught one of those weird spikes. It took a bit of staring to figure out what went wrong this time, but what I now think is the thing that sets off the chain of fail is a combination of DELAY_DEQUEUE and the cgroup reweight stuff.

Specifically, when a cgroup's CPU queue becomes empty, calc_group_shares() will drop its weight to the floor.

Now, normally, when a queue goes empty, it gets dequeued from its parent and its weight is immaterial. However, with DELAY_DEQUEUE the thing will stick around for a while -- at a very low weight.

What makes this esp. troublesome is that even for an active cgroup (like the 'yes' group) the per-cpu weight will be relatively small (~1/nr_cpus like). Worse, the avg_vruntime thing uses load_scale_down() because u64 just isn't all that big :/

(if only all 64bit machines could do 128bit divisions as cheaply as x86_64)

This means that on a 16 CPU machine, the weight of a 'normal' all busy queue will be 64, and the weight of an empty queue will be 2, which means the effect of the ginormous lag on the avg_vruntime is fairly significant, pushing it wildly off balance and affecting placement of new tasks.

Also, this violates the spirit of DELAY_DEQUEUE, that wants to continue competition as the entity was.

As such, we should not adjust the weight of an empty queue.

I've started a new run, and some 15 minutes of runtime show nothing interesting, I'll have to let it run for a while again.

---

kernel/sched/fair.c +0 -0

index 3e9ca38512de..93644b3983d4 100644
@@ -4065,7 +4019,11 @@ static void update_cfs_group(struct sched_entity *se)
 	struct cfs_rq *gcfs_rq = group_cfs_rq(se);
 	long shares;

I tested the above patch on top of the previous patch.

Multiple tests and multiple methods over many hours and
I never got any hit at all for a detected CPU migration greater than or equal to 10 milliseconds.
Which is good news.

The test I have been running to create some of the graphs I have been attaching is a little different, using turbostat with different options:

turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz,Time_Of_Day_Seconds --interval 1

And with this test I get intervals over 1 second by over 10 milliseconds. (I referred to this observation in the previous email.).

Third: Kernel 6.13-rc6+the first patch+the above patch:

1.000000, 2034
1.001000, 2108
1.002000, 2030
1.003000, 2492
1.004000, 216
1.005000, 109
1.006000, 23
1.007000, 8
1.008000, 3
1.009000, 9
1.010000, 1
1.011000, 2
1.012000, 2
1.014000, 3
1.015000, 10
1.016000, 19
1.017000, 1
1.018000, 1

Total: 9071 : Total >= 10 mSec: 39 ( 0.43 percent)

Where, and for example, this line:

1.016000, 19

means that there were 19 occurrences of turbostat interval times between 1.016 and 1.016999 seconds.

Quoted 2 lines · Doug Smythies

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 :-)

Quoted 7 lines · Peter Zijlstra

Quoted 2 lines · Doug Smythies

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 :-(

Doug,
Your attention to detail and persistence has once again found a tricky underlying bug -- kudos!

Re: turbostat behaviour

Yes, TSC_MHz -- "the measured rate of the TSC during an interval", is printed as a sanity check. If there are any irregularities in it, as you noticed, then something very strange in the hardware or software is going wrong (and the actual turbostat results will likely not be reliable).

Yes, the "usec" column measures how long it takes to migrate to a CPU and collect stats there. So if you are hunting down a glitch in migration all you need is this column to see it. "usec" on the summary row is the difference between the 1st migration and after the last -- excluding the sysfs/procfs time that is consumed on the last CPU. So migration delays will also be reflected there.

Note: we have a patch queued which changes the "usec" on the Summary row to *include* the sysfs/procfs time on the last CPU.

(The per-cpu
"usec" values are unchanged.) This is because we've noticed some really weird delays in doing things like reading /proc/interrupts and we want to be able to easily do A/B comparisons by simply including or excluding counters.

Also FYI, The scheme of migrating to each CPU so that collecting stats there will be "local" isn't scaling so well on very large systems, and I'm about to take a close look at it. In yogini we used a different scheme, where a thread is bound to each CPU, so they can collect in parallel; and we may be moving to something like that.

cheers,
Len Brown, Intel Open Source Technology Center

Quoted 7 lines · Peter Zijlstra

Quoted 2 lines · Doug Smythies

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 :-(

Hi Peter,

An update.

Quoted 10 lines · On 2025.01.14 02:59 Peter Zijlstra wrote:

Quoted 7 lines · Peter Zijlstra

Quoted 2 lines · Doug Smythies

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.

I am saying there were 2 different issues. The 2nd was hidden by the 1st because its magnitude was about 260 times less.

Hi Peter,

I now know that the 2nd issue I mentioned yesterday is a completely separate issue. I would have to do a new kernel bisection to isolate it and then start a new thread with whomever about it.

Hi Peter,

An update.

Quoted 6 lines · On 2025.01.14 02:59 Peter Zijlstra wrote:

Quoted 5 lines · Peter Zijlstra

Quoted 2 lines · Doug Smythies

means that there were 19 occurrences of turbostat interval times between 1.016 and 1.016999 seconds.

Quoted 4 lines

Quoted 2 lines

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:

Quoted 1 line

I modified your tracing trigger thing in turbostat to this:

Shiny!

What turbostat invocation do I use? I think the last I had was:

  tools/power/x86/turbostat/turbostat --quiet --show Busy%,IRQ,Time_Of_Day_Seconds,CPU,usec --interval 1

I've started a new run of yes-vs-turbostate with the modified trigger condition. Lets see what pops out.

Quoted 10 lines · Peter Zijlstra

Quoted 1 line

I modified your tracing trigger thing in turbostat to this:

Shiny!

What turbostat invocation do I use? I think the last I had was:

  tools/power/x86/turbostat/turbostat --quiet --show Busy%,IRQ,Time_Of_Day_Seconds,CPU,usec --interval 1

I've started a new run of yes-vs-turbostate with the modified trigger condition. Lets see what pops out.

Ok, I have a trace.o

So I see turbostat wake up on CPU 15, do its migration round 0-15 and when its back at 15 it prints the WHOOPSIE.

(trimmed trace):

            yes-1169    [015] dNh4.  4238.261759: sched_wakeup: comm=turbostat pid=1185 prio=100 target_cpu=015
            yes-1169    [015] d..2.  4238.261761: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R ==>

   migration/15-158     [015] d..3.  4238.261977: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=15 dest_cpu=0
   migration/0-20      [000] d..3.  4238.261991: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=0 dest_cpu=1
    migration/1-116     [001] d..3.  4238.262003: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=1 dest_cpu=2
    migration/2-25      [002] d..3.  4238.262018: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=2 dest_cpu=3
    migration/3-122     [003] d..3.  4238.262031: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=3 dest_cpu=4
    migration/4-31      [004] d..3.  4238.262044: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=4 dest_cpu=5
    migration/5-128     [005] d..3.  4238.262057: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=5 dest_cpu=6
    migration/6-37      [006] d..3.  4238.262071: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=6 dest_cpu=7
    migration/7-134     [007] d..3.  4238.262084: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=7 dest_cpu=8

    migration/8-43      [008] d..3.  4238.262097: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=8 dest_cpu=9
    migration/9-140     [009] d..3.  4238.262109: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=9 dest_cpu=10
   migration/10-49      [010] d..3.  4238.262123: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=10 dest_cpu=11
   migration/11-146     [011] d..3.  4238.262136: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=11 dest_cpu=12
   migration/12-55      [012] d..3.  4238.262150: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=12 dest_cpu=13
   migration/13-152     [013] d..3.  4238.262164: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=13 dest_cpu=14
   migration/14-62      [014] d..3.  4238.262177: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=14 dest_cpu=15
            yes-1169    [015] d..2.  4238.262182: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R+ ==>

      turbostat-1185    [015] .....  4238.262189: __x64_sys_gettimeofday: WHOOPSIE!

The time between wakeup and whoopsie 4238.262189-4238.261759 = .000430 or 430us, which doesn't seem excessive to me.

Let me go read this turbostat code to figure out what exactly the trigger condition signifies. Because I'm not seeing nothing weird here.

Quoted 15 lines · On 2025.01.21 03:22 Peter Zijlstra wrote:

Quoted 10 lines · Peter Zijlstra

Quoted 1 line

I modified your tracing trigger thing in turbostat to this:

Shiny!

What turbostat invocation do I use? I think the last I had was:

  tools/power/x86/turbostat/turbostat --quiet --show Busy%,IRQ,Time_Of_Day_Seconds,CPU,usec --interval 1

I've started a new run of yes-vs-turbostate with the modified trigger condition. Lets see what pops out.

Ok, I have a trace.o

Quoted 7 lines

So I see turbostat wake up on CPU 15, do its migration round 0-15 and when its back at 15 it prints the WHOOPSIE.

(trimmed trace):

            yes-1169    [015] dNh4.  4238.261759: sched_wakeup: comm=turbostat pid=1185 prio=100 target_cpu=015
            yes-1169    [015] d..2.  4238.261761: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R ==>

next_comm=turbostat next_pid=1185 next_prio=100

Quoted 9 lines

   migration/15-158     [015] d..3.  4238.261977: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=15 dest_cpu=0
   migration/0-20      [000] d..3.  4238.261991: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=0 dest_cpu=1
    migration/1-116     [001] d..3.  4238.262003: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=1 dest_cpu=2
    migration/2-25      [002] d..3.  4238.262018: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=2 dest_cpu=3
    migration/3-122     [003] d..3.  4238.262031: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=3 dest_cpu=4
    migration/4-31      [004] d..3.  4238.262044: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=4 dest_cpu=5
    migration/5-128     [005] d..3.  4238.262057: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=5 dest_cpu=6
    migration/6-37      [006] d..3.  4238.262071: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=6 dest_cpu=7
    migration/7-134     [007] d..3.  4238.262084: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=7 dest_cpu=8

Quoted 8 lines

    migration/8-43      [008] d..3.  4238.262097: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=8 dest_cpu=9
    migration/9-140     [009] d..3.  4238.262109: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=9 dest_cpu=10
   migration/10-49      [010] d..3.  4238.262123: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=10 dest_cpu=11
   migration/11-146     [011] d..3.  4238.262136: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=11 dest_cpu=12
   migration/12-55      [012] d..3.  4238.262150: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=12 dest_cpu=13
   migration/13-152     [013] d..3.  4238.262164: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=13 dest_cpu=14
   migration/14-62      [014] d..3.  4238.262177: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=14 dest_cpu=15
            yes-1169    [015] d..2.  4238.262182: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R+ ==>

next_comm=turbostat next_pid=1185 next_prio=100

Quoted 7 lines

      turbostat-1185    [015] .....  4238.262189: __x64_sys_gettimeofday: WHOOPSIE!

The time between wakeup and whoopsie 4238.262189-4238.261759 = .000430 or 430us, which doesn't seem excessive to me.

Let me go read this turbostat code to figure out what exactly the trigger condition signifies. Because I'm not seeing nothing weird here.

I think the anomaly would have been about 1 second ago, on CPU 15, and before entering sleep.
But after the previous call to the time of day stuff.

Somewhere in this code:

delta_platform(&platform_counters_even, &platform_counters_odd); compute_average(ODD_COUNTERS); format_all_counters(ODD_COUNTERS); flush_output_stdout();

Please know that I ran a couple of tests yesterday for a total of about 8 hours and never got a measured interval time >= 10 mSec.
I was using kernel 6.13, which includes your 2 patches, and I tried a slight modification to the turbostat command:

sudo ./turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz,Time_Of_Day_Seconds,usec --interval 1 --out

That allowed me to acquire more than my ssh session history limit of about 9000 lines (seconds) and also eliminated ssh communications.
It was on purpose that I used RAM to write the log file to.

I have run more tests over the last couple of days, totalling over 30 hours. I simply do not get a measured interval time >= 10mSec using kernel 6.13. The previous work was kernel 6.13-rc6 + the 2 patches + the tracing stuff. I never tried kernel 6.13-rc7.

The test I have been running to create some of the graphs I have been attaching is a little different, using turbostat with different options:

turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz,Time_Of_Day_Seconds --interval 1

And with this test I get intervals over 1 second by over 10 milliseconds.

First the b12 kernel (the last good one in the kernel bisection):

Time Occurrences
1.000000, 3282
1.001000, 1826
1.002000, 227
1.003000, 1852
1.004000, 1036
1.005000, 731
1.006000, 75
1.007000, 30
1.008000, 9
1.009000, 2
1.010000, 1
1.011000, 1

Quoted 9 lines · Doug Smythies

The test I have been running to create some of the graphs I have been attaching is a little different, using turbostat with different options:

turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz,Time_Of_Day_Seconds --interval 1

And with this test I get intervals over 1 second by over 10 milliseconds.

First the b12 kernel (the last good one in the kernel bisection):

Quoted 13 lines

Time Occurrences
1.000000, 3282
1.001000, 1826
1.002000, 227
1.003000, 1852
1.004000, 1036
1.005000, 731
1.006000, 75
1.007000, 30
1.008000, 9
1.009000, 2
1.010000, 1
1.011000, 1

You're creating these Time values from the consecutive Time_Of_Day_Seconds data using a script? Let me go check the turbostat code to see if my hackery is still invoked, even if not displayed.

On 2025.01.09 03:00 Peter Zijlstra wrote:

...

Quoted 8 lines

This made me have a very hard look at reweight_entity(), and specifically the ->on_rq case, which is more prominent with DELAY_DEQUEUE.

And indeed, it is all sorts of broken. While the computation of the new lag is correct, the computation for the new vruntime, using the new lag is broken for it does not consider the logic set out in place_entity().

Quoted 4 lines

With the below patch, I now see things like:

   migration/12-55      [012] d..3.   309.006650: reweight_entity: (ffff8881e0e6f600-ffff88885f235f40-12)
                              { weight: 977582 avg_vruntime: 4860513347366 vruntime: 4860513347908 (-542) deadline: 4860516552475

} ->

Quoted 1 line

                              { weight: 2 avg_vruntime: 4860528915984 vruntime: 4860793840706 (-264924722) deadline:

}

Quoted 2 lines

   migration/14-62      [014] d..3.   309.006698: reweight_entity: (ffff8881e0e6cc00-ffff88885f3b5f40-15)
                              { weight: 2 avg_vruntime: 4874472992283 vruntime: 4939833828823 (-65360836540) deadline:

6316614641111 } ->

Quoted 1 line

                              { weight: 967149 avg_vruntime: 4874217684324 vruntime: 4874217688559 (-4235) deadline:

}

Quoted 2 lines

Which isn't perfect yet, but much closer.

Agreed.
I tested the patch. Attached is a repeat of a graph I had sent before, with different y axis scale and old data deleted. It still compares to the "b12" kernel (the last good one in the kernel bisection).
It was a 2 hour and 31 minute duration test, and the maximum CPU migration time was 24 milliseconds, verses 6 seconds without the patch.

I left things running for many hours and will let it continue overnight. There seems to have been an issue at one spot in time:

usec    Time_Of_Day_Seconds     CPU     Busy%   IRQ
488994  1736476550.732222       -       99.76   12889
488520  1736476550.732222       11      99.76   1012
960999  1736476552.694222       -       99.76   17922
960587  1736476552.694222       11      99.76   1493
914999  1736476554.610222       -       99.76   23579
914597  1736476554.610222       11      99.76   1962
809999  1736476556.421222       -       99.76   23134
809598  1736476556.421222       11      99.76   1917
770998  1736476558.193221       -       99.76   21757
770603  1736476558.193221       11      99.76   1811

726999  1736476559.921222       -       99.76   21294
726600  1736476559.921222       11      99.76   1772
686998  1736476561.609221       -       99.76   20801
686600  1736476561.609221       11      99.76   1731
650998  1736476563.261221       -       99.76   20280
650601  1736476563.261221       11      99.76   1688
610998  1736476564.873221       -       99.76   19857
610606  1736476564.873221       11      99.76   1653

I had one of these the other day also, but they were all 6 seconds. Its like a burst of problematic data. I have the data somewhere, and can try to find it tomorrow.

Quoted 3 lines

Fixes eab03c23c2a1 ("sched/eevdf: Fix vruntime adjustment on reweight")

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

...