[SOLVED] how to troubleshoot v e r y s l o w shutdown/reboot?

[hooly]

shutdown/restart begins, goes to the Mint logo with the shifty little green dots, does that for 1.5-2 minutes before actually completing the shutdown/reboot.
that process used to take seconds and i'd very much like that to be the case once again.
searched around, haven't found much helpful. any tips/leads/hints/suggestions?
my system:

Code: Select all

$ inxi -Fz
System:    Host: cinna2-box Kernel: 4.10.0-38-generic x86_64 (64 bit) Desktop: Cinnamon 3.6.7
           Distro: Linux Mint 18.3 Sylvia
Machine:   Mobo: ASRock model: Z97 Extreme6 Bios: American Megatrends v: P2.50 date: 10/06/2015
CPU:       Quad core Intel Core i7-4790 (-HT-MCP-) cache: 8192 KB 
           clock speeds: max: 4000 MHz 1: 3949 MHz 2: 3990 MHz 3: 3362 MHz 4: 3949 MHz 5: 3877 MHz 6: 3975 MHz
           7: 3937 MHz 8: 3939 MHz
Graphics:  Card: NVIDIA GM204 [GeForce GTX 970]
           Display Server: X.Org 1.18.4 drivers: nvidia (unloaded: fbdev,vesa,nouveau)
           Resolution: 1920x1080@60.00hz
           GLX Renderer: GeForce GTX 970/PCIe/SSE2 GLX Version: 4.5.0 NVIDIA 384.111
Audio:     Card-1 NVIDIA GM204 High Definition Audio Controller driver: snd_hda_intel
           Card-2 Intel 9 Series Family HD Audio Controller driver: snd_hda_intel
           Sound: Advanced Linux Sound Architecture v: k4.10.0-38-generic
Network:   Card-1: Intel Ethernet Connection (2) I218-V driver: e1000e
           IF: enp0s25 state: up speed: 1000 Mbps duplex: full mac: <filter>
           Card-2: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller driver: r8169
           IF: enp3s0 state: down mac: <filter>
Drives:    HDD Total Size: 4512.9GB (0.5% used) ID-1: /dev/sda model: Samsung_SSD_850 size: 512.1GB
           ID-2: /dev/sdb model: ST4000DM000 size: 4000.8GB
Partition: ID-1: / size: 257G used: 12G (5%) fs: ext4 dev: /dev/sda4
           ID-2: swap-1 size: 10.00GB used: 0.00GB (0%) fs: swap dev: /dev/sda5
RAID:      No RAID devices: /proc/mdstat, md_mod kernel module present
Sensors:   System Temperatures: cpu: 36.0C mobo: N/A gpu: 52C
           Fan Speeds (in rpm): cpu: N/A
Info:      Processes: 261 Uptime: 1:40 Memory: 3425.5/15991.1MB Client: Shell (bash) inxi: 2.2.35 

[Hoser Rob]

Start/restart the machine and then run this immediately in the terminal to see what's taking so long on startup:

Code: Select all

systemd-analyze blame

Copy/paste the text output of that here. It's quite possible the shutdown delay is caused by the same thing.

[hooly]

thank you for the reply. i can't say that i notice any slowdown during startup but what the heck, maybe there is something there. here's the first page of that output.

Code: Select all

1.169s lvm2-monitor.service
   200ms dev-sda4.device
   118ms upower.service
	76ms accounts-daemon.service
	65ms ModemManager.service
	65ms networking.service
	62ms systemd-logind.service
	61ms irqbalance.service
	60ms grub-common.service
	60ms apport.service
	57ms lightdm.service
	53ms console-setup.service
	50ms NetworkManager.service
	46ms loadcpufreq.service
	45ms hddtemp.service
	43ms ntp.service
	42ms ondemand.service
	40ms speech-dispatcher.service
	39ms systemd-udev-trigger.service
	36ms plymouth-quit-wait.service
	34ms keyboard-setup.service
	31ms udisks2.service
	29ms apparmor.service
	28ms systemd-journald.service
	26ms alsa-restore.service
	24ms lm-sensors.service
	23ms console-kit-log-system-start.service
	22ms systemd-tmpfiles-setup-dev.service
	21ms systemd-user-sessions.service
	21ms pppd-dns.service
	18ms systemd-udevd.service
	17ms gpu-manager.service
	16ms systemd-fsck@dev-disk-by\x2duuid-FF27\x2d06D1.service
	16ms thermald.service
	15ms systemd-modules-load.service
	15ms cpufrequtils.service
	15ms rsyslog.service
	12ms binfmt-support.service
	12ms plymouth-start.service
	11ms plymouth-read-write.service
	11ms colord.service
	11ms user@1000.service
	 9ms polkitd.service
	 8ms iio-sensor-proxy.service
	 8ms flatpak-system-helper.service
	 7ms avahi-daemon.service
	 7ms dev-mqueue.mount
	 6ms systemd-update-utmp.service
	 6ms resolvconf.service
	 5ms systemd-remount-fs.service
	 5ms boot-efi.mount
	 5ms dev-hugepages.mount
	 5ms systemd-sysctl.service
	 4ms kmod-static-nodes.service
	 4ms systemd-tmpfiles-setup.service
	 4ms ufw.service
	 4ms dev-sda5.swap
	 4ms sys-kernel-debug.mount
	 4ms systemd-journal-flush.service
	 3ms rtkit-daemon.service
	 2ms dns-clean.service
	 2ms proc-sys-fs-binfmt_misc.mount
	 1ms systemd-update-utmp-runlevel.service
	 1ms systemd-random-seed.service
	 1ms setvtrgb.service
	 1ms sys-fs-fuse-connections.mount
	 1ms nvidia-persistenced.service
	 1ms openvpn.service
