You are not logged in.

#1 2019-04-11 22:13:01

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Troubleshooting (what looks like) slow 1st disk access

Dear all.

I have a Dell machine with a i7 processor, 16Gb RAM and a 1Tb hard disk running an up to date Hydrogen (debian 8.11 under the hood).

Everything runs fine without almost any tweaking or optimization except one thing: the 1st time after login that I need to access the disk takes 3~5 seconds, always. After that 1st long access, it's intantaneous every time until next login. Examples of this slow access are quite common operations like opening a file manager (thunar, spacefm, whatever) or even saving a file to disk from a browser. What it seems to take time is until the window with the directories and files can be showed.

I feel it's also a bit slow to boot (~60 seconds) and maybe I'm wrong, but I think the machine should be snappier with this hardware...
Anyway, that may be related or not to the cited core point, so let's start with the most concrete observable thing: the 1st slow access to disk.

The disk, as reported by "hwinfo --disk" is:

20: IDE 200.0: 10600 Disk                                       
  [Created at block.245]
  Unique ID: 3OOL.aHw8zgfSNH5
  Parent ID: abAj.NYy_G2yDmh4
  SysFS ID: /class/block/sda
  SysFS BusID: 2:0:0:0
  SysFS Device Link: /devices/pci0000:00/0000:00:17.0/ata3/host2/target2:0:0/2:0:0:0
  Hardware Class: disk
  Model: "HGST HTS541010A7"
  Vendor: "HGST"
  Device: "HTS541010A7"
  Revision: "A4C0"
  Serial ID: "S00001SSHV79WF"
  Driver: "ahci", "sd"
  Driver Modules: "ahci", "sd_mod"
  Device File: /dev/sda
  Device Files: /dev/sda, /dev/disk/by-id/ata-HGST_HTS541010A7E630_S00001SSHV79WF, /dev/disk/by-id/wwn-0x5000cca756da04a0
  Device Number: block 8:0-8:15
  BIOS id: 0x80
  Geometry (Logical): CHS 121601/255/63
  Size: 1953525168 sectors a 512 bytes
  Capacity: 931 GB (1000204886016 bytes)
  Config Status: cfg=new, avail=yes, need=no, active=unknown
  Attached to: #10 (RAID bus controller)

The linux partitions are formatted with ext4 except the swap and the original Windows7 that came with the hardware (left in a small partition that I never used).  ;D

In order to make this case more useful to others too, the 1st questions are: how can I measure this observation? How can it be diagnosed?

As always, thanks a lot for your kind attention and help. smile

Best regards...

--
eduardo


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#2 2019-04-11 23:24:36

damo
....moderator....
Registered: 2015-08-20
Posts: 4,878

Re: Troubleshooting (what looks like) slow 1st disk access

Have you considered upgrading to a more recent release? Hydrogen is getting pretty old now, compared with Helium/stretch.

Perhaps a newer kernel and packages may fix you problems.

Use systemd-analyze, dmesg and journalctl to see what is taking the time.
For usage:

systemd-analyze --help

dmesg output:

sudo dmesg

latest systemd user session output:

journalctl -b

Be Excellent to Each Other...

FORUM RULES and posting guidelines «» Help page for forum post formatting
Artwork on DeviantArt  «» BunsenLabs on DeviantArt

Offline

#3 2019-04-12 19:37:11

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Hello Damo.

damo wrote:

Have you considered upgrading to a more recent release? Hydrogen is getting pretty old now, compared with Helium/stretch. Perhaps a newer kernel and packages may fix you problems.

Sure, but once you have everything tuned up, to reinstall all the OS and the personal configurations -loosing a couple days on it- becomes a thing to really consider... wink

damo wrote:

Use systemd-analyze, dmesg and journalctl to see what is taking the time.
For usage:

systemd-analyze --help

Thanks!

Using *systemd-analyze blame, critical-chain and -plot* found some unused services and shaved 15 seconds from boot. smile

Now the most time consuming services that remain are:

         14.211s NetworkManager.service
          7.151s binfmt-support.service
          5.686s lm-sensors.service
          5.666s incron.service
          5.665s alsa-restore.service
          5.663s pppd-dns.service
          5.657s rsyslog.service
          5.626s systemd-logind.service
          5.613s ssh.service
          5.606s systemd-user-sessions.service
          5.592s rc-local.service
          5.482s bluetooth.service
          5.480s avahi-daemon.service

*NetworkManager.service* seems to be the longest culprit, so I'm searching about how to reduce that time. With that, boot time will be ok.

Back to our slow disk issue... smile

damo wrote:

dmesg output:

sudo dmesg

latest systemd user session output:

journalctl -b

Both commands give a huge amount of info, but I don't know how to interpret it in the context of a slow disk. How can I use this info?

Thanks a lot for sharing your knowledge... smile


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#4 2019-04-13 05:19:18

