| Demonstrations of criticalstat: Find long atomic critical sections in the kernel. |
| |
| criticalstat traces and reports occurrences of atomic critical sections in the |
| kernel with useful stacktraces showing the origin of them. Such critical |
| sections frequently occur due to use of spinlocks, or if interrupts or |
| preemption were explicitly disabled by a driver. IRQ routines in Linux are also |
| executed with interrupts disabled. There are many reasons. Such critical |
| sections are a source of long latency/responsive issues for real-time systems. |
| |
| This works by probing the preempt/irq and cpuidle tracepoints in the kernel. |
| Since this uses BPF, only the root user can use this tool. Further, the kernel |
| has to be built with certain CONFIG options enabled inorder for it to work: |
| CONFIG_PREEMPTIRQ_EVENTS before kernel 4.19 |
| CONFIG_PREEMPTIRQ_TRACEPOINTS in kernel 4.19 and later |
| CONFIG_DEBUG_PREEMPT |
| CONFIG_PREEMPT_TRACER |
| Additionally, the following options should be turned off on older kernels: |
| CONFIG_PROVE_LOCKING |
| CONFIG_LOCKDEP |
| |
| USAGE: |
| # ./criticalstat -h |
| usage: criticalstat [-h] [-p] [-i] [-d DURATION] |
| |
| Trace long critical sections |
| |
| optional arguments: |
| -h, --help Show this help message and exit |
| -p, --preemptoff Find long sections where preemption was off |
| -i, --irqoff Find long sections where IRQ was off |
| -d DURATION, --duration DURATION |
| Duration in uS (microseconds) below which we filter |
| |
| examples: |
| ./criticalstat # run with default options: irq off for more than 100 uS |
| ./criticalstat -p # find sections with preemption disabled for more than 100 uS |
| ./criticalstat -d 500 # find sections with IRQs disabled for more than 500 uS |
| ./criticalstat -p -d 500 # find sections with preemption disabled for more than 500 uS |
| |
| The tool runs continuously until interrupted by Ctrl-C |
| |
| |
| By default, criticalstat finds IRQ disable sections for > 100us. |
| |
| # ./criticalstat |
| Finding critical section with IRQ disabled for > 100us |
| =================================== |
| TASK: kworker/u16:5 (pid 5903 tid 5903) Total Time: 194.427 us |
| |
| Section start: __schedule -> schedule |
| Section end: _raw_spin_unlock_irq -> finish_task_switch |
| trace_hardirqs_on+0xdc |
| trace_hardirqs_on+0xdc |
| _raw_spin_unlock_irq+0x18 |
| finish_task_switch+0xf0 |
| __schedule+0x8c8 |
| preempt_schedule_irq+0x38 |
| el1_preempt+0x8 |
| =================================== |
| |
| |
| If too many sections are showing up, the user can raise the threshold to only |
| show critical sections that are > 500us by passing "-d" option: |
| |
| # ./criticalstat -d 500 |
| Finding critical section with IRQ disabled for > 500us |
| =================================== |
| TASK: crtc_commit:111 (pid 246 tid 246) Total Time: 580.730 us |
| |
| Section start: clk_enable_lock -> clk_enable |
| Section end: _raw_spin_unlock_irqrestore -> clk_enable |
| trace_hardirqs_on+0xdc |
| trace_hardirqs_on+0xdc |
| _raw_spin_unlock_irqrestore+0x24 |
| clk_enable+0x80 |
| msm_dss_enable_clk+0x7c |
| sde_power_resource_enable+0x578 |
| _sde_crtc_vblank_enable_no_lock+0x68 |
| sde_crtc_vblank+0x8c |
| sde_kms_enable_vblank+0x18 |
| vblank_ctrl_worker+0xd0 |
| kthread_worker_fn+0xf8 |
| kthread+0x114 |
| ret_from_fork+0x10 |
| =================================== |
| |
| |
| If instead of irq disabled sections, we want to see preempt disabled sections, |
| then pass the "-p" option. Below we try to find preempt-disabled critical |
| sections that are > 500us. |
| |
| # ./criticalstat -p -d 500 |
| Finding critical section with preempt disabled for > 500us |
| =================================== |
| TASK: swapper/1 (pid 0 tid 0) Total Time: 618.437 us |
| |
| Section start: preempt_count_add -> preempt_count_add |
| Section end: preempt_count_sub -> preempt_count_sub |
| trace_preempt_on+0x98 |
| trace_preempt_on+0x98 |
| preempt_latency_stop+0x164 |
| preempt_count_sub+0x50 |
| schedule+0x74 |
| schedule_preempt_disabled+0x14 |
| cpu_startup_entry+0x84 |
| secondary_start_kernel+0x1c8 |
| [unknown] |
| =================================== |
| |
| |
| criticalstat -p can also reflect kernel scheduler issues sometimes. These may |
| show up as long preempt-off sections if the functions in the scheduler take a |
| long time to run (such as pick_next_task_fair which selects the CPU for a task |
| |
| Follow is a report showing a preempt-off latency of 700us during the schedule |
| loop's execution: |
| |
| =================================== |
| TASK: irq/296-cs35l36 (pid 666 tid 666) Total Time: 732.657 us |
| |
| Section start: schedule -> schedule |
| Section end: schedule -> schedule |
| trace_preempt_on+0x98 |
| trace_preempt_on+0x98 |
| preempt_count_sub+0xa4 |
| schedule+0x78 |
| schedule_timeout+0x80 |
| wait_for_common+0xb4 |
| wait_for_completion_timeout+0x28 |
| geni_i2c_xfer+0x298 |
| __i2c_transfer+0x4e0 |
| i2c_transfer+0x8 |
| irq_thread_fn+0x2c |
| irq_thread+0x160 |
| kthread+0x118 |
| ret_from_fork+0x10 |
| =================================== |
| |
| |
| See Also: Linux kernel's preemptoff and irqoff tracers which provide similar |
| tracing but with some limitations. |
