Slow 5+ minute boot; fsck on each boot

grokov · 2. April 2020

I am reinstalling/reconfiguring OMV on my Odroid-HC2 and while it previously would boot in about 1 minute, it now takes around 5 minutes.

I notice large time gaps in dmesg (click here for full log) around hard drive activity:

Code

[   35.498895] usb 4-1: new SuperSpeed USB device number 2 using xhci-hcd
[   35.520938] usb 4-1: New USB device found, idVendor=152d, idProduct=0578
[   35.520978] usb 4-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[   35.521009] usb 4-1: Product: USB to SATA bridge
[   35.521038] usb 4-1: Manufacturer: JMicron
[   35.521067] usb 4-1: SerialNumber: DB00000000013B
[   35.553958] scsi host0: uas
[   35.554923] scsi 0:0:0:0: Direct-Access     JMicron                   3101 PQ: 0 ANSI: 6
[   35.556089] sd 0:0:0:0: Attached scsi generic sg0 type 0
[   35.556595] usbcore: registered new interface driver uas
[   35.556810] sd 0:0:0:0: [sda] 19532873728 512-byte logical blocks: (10.0 TB/9.10 TiB)
[   35.556817] sd 0:0:0:0: [sda] 4096-byte physical blocks
[   35.557018] sd 0:0:0:0: [sda] Write Protect is off
[   35.557025] sd 0:0:0:0: [sda] Mode Sense: 53 00 00 08
[   35.557403] sd 0:0:0:0: [sda] Disabling FUA
[   35.557412] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[   35.557807] sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes not a multiple of physical block size (4096 bytes)
[   35.614759] sd 0:0:0:0: [sda] Attached SCSI disk
[   51.950768] sd 0:0:0:0: [sda] tag#0 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD IN 
[   51.950825] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x85 85 08 0e 00 00 00 01 00 00 00 00 00 00 40 ec 00
[   51.966622] scsi host0: uas_eh_device_reset_handler start
[   52.095401] usb 4-1: reset SuperSpeed USB device number 2 using xhci-hcd
[   52.116965] scsi host0: uas_eh_device_reset_handler success
[   67.822765] sd 0:0:0:0: [sda] tag#0 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD 
[   67.822821] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x85 85 06 20 00 82 00 00 00 00 00 00 00 00 40 ef 00
[   67.838617] scsi host0: uas_eh_device_reset_handler start
[   67.966908] usb 4-1: reset SuperSpeed USB device number 2 using xhci-hcd
[   67.991113] scsi host0: uas_eh_device_reset_handler success
[   67.991362] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x0e
[   67.991399] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x0 [current] [descriptor] 
[   67.991429] sd 0:0:0:0: [sda] tag#0 ASC=0x0 ASCQ=0x1d 
[   67.991461] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x85 85 06 20 00 82 00 00 00 00 00 00 00 00 40 ef 00
[  259.875998] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x08
[  259.876120] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[  259.876184] sd 0:0:0:0: [sda] tag#0 ASC=0x4 ASCQ=0x1 
[  259.876250] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 04 8c 3f ff 80 00 00 00 08 00 00
[  259.876307] print_req_error: I/O error, dev sda, sector 19532873600
[  312.014552] EXT4-fs (sda): mounted filesystem with ordered data mode. Opts: user_xattr,usrjquota=aquota.user,grpjquota=aquota.group,jqfmt=vfsv0,acl

Alles anzeigen

I was concerned by the error message print_req_error: I/O error, dev sda, sector 19532873600 so I ran e2fsck -c -c /dev/sda (took over 3 days!) for a non-destructive read-write test checking for bad blocks and it reported no errors. SMART's short self-test also reports OK status. Since the hdd is used for backups, I also ran a consistency check of all the backups contained on it and no problems were found.

Systemd shows that fsck took ~4 minutes to run, and it runs on each boot. This could perfectly explain the boot time jump from ~1 minute to ~5 minutes.

Code

Startup finished in 17.085s (kernel) + 5min 7.011s (userspace) = 5min 24.097s

    3min 53.356s systemd-fsck@dev-disk-by\x2dlabel-WD100EFAX.service
          9.898s networking.service
          6.108s NetworkManager-wait-online.service
          2.003s folder2ram_startup.service
          1.539s dev-mmcblk1p2.device
           796ms armbian-ramlog.service
           656ms nginx.service
           656ms openmediavault-issue.service
           564ms srv-dev\x2ddisk\x2dby\x2dlabel\x2dWD100EFAX.mount
           555ms run-rpc_pipefs.mount
           547ms sys-kernel-debug.mount
           543ms openmediavault-engined.service
           488ms quota.service
           478ms lvm2-monitor.service
           469ms resolvconf.service
           453ms smbd.service
           453ms phpsessionclean.service
           433ms loadcpufreq.service
           431ms proc-fs-nfsd.mount
           425ms dev-mqueue.mount
           423ms rrdcached.service
           410ms systemd-udev-trigger.service
           407ms openmediavault-beep-up.service

