LinuxQuestions.org
Welcome to the most active Linux Forum on the web.
Go Back   LinuxQuestions.org > Forums > Linux Forums > Linux - Software
User Name
Password
Linux - Software This forum is for Software issues.
Having a problem installing a new program? Want to know which application is best for the job? Post your question in this forum.

Notices


Reply
  Search this Thread
Old 07-05-2015, 04:30 PM   #1
joe_2000
Senior Member
 
Registered: Jul 2012
Location: Aachen, Germany
Distribution: Void, Debian
Posts: 1,019

Rep: Reputation: 308Reputation: 308Reputation: 308Reputation: 308
Boot sometimes hangs: kworker/0:1:42 blocked for more than 120 seconds


On my Arch laptop the boot process sometimes hangs several minutes.
When that happens, typically also the shutdown will hang.
This is what gets printed to the journal log in these cases:
Code:
Jul 05 20:58:55 ideapad kernel: INFO: task kworker/0:1:42 blocked for more than 120 seconds.
Jul 05 20:58:55 ideapad kernel:       Not tainted 4.0.7-2-ARCH #1
Jul 05 20:58:55 ideapad kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 05 20:58:55 ideapad kernel: kworker/0:1     D ffff88015989b678     0    42      2 0x00000000
Jul 05 20:58:55 ideapad kernel: Workqueue: kacpid acpi_os_execute_deferred
Jul 05 20:58:55 ideapad kernel:  ffff88015989b678 ffffffff818124c0 ffff880159890000 fffffffffff7ffff
Jul 05 20:58:55 ideapad kernel:  ffff88015989bfd8 ffff880159efb4bc ffff880159890000 00000000ffffffff
Jul 05 20:58:55 ideapad kernel:  ffff880159efb4c0 ffff88015989b698 ffffffff81576a87 00000000000000ed
Jul 05 20:58:55 ideapad kernel: Call Trace:
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81576a87>] schedule+0x37/0x90
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81576e55>] schedule_preempt_disabled+0x15/0x20
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81578395>] __mutex_lock_slowpath+0xd5/0x150
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8157842b>] mutex_lock+0x1b/0x30
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8134cae2>] acpi_ec_transaction+0x84/0x438
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8134cef0>] acpi_ec_read+0x5a/0x7a
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8134d0c1>] acpi_ec_space_handler+0xde/0x1ff
Jul 05 20:58:55 ideapad kernel:  [<ffffffff810bdca2>] ? up+0x32/0x50
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8134cfe3>] ? ec_transaction+0x70/0x70
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135a2ff>] acpi_ev_address_space_dispatch+0x201/0x262
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135de09>] acpi_ex_access_region+0x1ea/0x27a
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135a2ff>] ? acpi_ev_address_space_dispatch+0x201/0x262
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135e1d0>] acpi_ex_field_datum_io+0x10a/0x198
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135e2d4>] acpi_ex_write_with_update_rule+0x76/0xf2
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135e08a>] acpi_ex_insert_into_field+0x1f1/0x22d
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135dbab>] acpi_ex_write_data_to_field+0x1e7/0x212
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81361d06>] acpi_ex_store_object_to_node+0xc1/0xf1
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81361e06>] acpi_ex_store+0xd0/0x261
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8135f28d>] acpi_ex_opcode_1A_1T_1R+0x3ef/0x528
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81361905>] ? acpi_ex_resolve_operands+0x212/0x4ed
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81356f1a>] acpi_ds_exec_end_op+0xd0/0x3ef
Jul 05 20:58:55 ideapad kernel:  [<ffffffff813698e4>] acpi_ps_parse_loop+0x532/0x598
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81371e1b>] ? acpi_ut_create_generic_state+0x37/0x42
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8136a3e7>] acpi_ps_parse_aml+0x99/0x271
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8136ac3e>] acpi_ps_execute_method+0x1c0/0x264
Jul 05 20:58:55 ideapad kernel:  [<ffffffff813652a1>] acpi_ns_evaluate+0x1c3/0x24f
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81367d37>] acpi_evaluate_object+0x196/0x2a6
Jul 05 20:58:55 ideapad kernel:  [<ffffffff810145a8>] ? __switch_to+0xe8/0x610
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8134c12c>] acpi_ec_run+0x5a/0x88
Jul 05 20:58:55 ideapad kernel:  [<ffffffff81342f19>] acpi_os_execute_deferred+0x15/0x22
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8108dadb>] process_one_work+0x14b/0x470
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8108e228>] worker_thread+0x48/0x4b0
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8108e1e0>] ? init_pwq.part.7+0x10/0x10
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8108e1e0>] ? init_pwq.part.7+0x10/0x10
Jul 05 20:58:55 ideapad kernel:  [<ffffffff810934b8>] kthread+0xd8/0xf0
Jul 05 20:58:55 ideapad kernel:  [<ffffffff810933e0>] ? kthread_worker_fn+0x170/0x170
Jul 05 20:58:55 ideapad kernel:  [<ffffffff8157a718>] ret_from_fork+0x58/0x90
Jul 05 20:58:55 ideapad kernel:  [<ffffffff810933e0>] ? kthread_worker_fn+0x170/0x170
And one example message where it blocked at shutdown:
Code:
Jul 05 21:00:16 ideapad systemd[1]: Stopping Local File Systems.
Jul 05 21:00:16 ideapad systemd[1]: Unmounting /run/user/1000...
Jul 05 21:00:16 ideapad systemd[1]: Unmounting /srv/edr-data...
Jul 05 21:00:16 ideapad umount[997]: umount: /srv/edr-data: target is busy
Jul 05 21:00:16 ideapad umount[997]: (In some cases useful info about processes that
Jul 05 21:00:16 ideapad umount[997]: use the device is found by lsof(8) or fuser(1).)
Jul 05 21:00:16 ideapad systemd[1]: Unmounting Temporary Directory...
Jul 05 21:00:16 ideapad umount[998]: umount: /tmp: target is busy
Jul 05 21:00:16 ideapad umount[998]: (In some cases useful info about processes that
Jul 05 21:00:16 ideapad umount[998]: use the device is found by lsof(8) or fuser(1).)
Jul 05 21:00:16 ideapad systemd[1]: srv-edr\x2ddata.mount: Mount process exited, code=exited status=32
Jul 05 21:00:16 ideapad systemd[1]: Failed unmounting /srv/edr-data.
Jul 05 21:00:16 ideapad systemd[1]: tmp.mount: Mount process exited, code=exited status=32
Jul 05 21:00:16 ideapad systemd[1]: Failed unmounting Temporary Directory.
Jul 05 21:00:16 ideapad systemd[1]: Unmounted /run/user/1000.
Jul 05 21:00:16 ideapad systemd[1]: Reached target Unmount All Filesystems.
Jul 05 21:00:16 ideapad systemd[1]: Starting Unmount All Filesystems.
Jul 05 21:00:16 ideapad systemd[1]: Stopped target Local File Systems (Pre).
Jul 05 21:00:16 ideapad systemd[1]: Stopping Local File Systems (Pre).
Jul 05 21:00:16 ideapad systemd[1]: Stopped Create Static Device Nodes in /dev.
Jul 05 21:00:16 ideapad systemd[1]: Stopping Create Static Device Nodes in /dev...
Jul 05 21:00:16 ideapad systemd[1]: Stopped Remount Root and Kernel File Systems.
Jul 05 21:00:16 ideapad systemd[1]: Stopping Remount Root and Kernel File Systems...
Jul 05 21:00:16 ideapad systemd[1]: Reached target Shutdown.
Jul 05 21:00:16 ideapad systemd[1]: Starting Shutdown.
Jul 05 21:00:16 ideapad systemd[1]: Reached target Final Step.
Jul 05 21:00:16 ideapad systemd[1]: Starting Final Step.
Jul 05 21:00:16 ideapad systemd[1]: Starting Reboot...
Jul 05 21:00:16 ideapad systemd[1]: Shutting down.
Jul 05 21:00:16 ideapad systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Jul 05 21:00:16 ideapad systemd[1]: Set hardware watchdog to 10min.
Jul 05 21:00:16 ideapad kernel: watchdog watchdog0: watchdog did not stop!
Jul 05 21:00:17 ideapad systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Jul 05 21:00:17 ideapad systemd-journal[256]: Journal stopped
I'd say this happens maybe in 1 out of 10 boots. The system layout is based on this full disk encryption guide in case that's relevant.