lines 1-68

[thx-1138]

...1) try pressing ESC while it shutdowns, take note of any messages displayed...
...2) open Log File Viewer, check past logs at around the time the shutdown was initiated...

[hooly]

@ thx-1138 : thank you for the suggestions. pressing ESC had no visible effect, shutdown proceeded with only the logo onscreen, no messages. at the very last instant one short line popped up at the top of the screen but it's gone in a fraction of a second.

as to Log File Viewer i have no such application in my installation nor in the Software Manager. i did find "System Log" in the Administration app list. in that i see these messages from the end of syslog during a shutdown:

Code: Select all

May 31 07:38:09 cinna2-box anacron[928]: ...Normal exit (1 job run)
May 31 07:42:07 cinna2-box systemd[1]: Stopping Disk Manager...
May 31 07:42:07 cinna2-box systemd[1]: Stopping Save/Restore Sound Card State...
May 31 07:42:07 cinna2-box systemd[1]: Stopping User Manager for UID 1000...
May 31 07:42:07 cinna2-box systemd[1]: Closed Load/Save RF Kill Switch Status /dev/rfkill Watch.
May 31 07:42:07 cinna2-box systemd[1]: Stopping Manage, Install and Generate Color Profiles...
May 31 07:42:07 cinna2-box systemd[1]: Stopping Authenticate and Authorize Users to Run Privileged Tasks...
May 31 07:42:07 cinna2-box systemd[1]: Stopped Stop ureadahead data collection 45s after completed startup.
May 31 07:42:07 cinna2-box systemd[1]: Stopping flatpak system helper...
May 31 07:42:07 cinna2-box systemd[1]: Stopping Daemon for power management...
May 31 07:42:07 cinna2-box systemd[1]: Stopping RealtimeKit Scheduling Policy Service...
May 31 07:42:07 cinna2-box systemd[1]: Stopping ACPI event daemon...
May 31 07:42:07 cinna2-box systemd[1]: Stopping NVIDIA Persistence Daemon...
May 31 07:42:07 cinna2-box systemd[1]: Stopped target Sound Card.
May 31 07:42:07 cinna2-box nvidia-persistenced: Received signal 15
May 31 07:42:07 cinna2-box obexd[1916]: Terminating
May 31 07:42:07 cinna2-box systemd[1]: Stopping Session c1 of user cinna2.
May 31 07:42:07 cinna2-box systemd[1]: Stopped target Graphical Interface.
May 31 07:42:07 cinna2-box systemd[1]: Stopped target Multi-User System.
May 31 07:42:07 cinna2-box systemd[1]: Stopped OpenVPN service.
May 31 07:42:07 cinna2-box systemd[1]: Stopped Initialize hardware monitoring sensors.
May 31 07:42:07 cinna2-box rsyslogd: [origin software="rsyslogd" swVersion="8.16.0" x-pid="923" x-info="http://www.rsyslog.com"] exiting on signal 15.

is there a problem revealed in that? if so it's well over my head.

[thx-1138]

...can you remember more or less when that behavior started? Had you by any chance updated / changed your NVidia driver? Or else, maybe you had plugged-in / mounted an external device?

[hooly]

i did switch over from the default Nouveau video driver to Nvidia-384 after installation, could not boot up properly without it (had to use nomodeset to boot, install the Nvidia driver, then boot normally).
as to when the slow-down occurred ... pretty much right away as i recall. this is a fresh install from earlier in the week.
external devices are a Bluetooth key for my mouse, a wired keyboard, an old Samsung printer, an ethernet modem.

