HDD spinning up every 10min

ptbgfoot · 17 October 2021 19:14

Confirmed happening the same to me too, on /dev/sda, even with latest update today

[   74.203057] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   74.204291] ata1.00: configured for UDMA/100
[   74.204503] sd 0:0:0:0: [sda] Starting disk
[   91.711087] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   91.711611] sd 0:0:0:0: [sda] Stopping disk
[  611.879713] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  611.881337] ata1.00: configured for UDMA/100
[  611.881964] sd 0:0:0:0: [sda] Starting disk
[  640.656388] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  640.656915] sd 0:0:0:0: [sda] Stopping disk
[  753.846377] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  753.848008] ata1.00: configured for UDMA/100
[  753.848641] sd 0:0:0:0: [sda] Starting disk
[  784.283053] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  784.283577] sd 0:0:0:0: [sda] Stopping disk
[  788.086375] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  788.087999] ata1.00: configured for UDMA/100
[  788.088629] sd 0:0:0:0: [sda] Starting disk
[  811.559884] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  811.560406] sd 0:0:0:0: [sda] Stopping disk

# hdparm -I /dev/sda

/dev/sda:

ATA device, with non-removable media
	Model Number:       TOSHIBA MD04ACA600                      
	Serial Number:      X5HFK0HEFFQC
	Firmware Revision:  FS2A    
	Transport:          Serial, ATA8-AST, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Supported: 8 7 6 5 
	Likely used: 8

# uname -r
5.13.19-2-MANJARO

Termy · 17 October 2021 19:19

Nothing regarding the attempted unmount
The only other thing in dmesg besides the disk related lines mentioned at the beginning are this:

[33024.797825] audit: type=1100 audit(1634498064.574:534): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:authentication grantors=pam_faillock,pam_permit,pam_faillock acct="termy" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33024.798653] audit: type=1101 audit(1634498064.574:535): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="termy" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33024.798761] audit: type=1110 audit(1634498064.574:536): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33024.799270] audit: type=1105 audit(1634498064.578:537): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33024.801156] audit: type=1106 audit(1634498064.578:538): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33024.801185] audit: type=1104 audit(1634498064.578:539): pid=73583 uid=1000 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_faillock,pam_permit,pam_faillock acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33032.690388] audit: type=1101 audit(1634498072.468:540): pid=73624 uid=1000 auid=1000 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="termy" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33032.690465] audit: type=1110 audit(1634498072.468:541): pid=73624 uid=1000 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_faillock,pam_permit,pam_env,pam_faillock acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[33032.691102] audit: type=1105 audit(1634498072.468:542): pid=73624 uid=1000 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'

At least judging by the timestamp those have no direct correlation with the drive events - but maybe someone has an idea what that can be and if that might cause this behaviour?

winnie · 17 October 2021 19:21

If it’s failing or spitting out an error like “device or resource busy”, it surely should be logged in the recent messages.

Termy · 17 October 2021 20:00

I would normally assume as much, yeah…just skimmed through journalctl, nothing stands out there either

alven · 17 October 2021 20:14

I’m also still have no idea what is that secret setup. does it use network?
10 min interval is typical Mikrotik’s RouterOS DHCP lease time near that time clients “pings” to prolongs or to do not the IP lease time. May be it is that power up to read somewhat caused network and may be other not DHCP-related packages.

Termy · 17 October 2021 20:20

It’s just my Desktop PC - / is on an nvme, the affected drive is used for bulk storage (Fotos, Music, Videos and so on), the unaffected twin is used for backup. My usage doesn’t seem to matter, watching youtube, playing games, idling around.
Or did i missunderstand the question?

alven · 17 October 2021 21:06

A bit, I meant setup/architecture point of view: is a network device they are connected to or connected to local PC internally (SATA/SCSI/other internal bus). To local PC internally. OK.

And none of them is system one (not have a running OS), right? Backup only.
and somewhat spins them up.

So somehow need to log a new processes starting/appearing by that HDD activation time or to log a process activation detection (which one sends a command to the HDD).

Termy · 17 October 2021 21:20

Network is just over the mainboard-NIC. And yes, OS is on another drive.
As ptbgfoot is encountering the same issue, it seems to be either some kind of upstream-bug (kind of unlikely i’d say) or some manjaro-defaults that have been changed with the last updates.
I tried to keep iotop open with a timer to see if any new process (with I/O utilization) is spawned when the disk spins up - no luck though. Know any good way to monitor that?

winnie · 17 October 2021 22:07

The fact that you can’t even unmount the file-system on the drive is a red flag. I would address that first, as it might be related with your issue.

Termy · 18 October 2021 07:58

At least it was temporary - now after a fresh boot i can unmount it. Lets see if the sync stops now…
Edit: yep, still happening with unmounted drive - so usually i would now guess “kernel-related”, but as 5.13-5.15 are affected that seems kind of unlikely?!

