Very Slow Booting

You have a problem with Salix? Post here and we'll do what we can to help.
Post Reply
User avatar
Atip
Posts: 539
Joined: 5. Jun 2011, 04:27

Very Slow Booting

Post by Atip »

A few days ago our great-granddaughter was watching Papa Pig with SMPlayer.
When she finished a serie she left and I forgot about it. Getting back to my PC
after may be one hour SMPlayer showed a black page and could not be killed.

Since this event my booting does not work properly. It takes up 6 minutes to complete.
This happens to all my partitions as well as booting from live USB sticks.

The booting lines report:
device reported invalid CHS sector 0
failed command: READ DMA
failed command READ SECTOR
status: (DRDY)
Here some section from dmesg:
...snip...
[ 37.642347] sdc: sdc1
[ 37.645711] sd 6:0:0:0: [sdc] Attached SCSI removable disk
[ 64.745024] ata1: lost interrupt (Status 0x50)
[ 64.745054] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 64.745119] ata1.00: failed command: READ DMA
[ 64.745161] ata1.00: cmd c8/00:f0:10:01:00/00:00:00:00:00/e0 tag 0 dma 122880 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
[ 64.745273] ata1.00: status: { DRDY }
[ 64.745330] ata1: soft resetting link
[ 65.012888] ata1.00: configured for UDMA/33
[ 65.012899] ata1: EH complete
[ 95.721021] ata1: lost interrupt (Status 0x50)
[ 95.721043] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 95.721104] ata1.00: failed command: READ DMA
....snip....
[ 157.801236] ata1.00: status: { DRDY }
[ 157.801271] ata1: soft resetting link
[ 158.065857] ata1.00: configured for UDMA/25
[ 158.065869] ata1: EH complete
[ 158.320944] EXT4-fs (sdb6): mounted filesystem with ordered data mode. Opts: (null)
[ 158.418174] EXT4-fs (sdb5): mounted filesystem with ordered data mode. Opts: (null)
[ 159.625628] intel_rng: FWH not detected
[ 159.634253] leds_ss4200: no LED devices found
[ 188.777024] ata1: lost interrupt (Status 0x50)
[ 188.777052] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 188.777058] ata1.00: failed command: READ DMA
[ 188.777067] ata1.00: cmd c8/00:08:00:00:00/00:00:00:00:00/e0 tag 0 dma 4096 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
[ 188.777072] ata1.00: status: { DRDY }
[ 188.777101] ata1: soft resetting link
...snip...
[ 282.729060] ata1.00: failed command: READ DMA
[ 282.729070] ata1.00: cmd c8/00:08:08:00:00/00:00:00:00:00/e0 tag 0 dma 4096 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
[ 282.729075] ata1.00: status: { DRDY }
[ 282.729104] ata1: soft resetting link
[ 283.004022] ata1.00: configured for UDMA/25
[ 283.004038] ata1: EH complete
[ 293.439896] NET: Registered protocol family 10
[ 295.389622] usb 1-6.4: 3:1: cannot get freq at ep 0x84
[ 295.411743] usb 1-6.4: 3:1: cannot get freq at ep 0x84
[ 295.452867] usb 1-6.4: 3:1: cannot get freq at ep 0x84
[ 295.474867] usb 1-6.4: 3:1: cannot get freq at ep 0x84
[ 295.757169] NET: Registered protocol family 4
[ 295.776742] NET: Registered protocol family 3
[ 295.864103] NET: Registered protocol family 5
[ 314.089027] ata1: lost interrupt (Status 0x50)
[ 314.089059] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 314.089065] ata1.00: failed command: READ DMA
[ 314.089075] ata1.00: cmd c8/00:08:08:00:00/00:00:00:00:00/e0 tag 0 dma 4096 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
[ 314.089080] ata1.00: status: { DRDY }
[ 314.089110] ata1: soft resetting link
[ 314.363588] ata1.00: configured for UDMA/25
[ 314.363605] ata1: EH complete
[ 345.065027] ata1: lost interrupt (Status 0x50)
[ 345.065053] ata1.00: limiting speed to PIO4
[ 345.065059] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[ 345.065064] ata1.00: failed command: READ DMA
[ 345.065074] ata1.00: cmd c8/00:08:18:00:00/00:00:00:00:00/e0 tag 0 dma 4096 in
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
[ 345.065079] ata1.00: status: { DRDY }
[ 345.065107] ata1: soft resetting link
[ 345.337028] ata1.00: configured for PIO4
[ 345.337048] ata1: EH complete
end of dmesg
Here are some /var/log/messages:
May 2 10:57:09 smartbro kernel: [ 37.312634] input: USB 2.0 Camera as /devices/pci0000
:00/0000:00:1d.7/usb1/1-6/1-6.4/1-6.4:1.0/input/input14
May 2 10:57:09 smartbro kernel: [ 37.312702] usbcore: registered new interface driver
uvcvideo
May 2 10:57:09 smartbro kernel: [ 37.312703] USB Video Class driver (1.1.1)
May 2 10:57:09 smartbro kernel: [ 37.631718] scsi 6:0:0:0: Direct-Access SanDisk
Cruzer Blade 1.26 PQ: 0 ANSI: 5
May 2 10:57:09 smartbro kernel: [ 37.634019] sd 6:0:0:0: [sdc] 7821312 512-byte logica
l blocks: (4.00 GB/3.73 GiB)
May 2 10:57:09 smartbro kernel: [ 37.635585] sd 6:0:0:0: [sdc] Write Protect is off
May 2 10:57:09 smartbro kernel: [ 37.636582] sd 6:0:0:0: [sdc] Write cache: disabled,
read cache: enabled, doesn't support DPO or FUA
May 2 10:57:09 smartbro kernel: [ 37.642347] sdc: sdc1
May 2 10:57:09 smartbro kernel: [ 37.645711] sd 6:0:0:0: [sdc] Attached SCSI removable
disk
May 2 10:57:09 smartbro kernel: [ 64.745330] ata1: soft resetting link
May 2 10:57:09 smartbro kernel: [ 65.012888] ata1.00: configured for UDMA/33
May 2 10:57:09 smartbro kernel: [ 65.012899] ata1: EH complete
May 2 10:57:09 smartbro kernel: [ 95.721260] ata1: soft resetting link
May 2 10:57:09 smartbro kernel: [ 95.994030] ata1.00: configured for UDMA/33
May 2 10:57:09 smartbro kernel: [ 95.994041] ata1: EH complete
May 2 10:57:09 smartbro kernel: [ 126.761321] ata1: soft resetting link
May 2 10:57:09 smartbro kernel: [ 127.027448] ata1.00: configured for UDMA/25
May 2 10:57:09 smartbro kernel: [ 127.027458] ata1: EH complete
May 2 10:57:09 smartbro kernel: [ 154.063733] fuse init (API version 7.23)
May 2 10:57:09 smartbro kernel: [ 154.508093] EXT4-fs (sdb7): re-mounted. Opts: (null)
May 2 10:57:09 smartbro kernel: [ 157.801271] ata1: soft resetting link
May 2 10:57:09 smartbro kernel: [ 158.065857] ata1.00: configured for UDMA/25
May 2 10:57:09 smartbro kernel: [ 158.065869] ata1: EH complete
May 2 10:57:09 smartbro kernel: [ 158.320944] EXT4-fs (sdb6): mounted filesystem with o
rdered data mode. Opts: (null)
May 2 10:57:09 smartbro kernel: [ 158.418174] EXT4-fs (sdb5): mounted filesystem with o
rdered data mode. Opts: (null)
May 2 10:57:09 smartbro kernel: [ 159.625628] intel_rng: FWH not detected
May 2 10:57:09 smartbro kernel: [ 159.634253] leds_ss4200: no LED devices found
May 2 10:57:38 smartbro kernel: [ 188.777101] ata1: soft resetting link
May 2 10:57:38 smartbro kernel: [ 189.046053] ata1.00: configured for UDMA/25
May 2 10:57:38 smartbro kernel: [ 189.046066] ata1: EH complete
May 2 10:58:09 smartbro kernel: [ 219.753098] ata1: soft resetting link
May 2 10:58:09 smartbro kernel: [ 220.021972] ata1.00: configured for UDMA/25
May 2 10:58:09 smartbro kernel: [ 220.021984] ata1: EH complete
May 2 10:58:41 smartbro kernel: [ 251.753104] ata1: soft resetting link
May 2 10:58:41 smartbro kernel: [ 252.024473] ata1.00: configured for UDMA/25
May 2 10:58:41 smartbro kernel: [ 252.024485] ata1: EH complete
May 2 10:59:02 smartbro kernel: [ 272.780385] usb 1-6.2: USB disconnect, device number 5
And here /var/log/syslog:
...snip...
May 2 10:57:09 smartbro kernel: [ 34.640541] lpc_ich: Resource conflict(s) found affec
ting gpio_ich
May 2 10:57:09 smartbro kernel: [ 37.200691] usb 1-6.4: 3:1: cannot get freq at ep 0x8
4
May 2 10:57:09 smartbro kernel: [ 37.207436] usb 1-6.4: Warning! Unlikely big volume r
ange (=512), cval->res is probably wrong.
May 2 10:57:09 smartbro kernel: [ 37.207443] usb 1-6.4: [2] FU [Mic Capture Volume] ch
= 1, val = 0/512/1
May 2 10:57:09 smartbro kernel: [ 64.745024] ata1: lost interrupt (Status 0x50)
May 2 10:57:09 smartbro kernel: [ 64.745054] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
May 2 10:57:09 smartbro kernel: [ 64.745119] ata1.00: failed command: READ DMA
May 2 10:57:09 smartbro kernel: [ 64.745161] ata1.00: cmd c8/00:f0:10:01:00/00:00:00:0
0:00/e0 tag 0 dma 122880 in
May 2 10:57:09 smartbro kernel: [ 64.745161] res 40/00:00:00:00:00/00:00:00:0
0:00/00 Emask 0x4 (timeout)
May 2 10:57:09 smartbro kernel: [ 64.745273] ata1.00: status: { DRDY }
May 2 10:57:09 smartbro kernel: [ 95.721021] ata1: lost interrupt (Status 0x50)
May 2 10:57:09 smartbro kernel: [ 95.721043] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
May 2 10:57:09 smartbro kernel: [ 95.721104] ata1.00: failed command: READ DMA
May 2 10:57:09 smartbro kernel: [ 95.721146] ata1.00: cmd c8/00:f0:10:01:00/00:00:00:0
0:00/e0 tag 0 dma 122880 in
May 2 10:57:09 smartbro kernel: [ 95.721146] res 40/00:00:00:00:00/00:00:00:0
0:00/00 Emask 0x4 (timeout)
May 2 10:57:09 smartbro kernel: [ 95.721228] ata1.00: status: { DRDY }
May 2 10:57:09 smartbro kernel: [ 126.761022] ata1: lost interrupt (Status 0x50)
May 2 10:57:09 smartbro kernel: [ 126.761046] ata1.00: limiting speed to UDMA/25:PIO4
May 2 10:57:09 smartbro kernel: [ 126.761052] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
May 2 10:57:09 smartbro kernel: [ 126.761113] ata1.00: failed command: READ DMA
May 2 10:57:09 smartbro kernel: [ 126.761155] ata1.00: cmd c8/00:00:00:03:00/00:00:00:0
0:00/e0 tag 0 dma 131072 in
May 2 10:57:09 smartbro kernel: [ 126.761155] res 40/00:00:00:00:00/00:00:00:0
0:00/00 Emask 0x4 (timeout)
May 2 10:57:09 smartbro kernel: [ 126.761267] ata1.00: status: { DRDY }
May 2 10:57:09 smartbro kernel: [ 157.801026] ata1: lost interrupt (Status 0x50)
May 2 10:57:09 smartbro kernel: [ 157.801057] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
May 2 10:57:09 smartbro kernel: [ 157.801123] ata1.00: failed command: READ DMA
May 2 10:57:09 smartbro kernel: [ 157.801164] ata1.00: cmd c8/00:f0:4f:01:00/00:00:00:0
0:00/e0 tag 0 dma 122880 in
May 2 10:57:09 smartbro kernel: [ 157.801164] res 40/00:00:00:00:00/00:00:00:0
0:00/00 Emask 0x4 (timeout)
May 2 10:57:09 smartbro kernel: [ 157.801236] ata1.00: status: { DRDY }
May 2 10:57:38 smartbro kernel: [ 188.777024] ata1: lost interrupt (Status 0x50)
May 2 10:57:38 smartbro kernel: [ 188.777052] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
May 2 10:57:38 smartbro kernel: [ 188.777058] ata1.00: failed command: READ DMA
May 2 10:57:38 smartbro kernel: [ 188.777067] ata1.00: cmd c8/00:08:00:00:00/00:00:00:0
0:00/e0 tag 0 dma 4096 in
May 2 10:57:38 smartbro kernel: [ 188.777067] res 40/00:00:00:00:00/00:00:00:0
0:00/00 Emask 0x4 (timeout)
May 2 10:57:38 smartbro kernel: [ 188.777072] ata1.00: status: { DRDY }
May 2 10:58:09 smartbro kernel: [ 219.753026] ata1: lost interrupt (Status 0x50)
May 2 10:58:09 smartbro kernel: [ 219.753051] ata1.00: exception Emask 0x0 SAct 0x0 SEr
r 0x0 action 0x6 frozen
.../snip...
When booting starts it shows the 2 pinguins at the top of the console and already there they sit an unusual
long time before booting continues. Once booting is complete and I have loged-in my PC operates
normally.