[greerd]

You should be able to reboot from a virtual console that will show the process.
Ctl-Alt-F1 gets you into virtual console #1, from there, login as normal, then enter sudo reboot, enter your password again and take note of the process that's hanging.

[thx-1138]

...Since this is a fairly new install, if you haven't yet updated the bits & parts under Level 4 in Update Manager, it might be a good idea doing so (also, in a complementary note, kernel 4.10 is unsupported by now...only kernels 4.4.x & 4.13.x actually receive bug fixes & security updates).
Just in case, post also the output from dmesg | grep "rror\|arn\|ail"...

...do try what as greerd suggested (as the above log snippet didn't really revealed anything extra ordinary, hence we can only make semi-random guesswork-alike proposals)...

[hooly]

ok, tried console reboot. not sure what i was supposed to see but all i got was the regular reboot process: Mint logo, cycling green dots, took 2ish minutes and then finally completed and booted back up. no messages shown so nothing to make note of.

i'd happily do the level 4s to 4.13 but i did that on a previous installation from about 2 weeks ago and ended up with no network (see viewtopic.php?t=270087 ) which is what brought me to reinstall again this week.

here's that dmesg output:

Code: Select all

dmesg | grep "rror\|arn\|ail"
[    0.000000] e820: [mem 0xcf000000-0xefffffff] available for PCI devices
[    0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[    0.000000] Memory: 16111824K/16723808K available (9070K kernel code, 1667K rwdata, 3828K rodata, 2228K init, 2364K bss, 611984K reserved, 0K cma-reserved)
[    0.847040] EDD information not available.
[    3.952937] EXT4-fs (sda4): re-mounted. Opts: errors=remount-ro
[    4.034747] ACPI Warning: SystemIO range 0x0000000000001828-0x000000000000182F conflicts with OpRegion 0x0000000000001800-0x000000000000187F (\PMIO) (20160930/utaddress-247)
[    4.034751] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[    4.034753] ACPI Warning: SystemIO range 0x0000000000001C40-0x0000000000001C4F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
[    4.034756] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[    4.034756] ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-247)
[    4.034759] ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
[    4.034761] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[    4.034762] ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-247)
[    4.034764] ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
[    4.034766] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
[    4.078042] nvidia: module verification failed: signature and/or required key missing - tainting kernel

[thx-1138]

...just some ACPI warnings, but nothing really to worry about. So let's try some guesswork...

1)Before shutting down, try disabling Networking / WiFi from NetworkManager's applet, in case it somehow interferes.If still nada...

2)gksudo xed /etc/systemd/system.conf
Change the values in the following lines as:
DefaultTimeoutStartSec=15s
DefaultTimeoutStopSec=15s
Then run: sudo systemctl daemon-reload

[hooly]

ok, no joy on the network disconnect thing, made no difference whatsoever.
now doing the system.conf tweaks ...

i see the lines in system.conf pretty much all start with "#". i assume that means they are commented out, yes?
assuming so until I hear otherwise so copied the lines that were there:

Code: Select all

#DefaultTimeoutStartSec=90s
#DefaultTimeoutStopSec=90s

removed the #s and changed the values to 15s.

so what am i looking for when i do

Code: Select all

sudo systemctl daemon-reload

? i got nothing, just back to the shell prompt.

guessed and did a reboot: SUCCESS! much faster now, about 15s at a rough count. that can't be a coincidence.
so what, was there actually a 90s timer running somewhere?
and if that system.conf change made the difference is there any reason to NOT set the DefaultTimeoutStopSec to something nice and short like 5s?

[hooly]

curious fellow that i am i started poking around for info on safe values for DefaultTimeoutStopSec.
found lots of dire warnings about low values corrupting journalling and such.

did run across one thing that suggested logging out of the user session first, then doing the shutdown.

tried that and WOW, speedy shutdown indeed! couple of seconds or so from the login screen to system powered off.

so why is it safe to exit that way -- logging out happens pretty fast too -- and not the small values for DefaultTimeoutStopSec way?

being the tweaker that i am i'm tempted to try scripting something that does logout then shutdown. seems like a great idea given what i've seen. anything wrong with doing so?

[thx-1138]

...in regards to the DefaultTimeoutStopSec 'trick', read marfig's replies here.
Ie. generally speaking, more or less, those are hackish quick'n'dirty workarounds - what someone actually needs to do, is to identify what service / task hangs the shutdown process in the first place (via checking the logs...)
Why logging out first works, no idea - apparently because some background tasks get 'killed' or have their state changed in doing so (including the allegedly problematic one).