Alles anzeigen

Any tips to identify what is going on and bringing the boot time back to normal?

Adoby · 2. April 2020

It might help if you remove the drive and, using SATA, plug it in to a more powerful Linux computer. Then diagnostics, fsck and format may go faster. Also you can use for instance gparted to check and possibly fix the hdd.

A full format may be needed. Not a "fast" format. If the drive is bad, it may make it worse. Or fix it.

Possibly use a temporary Linux computer by booting from a thumbdrive with a live Linux version, like Ubuntu.

grokov · 2. April 2020

Thanks, but as mentioned the checks are already done and found no problems. It takes a long time because it's a 10TB drive. I checked it with badblocks when I first got the drive, in a USB3 dock attached to a linux computer, and then too it took 3 days to complete.

In any case, I still have no clue what the issue is with the long boot time and fsck at each boot.

Adoby · 2. April 2020

I believe the time used by fsck is proportional to the number of files on the drive. If you recently have unpacked archives or compressed backups, so the number of files have increased a lot, then that may be a cause?

KM0201 · 2. April 2020

Zitat von grokov

Thanks, but as mentioned the checks are already done and found no problems. It takes a long time because it's a 10TB drive. I checked it with badblocks when I first got the drive, in a USB3 dock attached to a linux computer, and then too it took 3 days to complete.

In any case, I still have no clue what the issue is with the long boot time and fsck at each boot.

Back in the day I had this sort of thing happen to me twice... I found the problem wasn't "the drive" (at least internally) at all.. On one, one of the wires on from the power supply connector, had worked itself loose and was causing very erratic behavior with the drive. Taped off connector and used a splitter from another drive. Problem solved.

The other.. and this was a lot more frustrating.. again erratic drive behavior, etc.. Given my previous experiences I double checked the PSU, connectors, etc. What I eventually found, the small "ear" on the data port, had a slight crack, so if no cable was attached, the ear would kind of swing like a door. If a cable was attached, it would still move slightly.. thus causing erratic problems while transferring data, booting, etc. Replaced the drive as it was just out of warranty.

grokov · 2. April 2020

Adoby No, the number of files has not changed.

Boot time was ~1 minute before, and now I'm reinstalling due to my OMV installation having gotten messed up with the WebGUI login loop issue and beyond. I don't know why boot time is now consistently 5+ minutes each time.

KM0201 Oh my... I sure hope it's not a physical problem. In my case I'm using just an Odroid HC2, so there is no SATA or power supply cable to the drive. If there is a physical problem it would be the HC2's SATA connector on the board. Not sure how to check for that, but that would be bad...

One thought would be to use a different drive and see if the same problem comes up, but since the other drive would probably not get mounted at boot, I'm not sure it would be equivalent.

The other option that I'm leaning towards right now is to set up OMV5 from scratch, since it was just released as stable, and see if the problem persists.

grokov · 5. April 2020

Updating the bridge chip firmware on the Odroid seems to have solved the problem for me: https://wiki.odroid.com/odroid-xu4/software/jms578_fw_update Now there is no more delay, and with OMV5 the boot time is 42 seconds!

In OMV4 the boot time was long due to fsck taking ~4 minutes to run on each boot. In OMV5, fsck timed out during the boot process after almost 2 minutes resulting in the service failing and the drive not getting mounted at all, and that caused all kinds of other errors in OMV.

I don't know if somehow original firmware (v173.1.0.1) got corrupted (since it worked fine for months before) or if the issue was something else, but at least it seems fixed now and has been fine over several warm and cold boots. A bonus is that the latest (v173.1.0.2) firmware adds a new feature: hot swap.

One note: after updating the firmware a *cold* boot is required. The wiki mentions it, but I had forgotten and after initial warm reboots the drive was simply not detected. There were a few cold sweats until after a cold boot.

One great thing about OMV5, aside from the speedy boot time, is that ping responses, SSH, and the webgui are up really quickly, even before the boot process has completed. It quickly lets me know that it is working, which is reassuring for a headless system.

macom · 5. April 2020

I assume you started with Armbian. On the download page there is a note:

"This board is stripped Odroid XU4 and we use the same images, however, we provide a specially optimized config (for kernel 4.14.y or higher) which has to be applied manually. This results in shorter boot time and lower consumption. Run armbian-config utility and go to section system -> DTB and select optimized board configuration for Odroid HC1. The same config is valid for HC2 and MC1."

Might be worth to apply, if you have not done already.

grokov · 5. April 2020

Thanks, yes I started with Armbian and I already applied armbian-config's optimized board configuration for the HC2. I don't have a before/after on OMV5 but I have no complaints with 42s, it's faster than my desktop!

Slow 5+ minute boot; fsck on each boot

grokov 5. April 2020

Jetzt mitmachen!

Tags