ohnonot
...again
Registered: 2015-09-29
Posts: 3,673
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Eduardo Mercovich wrote:
         14.211s NetworkManager.service
          7.151s binfmt-support.service
          5.686s lm-sensors.service
          5.666s incron.service
          5.665s alsa-restore.service
          5.663s pppd-dns.service
          5.657s rsyslog.service
          5.626s systemd-logind.service
          5.613s ssh.service
          5.606s systemd-user-sessions.service
          5.592s rc-local.service
          5.482s bluetooth.service
          5.480s avahi-daemon.service

imho _everything_ in there takes too long.
i also notice that many of these services are NOT present on either my archlinux or my debian or my bunsenlabs install:

$ systemctl|grep -E 'incron|pppd|rsyslogd|ssh|avahi'
$

just something for you to ponder.

if you use wifi at boot time, shortening networkmanager might be out of your hands.

that said, it looks like all services are delayed by 5s.
this _could_ be because they all depend on something that takes 5s.

if not i worry about your state-of-the-art laptop that most certainly has a fast hard drive, if not an ssd.


sudo dmesg
journalctl -b

Both commands give a huge amount of info, but I don't know how to interpret it in the context of a slow disk. How can I use this info?

it takes some sifting.
thankfully it's all made to be human readable. look for certain keywords (maybe "ata" and "scsi" (case insensitive) for hard drives) ansd see what you get. it's hard and tedious work.

Offline

#5 2019-04-19 22:47:18

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Sorry the delay in the reply, crazy days here. smile

ohnonot wrote:
Eduardo Mercovich wrote:
         14.211s NetworkManager.service
          7.151s binfmt-support.service
  [...]

imho _everything_ in there takes too long.
i also notice that many of these services are NOT present on either my archlinux or my debian or my bunsenlabs install:

$ systemctl|grep -E 'incron|pppd|rsyslogd|ssh|avahi'
$

just something for you to ponder.
if you use wifi at boot time, shortening networkmanager might be out of your hands.

I don't use it until X is loaded and it seems the longest culprit, so if it can be delayed or speeded or changed somehow, I would certainly appreciate it.

In the meantime, some pruning of unneeded services made it better.

Startup finished in 4.054s (kernel) + 24.328s (userspace) = 28.382s

$ systemd-analyze blame
         14.090s NetworkManager.service
          7.582s alsa-restore.service
          6.796s lm-sensors.service
          6.743s systemd-logind.service
          6.680s incron.service
          6.679s rsyslog.service
          6.639s ssh.service
          6.618s rc-local.service
          6.618s systemd-user-sessions.service
          3.212s nfs-common.service
          3.188s networking.service
          2.863s upower.service
          2.802s kbd.service
          2.705s lightdm.service
          2.026s loadcpufreq.service
          1.969s dirmngr.service
          1.609s ntp.service
          1.558s colord.service
          1.542s keyboard-setup.service
          1.305s systemd-tmpfiles-setup-dev.service
          1.277s resolvconf.service
          1.257s irqbalance.service
          1.234s accounts-daemon.service
          1.234s minissdpd.service
          1.168s systemd-modules-load.service
          1.156s systemd-update-utmp.service
          1.036s systemd-tmpfiles-setup.service

(the rest are under 1 sec).

ohnonot wrote:

that said, it looks like all services are delayed by 5s.
this _could_ be because they all depend on something that takes 5s.

if not i worry about your state-of-the-art laptop that most certainly has a fast hard drive, if not an ssd.

It has a classic, spinning, hard drive of 1 Tb.

BTW my *state-of-the-art laptop* is a Dell compensation for a serious mistreatmente that I made public when they didn't responded as it should. big_smile

Back to that 5 secs delay, there are some messages at boot time that may be related (sorry if they're not, I'm learning as I go) and looks like drivers not found?

Apr 19 18:40:35 biologica kernel: [   11.512133] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-26.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512216] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-25.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512290] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-24.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512402] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-23.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.534778] radeon 0000:01:00.0: Direct firmware load for radeon/oland_pfp.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.567013] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_pfp.bin
Apr 19 18:40:35 biologica kernel: [   11.567108] radeon 0000:01:00.0: Direct firmware load for radeon/oland_me.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.600672] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_me.bin
Apr 19 18:40:35 biologica kernel: [   11.600767] radeon 0000:01:00.0: Direct firmware load for radeon/oland_ce.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.636766] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_ce.bin
Apr 19 18:40:35 biologica kernel: [   11.636862] radeon 0000:01:00.0: Direct firmware load for radeon/oland_rlc.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.673088] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_rlc.bin
Apr 19 18:40:35 biologica kernel: [   11.673172] radeon 0000:01:00.0: Direct firmware load for radeon/si58_mc.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.699969] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_mc2.bin
ohnonot wrote:
sudo dmesg
journalctl -b

Both commands give a huge amount of info, but I don't know how to interpret it in the context of a slow disk. How can I use this info?

it takes some sifting.
thankfully it's all made to be human readable. look for certain keywords (maybe "ata" and "scsi" (case insensitive) for hard drives) ansd see what you get. it's hard and tedious work.