If I read the stack traces right, this has to do with acpi, right? How can I fix this?
 
Old 07-06-2015, 06:35 AM   #2
dijetlo
Senior Member
 
Registered: Jan 2009
Location: RHELtopia....
Distribution: Solaris 11.2/Slackware/RHEL/
Posts: 1,491
Blog Entries: 2

Rep: Reputation: Disabled
Um... you could try turning off ACPI in you bios or you could pass the kernel a
Quote:
acpi=off noacpi
switch as a boot parameter.

Course, that might lock out your power management software and just end up causing you a different problem, however fortune favors the bold
 
1 members found this post helpful.
Old 07-06-2015, 07:09 AM   #3
joe_2000
Senior Member
 
Registered: Jul 2012
Location: Aachen, Germany
Distribution: Void, Debian
Posts: 1,019

Original Poster
Rep: Reputation: 308Reputation: 308Reputation: 308Reputation: 308
Quote:
Originally Posted by dijetlo View Post
Um... you could try turning off ACPI in you bios or you could pass the kernel a
switch as a boot parameter.

Course, that might lock out your power management software and just end up causing you a different problem, however fortune favors the bold
Thanks for the suggestion. I refrained from doing so because I read that this might also turn off temperature control and thus lead to overheating. Not sure if I am bold enough for such a move :-)
 
