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

[Leizhen (ThunderTown)]

On 2022/11/5 9:58, Elliott, Robert (Servers) wrote:
> 
>> --- a/kernel/rcu/Kconfig.debug
>> +++ b/kernel/rcu/Kconfig.debug
>> @@ -95,6 +95,16 @@ config RCU_EXP_CPU_STALL_TIMEOUT
>>  	  says to use the RCU_CPU_STALL_TIMEOUT value converted from
>>  	  seconds to milliseconds.
>>
>> +config RCU_CPU_STALL_CPUTIME
> 
> Since the information might change and grow over time, consider
> calling it "ADDITIONAL_INFO" rather than just "CPUTIME".

I think it's okay. But I need to wait for Paul's opinion.
In fact, I've also considered using MORE_DEBUG_INFO.

> 
>> +	bool "Provide additional rcu stall debug information"
>> +	depends on RCU_STALL_COMMON
>> +	default n
>> +	help
>> +	  Statistics during the period from RCU_CPU_STALL_TIMEOUT/2 to
>> +	  RCU_CPU_STALL_TIMEOUT, such as the number of (hard interrupts,
>> soft
>> +	  interrupts, task switches) and the cputime of (hard interrupts,
>> soft
>> +	  interrupts, kerenl tasks) are added to the rcu stall report.
> 
> s/kerenl/kernel/

Good catch.

> 
> Those parenthetical words are not grammatically correct, and
> nobody will remember to update Kconfig if they change the code.
> 
> Try making it is a little less precise: 
> "Collect statistics during the RCU stall timeout period

the second half period of RCU stall timeout

> (e.g., counts and CPU time consumed by hard interrupts, soft
> interrupts, task switches, and kernel tasks) and include

Maybe we can remove "task switches, and kernel tasks". Just for example,
no need to exhaustively.

> them in the RCU stall console error message."

Looks good above. Thanks.

> 
> ...
>> +
>> +	pr_err("         hardirqs   softirqs   csw/system\n");
>> +	pr_err(" number: %8ld %10d %12lld\n",
> 
> Everything after a %d is a "number". These are more specifically counts.
> 
>> +		kstat_cpu_irqs_sum(cpu) - rsrp->nr_hardirqs,
>> +		kstat_cpu_softirqs_sum(cpu) - rsrp->nr_softirqs,
>> +		nr_context_switches_cpu(cpu) - rsrp->nr_csw);
> 
> Two columns are plural and one is not. 

I didn't understand. Do you mean:
(1)
             hardirqs   softirqs  csw  system
     number:                      xx   N/A
cputime(ms):                      N/A   xx

> 
> Within a few lines, this is referred to as "context_switches", cws, 
> and "task switches." One term would be better. vmstat uses "cs", 
> pidstat uses "cswch", and /proc/<pid>/status uses "ctxt_switches,"
> so there's not one ideal term for that column. Matching one
> of those might be better than using another unique name.

struct task_struct {
        /* Context switch counts: */
        unsigned long                   nvcsw;
        unsigned long                   nivcsw;

There's nothing wrong with 'csw'.

> 
> Since no other variants are shown, the "/system" suffix is a bit
> confusing.

I don't think it's a problem! Because the prefix cputime already exists,
so CPUTIME_SYSTEM --> system.

How about:
             hardirqs   softirqs  tasks
     counts:
cputime(ms):

It's like drawing a head with a pipe in the men's room, and a head with
long hair in the women's room. Although women may also have smokers, men
may also have long hair. Oh, the example right in front of us, who would
interpret the first line as the number of interrupt types? So I think
it's pretty good to use 'tasks'.

> 
> 
>> +	pr_err("cputime: %8lld %10lld %12lld   ==> %lld(ms)\n",
>> +		div_u64(cpustat[CPUTIME_IRQ] - rsrp->cputime_irq, NSEC_PER_MSEC),
>> +		div_u64(cpustat[CPUTIME_SOFTIRQ] - rsrp->cputime_softirq, NSEC_PER_MSEC),
>> +		div_u64(cpustat[CPUTIME_SYSTEM] - rsrp->cputime_system, NSEC_PER_MSEC),
>> +		jiffies64_to_msecs(half_timeout));
> 
> There is no column header for that fourth number. "half_timeout"
> might be good, dropping the "==>".

If we use words, I'll use "sampling period" or "period".

To be honest, the printed information of the RCU needs to be understood in
combination with the code. For exmaple:

pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%04x/%ld/%#lx softirq=%u/%u fqs=%ld%s%s\n",
               cpu,
               "O."[!!cpu_online(cpu)],
               "o."[!!(rdp->grpmask & rdp->mynode->qsmaskinit)],
               "N."[!!(rdp->grpmask & rdp->mynode->qsmaskinitnext)],

Paul mentioned a few days ago that there were complaints that the RCU was
printing too much. So "==>" is better suited for people who often deal with
rcu stall issues.

> 
> The "(ms)" at the end is awkward. Try moving it to the left
> as "cputime (ms): "

OK

> 
>> +int rcu_cpu_stall_cputime __read_mostly =
>> IS_ENABLED(CONFIG_RCU_CPU_STALL_CPUTIME);
> 
> As a config option and module parameter, adding some more
> instrumentation overhead might be worthwhile for other
> likely causes of rcu stalls.
> 
> For example, if enabled, have these functions (if available
> on the architecture) maintain a per-CPU running count of
> their invocations, which also cause the CPU to be unavailable
> for rcu: 
> - kernel_fpu_begin() calls - FPU/SIMD context preservation,
>   which also calls preempt_disable()
> - preempt_disable() calls - scheduler context switches disabled
> - local_irq_save() calls - interrupts disabled
> - cond_resched() calls - lack of these is a problem
> 
> For kernel_fpu_begin and preempt_disable, knowing if it is
> currently blocked for those reasons is probably the most
> helpful.

These instructions is already in Documentation/RCU/stallwarn.rst

> 
> .
> 

-- 
Regards,
  Zhen Lei