You are not logged in.

#1 2012-10-27 22:10:22

hamelg
Member
From: France
Registered: 2008-06-19
Posts: 128

[Solved] Resume from sleep to RAM very slow (takes 5min)

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

#2 2012-11-10 11:01:25

hamelg
Member
From: France
Registered: 2008-06-19
Posts: 128

Re: [Solved] Resume from sleep to RAM very slow (takes 5min)

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 smile

Last edited by hamelg (2012-11-10 11:03:09)

Offline

#3 2012-11-12 21:45:56

hamelg
Member
From: France
Registered: 2008-06-19
Posts: 128

Re: [Solved] Resume from sleep to RAM very slow (takes 5min)

In final, not solved sad
The nfs fs was another problem.
This issue comes back sporadically.
I note it's always the same stack.

Offline

#4 2012-12-08 16:05:57

hamelg
Member
From: France
Registered: 2008-06-19
Posts: 128

Re: [Solved] Resume from sleep to RAM very slow (takes 5min)

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

Board footer

Powered by FluxBB