[PATCH 0/3] sched: Fix irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

[PATCH 0/3] sched: Fix irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

[Yafang Shao]

After enabling CONFIG_IRQ_TIME_ACCOUNTING to track IRQ pressure in our
container environment, we encountered several user-visible behavioral
changes:

- Interrupted IRQ/softirq time is not accounted for in the cpuacct cgroup

  This breaks userspace applications that rely on CPU usage data from
  cgroups to monitor CPU pressure. This patchset resolves the issue by
  ensuring that IRQ/softirq time is accounted for in the cgroup of the
  interrupted tasks.

- getrusage(2) does not include time interrupted by IRQ/softirq 

  Some services use getrusage(2) to check if workloads are experiencing CPU
  pressure. Since IRQ/softirq time is no longer charged to task runtime,
  getrusage(2) can no longer reflect the CPU pressure caused by heavy
  interrupts.

This patchset addresses the first issue, which is relatively
straightforward. However, the second issue remains unresolved, as there
might be debate over whether interrupted time should be considered part of
a task’s usage. Nonetheless, it is important to report interrupted time to
the user via some metric, though that is a separate discussion.

Yafang Shao (3):
  sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING
  sched: Define sched_clock_irqtime as static key
  sched: Don't account irq time if sched_clock_irqtime is disabled

 kernel/sched/core.c    | 44 ++++++++++++++++++++++--------------------
 kernel/sched/cputime.c | 26 +++++++++++++------------
 kernel/sched/sched.h   |  1 +
 3 files changed, 38 insertions(+), 33 deletions(-)

-- 
2.43.5

[PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

[Yafang Shao]

After enabling CONFIG_IRQ_TIME_ACCOUNTING to monitor IRQ pressure in our
container environment, we observed several noticeable behavioral changes.

One of our IRQ-heavy services, such as Redis, reported a significant
reduction in CPU usage after upgrading to the new kernel with
CONFIG_IRQ_TIME_ACCOUNTING enabled. However, despite adding more threads
to handle an increased workload, the CPU usage could not be raised. In
other words, even though the container’s CPU usage appeared low, it was
unable to process more workloads to utilize additional CPU resources, which
caused issues.

This behavior can be demonstrated using netperf:

  function start_server() {
      for j in `seq 1 3`; do
          netserver -p $[12345+j] > /dev/null &
      done
  }

  server_ip=$1
  function start_client() {
    # That applies to cgroup2 as well.
    mkdir -p /sys/fs/cgroup/cpuacct/test
    echo $$ > /sys/fs/cgroup/cpuacct/test/cgroup.procs
    for j in `seq 1 3`; do
        port=$[12345+j]
        taskset -c 0 netperf -H ${server_ip} -l ${run_time:-30000}   \
                -t TCP_STREAM -p $port -- -D -m 1k -M 1K -s 8k -S 8k \
                > /dev/null &
    done
  }

  start_server
  start_client

We can verify the CPU usage of the test cgroup using cpuacct.stat. The
output shows:

  system: 53
  user: 2

The CPU usage of the cgroup is relatively low at around 55%, but this usage
doesn't increase, even with more netperf tasks. The reason is that CPU0 is
at 100% utilization, as confirmed by mpstat:

  02:56:22 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
  02:56:23 PM    0    0.99    0.00   55.45    0.00    0.99   42.57    0.00    0.00    0.00    0.00

  02:56:23 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
  02:56:24 PM    0    2.00    0.00   55.00    0.00    0.00   43.00    0.00    0.00    0.00    0.00

This behavior is unexpected. We should account for IRQ time to the cgroup
to reflect the pressure the group is under.

After a thorough analysis, I discovered that this change in behavior is due
to commit 305e6835e055 ("sched: Do not account irq time to current task"),
which altered whether IRQ time should be charged to the interrupted task.
While I agree that a task should not be penalized by random interrupts, the
task itself cannot progress while interrupted. Therefore, the interrupted
time should be reported to the user.

The system metric in cpuacct.stat is crucial in indicating whether a
container is under heavy system pressure, including IRQ/softirq activity.
Hence, IRQ/softirq time should be accounted for in the cpuacct system
usage, which also applies to cgroup2’s rstat.

This patch reintroduces IRQ/softirq accounting to cgroups.

Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
---
 kernel/sched/cputime.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/kernel/sched/cputime.c b/kernel/sched/cputime.c
index 0bed0fa1acd9..4586db5cf3a8 100644
--- a/kernel/sched/cputime.c
+++ b/kernel/sched/cputime.c
@@ -34,7 +34,8 @@ void disable_sched_clock_irqtime(void)
 	sched_clock_irqtime = 0;
 }
 
