You are not logged in.
Hello,
I saw another thread about that https://bbs.archlinux.org/viewtopic.php?id=150891, but my problem looks like different, so I start a new topic.
wake-up sometimes hangs with the task pm-suspend blocked several minutes. When happening, I see theses kernel messages :
[ 6486.126102] r8169 0000:03:00.0: eth0: link up
[ 6720.259336] INFO: task pm-suspend:2629 blocked for more than 120 seconds.
[ 6720.340646] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 6720.434473] pm-suspend D
ffff8800cb9d27b0
0 2629 2628 0x00000000
[ 6720.519377] ffff8801246bfc08
0000000000000082
ffff8800cb9d27b0
ffff8801246bffd8
[ 6720.608794] ffff8801246bffd8
ffff8801246bffd8
ffff88012aa6df40
ffff8800cb9d27b0
[ 6720.698238] ffff8801246bfb38
ffffffff81070e34
ffff8801246bfb48
0000000000000046
[ 6720.787664] Call Trace:
[ 6720.817008] [<ffffffff81070e34>] ? wake_up_worker+0x24/0x30
[ 6720.884827] [<ffffffff8107487f>] ? __queue_work+0xcf/0x410
[ 6720.951582] [<ffffffff8108b757>] ? try_to_wake_up+0x1e7/0x2f0
[ 6721.021466] [<ffffffff8108b895>] ? wake_up_process+0x15/0x20
[ 6721.090309] [<ffffffff814877d9>] schedule+0x29/0x70
[ 6721.149792] [<ffffffff814851d4>] schedule_timeout+0x204/0x260
[ 6721.219670] [<ffffffff8148623e>] ? __mutex_lock_slowpath+0x24e/0x340
[ 6721.296835] [<ffffffff81346839>] ? input_pass_event+0x49/0xf0
[ 6721.366719] [<ffffffff81486aad>] wait_for_common+0xcd/0x160
[ 6721.434513] [<ffffffff8108b860>] ? try_to_wake_up+0x2f0/0x2f0
[ 6721.504396] [<ffffffff81486b5d>] wait_for_completion+0x1d/0x20
[ 6721.575317] [<ffffffff8132e632>] dpm_wait+0x32/0x40
[ 6721.634801] [<ffffffff8132f5bd>] device_resume+0x2d/0x160
[ 6721.700519] [<ffffffff8132fb34>] dpm_resume+0x104/0x230
[ 6721.764162] [<ffffffff8132fe25>] dpm_resume_end+0x15/0x30
[ 6721.829884] [<ffffffff812b03f7>] ? acpi_suspend_begin_old+0x2d/0x2d
[ 6721.906012] [<ffffffff8109d2c6>] suspend_devices_and_enter+0xb6/0x340
[ 6721.984211] [<ffffffff8109d744>] pm_suspend+0x1f4/0x200
[ 6722.047847] [<ffffffff8109c9e5>] state_store+0xa5/0xc0
[ 6722.110456] [<ffffffff812535ff>] kobj_attr_store+0xf/0x20
[ 6722.176173] [<ffffffff811e6ebd>] sysfs_write_file+0xcd/0x140
[ 6722.245017] [<ffffffff81176c98>] vfs_write+0xa8/0x180
[ 6722.306572] [<ffffffff81176fda>] sys_write+0x4a/0xa0
[ 6722.367103] [<ffffffff8148fbad>] system_call_fastpath+0x1a/0x1f
[ 6842.435993] INFO: task pm-suspend:2629 blocked for more than 120 seconds.
[ 6842.517348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 6842.611172] pm-suspend D
ffff8800cb9d27b0
0 2629 2628 0x00000000
[ 6842.696083] ffff8801246bfc08
0000000000000082
ffff8800cb9d27b0
ffff8801246bffd8
[ 6842.785502] ffff8801246bffd8
ffff8801246bffd8
ffff88012aa6df40
ffff8800cb9d27b0
[ 6842.874926] ffff8801246bfb38
ffffffff81070e34
ffff8801246bfb48
0000000000000046
[ 6842.964374] Call Trace:
[ 6842.993709] [<ffffffff81070e34>] ? wake_up_worker+0x24/0x30
[ 6843.061524] [<ffffffff8107487f>] ? __queue_work+0xcf/0x410
[ 6843.128290] [<ffffffff8108b757>] ? try_to_wake_up+0x1e7/0x2f0
[ 6843.198166] [<ffffffff8108b895>] ? wake_up_process+0x15/0x20
[ 6843.267011] [<ffffffff814877d9>] schedule+0x29/0x70
[ 6843.326487] [<ffffffff814851d4>] schedule_timeout+0x204/0x260
[ 6843.396381] [<ffffffff8148623e>] ? __mutex_lock_slowpath+0x24e/0x340
[ 6843.473538] [<ffffffff81346839>] ? input_pass_event+0x49/0xf0
[ 6843.543415] [<ffffffff81486aad>] wait_for_common+0xcd/0x160
[ 6843.611223] [<ffffffff8108b860>] ? try_to_wake_up+0x2f0/0x2f0
[ 6843.681100] [<ffffffff81486b5d>] wait_for_completion+0x1d/0x20
[ 6843.752021] [<ffffffff8132e632>] dpm_wait+0x32/0x40
[ 6843.811501] [<ffffffff8132f5bd>] device_resume+0x2d/0x160
[ 6843.877228] [<ffffffff8132fb34>] dpm_resume+0x104/0x230
[ 6843.940865] [<ffffffff8132fe25>] dpm_resume_end+0x15/0x30
[ 6844.006587] [<ffffffff812b03f7>] ? acpi_suspend_begin_old+0x2d/0x2d
[ 6844.082708] [<ffffffff8109d2c6>] suspend_devices_and_enter+0xb6/0x340
[ 6844.160917] [<ffffffff8109d744>] pm_suspend+0x1f4/0x200
[ 6844.224548] [<ffffffff8109c9e5>] state_store+0xa5/0xc0
[ 6844.287152] [<ffffffff812535ff>] kobj_attr_store+0xf/0x20
[ 6844.352881] [<ffffffff811e6ebd>] sysfs_write_file+0xcd/0x140
[ 6844.421718] [<ffffffff81176c98>] vfs_write+0xa8/0x180
[ 6844.483275] [<ffffffff81176fda>] sys_write+0x4a/0xa0
[ 6844.543799] [<ffffffff8148fbad>] system_call_fastpath+0x1a/0x1f
[ 6964.612645] INFO: task pm-suspend:2629 blocked for more than 120 seconds.
[ 6964.693946] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 6964.787768] pm-suspend D
ffff8800cb9d27b0
0 2629 2628 0x00000000
[ 6964.872590] ffff8801246bfc08
0000000000000082
ffff8800cb9d27b0
ffff8801246bffd8
[ 6964.961992] ffff8801246bffd8
ffff8801246bffd8
ffff88012aa6df40
ffff8800cb9d27b0
[ 6965.051436] ffff8801246bfb38
ffffffff81070e34
ffff8801246bfb48
0000000000000046
[ 6965.140861] Call Trace:
[ 6965.170204] [<ffffffff81070e34>] ? wake_up_worker+0x24/0x30
[ 6965.238019] [<ffffffff8107487f>] ? __queue_work+0xcf/0x410
[ 6965.304769] [<ffffffff8108b757>] ? try_to_wake_up+0x1e7/0x2f0
[ 6965.326311] PM: resume of devices complete after 483616.328 msecs
[ 6965.339825] Restarting tasks ... done.
[ 6965.493084] [<ffffffff812519db>] cpumask_any_but+0x2b/0x40
[ 6965.559927] [<ffffffff8104c038>] flush_tlb_page+0x58/0xf0
[ 6965.625680] [<ffffffff8112a0e4>] ? lru_cache_add_lru+0x24/0x50
[ 6965.696717] [<ffffffff810904d6>] update_cfs_shares+0xb6/0x120
[ 6965.696719] [<ffffffff81090842>] dequeue_entity+0xb2/0x210
[ 6965.696803] [<ffffffff8108e77f>] ? __dequeue_entity+0x2f/0x50
[ 6965.696804] [<ffffffff8108e820>] ? set_next_entity+0x80/0x90
[ 6965.696806] [<ffffffff8108fbdb>] ? pick_next_task_fair+0x6b/0x190
[ 6965.696808] [<ffffffff8108e944>] ? __enqueue_entity+0x74/0x80
[ 6965.696811] [<ffffffff81145f09>] ? handle_mm_fault+0x249/0x310
[ 6965.696813] [<ffffffff812089a6>] ? security_task_wait+0x16/0x20
[ 6965.696815] [<ffffffff8105a59d>] ? wait_consider_task+0x9d/0xae0
[ 6965.696818] [<ffffffff814877d9>] ? schedule+0x29/0x70
[ 6965.696819] [<ffffffff8105b1cf>] ? do_wait+0x1ef/0x280
[ 6965.696821] [<ffffffff8105c505>] ? sys_wait4+0x75/0xf0
[ 6965.696822] [<ffffffff8105a020>] ? task_stopped_code+0x60/0x60
[ 6965.696824] [<ffffffff8148fbad>] ? system_call_fastpath+0x1a/0x1f
[ 6967.764811] aureal 0003:0755:2626.0001: fixing Aureal Cy se W-01RN USB_V3.1 report descriptor.
[ 6967.868673] input: www.irfmedia.com W-01RN USB_V3.1 as /devices/pci0000:00/0000:00:1d.3/usb5/5-2/5-2:1.0/input/input19
[ 6967.998013] aureal 0003:0755:2626.0001: input,hidraw0: USB HID v1.10 Keyboard [www.irfmedia.com W-01RN USB_V3.1] on usb-0000:00:1d.3-2/input0
[ 6968.175145] input: www.irfmedia.com W-01RN USB_V3.1 as /devices/pci0000:00/0000:00:1d.3/usb5/5-2/5-2:1.1/input/input20
[ 6968.304752] aureal 0003:0755:2626.0002: input,hidraw1: USB HID v1.10 Mouse [www.irfmedia.com W-01RN USB_V3.1] on usb-0000:00:1d.3-2/input1
[ 6968.456162] usbcore: registered new interface driver usbhid
[ 6968.522934] usbhid: USB HID core driver
[ 6968.610100] EXT4-fs (sda2): re-mounted. Opts: discard,commit=0
[ 6968.681716] EXT4-fs (sda1): re-mounted. Opts: discard,commit=0
I have this issue since kernel 3.5.5.
It happens randomly about one time in ten.
Any ideas ?
Last edited by hamelg (2012-12-08 16:07:09)
Offline
The issue comes from a nfs fs where apps write on sometimes. When resume happens, pm-suspend forks a sync before the network is up. I remove my nfs mount or mount some with the ro option. Now pm-suspend works great
Last edited by hamelg (2012-11-10 11:03:09)
Offline
In final, not solved
The nfs fs was another problem.
This issue comes back sporadically.
I note it's always the same stack.
Offline
I've tried to troubleshoot my problem by using a custom kernel with options :
CONFIG_PM_TRACE=y
CONFIG_PM_TRACE_RTC=y
sysctl kernel.panic=2
sysctl kernel.hung_task_panic=1
sysctl kernel.hung_task_timeout_secs=60
With these options, my issue has vanished !
I've look in the source kernel and I saw that enabling trace disables asynchronous mode.
The asynchronous mode enabled by default doesn't work correctly on my hardware.
"echo 0 > /sys/power/pm_async" has fixed definitely my issue.
Offline