dmesg grepped by "ata" gives:

$ sudo dmesg | grep ata
[    0.000000] BIOS-e820: [mem 0x000000009b6d1000-0x000000009b721fff] ACPI data
[    0.000000] ACPI: SSDT 0x000000009B7134F8 00050E (v01 SataRe SataTabl 00001000 INTL 20120913)
[    0.000000] Memory: 16070736K/16430368K available (6245K kernel code, 1228K rwdata, 2872K rodata, 1424K init, 696K bss, 359632K reserved, 0K cma-reserved)
[    0.597096] Write protecting the kernel read-only data: 12288k
[    0.648181] libata version 3.00 loaded.
[    0.996075] ata1: DUMMY
[    0.996077] ata2: DUMMY
[    0.996085] ata3: SATA max UDMA/133 abar m2048@0xef353000 port 0xef353200 irq 128
[    0.996088] ata4: SATA max UDMA/133 abar m2048@0xef353000 port 0xef353280 irq 128
[    1.309860] ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[    1.311630] ata3.00: ATA-8: HGST HTS541010A7E630, SE0OA4C0, max UDMA/133
[    1.311636] ata3.00: 1953525168 sectors, multi 16: LBA48 NCQ (depth 31/32), AA
[    1.313736] ata3.00: configured for UDMA/133
[    1.660797] ata4: SATA link down (SStatus 0 SControl 300)
[    3.301776] EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)

dmesg grepped by "scsi" gives much less:

$ sudo dmesg | grep scsi
[    0.994118] scsi host0: ahci
[    0.994719] scsi host1: ahci
[    0.995384] scsi host2: ahci
[    0.995961] scsi host3: ahci
[    1.314387] scsi 2:0:0:0: Direct-Access     ATA      HGST HTS541010A7 A4C0 PQ: 0 ANSI: 5
[    1.757320] sd 2:0:0:0: Attached scsi generic sg0 type 0

And journalctl gives:

$ sudo journalctl -b | grep ata
abr 19 18:40:27 biologica kernel: BIOS-e820: [mem 0x000000009b6d1000-0x000000009b721fff] ACPI data
abr 19 18:40:27 biologica kernel: ACPI: SSDT 0x000000009B7134F8 00050E (v01 SataRe SataTabl 00001000 INTL 20120913)
abr 19 18:40:27 biologica kernel: Memory: 16070736K/16430368K available (6245K kernel code, 1228K rwdata, 2872K rodata, 1424K init, 696K bss, 359632K reserved, 0K cma-reserved)
abr 19 18:40:27 biologica kernel: Write protecting the kernel read-only data: 12288k
abr 19 18:40:27 biologica kernel: libata version 3.00 loaded.
abr 19 18:40:27 biologica kernel: ata1: DUMMY
abr 19 18:40:27 biologica kernel: ata2: DUMMY
abr 19 18:40:27 biologica kernel: ata3: SATA max UDMA/133 abar m2048@0xef353000 port 0xef353200 irq 128
abr 19 18:40:27 biologica kernel: ata4: SATA max UDMA/133 abar m2048@0xef353000 port 0xef353280 irq 128
abr 19 18:40:27 biologica kernel: ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
abr 19 18:40:27 biologica kernel: ata3.00: ATA-8: HGST HTS541010A7E630, SE0OA4C0, max UDMA/133
abr 19 18:40:27 biologica kernel: ata3.00: 1953525168 sectors, multi 16: LBA48 NCQ (depth 31/32), AA
abr 19 18:40:27 biologica kernel: ata3.00: configured for UDMA/133
abr 19 18:40:27 biologica kernel: ata4: SATA link down (SStatus 0 SControl 300)
abr 19 18:40:27 biologica kernel: EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)
abr 19 18:40:36 biologica smartd[774]: Device: /dev/sda [SAT], not found in smartd database.
abr 19 18:40:37 biologica smartd[774]: Device: /dev/sda [SAT], state read from /var/lib/smartmontools/smartd.HGST_HTS541010A7E630-S00001SSHV79WF.ata.state
abr 19 18:40:39 biologica smartd[774]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.HGST_HTS541010A7E630-S00001SSHV79WF.ata.state
abr 19 18:40:44 biologica colord[917]: Using mapping database file /var/lib/colord/mapping.db
abr 19 18:40:44 biologica colord[917]: Using device database file /var/lib/colord/storage.db
abr 19 18:40:44 biologica colord[917]: Using profile database file /var/lib/colord/storage.db
abr 19 19:35:47 biologica systemd[1]: Activated swap /dev/disk/by-id/ata-HGST_HTS541010A7E630_S00001SSHV79WF-part6.

Here I see a jump of almost 10 secs between these 2 lines:

abr 19 18:40:27 biologica kernel: EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)
abr 19 18:40:36 biologica smartd[774]: Device: /dev/sda [SAT], not found in smartd database.