Old 07-06-2015, 03:35 PM   #4
Head_on_a_Stick
Senior Member
 
Registered: Dec 2014
Location: London, England
Distribution: Debian stable (and OpenBSD-current)
Posts: 1,187

Rep: Reputation: 285Reputation: 285Reputation: 285
Have you tried the LTS kernel?

https://www.archlinux.org/packages/c..._64/linux-lts/
 
1 members found this post helpful.
Old 07-06-2015, 04:46 PM   #5
joe_2000
Senior Member
 
Registered: Jul 2012
Location: Aachen, Germany
Distribution: Void, Debian
Posts: 1,019

Original Poster
Rep: Reputation: 308Reputation: 308Reputation: 308Reputation: 308
Quote:
Originally Posted by Head_on_a_Stick View Post
Thanks for the idea. One of the things I find most exciting about Arch is running a bleeding edge kernel. But I agree with you, this is worth trying to see if it makes the problem go away. I'll give this a shot and report back.

Meanwhile I am happy for any further input on how to debug this...
 
Old 07-06-2015, 05:04 PM   #6
joe_2000
Senior Member
 
Registered: Jul 2012
Location: Aachen, Germany
Distribution: Void, Debian
Posts: 1,019

Original Poster
Rep: Reputation: 308Reputation: 308Reputation: 308Reputation: 308
Quote:
Originally Posted by Head_on_a_Stick View Post
Ok, I tried this, but it seems even worse. The boot freezed completely when trying to bring up udev. After 5 minutes without any output whatsoever I killed it by hard reset.
System back up and running with the standard kernel now. Crash message from the previous (failed) boot with the lts-kernel is this:
Code:
Jul 06 22:50:54 ideapad kernel: iwlwifi 0000:02:00.0: Detected Intel(R) Wireless N 7260, REV=0x144
Jul 06 22:50:54 ideapad kernel: iwlwifi 0000:02:00.0: L1 Disabled - LTR Enabled
Jul 06 22:50:54 ideapad kernel: iwlwifi 0000:02:00.0: L1 Disabled - LTR Enabled
Jul 06 22:50:54 ideapad systemd-udevd[282]: Process '/usr/lib/systemd/systemd-vconsole-setup' failed with exit code 1.
Jul 06 22:50:54 ideapad systemd-udevd[281]: Process '/sbin/modprobe -r psmouse' failed with exit code 1.
Jul 06 22:51:53 ideapad systemd-udevd[270]: seq 1376 '/devices/pci0000:00/0000:00:03.0' is taking a long time
Jul 06 22:51:53 ideapad systemd-udevd[270]: seq 1375 '/devices/pci0000:00/0000:00:02.0' is taking a long time
Jul 06 22:51:53 ideapad systemd-udevd[270]: seq 1394 '/devices/pci0000:00/0000:00:1b.0' is taking a long time
Jul 06 22:51:54 ideapad systemd-udevd[270]: seq 1616 '/devices/virtual/vtconsole/vtcon1' is taking a long time
Jul 06 22:53:53 ideapad systemd-udevd[270]: seq 1375 '/devices/pci0000:00/0000:00:02.0' killed
Jul 06 22:53:53 ideapad systemd-udevd[270]: seq 1376 '/devices/pci0000:00/0000:00:03.0' killed
Jul 06 22:53:53 ideapad systemd-udevd[270]: seq 1394 '/devices/pci0000:00/0000:00:1b.0' killed
Jul 06 22:53:53 ideapad systemd-udevd[270]: worker [274] terminated by signal 9 (Killed)
Jul 06 22:53:53 ideapad systemd-udevd[270]: worker [274] failed while handling '/devices/pci0000:00/0000:00:1b.0'
Jul 06 22:53:54 ideapad systemd-udevd[270]: seq 1616 '/devices/virtual/vtconsole/vtcon1' killed
Jul 06 22:53:54 ideapad systemd-udevd[270]: worker [286] terminated by signal 9 (Killed)
Jul 06 22:53:54 ideapad systemd-udevd[270]: worker [286] failed while handling '/devices/virtual/vtconsole/vtcon1'
 
