Hard Disk wake up very frecuently

[Jocko]

Hi

Previously, do you manage to get an access with fvdw-sl console ?

I assume you know this topic : http://plugout.net/viewtopic.php?f=7&t=2645. On a previous post you wrote you have also a VPN. So maybe you have to disable all ifaces and keep only one available. This includes also the virtual iface as may implement a VPN

[serram]

Finally I managed to establish the telnet connection...

:bananadance

The problem was this: The antivirus was blocking the file "tftpd32.exe" !!!

I checked the file at virustotal.com and this is the result:
https://www.virustotal.com/gui/file/c34 ... /detection

My conclusion is that the detection of the antivirus is wrong, and this is the case of a false positive.

Anyway, I finally managed to run the command e2fsck, and this is the output:

Code: Select all

root@fvdw-sta-kirkwood:/ # e2fsck -fy /dev/sda5
e2fsck 1.41.14 (22-Dec-2010)
/dev/sda5: recovering journal
Pass 1: Checking inodes, blocks, and sizes
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 4: Checking reference counts
Pass 5: Checking group summary information

/dev/sda5: ***** FILE SYSTEM WAS MODIFIED *****
/dev/sda5: 108/52304 files (7.4% non-contiguous), 8294/208845 blocks


[Jocko]

Hi

Thank you for your feedback
Yes it is a false positive. The tools of fvdw-sl console can not have a clean behaviour as they allows to upload data to a remote host (=> open a port), in our case the nas.
You would have the same result with a common ftp server installed on your laptop, but in this case the usual antivirus says nothing if you add rules on its ports (20,21 and others with PASV)

So now you have a clean fs on sda5.
Next step is to repeat this check:
- keep running all usual processes and do

Code: Select all

diskmon 15

check if diskmon daemon is running (ps axf)
Then remove the lan wire (to avoid any remote request from your LAN or WAN) and after a first disk spin down event (so 30min with your settings) look at when the disk spins up again.
In this case plug again the wire lan and open a shell session.
- Stop diskmon daemon

Code: Select all

killall diskmon

and read the content of log1 or log2 in /usr/var/diskmon

Code: Select all

cat /usr/var/diskmon/log1
cat /usr/var/diskmon/log2
cat /usr/var/diskmon/status

And if your reboot the nas, you will lose these files. So store the files in another location if you want keep them

[serram]

So I followed your instructions, ran diskmon, removed the lan wire. Then I waited until the disk remain still, and then I waited until it do a spin up again, and at that precise time I plug the cable and I opened a shell session, I killed the diskmon process and check the content of log1 and log2 files.
log2 is empty.
And this is the content of log1:

Code: Select all

root@fvdwsl-base:/usr/var/diskmon # cat log1
==== Sat Sep 19 13:35:04 CEST 2020 ====
[42392.345054] diskmon(2379): READ block 967334 on sda2 (2 sectors)
[42392.385698] diskmon(2379): READ block 972832 on sda2 (32 sectors)
[42392.392854] diskmon(2379): dirtied inode 120801 (touch) on sda2
[42392.393377] touch(2379): READ block 872354 on sda2 (22 sectors)
[42393.433848] diskmon(2383): READ block 967678 on sda2 (2 sectors)
[42393.434348] diskmon(2383): READ block 968422 on sda2 (32 sectors)
[42393.434857] diskmon(2383): dirtied inode 120557 (du) on sda2
[42393.435448] du(2383): READ block 692130 on sda2 (32 sectors)
[42393.435510] du(2383): READ block 692290 on sda2 (64 sectors)
[42393.435553] du(2383): READ block 689094 on sda2 (2 sectors)
[42393.435575] du(2383): READ block 692354 on sda2 (2 sectors)
[42393.435591] du(2383): READ block 692356 on sda2 (2 sectors)
[42393.435604] du(2383): READ block 692358 on sda2 (2 sectors)
[42393.435651] du(2383): READ block 692360 on sda2 (60 sectors)
[42393.519274] grep(2386): READ block 33294 on sda2 (2 sectors)
[42393.529339] diskmon(2387): dirtied inode 120414 (wc) on sda2
[42393.561354] diskmon(2392): dirtied inode 120659 (cat) on sda2
[42398.532741] jbd2/sda2-8(735): WRITE block 2638 on sda2 (2 sectors)
[42398.532782] jbd2/sda2-8(735): WRITE block 2640 on sda2 (2 sectors)
[42398.532801] jbd2/sda2-8(735): WRITE block 2642 on sda2 (2 sectors)
[42398.532815] jbd2/sda2-8(735): WRITE block 2644 on sda2 (2 sectors)
[42398.532828] jbd2/sda2-8(735): WRITE block 2646 on sda2 (2 sectors)
[42398.532841] jbd2/sda2-8(735): WRITE block 2648 on sda2 (2 sectors)
[42398.533255] jbd2/sda2-8(735): WRITE block 2650 on sda2 (2 sectors)
[42401.502652] mv643xx_eth_port mv643xx_eth_port.0 eth0: link up, 1000 Mb/s, full duplex, flow control disabled
[42434.372710] jbd2/sda2-8(735): WRITE block 2652 on sda2 (2 sectors)
[42434.372753] jbd2/sda2-8(735): WRITE block 2654 on sda2 (2 sectors)
[42434.372978] jbd2/sda5-8(786): WRITE block 535888 on sda5 (8 sectors)
[42434.373080] jbd2/sda5-8(786): WRITE block 535896 on sda5 (8 sectors)
[42434.373100] jbd2/sda5-8(786): WRITE block 535904 on sda5 (8 sectors)
[42434.373115] jbd2/sda5-8(786): WRITE block 535912 on sda5 (8 sectors)
[42434.373128] jbd2/sda5-8(786): WRITE block 535920 on sda5 (8 sectors)
[42434.373141] jbd2/sda5-8(786): WRITE block 535928 on sda5 (8 sectors)
[42434.373154] jbd2/sda5-8(786): WRITE block 535936 on sda5 (8 sectors)
[42434.373167] jbd2/sda5-8(786): WRITE block 535944 on sda5 (8 sectors)
[42434.373345] jbd2/sda2-8(735): WRITE block 2656 on sda2 (2 sectors)
[42434.373719] jbd2/sda5-8(786): WRITE block 535952 on sda5 (8 sectors)
Logging stopped : Sat Sep 19 13:35:54 CEST 2020