-static void irqtime_account_delta(struct irqtime *irqtime, u64 delta,
+static void irqtime_account_delta(struct task_struct *curr,
+				  struct irqtime *irqtime, u64 delta,
 				  enum cpu_usage_stat idx)
 {
 	u64 *cpustat = kcpustat_this_cpu->cpustat;
@@ -44,6 +45,9 @@ static void irqtime_account_delta(struct irqtime *irqtime, u64 delta,
 	irqtime->total += delta;
 	irqtime->tick_delta += delta;
 	u64_stats_update_end(&irqtime->sync);
+
+	cgroup_account_cputime(curr, delta);
+	cgroup_account_cputime_field(curr, idx, delta);
 }
 
 /*
@@ -72,9 +76,9 @@ void irqtime_account_irq(struct task_struct *curr, unsigned int offset)
 	 * that do not consume any time, but still wants to run.
 	 */
 	if (pc & HARDIRQ_MASK)
-		irqtime_account_delta(irqtime, delta, CPUTIME_IRQ);
+		irqtime_account_delta(curr, irqtime, delta, CPUTIME_IRQ);
 	else if ((pc & SOFTIRQ_OFFSET) && curr != this_cpu_ksoftirqd())
-		irqtime_account_delta(irqtime, delta, CPUTIME_SOFTIRQ);
+		irqtime_account_delta(curr, irqtime, delta, CPUTIME_SOFTIRQ);
 }
 
 static u64 irqtime_tick_accounted(u64 maxtime)
-- 
2.43.5

[PATCH 2/3] sched: Define sched_clock_irqtime as static key

[Yafang Shao]

Since CPU time accounting is a performance-critical path, let's define
sched_clock_irqtime as a static key to minimize potential overhead.

Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
---
 kernel/sched/cputime.c | 16 +++++++---------
 kernel/sched/sched.h   |  1 +
 2 files changed, 8 insertions(+), 9 deletions(-)

diff --git a/kernel/sched/cputime.c b/kernel/sched/cputime.c
index 4586db5cf3a8..de9a36e0fe04 100644
--- a/kernel/sched/cputime.c
+++ b/kernel/sched/cputime.c
@@ -7,6 +7,8 @@
  #include <asm/cputime.h>
 #endif
 
+DEFINE_STATIC_KEY_FALSE(sched_clock_irqtime);
+
 #ifdef CONFIG_IRQ_TIME_ACCOUNTING
 
 /*
@@ -22,16 +24,14 @@
  */
 DEFINE_PER_CPU(struct irqtime, cpu_irqtime);
 
-static int sched_clock_irqtime;
-
 void enable_sched_clock_irqtime(void)
 {
-	sched_clock_irqtime = 1;
+	static_branch_enable(&sched_clock_irqtime);
 }
 
 void disable_sched_clock_irqtime(void)
 {
-	sched_clock_irqtime = 0;
+	static_branch_disable(&sched_clock_irqtime);
 }
 
 static void irqtime_account_delta(struct task_struct *curr,
@@ -61,7 +61,7 @@ void irqtime_account_irq(struct task_struct *curr, unsigned int offset)
 	s64 delta;
 	int cpu;
 
-	if (!sched_clock_irqtime)
+	if (!static_branch_likely(&sched_clock_irqtime))
 		return;
 
 	cpu = smp_processor_id();
@@ -94,8 +94,6 @@ static u64 irqtime_tick_accounted(u64 maxtime)
 
 #else /* CONFIG_IRQ_TIME_ACCOUNTING */
 
-#define sched_clock_irqtime	(0)
-
 static u64 irqtime_tick_accounted(u64 dummy)
 {
 	return 0;
@@ -482,7 +480,7 @@ void account_process_tick(struct task_struct *p, int user_tick)
 	if (vtime_accounting_enabled_this_cpu())
 		return;
 
-	if (sched_clock_irqtime) {
+	if (static_branch_likely(&sched_clock_irqtime)) {
 		irqtime_account_process_tick(p, user_tick, 1);
 		return;
 	}
@@ -511,7 +509,7 @@ void account_idle_ticks(unsigned long ticks)
 {
 	u64 cputime, steal;
 
-	if (sched_clock_irqtime) {
+	if (static_branch_likely(&sched_clock_irqtime)) {
 		irqtime_account_idle_ticks(ticks);
 		return;
 	}
diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
index 8063db62b027..db7d541eebff 100644
--- a/kernel/sched/sched.h
+++ b/kernel/sched/sched.h
@@ -3174,6 +3174,7 @@ struct irqtime {
 };
 
 DECLARE_PER_CPU(struct irqtime, cpu_irqtime);
+DECLARE_STATIC_KEY_FALSE(sched_clock_irqtime);
 
 /*
  * Returns the irqtime minus the softirq time computed by ksoftirqd.
-- 
2.43.5

[PATCH 3/3] sched: Don't account irq time if sched_clock_irqtime is disabled

[Yafang Shao]

sched_clock_irqtime may be disabled due to the clock source, in which case
IRQ time should not be accounted. Let's add a conditional check to avoid
unnecessary logic.

Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
---
 kernel/sched/core.c | 44 +++++++++++++++++++++++---------------------
 1 file changed, 23 insertions(+), 21 deletions(-)

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index b6cc1cf499d6..8b633a14a60f 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -735,29 +735,31 @@ static void update_rq_clock_task(struct rq *rq, s64 delta)
 	s64 __maybe_unused steal = 0, irq_delta = 0;
 
 #ifdef CONFIG_IRQ_TIME_ACCOUNTING
-	irq_delta = irq_time_read(cpu_of(rq)) - rq->prev_irq_time;
+	if (static_branch_likely(&sched_clock_irqtime)) {
+		irq_delta = irq_time_read(cpu_of(rq)) - rq->prev_irq_time;
 
-	/*
-	 * Since irq_time is only updated on {soft,}irq_exit, we might run into
-	 * this case when a previous update_rq_clock() happened inside a
-	 * {soft,}IRQ region.
-	 *
-	 * When this happens, we stop ->clock_task and only update the
-	 * prev_irq_time stamp to account for the part that fit, so that a next
-	 * update will consume the rest. This ensures ->clock_task is
-	 * monotonic.
-	 *
-	 * It does however cause some slight miss-attribution of {soft,}IRQ
-	 * time, a more accurate solution would be to update the irq_time using
-	 * the current rq->clock timestamp, except that would require using
-	 * atomic ops.
-	 */
-	if (irq_delta > delta)
-		irq_delta = delta;
+		/*
+		 * Since irq_time is only updated on {soft,}irq_exit, we might run into
+		 * this case when a previous update_rq_clock() happened inside a
+		 * {soft,}IRQ region.
+		 *
+		 * When this happens, we stop ->clock_task and only update the
+		 * prev_irq_time stamp to account for the part that fit, so that a next
+		 * update will consume the rest. This ensures ->clock_task is
+		 * monotonic.
+		 *
+		 * It does however cause some slight miss-attribution of {soft,}IRQ
+		 * time, a more accurate solution would be to update the irq_time using
+		 * the current rq->clock timestamp, except that would require using
+		 * atomic ops.
+		 */
+		if (irq_delta > delta)
+			irq_delta = delta;
 
-	rq->prev_irq_time += irq_delta;
-	delta -= irq_delta;
-	delayacct_irq(rq->curr, irq_delta);
+		rq->prev_irq_time += irq_delta;
+		delta -= irq_delta;
+		delayacct_irq(rq->curr, irq_delta);
+	}
 #endif
 #ifdef CONFIG_PARAVIRT_TIME_ACCOUNTING
 	if (static_key_false((&paravirt_steal_rq_enabled))) {
-- 
2.43.5

Re: [PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

[kernel test robot]

Hello,

kernel test robot noticed "WARNING:at_kernel/sched/sched.h:#cpuacct_charge" on:

commit: e5633f7cf7d093cf5bb191663054441fbc745a5a ("[PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING")
url: https://github.com/intel-lab-lkp/linux/commits/Yafang-Shao/sched-Fix-cgroup-irq-accounting-for-CONFIG_IRQ_TIME_ACCOUNTING/20240923-170321
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git bc9057da1a220ff2cb6c8885fd5352558aceba2c
patch link: https://lore.kernel.org/all/20240923090028.16368-2-laoar.shao@gmail.com/
patch subject: [PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

in testcase: boot

compiler: clang-18
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)


+-------------------------------------------------+------------+------------+
|                                                 | bc9057da1a | e5633f7cf7 |
+-------------------------------------------------+------------+------------+
| boot_successes                                  | 12         | 0          |
| boot_failures                                   | 0          | 12         |
| RIP:cpuacct_charge                              | 0          | 12         |
| WARNING:at_kernel/sched/sched.h:#cpuacct_charge | 0          | 12         |
| RIP:console_flush_all                           | 0          | 12         |
| RIP:ftrace_likely_update                        | 0          | 12         |
| RIP:desc_read                                   | 0          | 12         |
| RIP:handle_softirqs                             | 0          | 12         |
| RIP:kasan_check_range                           | 0          | 12         |
| RIP:_prb_read_valid                             | 0          | 12         |
+-------------------------------------------------+------------+------------+


If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202409261230.c7f0e4eb-lkp@intel.com


[    6.485339][    C0] ------------[ cut here ]------------
[ 6.485374][ C0] WARNING: CPU: 0 PID: 0 at kernel/sched/sched.h:1414 cpuacct_charge (kernel/sched/sched.h:1414) 
[    6.485389][    C0] Modules linked in:
[    6.485398][    C0] CPU: 0 UID: 0 PID: 0 Comm: swapper Tainted: G                T  6.11.0-rc1-00070-ge5633f7cf7d0 #1
[    6.485406][    C0] Tainted: [T]=RANDSTRUCT
[    6.485408][    C0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 6.485412][ C0] RIP: 0010:cpuacct_charge (kernel/sched/sched.h:1414) 
[ 6.485419][ C0] Code: ff ff e8 26 8e 4d 02 85 c0 0f 94 c0 eb 02 31 c0 0f b6 e8 48 c7 c7 30 88 c2 85 31 d2 31 c9 89 ee e8 38 23 21 00 40 84 ed 74 02 <0f> 0b 48 c7 c7 60 88 c2 85 89 ee 31 d2 31 c9 e8 1f 23 21 00 4d 8d
All code
========
   0:	ff                   	(bad)
   1:	ff                   	(bad)
   2:	e8 26 8e 4d 02       	call   0x24d8e2d
   7:	85 c0                	test   %eax,%eax
   9:	0f 94 c0             	sete   %al
   c:	eb 02                	jmp    0x10
   e:	31 c0                	xor    %eax,%eax
  10:	0f b6 e8             	movzbl %al,%ebp
  13:	48 c7 c7 30 88 c2 85 	mov    $0xffffffff85c28830,%rdi
  1a:	31 d2                	xor    %edx,%edx
  1c:	31 c9                	xor    %ecx,%ecx
  1e:	89 ee                	mov    %ebp,%esi
  20:	e8 38 23 21 00       	call   0x21235d
  25:	40 84 ed             	test   %bpl,%bpl
  28:	74 02                	je     0x2c
  2a:*	0f 0b                	ud2		<-- trapping instruction
  2c:	48 c7 c7 60 88 c2 85 	mov    $0xffffffff85c28860,%rdi
  33:	89 ee                	mov    %ebp,%esi
  35:	31 d2                	xor    %edx,%edx
  37:	31 c9                	xor    %ecx,%ecx
  39:	e8 1f 23 21 00       	call   0x21235d
  3e:	4d                   	rex.WRB
  3f:	8d                   	.byte 0x8d

Code starting with the faulting instruction
===========================================
   0:	0f 0b                	ud2
   2:	48 c7 c7 60 88 c2 85 	mov    $0xffffffff85c28860,%rdi
   9:	89 ee                	mov    %ebp,%esi
   b:	31 d2                	xor    %edx,%edx
   d:	31 c9                	xor    %ecx,%ecx
   f:	e8 1f 23 21 00       	call   0x212333
  14:	4d                   	rex.WRB
  15:	8d                   	.byte 0x8d
[    6.485424][    C0] RSP: 0000:ffffc90000007f68 EFLAGS: 00010002
[    6.485431][    C0] RAX: 0000000000000000 RBX: 0000000000007ab8 RCX: 0000000000000000
[    6.485435][    C0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[    6.485439][    C0] RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000000
[    6.485442][    C0] R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
[    6.485446][    C0] R13: dffffc0000000000 R14: ffffffff84c8c080 R15: ffffffff84d62f90
[    6.485451][    C0] FS:  0000000000000000(0000) GS:ffffffff84cdd000(0000) knlGS:0000000000000000
[    6.485456][    C0] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    6.485459][    C0] CR2: ffff88843ffff000 CR3: 0000000004cb9000 CR4: 00000000000000b0
[    6.485467][    C0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[    6.485470][    C0] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[    6.485475][    C0] Call Trace:
[    6.485478][    C0]  <IRQ>
[ 6.485483][ C0] ? __warn (kernel/panic.c:240 kernel/panic.c:735) 
[ 6.485490][ C0] ? cpuacct_charge (kernel/sched/sched.h:1414) 
[ 6.485496][ C0] ? cpuacct_charge (kernel/sched/sched.h:1414) 
[ 6.485503][ C0] ? report_bug (lib/bug.c:?) 
[ 6.485529][ C0] ? handle_bug (arch/x86/kernel/traps.c:239) 
[ 6.485534][ C0] ? exc_invalid_op (arch/x86/kernel/traps.c:260) 
[ 6.485540][ C0] ? asm_exc_invalid_op (arch/x86/include/asm/idtentry.h:621) 
[ 6.485555][ C0] ? cpuacct_charge (kernel/sched/sched.h:1414) 
[ 6.485562][ C0] ? cpuacct_charge (kernel/sched/sched.h:1414) 
[ 6.485569][ C0] irqtime_account_delta (include/linux/cgroup.h:420) 
[ 6.485579][ C0] __irq_exit_rcu (arch/x86/include/asm/preempt.h:84 kernel/softirq.c:635) 
[ 6.485586][ C0] irq_exit_rcu (kernel/softirq.c:651) 
[ 6.485591][ C0] common_interrupt (arch/x86/kernel/irq.c:278) 
[    6.485597][    C0]  </IRQ>
[    6.485600][    C0]  <TASK>
[ 6.485605][ C0] asm_common_interrupt (arch/x86/include/asm/idtentry.h:693) 
[ 6.485610][ C0] RIP: 0010:console_flush_all (kernel/printk/printk.c:3055) 
[ 6.485619][ C0] Code: 1d 00 4d 85 f6 74 05 e8 7e 94 49 02 44 0f b6 74 24 07 f7 c3 00 02 00 00 48 bb 00 00 00 00 00 fc ff df 74 01 fb 48 8b 44 24 38 <0f> b6 04 18 84 c0 0f 85 ec 01 00 00 41 80 7d 00 00 4c 8b 7c 24 50
All code
========
   0:	1d 00 4d 85 f6       	sbb    $0xf6854d00,%eax
   5:	74 05                	je     0xc
   7:	e8 7e 94 49 02       	call   0x249948a
   c:	44 0f b6 74 24 07    	movzbl 0x7(%rsp),%r14d
  12:	f7 c3 00 02 00 00    	test   $0x200,%ebx
  18:	48 bb 00 00 00 00 00 	movabs $0xdffffc0000000000,%rbx
  1f:	fc ff df 
  22:	74 01                	je     0x25
  24:	fb                   	sti
  25:	48 8b 44 24 38       	mov    0x38(%rsp),%rax
  2a:*	0f b6 04 18          	movzbl (%rax,%rbx,1),%eax		<-- trapping instruction
  2e:	84 c0                	test   %al,%al
  30:	0f 85 ec 01 00 00    	jne    0x222
  36:	41 80 7d 00 00       	cmpb   $0x0,0x0(%r13)
  3b:	4c 8b 7c 24 50       	mov    0x50(%rsp),%r15

Code starting with the faulting instruction
===========================================
   0:	0f b6 04 18          	movzbl (%rax,%rbx,1),%eax
   4:	84 c0                	test   %al,%al
   6:	0f 85 ec 01 00 00    	jne    0x1f8
   c:	41 80 7d 00 00       	cmpb   $0x0,0x0(%r13)
  11:	4c 8b 7c 24 50       	mov    0x50(%rsp),%r15
[    6.485623][    C0] RSP: 0000:ffffffff84c07c68 EFLAGS: 00000206
[    6.485630][    C0] RAX: 1ffffffff0980fa8 RBX: dffffc0000000000 RCX: 0000000000000000
[    6.485633][    C0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[    6.485637][    C0] RBP: ffffffff85620b00 R08: 0000000000000000 R09: 0000000000000000
[    6.485640][    C0] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000016
[    6.485644][    C0] R13: ffffffff84c07d47 R14: 0000000000000001 R15: 00000000ffffffff
[ 6.485660][ C0] ? console_flush_all (arch/x86/include/asm/irqflags.h:142) 
[ 6.485670][ C0] ? console_flush_all (include/linux/rcupdate.h:331 include/linux/srcu.h:267 kernel/printk/printk.c:286 kernel/printk/printk.c:3041) 
[ 6.485686][ C0] console_unlock (kernel/printk/printk.c:3119) 
[ 6.485697][ C0] vprintk_emit (kernel/printk/printk.c:?) 
[ 6.485708][ C0] _printk (kernel/printk/printk.c:2376) 
[ 6.485724][ C0] __clocksource_register_scale (kernel/time/clocksource.c:1224) 
[ 6.485739][ C0] tsc_init (arch/x86/kernel/tsc.c:1566) 
[ 6.485750][ C0] x86_late_time_init (arch/x86/include/asm/cpufeature.h:178 arch/x86/kernel/time.c:85) 
[ 6.485756][ C0] start_kernel (init/main.c:1066) 
[ 6.485765][ C0] x86_64_start_reservations (arch/x86/kernel/ebda.c:57) 
[ 6.485771][ C0] x86_64_start_kernel (arch/x86/kernel/head64.c:437) 
[ 6.485778][ C0] common_startup_64 (arch/x86/kernel/head_64.S:421) 
[    6.485795][    C0]  </TASK>
[    6.485798][    C0] irq event stamp: 2166
[ 6.485801][ C0] hardirqs last enabled at (2165): console_flush_all (arch/x86/include/asm/irqflags.h:19) 
[ 6.485807][ C0] hardirqs last disabled at (2166): common_interrupt (arch/x86/include/asm/ptrace.h:214 arch/x86/kernel/irq.c:278) 
[ 6.485813][ C0] softirqs last enabled at (1370): handle_softirqs (arch/x86/include/asm/preempt.h:26 kernel/softirq.c:401 kernel/softirq.c:582) 
[ 6.485818][ C0] softirqs last disabled at (1359): __irq_exit_rcu (include/linux/sched.h:2183 kernel/softirq.c:620 kernel/softirq.c:639) 
[    6.485822][    C0] ---[ end trace 0000000000000000 ]---


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240926/202409261230.c7f0e4eb-lkp@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING

[Yafang Shao]

On Thu, Sep 26, 2024 at 2:14 PM kernel test robot <oliver.sang@intel.com> wrote:
>
>
>
> Hello,
>
> kernel test robot noticed "WARNING:at_kernel/sched/sched.h:#cpuacct_charge" on:
>
> commit: e5633f7cf7d093cf5bb191663054441fbc745a5a ("[PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING")
> url: https://github.com/intel-lab-lkp/linux/commits/Yafang-Shao/sched-Fix-cgroup-irq-accounting-for-CONFIG_IRQ_TIME_ACCOUNTING/20240923-170321
> base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git bc9057da1a220ff2cb6c8885fd5352558aceba2c
> patch link: https://lore.kernel.org/all/20240923090028.16368-2-laoar.shao@gmail.com/
> patch subject: [PATCH 1/3] sched: Fix cgroup irq accounting for CONFIG_IRQ_TIME_ACCOUNTING
>
> in testcase: boot
>
> compiler: clang-18
> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
> +-------------------------------------------------+------------+------------+
> |                                                 | bc9057da1a | e5633f7cf7 |
> +-------------------------------------------------+------------+------------+
> | boot_successes                                  | 12         | 0          |
> | boot_failures                                   | 0          | 12         |
> | RIP:cpuacct_charge                              | 0          | 12         |
> | WARNING:at_kernel/sched/sched.h:#cpuacct_charge | 0          | 12         |
> | RIP:console_flush_all                           | 0          | 12         |
> | RIP:ftrace_likely_update                        | 0          | 12         |
> | RIP:desc_read                                   | 0          | 12         |
> | RIP:handle_softirqs                             | 0          | 12         |
> | RIP:kasan_check_range                           | 0          | 12         |
> | RIP:_prb_read_valid                             | 0          | 12         |
> +-------------------------------------------------+------------+------------+
>
>
> If you fix the issue in a separate patch/commit (i.e. not just a new version of
> the same patch/commit), kindly add following tags
> | Reported-by: kernel test robot <oliver.sang@intel.com>
> | Closes: https://lore.kernel.org/oe-lkp/202409261230.c7f0e4eb-lkp@intel.com

Thanks for the report.
The rq_lock should be held. I missed it.

-- 
Regards
Yafang