Old 08-26-2015, 05:04 PM   #7
joe_2000
Senior Member
 
Registered: Jul 2012
Location: Aachen, Germany
Distribution: Void, Debian
Posts: 1,019

Original Poster
Rep: Reputation: 308Reputation: 308Reputation: 308Reputation: 308
After changing the init system, the initial ramdisk creation tool and even the distro (none of this helped) I now finally seem to have found a solution to this.

Sometimes in the dmesg.log the last line before hangs of approximately a minute would be
Code:
Switched to clocksource tsc
So I tried changing the clocksource to hpet using the following kernel parameter:
Code:
clocksource=hpet
I have now booted about 10 times and no hangs... Will mark as solved.
 
  


Reply

Tags
boot, deadlock, hang, systemd


Thread Tools Search this Thread
Search this Thread:

Advanced Search

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is Off
HTML code is Off



Similar Threads
Thread Thread Starter Forum Replies Last Post
INFO : task events/2:69 blocked for more than 120 seconds ttinvent Linux - Server 5 12-29-2014 04:12 AM
Task blocked for more than 120 seconds errors and crashes Red Squirrel Linux - Server 17 04-01-2014 02:12 PM
RHEL VM - blocked for more than 120 seconds rajaniyer123 Linux - Virtualization and Cloud 0 07-13-2012 10:35 AM
Task blocked for more than 120 seconds errors and crashes sanjay87 Linux - Server 3 06-19-2012 02:51 AM
INFO: <application>blocked for more than 120 seconds alok.rhct Linux - Hardware 1 04-08-2009 02:35 AM

LinuxQuestions.org > Forums > Linux Forums > Linux - Software

All times are GMT -5. The time now is 11:17 PM.

Main Menu
Advertisement
My LQ
Write for LQ
LinuxQuestions.org is looking for people interested in writing Editorials, Articles, Reviews, and more. If you'd like to contribute content, let us know.
Main Menu
Syndicate
RSS1  Latest Threads
RSS1  LQ News
Twitter: @linuxquestions
Open Source Consulting | Domain Registration