* How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?
@ 2018-08-28 5:27 Paul Menzel
2018-08-28 11:43 ` Paul Menzel
0 siblings, 1 reply; 2+ messages in thread
From: Paul Menzel @ 2018-08-28 5:27 UTC (permalink / raw)
To: linux-fsdevel; +Cc: LKML
[-- Attachment #1: Type: text/plain, Size: 12081 bytes --]
Dear Linux folks,
Using `sleepgraph.py` [1][2] to profile the suspend to RAM (STR) times,
shows that `ksys_enter` takes a noticeable amount of time.
13 ms on a TUXEDO Book BU1406 with the NVMe device *SAMSUNG
MZVKW512HMJP-00000*, which is quite good, and over a 60 ms on ASRock
E350M1 with an SSD SanDisk device.
Adding `devicefilter: ksys_sync` to `config/suspend-callgraph.cfg`, and
running `sudo ./sleepgraph.py -config config/suspend-callgraph.cfg`, the
attached HTML output shows, that `iterate_supers` takes 6 to 7 ms twice.
• `iterate_supers` (6.316 ms @ 388.944557)
• `iterate_supers` (0.201 ms @ 388.950873)
• `iterate_supers` (7.421 ms @ 388.951074)
Normally, `sync_inodes_one_sb` only takes microseconds, but once in both
cases it takes several milliseconds.
• sync_inodes_one_sb (0.001 ms @ 388.944660)
• sync_inodes_one_sb (5.978 ms @ 388.944665)
• sync_inodes_one_sb (0.001 ms @ 388.950645)
Please find an excerpt from the call graph from ftrace below, and note
the time increase between 388.944751 and 388.950636.
> 388.944700 | 0) sleepgr-11355 | | wb_wait_for_completion() {
> 388.944701 | 0) sleepgr-11355 | | _cond_resched() {
> 388.944701 | 0) sleepgr-11355 | 0.064 us | rcu_all_qs();
> 388.944702 | 0) sleepgr-11355 | 0.664 us | } /* _cond_resched */
> 388.944702 | 0) sleepgr-11355 | 0.067 us | init_wait_entry();
> 388.944703 | 0) sleepgr-11355 | | prepare_to_wait_event() {
> 388.944703 | 0) sleepgr-11355 | 0.080 us | _raw_spin_lock_irqsave();
> 388.944704 | 0) sleepgr-11355 | 0.073 us | _raw_spin_unlock_irqrestore();
> 388.944704 | 0) sleepgr-11355 | 1.388 us | } /* prepare_to_wait_event */
> 388.944705 | 0) sleepgr-11355 | | schedule() {
> 388.944705 | 0) sleepgr-11355 | 0.085 us | rcu_note_context_switch();
> 388.944706 | 0) sleepgr-11355 | 0.064 us | _raw_spin_lock();
> 388.944707 | 0) sleepgr-11355 | 0.093 us | update_rq_clock();
> 388.944708 | 0) sleepgr-11355 | | deactivate_task() {
> 388.944708 | 0) sleepgr-11355 | | dequeue_task_fair() {
> 388.944708 | 0) sleepgr-11355 | | dequeue_entity() {
> 388.944709 | 0) sleepgr-11355 | | update_curr() {
> 388.944709 | 0) sleepgr-11355 | 0.095 us | update_min_vruntime();
> 388.944710 | 0) sleepgr-11355 | 0.126 us | cpuacct_charge();
> 388.944710 | 0) sleepgr-11355 | | __cgroup_account_cputime() {
> 388.944711 | 0) sleepgr-11355 | 0.055 us | cgroup_rstat_updated();
> 388.944711 | 0) sleepgr-11355 | 0.675 us | } /* __cgroup_account_cputime */
> 388.944712 | 0) sleepgr-11355 | 2.779 us | } /* update_curr */
> 388.944712 | 0) sleepgr-11355 | 0.121 us | __update_load_avg_se();
> 388.944713 | 0) sleepgr-11355 | 0.118 us | __update_load_avg_cfs_rq();
> 388.944713 | 0) sleepgr-11355 | 0.056 us | clear_buddies();
> 388.944714 | 0) sleepgr-11355 | 0.066 us | account_entity_dequeue();
> 388.944714 | 0) sleepgr-11355 | 0.050 us | update_cfs_group();
> 388.944715 | 0) sleepgr-11355 | 6.127 us | } /* dequeue_entity */
> 388.944715 | 0) sleepgr-11355 | | dequeue_entity() {
> 388.944715 | 0) sleepgr-11355 | | update_curr() {
> 388.944716 | 0) sleepgr-11355 | 0.097 us | __calc_delta();
> 388.944716 | 0) sleepgr-11355 | 0.071 us | update_min_vruntime();
> 388.944717 | 0) sleepgr-11355 | 1.473 us | } /* update_curr */
> 388.944717 | 0) sleepgr-11355 | 0.142 us | __update_load_avg_se();
> 388.944718 | 0) sleepgr-11355 | 0.100 us | __update_load_avg_cfs_rq();
> 388.944719 | 0) sleepgr-11355 | 0.069 us | clear_buddies();
> 388.944719 | 0) sleepgr-11355 | 0.098 us | account_entity_dequeue();
> 388.944720 | 0) sleepgr-11355 | | update_cfs_group() {
> 388.944720 | 0) sleepgr-11355 | 0.110 us | reweight_entity();
> 388.944721 | 0) sleepgr-11355 | 0.847 us | } /* update_cfs_group */
> 388.944721 | 0) sleepgr-11355 | 6.197 us | } /* dequeue_entity */
> 388.944722 | 0) sleepgr-11355 | 0.053 us | hrtick_update();
> 388.944722 | 0) sleepgr-11355 | 14.141 us | } /* dequeue_task_fair */
> 388.944723 | 0) sleepgr-11355 | 14.827 us | } /* deactivate_task */
> 388.944723 | 0) sleepgr-11355 | | pick_next_task_fair() {
> 388.944723 | 0) sleepgr-11355 | | update_blocked_averages() {
> 388.944724 | 0) sleepgr-11355 | 0.070 us | _raw_spin_lock_irqsave();
> 388.944724 | 0) sleepgr-11355 | 0.090 us | update_rq_clock();
> 388.944725 | 0) sleepgr-11355 | 0.120 us | __update_load_avg_cfs_rq();
> 388.944726 | 0) sleepgr-11355 | 0.162 us | __update_load_avg_se();
> 388.944727 | 0) sleepgr-11355 | 0.090 us | __update_load_avg_cfs_rq();
> 388.944727 | 0) sleepgr-11355 | 0.081 us | __update_load_avg_cfs_rq();
> 388.944728 | 0) sleepgr-11355 | | update_rt_rq_load_avg() {
> 388.944728 | 0) sleepgr-11355 | 0.063 us | __accumulate_pelt_segments();
> 388.944729 | 0) sleepgr-11355 | 0.785 us | } /* update_rt_rq_load_avg */
> 388.944729 | 0) sleepgr-11355 | | update_dl_rq_load_avg() {
> 388.944730 | 0) sleepgr-11355 | 0.066 us | __accumulate_pelt_segments();
> 388.944730 | 0) sleepgr-11355 | 0.763 us | } /* update_dl_rq_load_avg */
> 388.944731 | 0) sleepgr-11355 | 0.061 us | _raw_spin_unlock_irqrestore();
> 388.944731 | 0) sleepgr-11355 | 7.452 us | } /* update_blocked_averages */
> 388.944731 | 0) sleepgr-11355 | | load_balance() {
> 388.944732 | 0) sleepgr-11355 | | find_busiest_group() {
> 388.944732 | 0) sleepgr-11355 | 0.100 us | update_nohz_stats();
> 388.944733 | 0) sleepgr-11355 | 0.057 us | idle_cpu();
> 388.944734 | 0) sleepgr-11355 | 0.098 us | update_nohz_stats();
> 388.944734 | 0) sleepgr-11355 | 2.407 us | } /* find_busiest_group */
> 388.944735 | 0) sleepgr-11355 | 3.120 us | } /* load_balance */
> 388.944735 | 0) sleepgr-11355 | 0.065 us | __msecs_to_jiffies();
> 388.944736 | 0) sleepgr-11355 | | load_balance() {
> 388.944736 | 0) sleepgr-11355 | | find_busiest_group() {
> 388.944736 | 0) sleepgr-11355 | 0.087 us | update_nohz_stats();
> 388.944737 | 0) sleepgr-11355 | 0.063 us | idle_cpu();
> 388.944738 | 0) sleepgr-11355 | 0.086 us | update_nohz_stats();
> 388.944739 | 0) sleepgr-11355 | 0.068 us | update_nohz_stats();
> 388.944739 | 0) sleepgr-11355 | 0.098 us | idle_cpu();
> 388.944740 | 0) sleepgr-11355 | 0.094 us | update_nohz_stats();
> 388.944741 | 0) sleepgr-11355 | 0.065 us | idle_cpu();
> 388.944741 | 0) sleepgr-11355 | 5.160 us | } /* find_busiest_group */
> 388.944742 | 0) sleepgr-11355 | 5.831 us | } /* load_balance */
> 388.944742 | 0) sleepgr-11355 | 0.062 us | __msecs_to_jiffies();
> 388.944743 | 0) sleepgr-11355 | 0.065 us | _raw_spin_lock();
> 388.944743 | 0) sleepgr-11355 | 20.205 us | } /* pick_next_task_fair */
> 388.944744 | 0) sleepgr-11355 | | pick_next_task_idle() {
> 388.944744 | 0) sleepgr-11355 | | put_prev_task_fair() {
> 388.944745 | 0) sleepgr-11355 | | put_prev_entity() {
> 388.944745 | 0) sleepgr-11355 | 0.064 us | check_cfs_rq_runtime();
> 388.944746 | 0) sleepgr-11355 | 0.713 us | } /* put_prev_entity */
> 388.944746 | 0) sleepgr-11355 | | put_prev_entity() {
> 388.944746 | 0) sleepgr-11355 | 0.068 us | check_cfs_rq_runtime();
> 388.944747 | 0) sleepgr-11355 | 0.691 us | } /* put_prev_entity */
> 388.944747 | 0) sleepgr-11355 | 2.633 us | } /* put_prev_task_fair */
> 388.944748 | 0) sleepgr-11355 | 0.094 us | __update_idle_core();
> 388.944748 | 0) sleepgr-11355 | 3.899 us | } /* pick_next_task_idle */
> 388.944749 | 0) sleepgr-11355 | | enter_lazy_tlb() {
> 388.944749 | 0) sleepgr-11355 | | switch_mm() {
> 388.944749 | 0) sleepgr-11355 | | switch_mm_irqs_off() {
> 388.944750 | 0) sleepgr-11355 | 0.244 us | load_new_mm_cr3();
> 388.944751 | 0) sleepgr-11355 | 0.955 us | } /* switch_mm_irqs_off */
> 388.944751 | 0) sleepgr-11355 | 1.472 us | } /* switch_mm */
> 388.944751 | 0) sleepgr-11355 | 2.023 us | } /* enter_lazy_tlb */
> 388.950636 | 0) sleepgr-11355 | 0.103 us | finish_task_switch();
> 388.950638 | 0) sleepgr-11355 | 5932.632 us | } /* schedule */
> 388.950638 | 0) sleepgr-11355 | | prepare_to_wait_event() {
> 388.950638 | 0) sleepgr-11355 | 0.068 us | _raw_spin_lock_irqsave();
> 388.950638 | 0) sleepgr-11355 | 0.053 us | _raw_spin_unlock_irqrestore();
> 388.950639 | 0) sleepgr-11355 | 0.866 us | } /* prepare_to_wait_event */
> 388.950639 | 0) sleepgr-11355 | | finish_wait() {
> 388.950639 | 0) sleepgr-11355 | 0.046 us | _raw_spin_lock_irqsave();
> 388.950640 | 0) sleepgr-11355 | 0.052 us | _raw_spin_unlock_irqrestore();
> 388.950640 | 0) sleepgr-11355 | 0.788 us | } /* finish_wait */
> 388.950640 | 0) sleepgr-11355 | 5939.443 us | } /* wb_wait_for_completion */
Can these outliers be avoided? As this is in `schedule`, is it related
to the used scheduler? At least the Intel Skylake i7-7500U CPU @ 2.70GHz
processor with four threads in the TUXEDO laptop should have enough
performance.
No scheduler seems to be used for the NVMe device.
$ more
/sys/devices/pci0000:00/0000:00:1d.0/0000:04:00.0/nvme/nvme0/nvme0n1/queue/scheduler
[none]
Kind regards,
Paul
[1]: https://01.org/suspendresume
[2]: https://github.com/01org/pm-graph
[-- Attachment #2: helmuth-N24-25BU_mem.html.7z --]
[-- Type: application/x-7z-compressed, Size: 28194 bytes --]
^ permalink raw reply [flat|nested] 2+ messages in thread* Re: How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?
2018-08-28 5:27 How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`? Paul Menzel
@ 2018-08-28 11:43 ` Paul Menzel
0 siblings, 0 replies; 2+ messages in thread
From: Paul Menzel @ 2018-08-28 11:43 UTC (permalink / raw)
To: linux-fsdevel; +Cc: LKML
[-- Attachment #1.1: Type: text/plain, Size: 16229 bytes --]
Dear Linux folks,
On 08/28/18 07:27, Paul Menzel wrote:
> Using `sleepgraph.py` [1][2] to profile the suspend to RAM (STR)
> times, shows that `ksys_enter` takes a noticeable amount of time.
>
> 13 ms on a TUXEDO Book BU1406 with the NVMe device *SAMSUNG
> MZVKW512HMJP-00000*, which is quite good, and over a 60 ms on ASRock
> E350M1 with an SSD SanDisk device.
It’s 109 ms on the ASRock E350M1, which makes up one third of the
total time to reach ACPI S3.
> Adding `devicefilter: ksys_sync` to `config/suspend-callgraph.cfg`,
> and running `sudo ./sleepgraph.py -config
> config/suspend-callgraph.cfg`, the attached HTML output shows, that
> `iterate_supers` takes 6 to 7 ms twice.
>
> • `iterate_supers` (6.316 ms @ 388.944557)
> • `iterate_supers` (0.201 ms @ 388.950873)
> • `iterate_supers` (7.421 ms @ 388.951074)
>
> Normally, `sync_inodes_one_sb` only takes microseconds, but once in
> both cases it takes several milliseconds.
>
> • sync_inodes_one_sb (0.001 ms @ 388.944660)
> • sync_inodes_one_sb (5.978 ms @ 388.944665)
> • sync_inodes_one_sb (0.001 ms @ 388.950645)
>
> Please find an excerpt from the call graph from ftrace below, and
> note the time increase between 388.944751 and 388.950636.
>
>> 388.944700 | 0) sleepgr-11355 | | wb_wait_for_completion() {
>> 388.944701 | 0) sleepgr-11355 | | _cond_resched() {
>> 388.944701 | 0) sleepgr-11355 | 0.064 us | rcu_all_qs();
>> 388.944702 | 0) sleepgr-11355 | 0.664 us | } /* _cond_resched */
>> 388.944702 | 0) sleepgr-11355 | 0.067 us | init_wait_entry();
>> 388.944703 | 0) sleepgr-11355 | | prepare_to_wait_event() {
>> 388.944703 | 0) sleepgr-11355 | 0.080 us | _raw_spin_lock_irqsave();
>> 388.944704 | 0) sleepgr-11355 | 0.073 us | _raw_spin_unlock_irqrestore();
>> 388.944704 | 0) sleepgr-11355 | 1.388 us | } /* prepare_to_wait_event */
>> 388.944705 | 0) sleepgr-11355 | | schedule() {
>> 388.944705 | 0) sleepgr-11355 | 0.085 us | rcu_note_context_switch();
>> 388.944706 | 0) sleepgr-11355 | 0.064 us | _raw_spin_lock();
>> 388.944707 | 0) sleepgr-11355 | 0.093 us | update_rq_clock();
>> 388.944708 | 0) sleepgr-11355 | | deactivate_task() {
>> 388.944708 | 0) sleepgr-11355 | | dequeue_task_fair() {
>> 388.944708 | 0) sleepgr-11355 | | dequeue_entity() {
>> 388.944709 | 0) sleepgr-11355 | | update_curr() {
>> 388.944709 | 0) sleepgr-11355 | 0.095 us | update_min_vruntime();
>> 388.944710 | 0) sleepgr-11355 | 0.126 us | cpuacct_charge();
>> 388.944710 | 0) sleepgr-11355 | | __cgroup_account_cputime() {
>> 388.944711 | 0) sleepgr-11355 | 0.055 us | cgroup_rstat_updated();
>> 388.944711 | 0) sleepgr-11355 | 0.675 us | } /* __cgroup_account_cputime */
>> 388.944712 | 0) sleepgr-11355 | 2.779 us | } /* update_curr */
>> 388.944712 | 0) sleepgr-11355 | 0.121 us | __update_load_avg_se();
>> 388.944713 | 0) sleepgr-11355 | 0.118 us | __update_load_avg_cfs_rq();
>> 388.944713 | 0) sleepgr-11355 | 0.056 us | clear_buddies();
>> 388.944714 | 0) sleepgr-11355 | 0.066 us | account_entity_dequeue();
>> 388.944714 | 0) sleepgr-11355 | 0.050 us | update_cfs_group();
>> 388.944715 | 0) sleepgr-11355 | 6.127 us | } /* dequeue_entity */
>> 388.944715 | 0) sleepgr-11355 | | dequeue_entity() {
>> 388.944715 | 0) sleepgr-11355 | | update_curr() {
>> 388.944716 | 0) sleepgr-11355 | 0.097 us | __calc_delta();
>> 388.944716 | 0) sleepgr-11355 | 0.071 us | update_min_vruntime();
>> 388.944717 | 0) sleepgr-11355 | 1.473 us | } /* update_curr */
>> 388.944717 | 0) sleepgr-11355 | 0.142 us | __update_load_avg_se();
>> 388.944718 | 0) sleepgr-11355 | 0.100 us | __update_load_avg_cfs_rq();
>> 388.944719 | 0) sleepgr-11355 | 0.069 us | clear_buddies();
>> 388.944719 | 0) sleepgr-11355 | 0.098 us | account_entity_dequeue();
>> 388.944720 | 0) sleepgr-11355 | | update_cfs_group() {
>> 388.944720 | 0) sleepgr-11355 | 0.110 us | reweight_entity();
>> 388.944721 | 0) sleepgr-11355 | 0.847 us | } /* update_cfs_group */
>> 388.944721 | 0) sleepgr-11355 | 6.197 us | } /* dequeue_entity */
>> 388.944722 | 0) sleepgr-11355 | 0.053 us | hrtick_update();
>> 388.944722 | 0) sleepgr-11355 | 14.141 us | } /* dequeue_task_fair */
>> 388.944723 | 0) sleepgr-11355 | 14.827 us | } /* deactivate_task */
>> 388.944723 | 0) sleepgr-11355 | | pick_next_task_fair() {
>> 388.944723 | 0) sleepgr-11355 | | update_blocked_averages() {
>> 388.944724 | 0) sleepgr-11355 | 0.070 us | _raw_spin_lock_irqsave();
>> 388.944724 | 0) sleepgr-11355 | 0.090 us | update_rq_clock();
>> 388.944725 | 0) sleepgr-11355 | 0.120 us | __update_load_avg_cfs_rq();
>> 388.944726 | 0) sleepgr-11355 | 0.162 us | __update_load_avg_se();
>> 388.944727 | 0) sleepgr-11355 | 0.090 us | __update_load_avg_cfs_rq();
>> 388.944727 | 0) sleepgr-11355 | 0.081 us | __update_load_avg_cfs_rq();
>> 388.944728 | 0) sleepgr-11355 | | update_rt_rq_load_avg() {
>> 388.944728 | 0) sleepgr-11355 | 0.063 us | __accumulate_pelt_segments();
>> 388.944729 | 0) sleepgr-11355 | 0.785 us | } /* update_rt_rq_load_avg */
>> 388.944729 | 0) sleepgr-11355 | | update_dl_rq_load_avg() {
>> 388.944730 | 0) sleepgr-11355 | 0.066 us | __accumulate_pelt_segments();
>> 388.944730 | 0) sleepgr-11355 | 0.763 us | } /* update_dl_rq_load_avg */
>> 388.944731 | 0) sleepgr-11355 | 0.061 us | _raw_spin_unlock_irqrestore();
>> 388.944731 | 0) sleepgr-11355 | 7.452 us | } /* update_blocked_averages */
>> 388.944731 | 0) sleepgr-11355 | | load_balance() {
>> 388.944732 | 0) sleepgr-11355 | | find_busiest_group() {
>> 388.944732 | 0) sleepgr-11355 | 0.100 us | update_nohz_stats();
>> 388.944733 | 0) sleepgr-11355 | 0.057 us | idle_cpu();
>> 388.944734 | 0) sleepgr-11355 | 0.098 us | update_nohz_stats();
>> 388.944734 | 0) sleepgr-11355 | 2.407 us | } /* find_busiest_group */
>> 388.944735 | 0) sleepgr-11355 | 3.120 us | } /* load_balance */
>> 388.944735 | 0) sleepgr-11355 | 0.065 us | __msecs_to_jiffies();
>> 388.944736 | 0) sleepgr-11355 | | load_balance() {
>> 388.944736 | 0) sleepgr-11355 | | find_busiest_group() {
>> 388.944736 | 0) sleepgr-11355 | 0.087 us | update_nohz_stats();
>> 388.944737 | 0) sleepgr-11355 | 0.063 us | idle_cpu();
>> 388.944738 | 0) sleepgr-11355 | 0.086 us | update_nohz_stats();
>> 388.944739 | 0) sleepgr-11355 | 0.068 us | update_nohz_stats();
>> 388.944739 | 0) sleepgr-11355 | 0.098 us | idle_cpu();
>> 388.944740 | 0) sleepgr-11355 | 0.094 us | update_nohz_stats();
>> 388.944741 | 0) sleepgr-11355 | 0.065 us | idle_cpu();
>> 388.944741 | 0) sleepgr-11355 | 5.160 us | } /* find_busiest_group */
>> 388.944742 | 0) sleepgr-11355 | 5.831 us | } /* load_balance */
>> 388.944742 | 0) sleepgr-11355 | 0.062 us | __msecs_to_jiffies();
>> 388.944743 | 0) sleepgr-11355 | 0.065 us | _raw_spin_lock();
>> 388.944743 | 0) sleepgr-11355 | 20.205 us | } /* pick_next_task_fair */
>> 388.944744 | 0) sleepgr-11355 | | pick_next_task_idle() {
>> 388.944744 | 0) sleepgr-11355 | | put_prev_task_fair() {
>> 388.944745 | 0) sleepgr-11355 | | put_prev_entity() {
>> 388.944745 | 0) sleepgr-11355 | 0.064 us | check_cfs_rq_runtime();
>> 388.944746 | 0) sleepgr-11355 | 0.713 us | } /* put_prev_entity */
>> 388.944746 | 0) sleepgr-11355 | | put_prev_entity() {
>> 388.944746 | 0) sleepgr-11355 | 0.068 us | check_cfs_rq_runtime();
>> 388.944747 | 0) sleepgr-11355 | 0.691 us | } /* put_prev_entity */
>> 388.944747 | 0) sleepgr-11355 | 2.633 us | } /* put_prev_task_fair */
>> 388.944748 | 0) sleepgr-11355 | 0.094 us | __update_idle_core();
>> 388.944748 | 0) sleepgr-11355 | 3.899 us | } /* pick_next_task_idle */
>> 388.944749 | 0) sleepgr-11355 | | enter_lazy_tlb() {
>> 388.944749 | 0) sleepgr-11355 | | switch_mm() {
>> 388.944749 | 0) sleepgr-11355 | | switch_mm_irqs_off() {
>> 388.944750 | 0) sleepgr-11355 | 0.244 us | load_new_mm_cr3();
>> 388.944751 | 0) sleepgr-11355 | 0.955 us | } /* switch_mm_irqs_off */
>> 388.944751 | 0) sleepgr-11355 | 1.472 us | } /* switch_mm */
>> 388.944751 | 0) sleepgr-11355 | 2.023 us | } /* enter_lazy_tlb */
>> 388.950636 | 0) sleepgr-11355 | 0.103 us | finish_task_switch();
>> 388.950638 | 0) sleepgr-11355 | 5932.632 us | } /* schedule */
>> 388.950638 | 0) sleepgr-11355 | | prepare_to_wait_event() {
>> 388.950638 | 0) sleepgr-11355 | 0.068 us | _raw_spin_lock_irqsave();
>> 388.950638 | 0) sleepgr-11355 | 0.053 us | _raw_spin_unlock_irqrestore();
>> 388.950639 | 0) sleepgr-11355 | 0.866 us | } /* prepare_to_wait_event */
>> 388.950639 | 0) sleepgr-11355 | | finish_wait() {
>> 388.950639 | 0) sleepgr-11355 | 0.046 us | _raw_spin_lock_irqsave();
>> 388.950640 | 0) sleepgr-11355 | 0.052 us | _raw_spin_unlock_irqrestore();
>> 388.950640 | 0) sleepgr-11355 | 0.788 us | } /* finish_wait */
>> 388.950640 | 0) sleepgr-11355 | 5939.443 us | } /* wb_wait_for_completion */
>
> Can these outliers be avoided? As this is in `schedule`, is it
> related to the used scheduler? At least the Intel Skylake i7-7500U
> CPU @ 2.70GHz processor with four threads in the TUXEDO laptop should
> have enough performance.
>
> No scheduler seems to be used for the NVMe device.
>
> $ more /sys/devices/pci0000:00/0000:00:1d.0/0000:04:00.0/nvme/nvme0/nvme0n1/queue/scheduler
> [none]
Please find the data for the SSD SanDisk device (AHCI) attached. Here
is an excerpt.
iterate_supers (53.363 ms @ 921.357477)
sync_inodes_one_sb (52.417 ms @ 921.357858)
sync_inodes_sb (52.414 ms @ 921.357859)
[…]
wb_wait_for_completion (17.226 ms @ 921.358335)
[…]
[…]
filemap_fdatawait_keep_errors (34.120 ms @ 921.375575)
__filemap_fdatawait_range (34.117 ms @ 921.375576)
[…]
io_schedule (33.307 ms @ 921.375586)
[…]
[…]
Kind regards,
Paul
> [1]: https://01.org/suspendresume
> [2]: https://github.com/01org/pm-graph
[-- Attachment #1.2: kodi_mem.html.7z --]
[-- Type: application/x-7z-compressed, Size: 37338 bytes --]
[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 5174 bytes --]
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2018-08-28 15:34 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-08-28 5:27 How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`? Paul Menzel
2018-08-28 11:43 ` Paul Menzel
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).