And a 5 secs delay between these other too:

abr 19 18:40:39 biologica smartd[774]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.HGST_HTS541010A7E630-S00001SSHV79WF.ata.state
abr 19 18:40:44 biologica colord[917]: Using mapping database file /var/lib/colord/mapping.db

Does any of these messages tells you something? Should I make some speed test on the disk or review something about the BIOS settings?

Also, while booting faster is always welcome and may give us a clue, it still remains the disk slow 1st access. The 1st file-manager I ask to open, even after letting everything boot and load after login, takes ~10 seconds to show it's window. After that, it's instantaneous.

As always, thanks a lot for sharing your knowledge and most precious time. smile
Best regards...


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#6 2019-04-19 22:50:33

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Sorry, I forgot to add the journal filtered by scsi:

$ sudo journalctl -b | grep scsi
abr 19 18:40:27 biologica kernel: scsi host0: ahci
abr 19 18:40:27 biologica kernel: scsi host1: ahci
abr 19 18:40:27 biologica kernel: scsi host2: ahci
abr 19 18:40:27 biologica kernel: scsi host3: ahci
abr 19 18:40:27 biologica kernel: scsi 2:0:0:0: Direct-Access     ATA      HGST HTS541010A7 A4C0 PQ: 0 ANSI: 5
abr 19 18:40:27 biologica kernel: sd 2:0:0:0: Attached scsi generic sg0 type 0
abr 19 18:40:36 biologica smartd[774]: Device: /dev/sda, type changed from 'scsi' to 'sat'

Again, this almost 10 secs jump between

abr 19 18:40:27 biologica kernel: sd 2:0:0:0: Attached scsi generic sg0 type 0
abr 19 18:40:36 biologica smartd[774]: Device: /dev/sda, type changed from 'scsi' to 'sat'

eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#7 2019-04-20 06:13:06

ohnonot
...again
Registered: 2015-09-29
Posts: 3,673
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Eduardo Mercovich wrote:

I don't use it until X is loaded and it seems the longest culprit, so if it can be delayed or speeded or changed somehow, I would certainly appreciate it.

it=wifi?
there's some web searches for you - i did not link a particular article for you because all of them look relevant, but none of them an exact match.

i repeat:

ohnonot wrote:

that said, it looks like all services are delayed by 5s.
this _could_ be because they all depend on something that takes 5s.

there are other systemd commands that can help you analyze that.
try

systemd-analyze critical-chain

---

Back to that 5 secs delay, there are some messages at boot time that may be related (sorry if they're not, I'm learning as I go) and looks like drivers not found?

Apr 19 18:40:35 biologica kernel: [   11.512133] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-26.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512216] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-25.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512290] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-24.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.512402] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-8000C-23.ucode failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.534778] radeon 0000:01:00.0: Direct firmware load for radeon/oland_pfp.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.567013] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_pfp.bin
Apr 19 18:40:35 biologica kernel: [   11.567108] radeon 0000:01:00.0: Direct firmware load for radeon/oland_me.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.600672] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_me.bin
Apr 19 18:40:35 biologica kernel: [   11.600767] radeon 0000:01:00.0: Direct firmware load for radeon/oland_ce.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.636766] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_ce.bin
Apr 19 18:40:35 biologica kernel: [   11.636862] radeon 0000:01:00.0: Direct firmware load for radeon/oland_rlc.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.673088] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_rlc.bin
Apr 19 18:40:35 biologica kernel: [   11.673172] radeon 0000:01:00.0: Direct firmware load for radeon/si58_mc.bin failed with error -2
Apr 19 18:40:35 biologica kernel: [   11.699969] radeon 0000:01:00.0: firmware: direct-loading firmware radeon/OLAND_mc2.bin

how does your wifi even work if it cannot load the firmware? weird. maybe it's optional for some devices. or do you have 2 wifi devices?
please look at some existing wlan/wifi related threads to troubleshoot this further.
the same goes for your amd/ati/radeon gpu. while it probably works as is (does it?), it might benefit form that firmware.

dmesg grepped by "ata" gives:
...
dmesg grepped by "scsi" gives much less:
...
And journalctl gives:
...
Here I see a jump of almost 10 secs between these 2 lines:

abr 19 18:40:27 biologica kernel: EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)
abr 19 18:40:36 biologica smartd[774]: Device: /dev/sda [SAT], not found in smartd database.

And a 5 secs delay between these other too:

abr 19 18:40:39 biologica smartd[774]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.HGST_HTS541010A7E630-S00001SSHV79WF.ata.state
abr 19 18:40:44 biologica colord[917]: Using mapping database file /var/lib/colord/mapping.db

you have to understand what the commands i gave you do:
they grab (grep) lines containing the string 'ata' or 'scsi' from the output of journalctl or dmesg, and show you only these.
there's no "jump of 10s" - that's just the grep command's doing.
you need to look at the full 'dmesg' or 'journalctl -b' output to see what's happening before, after and in-between.
like i said, tedious work.