In my own personal experience, the couple of times that i've had long & slow delays out-of-the-blue (ie. without me having first installed weirdo services or buggy drivers), it was a matter of the kernel in question not playing nicely with my system...
But do note that i've never used NVidia under linux (and i've seen all kind of unusual behavior with such - hence the reason i asked previously if you changed it's driver / version etc)...

[hooly]

... the couple of times that i've had long & slow delays out-of-the-blue (ie. without me having first installed weirdo services or buggy drivers), it was a matter of the kernel in question not playing nicely with my system...

so sounds like we think there's still something unsolved here, yes?

[thx-1138]

...well, if you've found a workaround for the time being (either DefaultTimeoutStopSec, or scripting log-out then reboot) - then who am I to argue with such?
I mean, not everything is always solvable with an 100% 'correct'™ way in this life (if the logs aren't proven useful in any way, I'd probably do the same myself, keeping an eye every now & then on different kernel and -possibly- graphics driver versions) - thing is for you to be satisfied & get your job done in a set-it-and-forget-it hassle free manner...

[hooly]

fair enough, i'll mark this solved then.

i do have one remaining question: some time ago i recall reading that the shutdown process could be suspended at the end pending input from the user. the point being that that would allow one to see the shutdown messages that would have otherwise flown by and been lost in the reboot. does this ring any bells?

[powerwagon75]

hooly,

Look at the attached photo, at the very bottom of the display screen. This is likely what your system was pausing 90 seconds for. You can see its at 17 seconds of 1:30 to make CUPS printers available locally (?) It seems this was previously a bug (https://askubuntu.com/questions/982171/ ... d-shutdown) that was reportedly fixed.

However, on two of my test machines, the only ones that have Mint 18.3 Cinnamon on them, they both do this. The ones with Mint 18 and older do not do it.

If you wanted to verify why exactly it is stopping for you, you can edit your /etc/default/grub file (after making a backup of course), and remove the quiet splash from that particular line. Do your sudo update-grub in terminal, then restart, and then shut it off. (it didn't scroll right after the grub update on first shutdown on the HP test pc, but did on the second shutdown.)

For whatever odd reason, the two that have the delay, one is a Macbook Pro, and it will not show the shut down events scrolling through the display..all other systems do.

I haven't been able to figure out from where the timed event originates from.

[hooly]

thank you for that and yes, i've seen almost exactly that on one of my recent Mint 18.3 installations. can't recall that it mentioned CUPS but the format etc was certainly the same, even showed the same 90s countdown.

on my most recent Mint 18.3 installation i've removed "quiet splash" temporarily -- edited grub during boot -- and i DON'T see that message but it certainly behaves the same way, with or without the message. same delay during shutdown/reboot starting at the same time. i see the initial messages then nothing happens for the 90 seconds or so, ending with a brief burst of messages and the actual hardware reset. that's why i asked about suspending the reboot pending user input at the very end, that would give me a chance to see those last messages.

needless to say it would be nice to know what's doing it.

[phd21]

Hi "hooly",

I just read your post and the good replies to it. Here are my thoughts on this as well.

I too have noticed that it does take some time to shutdown or restart.

FYI: There are also various "shutdown" applications and or key combinations (and scripts), that can accelerate shutting down. "Qshutdown" in the Software Manager or Synaptic Package Manager (SPM) is a really nice application, you can just right-click its icon to select shutdown now, or even set timed options.


Other posts:

On my ancient under-powered computer, I always get boot error messages related to "ACPI and APIC", but the system always works. After reading these articles and posts, they recommend changing the "Grub2" boot up file to either turn this off (disable it), or add "acpi=force reboot=acpi" to the Linux command line.

To edit the Grub bootloader file using the "xed" text editor

Code: Select all

sudo xed /etc/default/grub

Locate the line below
GRUB_CMDLINE_LINUX_DEFAULT="quiet"

Change it to add acpi=force reboot=acpi between the quotes
GRUB_CMDLINE_LINUX_DEFAULT="quiet acpi=force reboot=acpi"
or disable "ACPI and APIC"
GRUB_CMDLINE_LINUX_DEFAULT="quiet noapic acpi=off"


Then, save the changes and exit the text editor, and update Grub2 changes, and reboot

Code: Select all

sudo update-grub2

=================================================================================
(1) {SOLVED}My PC won't shutdown with linux mint 18.3 - Linux Mint Forums
viewtopic.php?f=90&t=270377

Why can't I restart/shutdown? - Ask Ubuntu
https://askubuntu.com/questions/7114/wh ... t-shutdown

BootOptions - Community Help Wiki
* see Common Kernel Options category
https://help.ubuntu.com/community/BootOptions

Hope this helps ...