I have checked all pratitions with fsck and they are all clean.

What will I have to do to get my booting back to normal?
DidierSpaier
Posts: 518
Joined: 20. Jun 2016, 20:15

Re: Very Slow Booting

Post by DidierSpaier »

I have had something similar with a dying hard disk but that could be another issue.

Please provide the output of these commands to know what's what as you have several devices:

Code: Select all

lsblk -o model,name,size,fstype,mountpoint
df -h
User avatar
Atip
Posts: 539
Joined: 5. Jun 2011, 04:27

Re: Very Slow Booting

Post by Atip »

Code: Select all

lsblk -o model,name,size,fstype,mountpoint
MODEL            NAME     SIZE FSTYPE MOUNTPOINT
                 fd0        4K        
ST380215A        sda     74.5G        
                 |-sda1  23.5M swap   
                 |-sda2  23.5M ext2   
                 |-sda3     1K        
                 |-sda5  34.2G xfs    
                 |-sda6  15.6G ext4   
                 `-sda7  24.7G ext4   
ST500DM002-1BD14 sdb    465.8G        
                 |-sdb1     1K        
                 |-sdb2  78.3G ext4   
                 |-sdb3 117.3G ext4   
                 |-sdb4  58.9G ext4   
                 |-sdb5    75G ext4   /home
                 |-sdb6    40G ext4   /usr/local
                 `-sdb7    35G ext4   /