also read some man pages:

man journalctl
man systemd-analyze

---

Does any of these messages tells you something? Should I make some speed test on the disk or review something about the BIOS settings?

sorry, this is not my area of expertise.
all i noticed is that smartd does not find your hard drive in its database, that seems noteworthy.
keep in mind if you test your hard drive, it's best to not use it at the same time, i.e. boot a live usb.
try this: https://dt.iki.fi/hard-drive-and-fs-health-checks
and by means also have a look at your bios.

Also, while booting faster is always welcome and may give us a clue, it still remains the disk slow 1st access. The 1st file-manager I ask to open, even after letting everything boot and load after login, takes ~10 seconds to show it's window. After that, it's instantaneous.

again, look at the logs, this time also add /var/log/Xorg.0.log

all in all, i think we also need to see the output of

lspci -k
uname -a

and how old is the laptop.

Last edited by ohnonot (2019-04-20 06:16:48)

Offline

#8 2019-04-26 19:41:08

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

ohnonot wrote:
Eduardo Mercovich wrote:

I don't use it until X is loaded and it seems the longest culprit, so if it can be delayed or speeded or changed somehow, I would certainly appreciate it.

it=wifi?
there's some web searches for you - i did not link a particular article for you because all of them look relevant, but none of them an exact match.

i repeat:

ohnonot wrote:

that said, it looks like all services are delayed by 5s.
this _could_ be because they all depend on something that takes 5s.

there are other systemd commands that can help you analyze that.
try

systemd-analyze critical-chain

Yes, it=wifi. I thought that I could open NetworkManager upon opening X but it seems complex. Anyway, by enabling debugging and looking at the NM logs I found a couple seconds used to scan for very old wifi networks (zapped them), fixed my home router MAC address, and after that, optimizing boot time with e4rat resulted in NM using only 5 secs. smile

The "systemd-analyze plot" also helped. The difference between the 1st and last one are impressive... wink

Now it is 24 secs.

$ systemd-analyze 
Startup finished in 11.129s (kernel) + 13.028s (userspace) = 24.158s

Other systemd-analyze results are:

$ systemd-analyze blame 
          5.126s NetworkManager.service
          3.357s systemd-suspend.service
          3.085s loadcpufreq.service
          2.654s lightdm.service
          2.295s alsa-restore.service
          1.958s lm-sensors.service
          1.938s incron.service
          1.883s ssh.service
          1.621s dirmngr.service
          1.613s systemd-logind.service
          1.606s systemd-tmpfiles-setup.service
          1.585s rc-local.service
          1.585s systemd-user-sessions.service
           991ms nfs-common.service
           984ms hddtemp.service
           984ms irqbalance.service
           984ms acpi-support.service
           983ms dhcpcd.service
           983ms gdomap.service
           983ms minissdpd.service
           913ms systemd-backlight@backlight:intel_backlight.service
           881ms systemd-journal-flush.service
           706ms kbd.service
           699ms ntp.service
           621ms systemd-update-utmp.service
           618ms networking.service
           526ms user@117.service
           461ms wpa_supplicant.service
           361ms keyboard-setup.service
           309ms upower.service
           304ms systemd-modules-load.service
           281ms console-setup.service
           275ms systemd-random-seed.service
           270ms tlp-sleep.service
           233ms hdparm.service
           232ms dev-hugepages.mount
           220ms resolvconf.service
           215ms dev-mqueue.mount
           205ms packagekit.service
           200ms sys-kernel-debug.mount
           167ms dev-disk-by\x2duuid-d7f19613\x2d6f9c\x2d4a87\x2db190\x2d128700bdeac8.swap
           161ms systemd-udevd.service
            78ms systemd-tmpfiles-clean.service
            72ms systemd-sysctl.service
            72ms systemd-udev-trigger.service
            70ms udisks2.service
            67ms kmod-static-nodes.service
            51ms systemd-remount-fs.service
            19ms user@1000.service
            15ms tlp.service
            12ms systemd-tmpfiles-setup-dev.service
             6ms udev-finish.service
             5ms systemd-backlight@leds:dell::kbd_backlight.service
             5ms polkitd.service
             2ms cpufrequtils.service
             2ms rtkit-daemon.service
             2ms sys-fs-fuse-connections.mount
             2ms systemd-update-utmp-runlevel.service

And

$ systemd-analyze critical-chain 
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @13.012s
└─multi-user.target @13.012s
  └─NetworkManager.service @7.886s +5.126s
    └─basic.target @7.884s
      └─paths.target @7.884s
        └─cups.path @7.884s
          └─sysinit.target @7.813s
            └─swap.target @7.813s
              └─dev-disk-by\x2duuid-d7f19613\x2d6f9c\x2d4a87\x2db190\x2d128700bdeac8.swap @7.644s +167ms
                └─dev-disk-by\x2duuid-d7f19613\x2d6f9c\x2d4a87\x2db190\x2d128700bdeac8.device @7.644s

