linux-kernel - Re: [PATCH v4 4/4] rcu: Add RCU stall diagnosis information

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <3adb6360-ac90-2ef7-5dcb-e2013f19dd13@huawei.com>
Date:   Tue, 8 Nov 2022 11:18:53 +0800
From:   "Leizhen (ThunderTown)" <thunder.leizhen@...wei.com>
To:     "Elliott, Robert (Servers)" <elliott@....com>,
        "paulmck@...nel.org" <paulmck@...nel.org>
CC:     Frederic Weisbecker <frederic@...nel.org>,
        Neeraj Upadhyay <quic_neeraju@...cinc.com>,
        Josh Triplett <josh@...htriplett.org>,
        "Steven Rostedt" <rostedt@...dmis.org>,
        Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
        Lai Jiangshan <jiangshanlai@...il.com>,
        Joel Fernandes <joel@...lfernandes.org>,
        "rcu@...r.kernel.org" <rcu@...r.kernel.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH v4 4/4] rcu: Add RCU stall diagnosis information



On 2022/11/8 4:38, Elliott, Robert (Servers) wrote:
> 
> 
>>> Maybe this shouldn't be a table? Make it grep-friendly:
>>> [ 1816.719922] rcu: half-timeout counts: hardirq =5 softirq=10 csw=0
>>> [ 1816.725643] rcu: half_timeout cputimes (ms): time=1500 hardirq=3
>> softirq=0 system=1492
>>
>> I prefer the table. Table look clearer and easier to compare.
> 
> Here's an example where it also triggers expedited stalls. The 
> self-detected stall prints including the new table can end up
> interleaved with the expedited stall prints.

But even if use your format, it won't solve the printing
interleaving problem. We should use lock.

> 
> (the table is expanded a bit here to experiment with adding more info, 
> and I included the \t prefixes)
> 
> [  933.728032] tcrypt: rcu testing - kernel_fpu_disable for rude 6 s
> [  938.038278] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 46-.... } 4 jiffies s: 521 root: 0x8/.
> [  938.049151] rcu: blocking rcu_node structures (internal RCU debug): l=1:42-55:0x10/.
> [  938.057236] Sending NMI from CPU 35 to CPUs 46:
> [  938.062048] NMI backtrace for cpu 46
> [  938.062050] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  938.062052] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  938.062053] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  938.062151]  </TASK>
> [  938.073277] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 46-.... } 289 jiffies s: 521 root: 0x8/.
> [  938.334292] rcu: blocking rcu_node structures (internal RCU debug): l=1:42-55:0x10/.
> [  938.342289] Sending NMI from CPU 35 to CPUs 46:
> [  938.347049] NMI backtrace for cpu 46
> [  938.347050] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  938.347051] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  938.347052] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  938.347121]  </TASK>
> [  938.358275] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 46-.... } 573 jiffies s: 521 root: 0x8/.
> [  938.619182] rcu: blocking rcu_node structures (internal RCU debug): l=1:42-55:0x10/.
> [  938.627179] Sending NMI from CPU 35 to CPUs 46:
> [  938.631939] NMI backtrace for cpu 46
> [  938.631939] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  938.631941] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  938.631942] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  938.631997]  </TASK>
> [  938.643272] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
> [  938.734267] rcu: INFO: rcu_preempt self-detected stall on CPU
> [  938.740111]  46-....
> [  938.747282] rcu:     46-....: (4948 ticks this GP) idle=a9cc/1/0x4000000000000000 softirq=7598/7598 fqs=1253
> [  938.747285] rcu:               hardirqs   softirqs          csw     system cond_resched
> [  938.747286] rcu:      number:        0          0            0                      0
> [  938.754461]  } 720 jiffies s: 521 root: 0x8/.
> [  938.757178] rcu:     cputime:       62          0                     2436              ==> 2500 (ms)
> [  938.757179] rcu:     current: in_kernel_fpu_begin=1 this_cpu_preemptible=0
> [  938.757181]  (t=5023 jiffies g=61053 q=704 ncpus=56)
> [  938.759640] rcu: blocking rcu_node structures (internal RCU debug):
> 
> The first "46-" line is from the expedited stall.
> The second "46-" line is from the self-detected stall.
> The table lines are from the self-detected stall.
> The "} 720" line is from the expedited stall.
> The "(t=5023" line is from the self-detected stall.
> The "blocking" line is from the expedited stall.
> 
> [  938.761745] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  938.761747] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  938.982118] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  939.221833]  </TASK>
> [  939.224239]  l=1:42-55:0x10/.
> [  939.227440] Sending NMI from CPU 35 to CPUs 46:
> [  939.232204] NMI backtrace for cpu 46
> [  939.232205] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  939.232206] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  939.232207] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  939.232262]  </TASK>
> [  939.243264] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 46-.... } 1458 jiffies s: 521 root: 0x8/.
> [  939.503926] rcu: blocking rcu_node structures (internal RCU debug): l=1:42-55:0x10/.
> [  939.511920] Sending NMI from CPU 35 to CPUs 46:
> [  939.516678] NMI backtrace for cpu 46
> [  939.516679] CPU: 46 PID: 44184 Comm: modprobe Not tainted 6.0.0+ #11
> [  939.516680] Hardware name: HPE ProLiant DL360 Gen10/ProLiant DL360 Gen10, BIOS U32 03/08/2022
> [  939.516680] RIP: 0010:rude_sleep_cycles+0x13/0x27 [tcrypt]
> ...
> [  939.516732]  </TASK>
> [  939.528263] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
> [  939.748586] initcall tcrypt_mod_init+0x0/0x1000 [tcrypt] returned -11 after 6020623 usecs
> [  939.753200]  46-.... } 1718 jiffies s: 521 root: 0x8/.
> [  939.791580] rcu: blocking rcu_node structures (internal RCU debug):
> 
> 

-- 
Regards,
  Zhen Lei