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

From: Paul Menzel
Date: Tue Aug 28 2018 - 07:43:41 EST

Next message: J, KEERTHY: "Re: [PATCH v2] clocksource: ti-32k: Add CLOCK_SOURCE_SUSPEND_NONSTOP flag for non-am43 SoCs"
Previous message: Ulf Hansson: "Re: [PATCH] mmc: Convert to using %pOFn instead of device_node.name"
In reply to: Paul Menzel: "How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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: kodi_mem.html.7z
Description: application/7z-compressed

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature

Next message: J, KEERTHY: "Re: [PATCH v2] clocksource: ti-32k: Add CLOCK_SOURCE_SUSPEND_NONSTOP flag for non-am43 SoCs"
Previous message: Ulf Hansson: "Re: [PATCH] mmc: Convert to using %pOFn instead of device_node.name"
In reply to: Paul Menzel: "How to debug outliers in `wb_wait_for_completion()` in `ksys_sync()`?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]