I think 13:35:04 could be the excact moment when the disk spin up.
Did you get any conclusion with this information?

[Jocko]

Well,

I think understand what happens with diskmon.

diskmon uses a touch command when it wants to rotate the log (log1 -> log2): remove log2 (rm command) and use touch to recreate it.

So that would means log1 reached the limit size. What is it its filesize. Can you please attach the file log1 ?

[serram]

Of course, here it is, attached at this post.

[Jocko]

So a small file and nothing else

Maybe I did not enough explain one point.
When you start diskmon with an argument value 15, that means the daemon begins its job 15 minutes later. At this step disk may spin up by some disk I/O from diskmon.

When you noticed your disk spined up it was around this delay ?

You can reduce this delay if you can unplug the lan wire quickly. So use for example 5 as arg value.
Then when the disk spins down after this delay, monitor when the disk spins up again (if it occurs quickly you may wait another spin down/up cycle) , stop only at this step diskmon

[serram]

I have to say sorry, becouse I didn't know that the argument value of diskmon was the delay to start logging. :hammerhead
As I didn't know that, I reduced the value of the inactivity period for spin down from 30min to 5min (just for not wait so long). And I runed the script diskmon with argument 15, so I spoiled all the experiment... It was a waste of time, sorry.

Ok, this time I changed the inactivity period to 30 min again.
I attached here the whole file log1 (log2 is empty again), but I copy and paste the exact moment of spin up (after spin down) (19:41h):

Code: Select all

==== Sat Sep 19 19:41:44 CEST 2020 ====
[ 3675.313991] jbd2/sda5-8(785): WRITE block 530120 on sda5 (8 sectors)
[ 3675.314032] jbd2/sda5-8(785): WRITE block 530128 on sda5 (8 sectors)
[ 3675.314050] jbd2/sda5-8(785): WRITE block 530136 on sda5 (8 sectors)
[ 3675.314064] jbd2/sda5-8(785): WRITE block 530144 on sda5 (8 sectors)
[ 3675.314077] jbd2/sda5-8(785): WRITE block 530152 on sda5 (8 sectors)
[ 3675.314090] jbd2/sda5-8(785): WRITE block 530160 on sda5 (8 sectors)
[ 3681.032985] jbd2/sda5-8(785): WRITE block 530168 on sda5 (8 sectors)
[ 3681.154719] noflushd(1636): WRITE block 0 on sda5 (8 sectors)
[ 3681.154765] noflushd(1636): WRITE block 8 on sda5 (8 sectors)
[ 3681.154788] noflushd(1636): WRITE block 786856 on sda5 (8 sectors)
[ 3681.154813] noflushd(1636): WRITE block 786864 on sda5 (8 sectors)
[ 3681.154833] noflushd(1636): WRITE block 790608 on sda5 (8 sectors)
==== Sat Sep 19 19:42:04 CEST 2020 ====
[ 3694.671582] mv643xx_eth_port mv643xx_eth_port.0 eth0: link up, 1000 Mb/s, full duplex, flow control disabled
Logging stopped : Sat Sep 19 19:42:32 CEST 2020


By the way, the moment of spin down was 19:34h. So the disk remain still only 7 minutes...

[Jocko]

So still this kernel thread about journaling but what process behind it ?

I suggest to do this test on a long time (for example night):
- set inactivity period for spin down :10min
- run diskmon
- unplug lan wire

Later (morning?) stops diskmon and post log1 and log2

[Mijzelf]

Does diskmon run in busybox ash? AFAIK that uses 'internal' du, grep, ..., so those tools should never wake up the disk. Then I still don't know why diskmon itself causes disk reads. It's supposed to be in memory. Could it be swapped away?

These one's are also strange:

Code: Select all

[42392.392854] diskmon(2379): dirtied inode 120801 (touch) on sda2
[42393.434857] diskmon(2383): dirtied inode 120557 (du) on sda2
[42393.529339] diskmon(2387): dirtied inode 120414 (wc) on sda2
[42393.561354] diskmon(2392): dirtied inode 120659 (cat) on sda2

Something is dirtying the inode of a read-only tool? I'm wondering if the 'last accessed' timestamp is updated. Is the filesystem not mounted with relatime or noatime?