(in red are NetworkManager.service and dev-disk-by\x2duuid-d7f19613\x2d6f9c\x2d4a87\x2db190\x2d128700bdeac8.swap @7.644s +167ms


Back to that 5 secs delay, there are some messages at boot time that may be related (sorry if they're not, I'm learning as I go) and looks like drivers not found?
[...]

how does your wifi even work if it cannot load the firmware? weird. maybe it's optional for some devices. or do you have 2 wifi devices?
please look at some existing wlan/wifi related threads to troubleshoot this further.
the same goes for your amd/ati/radeon gpu. while it probably works as is (does it?), it might benefit form that firmware.

I have just 1 wifi card and it works. Same thing for the Radeon video card. Searching about that it seems that the current FLOSS driver is quite acceptable so I left it.


[...]
you have to understand what the commands i gave you do:
they grab (grep) lines containing the string 'ata' or 'scsi' from the output of journalctl or dmesg, and show you only these.
there's no "jump of 10s" - that's just the grep command's doing.
you need to look at the full 'dmesg' or 'journalctl -b' output to see what's happening before, after and in-between.
like i said, tedious work.

also read some man pages:

man journalctl
man systemd-analyze

Oh, now that you said it, it's obvious, sorry... I'm on that.
Already did it with NetworkManager, will keep doing it with the disk. smile

---

Does any of these messages tells you something? Should I make some speed test on the disk or review something about the BIOS settings?

sorry, this is not my area of expertise.
all i noticed is that smartd does not find your hard drive in its database, that seems noteworthy.
keep in mind if you test your hard drive, it's best to not use it at the same time, i.e. boot a live usb.
try this: https://dt.iki.fi/hard-drive-and-fs-health-checks
and by means also have a look at your bios.

In effect, it recognizes capabilities (and they seem enabled) but not the model.

=== START OF INFORMATION SECTION ===
Device Model:     HGST HTS541010A7E630
Serial Number:    S00001SSHV79WF
LU WWN Device Id: 5 000cca 756da04a0
Firmware Version: SE0OA4C0
User Capacity:    1.000.204.886.016 bytes [1,00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    5400 rpm
Form Factor:      2.5 inches
Device is:        Not in smartctl database [for details use: -P showall]
ATA Version is:   ATA8-ACS T13/1699-D revision 6
SATA Version is:  SATA 3.0, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Fri Apr 26 16:07:59 2019 -03
SMART support is: Available - device has SMART capability.
SMART support is: Enabled
[...]

I will look more into optimizing the disk.

Also, while booting faster is always welcome and may give us a clue, it still remains the disk slow 1st access. The 1st file-manager I ask to open, even after letting everything boot and load after login, takes ~10 seconds to show it's window. After that, it's instantaneous.

again, look at the logs, this time also add /var/log/Xorg.0.log

all in all, i think we also need to see the output of

lspci -k
uname -a

and

$ lspci -k
/dev/sda:
multcount     = 16 (on)
IO_support    =  1 (32-bit)
readonly      =  0 (off)
readahead     = 256 (on)
geometry      = 121601/255/63, sectors = 1953525168, start = 0

/dev/sda:
Timing cached reads:   28572 MB in  1.99 seconds = 14338.73 MB/sec
Timing buffered disk reads: 182 MB in  3.01 seconds =  60.48 MB/sec

$ uname -a
Linux biologica 4.9.0-0.bpo.6-amd64 #1 SMP Debian 4.9.88-1+deb9u1~bpo8+1 (2018-05-13) x86_64 GNU/Linux

how old is the laptop.

2 or 3 years...

I will look into the X log (/var/log/Xorg.0.log), the BIOS and the disk optimization and report back.
Thanks a lot... smile


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#9 2019-04-26 22:34:53

Sun For Miles
Member
Registered: 2017-04-12
Posts: 134

Re: Troubleshooting (what looks like) slow 1st disk access

Eduardo Mercovich wrote:

In order to make this case more useful to others too, the 1st questions are: how can I measure this observation? How can it be diagnosed?

The others showed you how to diagnose boot process in detail, and I would like to focus on disk performance only. This way you will know what kind of improvement you can expect from your drive, and if there is disparity between expected and real drive performance.

I see you have posted the output of the hdparm -Tt /dev/sda command which shows buffered and cached disk speeds (which imho are inconclusive). At first sight I would say that buffered read speed should be few time higher, but as I've said that number will probably be different every time you run said command, so we need some more stable test.

First, I am curious about confirming active bus speed of your drive (judging from your posted logs it should be udma6). We can check it with:

hdparm -i /dev/sda

Look for the asterisk that would indicate current bus speed.

To test drive speed, fire up these commands in mentioned order:

# set write caching off
hdparm -W0 /dev/sda

# test write speed
dd if=/dev/zero of=/tmp/disktest.img bs=2G count=1 oflag=dsync

# free pagecache, dentries and inodes
echo 3 | sudo tee /proc/sys/vm/drop_caches

# test read speed
dd if=/tmp/disktest.img of=/dev/null bs=8k

# return caching values to defaults and clear test file
echo 0 | sudo tee /proc/sys/vm/drop_caches
hdparm -W1 /dev/sda
rm -f /tmp/disktest.img

Señor Chang, why do you teach Spanish?

Offline

#10 2019-05-02 22:36:33

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Hello Sun for miles. smile

[...]

Sun For Miles wrote:

The others showed you how to diagnose boot process in detail, and I would like to focus on disk performance only. This way you will know what kind of improvement you can expect from your drive, and if there is disparity between expected and real drive performance.

I see you have posted the output of the hdparm -Tt /dev/sda command which shows buffered and cached disk speeds (which imho are inconclusive). At first sight I would say that buffered read speed should be few time higher, but as I've said that number will probably be different every time you run said command, so we need some more stable test.

First, I am curious about confirming active bus speed of your drive (judging from your posted logs it should be udma6). We can check it with:

hdparm -i /dev/sda

Look for the asterisk that would indicate current bus speed.

$ sudo hdparm -i /dev/sda

/dev/sda:

 Model=HGST HTS541010A7E630, FwRev=SE0OA4C0, SerialNo=S00001SSHV79WF
 Config={ HardSect NotMFM HdSw>15uSec Fixed DTR>10Mbs }
 RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=4
 BuffType=DualPortCache, BuffSize=unknown, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=1953525168
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
 AdvancedPM=yes: mode=0x80 (128) WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-2,3,4,5,6,7

 * signifies the current active mode

I only see asterisks in the UDMA mode (as you said, udma6).

(without sudo gives some

/dev/sda: HDIO_DRIVE_CMD(identify) failed: Operation not permitted

).


To test drive speed, fire up these commands in mentioned order:

# set write caching off
hdparm -W0 /dev/sda

# test write speed
dd if=/dev/zero of=/tmp/disktest.img bs=2G count=1 oflag=dsync

# free pagecache, dentries and inodes
echo 3 | sudo tee /proc/sys/vm/drop_caches

# test read speed
dd if=/tmp/disktest.img of=/dev/null bs=8k

# return caching values to defaults and clear test file
echo 0 | sudo tee /proc/sys/vm/drop_caches
hdparm -W1 /dev/sda
rm -f /tmp/disktest.img

This sequence (with something repeated because it needed sudo before and an error with

tee: /proc/sys/vm/drop_caches: Argumento inválido

), gives:

$ sudo hdparm -W0 /dev/sda

/dev/sda:
 setting drive write-caching to 0 (off)
 write-caching =  0 (off)

edumerco@biologica:~$ dd if=/dev/zero of=/tmp/disktest.img bs=2G count=1 oflag=dsync
0+1 registros leídos
0+1 registros escritos
2147479552 bytes (2,1 GB) copiados, 35,0756 s, 61,2 MB/s

edumerco@biologica:~$ echo 3 | sudo tee /proc/sys/vm/drop_caches
3

edumerco@biologica:~$ dd if=/tmp/disktest.img of=/dev/null bs=8k
262143+1 registros leídos
262143+1 registros escritos
2147479552 bytes (2,1 GB) copiados, 33,6088 s, 63,9 MB/s

edumerco@biologica:~$ echo 0 | sudo tee /proc/sys/vm/drop_caches
0
tee: /proc/sys/vm/drop_caches: Argumento inválido

edumerco@biologica:~$ hdparm -W1 /dev/sda

/dev/sda:
 setting drive write-caching to 1 (on)
 HDIO_DRIVE_CMD(setcache) failed: Operation not permitted
 HDIO_DRIVE_CMD(identify) failed: Operation not permitted
edumerco@biologica:~$ sudo hdparm -W1 /dev/sda

/dev/sda:
 setting drive write-caching to 1 (on)
 write-caching =  1 (on)
edumerco@biologica:~$ rm -f /tmp/disktest.img

Is this the expected speed? What do others have to compare with this test? 

BTW, other programs have the same huge difference in time between 1st and subsequent openings:
org-mode: 45 to 5 secs.
thunar: 15 to 0 secs.

Of course, there is some cache effect here, but the 1st opening of each program is severely slow. It shouldn't be with these specs... (3 years Dell Latitude, i7, 16Gb RAM, 1Tb hd, Debian 8.11).

Much thanks for your help. I'm learning a lot and I'm sure others will learn from this too. smile
Kind regards...


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

#11 2019-05-03 07:59:20

damo
....moderator....
Registered: 2015-08-20
Posts: 4,878

Re: Troubleshooting (what looks like) slow 1st disk access

Eduardo Mercovich wrote:

...

BTW, other programs have the same huge difference in time between 1st and subsequent openings:
org-mode: 45 to 5 secs.
thunar: 15 to 0 secs.
...

The thunar issue is common, and is related to network mounts. Maybe your problems are there?

This can often be solved by editing, as root, /usr/share/gvfs/mounts/network.mount and change AutoMount=true to AutoMount=false.


Be Excellent to Each Other...

FORUM RULES and posting guidelines «» Help page for forum post formatting
Artwork on DeviantArt  «» BunsenLabs on DeviantArt

Offline

#12 2019-05-03 21:49:40

Sun For Miles
Member
Registered: 2017-04-12
Posts: 134

Re: Troubleshooting (what looks like) slow 1st disk access

The only mismatch I've seen related to your drive in previous posts is Sector Sizes:     512 bytes logical, 4096 bytes physical. That difference in logical/physical sector size is usually offered by OS for compatibility purposes (if you didn't explicitely set 512b value when you formed file system) with no issues whatsoever, but could cause some esoteric problems with performance, either directly or as a consequence of parition "misalignement". I will write it off as nothing suspicious for now until we get more info about the file system.

Eduardo Mercovich wrote:

Is this the expected speed?

Yes, those transfer speeds (~60MB/s) are pretty standard for a 5200rpm mechanical drive. I wanted to rule out the possible drive malfunction, and it seems like your disk is operating in the expected margins. We didn't test random access time here.

Eduardo Mercovich wrote:

What do others have to compare with this test?

Today at work I hit the test on my BL laptop with cheap and subpar SSD inside, your hard drive is about 3x (write) to 5x (read) slower:
zN9fp2Lm.png
But as I've said, your disk is working fine for the traditional mechanical drive, and in todays standards my SSD is considered slow (SATA3 SSD drives can read/write about 2x faster than my curent disk, and even 4+ times faster if connected via PCIe bus).

Eduardo Mercovich wrote:

BTW, other programs have the same huge difference in time between 1st and subsequent openings:
org-mode: 45 to 5 secs.
thunar: 15 to 0 secs.

You have excellent hardware specs, and waiting 15s for file manager to load is certainly not the expected behaviour even when taken into consideration that hard drive is the slowest component of your system. Read performance of your drive doesn't seem like the issue here, and others were probably right to jump straight into OS troubleshooting. However, I'd like to see the output of these commands as well:

sudo fdisk -l
cat /etc/fstab

I assume you havent followed disk diagnostics that ohnonot suggested because you would need live disk and unmounted file systems. Copy output of this command since the info was cut out in previous posts:

sudo smartctl -A /dev/sda

Could you open two separate terminals and use these commands before starting slow loading program (something other than thunar) for the first time after system bootup? Post output of those commands here on forum and tell us which program you have been waiting to load.

Terminal 1:

vmstat -S M 2 15

Terminal 2 (if you don't have iostat hit the sudo apt-get install sysstat -y):

iostat -hx 2 15
-----------Suggestions-----------

Before we know a bit more about your file system structure, here are few things that might (or might not) help mitigate the problem.

Let's check swappiness level. Hit the console with

cat /proc/sys/vm/swappiness

Default value should be 60, which means that kernel will swap when you fill up 40% of RAM (which is around 6.5GB RAM in your case). If you would like to reduce kernel tendency to write RAM contents to swap, my suggestion would be:

sudo sysctl vm.swappiness=10

This way you told kernel to use swap after filling up 90% of RAM. You have significant amout of RAM and this is probably not the issue, but just in case after running this command test if your non cached programs are starting up faster than before. If yes, you can make the change permanent with:

echo "vm.swappiness=10" | sudo tee -a /etc/sysctl.conf

If nothing changed and programs are still slow to load first time, let's move on to another possible shot in the dark. smile

sudo sysctl -a | grep vm.vfs_cache_pressure

Default is 100, and it indicates rate in which system retains file and directory cache. Values over 100 are known to notably impact system performance in a negative way. Safe and a bit more optimized value would be 50:

sudo sysctl vm.vfs_cache_pressure=50

If you see a positive result in file operations or program loading time you can set it permanently with:

echo "vm.vfs_cache_pressure=50" | sudo tee -a /etc/sysctl.conf

Those are two main tricks I know for tuning the file system, but I'm not sure if any of those would help in your case. If not, post output of commands I mentioned earlier in this message and let's dig deeper. smile

Last edited by Sun For Miles (2019-05-03 21:51:02)


Señor Chang, why do you teach Spanish?

Offline

#13 2019-05-07 22:20:55

Eduardo Mercovich
Member
From: Buenos Aires, Argentina
Registered: 2015-11-12
Posts: 11
Website

Re: Troubleshooting (what looks like) slow 1st disk access

Hello Damo.

damo wrote:

The thunar issue is common, and is related to network mounts. Maybe your problems are there?
This can often be solved by editing, as root, /usr/share/gvfs/mounts/network.mount and change AutoMount=true to AutoMount=false.

Sadly, it is already false... sad


eduardo mercovich
Donde se cruzan tus talentos / con las necesidades del mundo, / ahí está tu vocación.

Offline

Board footer

Powered by FluxBB