| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Tue, 24 Jul 2018 19:50:02 +0200
From: Paul Menzel <pmenzel+linux-acpi@...gen.mpg.de>
To: linux-acpi@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: How to debug long `acpi_os_sleep()`?
Dear Linux folks,
On the MSI B350M MORTAR (MS-7A37) with Linux 4.18-rc6+ profiling suspend
to and resume from ACPI S3 resume with `sleepgraph.py` [1] there is one
call of the method `acpi_ds_exec_end_op()` taking over 300 ms.
```
227.661571 | 1) sleepgr-2147 | | acpi_ds_exec_end_op() {
227.661571 | 1) sleepgr-2147 | | acpi_ds_create_operands() {
227.661571 | 1) sleepgr-2147 | | acpi_ds_create_operand() {
227.661571 | 1) sleepgr-2147 | 0.040 us | acpi_ps_get_opcode_info();
227.661572 | 1) sleepgr-2147 | | acpi_ut_create_internal_object_dbg() {
227.661572 | 1) sleepgr-2147 | | acpi_ut_allocate_object_desc_dbg() {
227.661572 | 1) sleepgr-2147 | | kmem_cache_alloc() {
227.661572 | 1) sleepgr-2147 | | _cond_resched() {
227.661572 | 1) sleepgr-2147 | 0.030 us | rcu_all_qs();
227.661572 | 1) sleepgr-2147 | 0.299 us | } /* _cond_resched */
227.661573 | 1) sleepgr-2147 | 0.030 us | should_failslab();
227.661573 | 1) sleepgr-2147 | 0.040 us | memcg_kmem_put_cache();
227.661573 | 1) sleepgr-2147 | 1.139 us | } /* kmem_cache_alloc */
227.661573 | 1) sleepgr-2147 | 1.418 us | } /* acpi_ut_allocate_object_desc_dbg */
227.661573 | 1) sleepgr-2147 | 1.698 us | } /* acpi_ut_create_internal_object_dbg */
227.661574 | 1) sleepgr-2147 | | acpi_ds_init_object_from_op() {
227.661574 | 1) sleepgr-2147 | 0.030 us | acpi_ps_get_opcode_info();
227.661574 | 1) sleepgr-2147 | 0.050 us | acpi_ex_truncate_for32bit_table();
227.661575 | 1) sleepgr-2147 | 1.019 us | } /* acpi_ds_init_object_from_op */
227.661575 | 1) sleepgr-2147 | 0.040 us | acpi_ds_obj_stack_push();
227.661575 | 1) sleepgr-2147 | 3.805 us | } /* acpi_ds_create_operand */
227.661575 | 1) sleepgr-2147 | 4.105 us | } /* acpi_ds_create_operands */
227.661575 | 1) sleepgr-2147 | | acpi_ex_resolve_operands() {
227.661575 | 1) sleepgr-2147 | 0.040 us | acpi_ps_get_opcode_info();
227.661576 | 1) sleepgr-2147 | 0.040 us | acpi_ut_valid_object_type();
227.661576 | 1) sleepgr-2147 | 0.040 us | acpi_ex_resolve_to_value();
227.661576 | 1) sleepgr-2147 | 0.030 us | acpi_ex_convert_to_integer();
227.661577 | 1) sleepgr-2147 | 1.228 us | } /* acpi_ex_resolve_operands */
227.661577 | 1) sleepgr-2147 | | acpi_ex_opcode_1A_0T_0R() {
227.661577 | 1) sleepgr-2147 | | acpi_ex_system_do_sleep() {
227.661577 | 1) sleepgr-2147 | | acpi_ex_exit_interpreter() {
227.661577 | 1) sleepgr-2147 | | acpi_ut_release_mutex() {
227.661577 | 1) sleepgr-2147 | | acpi_os_signal_semaphore() {
227.661578 | 1) sleepgr-2147 | | up() {
227.661578 | 1) sleepgr-2147 | 0.030 us | _raw_spin_lock_irqsave();
227.661578 | 1) sleepgr-2147 | 0.039 us | _raw_spin_unlock_irqrestore();
227.661578 | 1) sleepgr-2147 | 0.579 us | } /* up */
227.661578 | 1) sleepgr-2147 | 0.849 us | } /* acpi_os_signal_semaphore */
227.661579 | 1) sleepgr-2147 | 1.129 us | } /* acpi_ut_release_mutex */
227.661579 | 1) sleepgr-2147 | | acpi_ut_release_mutex() {
227.661579 | 1) sleepgr-2147 | | acpi_os_signal_semaphore() {
227.661579 | 1) sleepgr-2147 | | up() {
227.661579 | 1) sleepgr-2147 | 0.030 us | _raw_spin_lock_irqsave();
227.661579 | 1) sleepgr-2147 | 0.040 us | _raw_spin_unlock_irqrestore();
227.661580 | 1) sleepgr-2147 | 0.580 us | } /* up */
227.661580 | 1) sleepgr-2147 | 0.839 us | } /* acpi_os_signal_semaphore */
227.661580 | 1) sleepgr-2147 | 1.118 us | } /* acpi_ut_release_mutex */
227.661580 | 1) sleepgr-2147 | 2.757 us | } /* acpi_ex_exit_interpreter */
227.661580 | 1) sleepgr-2147 | | acpi_os_sleep() {
227.661580 | 1) sleepgr-2147 | | msleep() {
227.661581 | 1) sleepgr-2147 | 0.030 us | __msecs_to_jiffies();
227.661581 | 1) sleepgr-2147 | | schedule_timeout() {
227.661581 | 1) sleepgr-2147 | | lock_timer_base() {
227.661581 | 1) sleepgr-2147 | 0.030 us | _raw_spin_lock_irqsave();
227.661581 | 1) sleepgr-2147 | 0.339 us | } /* lock_timer_base */
227.661582 | 1) sleepgr-2147 | 0.050 us | detach_if_pending();
227.661582 | 1) sleepgr-2147 | 0.040 us | get_nohz_timer_target();
227.661582 | 1) sleepgr-2147 | | __internal_add_timer() {
227.661582 | 1) sleepgr-2147 | 0.070 us | calc_wheel_index();
227.661583 | 1) sleepgr-2147 | 0.430 us | } /* __internal_add_timer */
227.661583 | 1) sleepgr-2147 | 0.060 us | trigger_dyntick_cpu.isra.29();
227.661583 | 1) sleepgr-2147 | 0.030 us | _raw_spin_unlock_irqrestore();
227.661583 | 1) sleepgr-2147 | | schedule() {
227.661584 | 1) sleepgr-2147 | 0.030 us | rcu_note_context_switch();
227.661584 | 1) sleepgr-2147 | 0.030 us | _raw_spin_lock();
227.661584 | 1) sleepgr-2147 | | update_rq_clock() {
227.661584 | 1) sleepgr-2147 | 0.030 us | sched_avg_update();
227.661585 | 1) sleepgr-2147 | 0.320 us | } /* update_rq_clock */
227.661585 | 1) sleepgr-2147 | | deactivate_task() {
227.661585 | 1) sleepgr-2147 | 1.009 us | dequeue_task_fair();
227.661586 | 1) sleepgr-2147 | 1.359 us | } /* deactivate_task */
227.661586 | 1) sleepgr-2147 | | pick_next_task_fair() {
227.661587 | 1) sleepgr-2147 | 0.030 us | __msecs_to_jiffies();
227.661587 | 1) sleepgr-2147 | 0.420 us | } /* pick_next_task_fair */
227.661587 | 1) sleepgr-2147 | | pick_next_task_idle() {
227.661587 | 1) sleepgr-2147 | 0.280 us | put_prev_task_fair();
227.661588 | 1) sleepgr-2147 | 0.640 us | } /* pick_next_task_idle */
227.661589 | 1) sleepgr-2147 | 0.050 us | enter_lazy_tlb();
227.970722 | 1) sleepgr-2147 | 0.469 us | finish_task_switch();
227.970726 | 1) sleepgr-2147 | 309142.1 us | } /* schedule */
227.970727 | 1) sleepgr-2147 | | del_timer_sync() {
227.970727 | 1) sleepgr-2147 | | try_to_del_timer_sync() {
227.970727 | 1) sleepgr-2147 | 0.210 us | lock_timer_base();
227.970728 | 1) sleepgr-2147 | 0.100 us | detach_if_pending();
227.970729 | 1) sleepgr-2147 | 0.070 us | _raw_spin_unlock_irqrestore();
227.970729 | 1) sleepgr-2147 | 2.197 us | } /* try_to_del_timer_sync */
227.970730 | 1) sleepgr-2147 | 2.797 us | } /* del_timer_sync */
227.970730 | 1) sleepgr-2147 | 309149.0 us | } /* schedule_timeout */
227.970731 | 1) sleepgr-2147 | 309150.1 us | } /* msleep */
227.970731 | 1) sleepgr-2147 | 309150.6 us | } /* acpi_os_sleep */
227.970731 | 1) sleepgr-2147 | | acpi_ex_enter_interpreter() {
227.970732 | 1) sleepgr-2147 | | acpi_ut_acquire_mutex() {
227.970733 | 1) sleepgr-2147 | | acpi_os_wait_semaphore() {
227.970733 | 1) sleepgr-2147 | | down_timeout() {
227.970733 | 1) sleepgr-2147 | 0.070 us | _raw_spin_lock_irqsave();
227.970734 | 1) sleepgr-2147 | 0.070 us | _raw_spin_unlock_irqrestore();
227.970734 | 1) sleepgr-2147 | 0.070 us | _raw_spin_unlock_irqrestore();
227.970735 | 1) sleepgr-2147 | 1.328 us | } /* down_timeout */
227.970735 | 1) sleepgr-2147 | 2.117 us | } /* acpi_os_wait_semaphore */
227.970736 | 1) sleepgr-2147 | 3.066 us | } /* acpi_ut_acquire_mutex */
227.970736 | 1) sleepgr-2147 | | acpi_ut_acquire_mutex() {
227.970737 | 1) sleepgr-2147 | | acpi_os_wait_semaphore() {
227.970737 | 1) sleepgr-2147 | | down_timeout() {
227.970737 | 1) sleepgr-2147 | 0.079 us | _raw_spin_lock_irqsave();
227.970738 | 1) sleepgr-2147 | 0.070 us | _raw_spin_unlock_irqrestore();
227.970738 | 1) sleepgr-2147 | 1.228 us | } /* down_timeout */
227.970739 | 1) sleepgr-2147 | 1.778 us | } /* acpi_os_wait_semaphore */
227.970739 | 1) sleepgr-2147 | 2.358 us | } /* acpi_ut_acquire_mutex */
227.970739 | 1) sleepgr-2147 | 7.531 us | } /* acpi_ex_enter_interpreter */
227.970740 | 1) sleepgr-2147 | 309162.3 us | } /* acpi_ex_system_do_sleep */
227.970740 | 1) sleepgr-2147 | 309162.8 us | } /* acpi_ex_opcode_1A_0T_0R */
227.970740 | 1) sleepgr-2147 | | acpi_ds_clear_operands() {
227.970741 | 1) sleepgr-2147 | | acpi_ut_remove_reference() {
227.970742 | 1) sleepgr-2147 | 0.070 us | acpi_ut_valid_internal_object();
227.970742 | 1) sleepgr-2147 | | acpi_ut_update_object_reference() {
227.970743 | 1) sleepgr-2147 | | acpi_ut_update_ref_count.part.1() {
227.970743 | 1) sleepgr-2147 | | acpi_os_acquire_lock() {
227.970743 | 1) sleepgr-2147 | 0.070 us | _raw_spin_lock_irqsave();
227.970744 | 1) sleepgr-2147 | 0.700 us | } /* acpi_os_acquire_lock */
227.970744 | 1) sleepgr-2147 | | acpi_os_release_lock() {
227.970745 | 1) sleepgr-2147 | 0.070 us | _raw_spin_unlock_irqrestore();
227.970745 | 1) sleepgr-2147 | 0.609 us | } /* acpi_os_release_lock */
227.970745 | 1) sleepgr-2147 | | acpi_ut_delete_object_desc() {
227.970746 | 1) sleepgr-2147 | | acpi_os_release_object() {
227.970746 | 1) sleepgr-2147 | 1.018 us | kmem_cache_free();
227.970748 | 1) sleepgr-2147 | 1.888 us | } /* acpi_os_release_object */
227.970748 | 1) sleepgr-2147 | 2.566 us | } /* acpi_ut_delete_object_desc */
227.970748 | 1) sleepgr-2147 | 5.633 us | } /* acpi_ut_update_ref_count.part.1 */
227.970749 | 1) sleepgr-2147 | 6.253 us | } /* acpi_ut_update_object_reference */
227.970749 | 1) sleepgr-2147 | 7.910 us | } /* acpi_ut_remove_reference */
227.970749 | 1) sleepgr-2147 | 8.649 us | } /* acpi_ds_clear_operands */
227.970750 | 1) sleepgr-2147 | 0.080 us | acpi_ex_truncate_for32bit_table();
227.970750 | 1) sleepgr-2147 | 309179.2 us | } /* acpi_ds_exec_end_op */
```
Despite reading the ACPI debug documentation [2], I couldn’t find out
how to easily determine with what value `acpi_os_sleep()` is called.
If it is really 300 ms, I need to contact the board vendor, but I
like to rule out a problem in the Linux kernel.
It’d be great if you could help me, what I have to use for
`debug_layer` and `debug_level`, so I do not have to debug with print
statements.
Kind regards,
Paul
[1]: https://01.org/suspendresume
[2]: Documentation/acpi/debug.txt
Download attachment "tokeiihto_mem.html.7z" of type "application/x-7z-compressed" (85838 bytes)
View attachment "tokeiihto_mem_dmesg.txt" of type "text/plain" (60738 bytes)
Powered by blists - more mailing lists