alven · 18 October 2021 09:22

if after that spin up the HDD is still unmounted, then looks like it is not the software-related.

Try to shut down PC, to pull out data cable over which the drive connects to motherboard and to leave only power cable as it was.

Still spins up every 10 minutes w/ only power cable connected?
Change power cable or used power socket (or if there is no other anymore exchange power sockets of that HDDs couple).

Termy · 18 October 2021 09:46

Yes, it was still unmounted.
If it would be hardware-related it wouldn’t show up in the kernel logs i’d say. Plus, there was no Hardware or Firmware change (either HDD or UEFI) in the last months, so i’m pretty sure that won’t be a thing.

winnie · 18 October 2021 13:29

Did you check the running system timers, as @alven posted earlier?

Termy · 18 October 2021 13:48

Oh sorry - yeah i did, nothing stood out to me (and no 10min timers of course )

winnie · 18 October 2021 16:32

Try to entirely disable polling with a udev rule to see if this gets you something.

Create a file named 99-disable-polling.rules under /etc/udev/rules.d/ with the contents:

ACTION=="add", SUBSYSTEM=="block", ATTR{events_poll_msecs}="0"

You might have to reboot for the change to take effect.

Running sudo udevadm control --reload might not be sufficient.

If a value of "0" doesn’t work, try again with "-1" and reboot.

sobrus · 18 October 2021 17:11

I’ve come across the same issue recently.

The sda rotational disk is a part of a mdadm RAID0 array and it gets stopped and started every couple of minutes. It is clearly visible in dmesg. The second drive behaves normally (both are set to 5 minutes sleep timeout - this is a rarely used backup array).

This doesn’t seem like normal disk access, because the second RAID disk is not affected on single filesystem. Rather the system itself keeps restarting the “sda” drive and only sda drive (although I’m not sure about further drives - sdc and sdd are SSDs).

Laptop Mode Tools are not installed (I’ve found information that they can cause similar issues)
This is a Ryzen 5950 desktop system running stable version.

edit: this starting/stopping disk event, although causes the drive to spin up/down, is not properly reported in gnome-disk-tools eg. the disk can spin down while apparently running, or it can be “started” in dmesg even though the disk is powered down by user (or hdparm timeout).

alven · 18 October 2021 17:14

Here is a sort of civil society: to unite to reach the goal.

renkforce · 19 October 2021 10:52

I’ve noticed the exact same issue.

In my case, sda is an unrelated/unmounted NTFS disk which keeps spinning up. sdb for the old Windows installation + ESP. Linux root is on sdc.

First I’ve thought udisks2 keeps triggering that issue, but this is not the case.

However, the disk seems to be re-appearing constantly, spinning up only to be put back to sleep immediately after.

I’d be happy to get your advice on this issue.

Okt 19 11:04:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:04:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:04:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:05:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:05:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 11:14:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:14:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:14:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:15:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:15:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 11:24:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:24:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:24:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:25:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:25:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 11:34:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:34:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:34:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:35:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:35:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 11:44:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:44:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:44:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:45:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:45:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 11:54:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 11:54:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 11:54:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 11:55:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 11:55:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:04:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:04:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:04:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:05:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:05:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:08:13 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:08:13 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:08:13 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:08:34 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:08:34 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:14:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:14:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:14:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:15:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:15:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:24:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:24:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:24:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:25:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:25:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:34:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:34:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:34:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:35:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:35:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk
Okt 19 12:44:46 xmg kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Okt 19 12:44:46 xmg kernel: ata1.00: configured for UDMA/133
Okt 19 12:44:46 xmg kernel: sd 0:0:0:0: [sda] Starting disk
Okt 19 12:45:07 xmg kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Okt 19 12:45:07 xmg kernel: sd 0:0:0:0: [sda] Stopping disk

