How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?

From: Paul Menzel
Date: Tue Aug 28 2018 - 01:27:20 EST

Next message: Previous message:
Next in thread:
Messages sorted by:
Dear Linux folks,

Using `sleepgraph.py` [1][2] to profile shows that `ksys_enter` takes a noticeable

13 ms on a TUXEDO Book BU1406 with the MZVKW512HMJP-00000*, which is quite good, E350M1 with an SSD SanDisk device.

Adding `devicefilter: ksys_sync` to `config/sus running `sudo ./sleepgraph.py -config attached HTML output shows, that `iterate_supers`

â `iterate_supers` (6.316 ms @ â `iterate_supers` (0.201 ms @ â `iterate_supers` (7.421 ms @
Normally, `sync_inodes_one_sb` only takes cases it takes several milliseconds.

â sync_inodes_one_sb (0.001 ms â sync_inodes_one_sb (5.978 ms â sync_inodes_one_sb (0.001 ms
Please find an excerpt from the call graph the time increase between 388.944751 and

Description: application/7z-compressed href="02001.html"> Joe Perches: "[PATCH] checkpatch: Add __ro_after_init to known $Attribute" AKASHI Takahiro: "Re: [PATCH v13 03/16] s390, kexec_file: drop arch_kexec_mem_walk()" Paul Menzel: "Re: How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?" href="date.html#02000">[ date ] [ thread ] [ subject ] [ author ] the suspend to RAM (STR) times, amount of time. NVMe device *SAMSUNG and over a 60 ms on ASRock pend-callgraph.cfg`, and config/suspend-callgraph.cfg`, the takes 6 to 7 ms twice. 388.944557)
388.950873)
388.951074)
microseconds, but once in both @ 388.944660)
@ 388.944665)
@ 388.950645)
from ftrace below, and note 388.950636. solid 0.2em; margin: 0em; padding-left: 0.85em"> | wb_wait_for_completion() {
| _cond_resched() {
rcu_all_qs();
} /* _cond_resched */
init_wait_entry();
| prepare_to_wait_event() {
_raw_spin_lock_irqsave();
_raw_spin_unlock_irqrestore();
} /* prepare_to_wait_event */
| schedule() {
rcu_note_context_switch();
_raw_spin_lock();
update_rq_clock();
| deactivate_task() {
| dequeue_task_fair() {
| dequeue_entity() {
| update_curr() {
update_min_vruntime();
cpuacct_charge();
| __cgroup_account_cputime() {
cgroup_rstat_updated();
} /* __cgroup_account_cputime */
} /* update_curr */
__update_load_avg_se();
__update_load_avg_cfs_rq();
clear_buddies();
account_entity_dequeue();
update_cfs_group();
} /* dequeue_entity */
| dequeue_entity() {
| update_curr() {
__calc_delta();
update_min_vruntime();
} /* update_curr */
__update_load_avg_se();
__update_load_avg_cfs_rq();
clear_buddies();
account_entity_dequeue();
| update_cfs_group() {
reweight_entity();
} /* update_cfs_group */
} /* dequeue_entity */
hrtick_update();
} /* dequeue_task_fair */
} /* deactivate_task */
| pick_next_task_fair() {
| update_blocked_averages() {
_raw_spin_lock_irqsave();
update_rq_clock();
__update_load_avg_cfs_rq();
__update_load_avg_se();
__update_load_avg_cfs_rq();
__update_load_avg_cfs_rq();
| update_rt_rq_load_avg() {
__accumulate_pelt_segments();
} /* update_rt_rq_load_avg */
| update_dl_rq_load_avg() {
__accumulate_pelt_segments();
} /* update_dl_rq_load_avg */
_raw_spin_unlock_irqrestore();
} /* update_blocked_averages */
| load_balance() {
| find_busiest_group() {
update_nohz_stats();
idle_cpu();
update_nohz_stats();
} /* find_busiest_group */
} /* load_balance */
__msecs_to_jiffies();
| load_balance() {
| find_busiest_group() {
update_nohz_stats();
idle_cpu();
update_nohz_stats();
update_nohz_stats();
idle_cpu();
update_nohz_stats();
idle_cpu();
} /* find_busiest_group */
} /* load_balance */
__msecs_to_jiffies();
_raw_spin_lock();
} /* pick_next_task_fair */
| pick_next_task_idle() {
| put_prev_task_fair() {
| put_prev_entity() {
check_cfs_rq_runtime();
} /* put_prev_entity */
| put_prev_entity() {
check_cfs_rq_runtime();
} /* put_prev_entity */
} /* put_prev_task_fair */
__update_idle_core();
} /* pick_next_task_idle */
| enter_lazy_tlb() {
| switch_mm() {
| switch_mm_irqs_off() {
load_new_mm_cr3();
} /* switch_mm_irqs_off */
} /* switch_mm */
} /* enter_lazy_tlb */
finish_task_switch();
} /* schedule */
| prepare_to_wait_event() {
_raw_spin_lock_irqsave();
_raw_spin_unlock_irqrestore();
} /* prepare_to_wait_event */
| finish_wait() {
_raw_spin_lock_irqsave();
_raw_spin_unlock_irqrestore();
} /* finish_wait */
} /* wb_wait_for_completion */
is in `schedule`, is it related Skylake i7-7500U CPU @ 2.70GHz laptop should have enough NVMe device.
.0/nvme/nvme0/nvme0n1/queue/scheduler spendresume">https://01.org/suspendresume
m/01org/pm-graph">https://github.com/01org/pm-graph
>helmuth-N24-25BU_mem.html.7z

Next message: Joe Perches: "[PATCH] checkpatch: Add __ro_after_init to known $Attribute"
Previous message: AKASHI Takahiro: "Re: [PATCH v13 03/16] s390, kexec_file: drop arch_kexec_mem_walk()"
Next in thread: Paul Menzel: "Re: How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]