DRW-24D5MT       sr0     1024M  

Code: Select all

df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        35G   19G   14G  59% /
devtmpfs        999M     0  999M   0% /dev
tmpfs          1000M  1.1M  999M   1% /run
tmpfs          1000M     0 1000M   0% /dev/shm
cgroup_root    1000M     0 1000M   0% /sys/fs/cgroup
/dev/sdb6        40G   12G   27G  30% /usr/local
/dev/sdb5        74G  6.1G   64G   9% /home
cgmfs           100K     0  100K   0% /run/cgmanager/fs
DidierSpaier
Posts: 518
Joined: 20. Jun 2016, 20:15

Re: Very Slow Booting

Post by DidierSpaier »

What is sdc then? A removable device drive like a USB hard disk? If that is the case, unplug it before booting.
User avatar
Atip
Posts: 539
Joined: 5. Jun 2011, 04:27

Re: Very Slow Booting

Post by Atip »

DidierSpaier wrote:What is sdc then? A removable device drive like a USB hard disk? If that is the case, unplug it before booting.
Yes this is my live salix USB. It has no meaning on slow booting if present or not. I just forgot
to unplug it when booting to my working partition. Booting with the live USB is even slower than booting from HD. Takes 6 minutes with live USB against 4 min from HD.
DidierSpaier
Posts: 518
Joined: 20. Jun 2016, 20:15

Re: Very Slow Booting

Post by DidierSpaier »

Atip wrote:Yes this is my live salix USB. It has no meaning on slow booting if present or not.
Anyway having it in the way doesn't help understand the logs so please boot with this live USB unplugged and post them again.

And please post the full output of dmesg (from the beginning) just after booting has completed.
User avatar
gapan
Salix Wizard
Posts: 6241
Joined: 6. Jun 2009, 17:40

Re: Very Slow Booting

Post by gapan »

Most probably the hard drive/usb disk is dying.
Image
Image
User avatar
Atip
Posts: 539
Joined: 5. Jun 2011, 04:27

Re: Very Slow Booting

Post by Atip »

Yes, it had something to do with my IDE HD /dev/sda.
Unplugged and replugged connection and booting is again normal. :D.
Thanks for the help.
Post Reply