root@xmg ~# btrace /dev/sda
  8,0    3        1     0.000000000   108  D   N 0 [kworker/3:1]
  8,0    6        1     2.238213089     0  C   N [0]
  8,0    6        2     2.238387756     0  C   N [0]
  8,0    6        3     2.239587310     0  C   R [0]
  8,0    6        4     2.244548652     0  C   R [0]
  8,0    3        2     2.238298152 11331  D   R 255 [kworker/3:0]
  8,0    3        3     2.238307888    38  C   R [0]
  8,0    3        4     2.238318594 11331  D   R 255 [kworker/3:0]
  8,0    3        5     2.238321280    38  C   R [0]
  8,0    3        6     2.238326025 11331  D   R 255 [kworker/3:0]
  8,0    3        7     2.238328341    38  C   R [0]
  8,0    3        8     2.238333874 11331  D   R 255 [kworker/3:0]
  8,0    3        9     2.238335895    38  C   R [0]
  8,0    3       10     2.238339514 11331  D   R 255 [kworker/3:0]
  8,0    3       11     2.238341445    38  C   R [0]
  8,0    3       12     2.238344627 11331  D   R 572 [kworker/3:0]
  8,0    3       13     2.238346350    38  C   R [0]
  8,0    3       14     2.238349554 11331  D   N 0 [kworker/3:0]
  8,0    3       15     2.238351181    38  C   N [0]
  8,0    3       16     2.238353981 11331  D   R 32 [kworker/3:0]
  8,0    3       17     2.238355853    38  C   R [0]
  8,0    3       18     2.238359565 11331  D   R 64 [kworker/3:0]
  8,0    3       19     2.238361249    38  C   R [0]
  8,0    3       20     2.238363737 11331  D   R 64 [kworker/3:0]
  8,0    3       21     2.238365449    38  C   R [0]
  8,0    3       22     2.238368383 11331  D   R 64 [kworker/3:0]
  8,0    3       23     2.238370027    38  C   R [0]
  8,0    3       24     2.238372450 11331  D   R 64 [kworker/3:0]
  8,0    3       25     2.238374265    38  C   R [0]
  8,0    3       26     2.238378089 11331  D   R 8 [kworker/3:0]
  8,0    3       27     2.238380274    38  C   R [0]
  8,0    3       28     2.238383191 11331  D   R 8 [kworker/3:0]
  8,0    3       29     2.238387299    38  C   R [0]
  8,0    3       30     2.238389988 11331  D   R 36 [kworker/3:0]
  8,0    3       31     2.238391719    38  C   R [0]
  8,0    3       32     2.238394525 11331  D   R 512 [kworker/3:0]
  8,0    3       33     2.238396291    38  C   R [0]
  8,0    3       34     2.238398574 11331  D   R 512 [kworker/3:0]
  8,0    3       35     2.238400223    38  C   R [0]
  8,0    3       36     2.238402502 11331  D   R 512 [kworker/3:0]
  8,0    3       37     2.238404139    38  C   R [0]
  8,0    1        1     2.238309586 11330  D   N 0 [pool-udisksd]
  8,0    1        2     2.238971932 11330  D   R 512 [pool-udisksd]
  8,0    1        3     2.239647306 11330  D   R 512 [pool-udisksd]
  8,0    1        4     2.244603927 11330  D   R 512 [pool-udisksd]
  8,0    1        5     2.249141913 11330  D   N 0 [pool-udisksd]
  8,0    6        5     2.249051476     0  C   R [0]
  8,0    6        6     2.353432925     0  C   N [0]
^CCPU1 (8,0):
 Reads Queued:           0,        0KiB  Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        0,        0KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
 Read depth:             5               Write depth:             0
 PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
 PC Read Disp.:          5,        1KiB  PC Write Disp.:          0,        0KiB
 PC Reads Req.:          0               PC Writes Req.:          0
 PC Reads Compl.:        0               PC Writes Compl.:        0
 IO unplugs:             0               Timer unplugs:           0
CPU3 (8,0):
 Reads Queued:           0,        0KiB  Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        0,        0KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
 Read depth:             5               Write depth:             0
 PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
 PC Read Disp.:         19,        3KiB  PC Write Disp.:          0,        0KiB
 PC Reads Req.:          0               PC Writes Req.:          0
 PC Reads Compl.:       18               PC Writes Compl.:        0
 IO unplugs:             0               Timer unplugs:           0
CPU6 (8,0):
 Reads Queued:           0,        0KiB  Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        0,        0KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
 Read depth:             5               Write depth:             0
 PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
 PC Read Disp.:          0,        0KiB  PC Write Disp.:          0,        0KiB
 PC Reads Req.:          0               PC Writes Req.:          0
 PC Reads Compl.:        6               PC Writes Compl.:        0
 IO unplugs:             0               Timer unplugs:           0

Total (8,0):
 Reads Queued:           0,        0KiB  Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        0,        0KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
 PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
 PC Read Disp.:         24,        5KiB  PC Write Disp.:          0,        0KiB
 PC Reads Req.:          0               PC Writes Req.:          0
 PC Reads Compl.:       24               PC Writes Compl.:        0
 IO unplugs:             0               Timer unplugs:           0

Throughput (R/W): 0KiB/s / 0KiB/s
Events (8,0): 48 entries
Skips: 0 forward (0 -   0.0%)
Trace started at Tue Oct 19 12:14:46 2021

winnie · 19 October 2021 13:25

@Termy and others, did you try the udev rule posted earlier?

Termy · 19 October 2021 15:28

not yet, no.
I was planing on switching to pure arch in the foreseeable future anyways, so i think i’ll expedite that and do that in the next days. That way we can also cross check if its something manjaro-specific or affecting upstream as well