[oS-en] Unending sync

Carlos E. R.

23 Oct 2021 23 Oct '21

18:52

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Hi, This afternoon I told this desktop machine to hibernate. My script to hibernate is this: date --rfc-3339=seconds echo Syncing sync date --rfc-3339=seconds echo "synced. Now screensaver" xscreensaver-command -lock sleep 3 #sudo chvt 10 #sleep 1 sudo /usr/local/sbin/beep sleep 1 #systemctl hibernate sudo /usr/bin/systemctl hibernate sleep 3 sudo /usr/local/sbin/beep #date --rfc-3339=seconds echo Well, at 19 hours it was still going at it: Telcontar:~ # hibernate 2021-10-23 15:23:17+02:00 Syncing It had been attempting to sync the filesystem for 4 hours, unsuccessfully. I do a separate sync previous to hibernating, because otherwise the hibernate stalls for long time not giving a hint of what is going on. What is going on? Well, the problem seems to be syncing the metadata of partition sdc9 (reiserfs, rotating rust), which holds /var/spool/news/. It can be a few millions of small files. Not really a news server, just the leafnode proxy. I know it takes very long after it runs /etc/cron.daily/leafnode, which calls "/usr/sbin/texpire": logger -p cron.warning -t texpire "CER: running leafnode's texpire without ionice" test -x /usr/sbin/texpire && su - news -c "/usr/sbin/texpire" logger -p cron.warning -t texpire "CER: finished texpire" sync -f /var/spool/news/ logger -p cron.warning -t texpire "CER: and synced -f" That sync can take half an hour normally, but that was not the time it runs: <9.4> 2021-10-22T23:45:01.361524+02:00 Telcontar texpire - - - CER: running leafnode's texpire without ionice ... <9.4> 2021-10-23T00:35:19.929058+02:00 Telcontar texpire - - - CER: finished texpire <9.4> 2021-10-23T00:37:09.833697+02:00 Telcontar texpire - - - CER: and synced -f So it should have not interfered. So what? Another possibility is that there is a cronjob that every 4 minutes tries to fetch news. So what I have done is disabling that job, and after a while, sync finished. So now my hibernate script will also need to stop news fetching. But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most? Is it some new problem with reiserfs? - -- Cheers Carlos E. R. (from 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXRaDBwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfViwEAoJFRSLa1AEeBDYv3uGZU gqh6eRzEAJ95ciPt1S737jGuo14SB+HPmsTYzA== =ls1+ -----END PGP SIGNATURE-----

Show replies by date

Dave Howorth

23 Oct 23 Oct

20:30

On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." wrote:

...

Hi,

This afternoon I told this desktop machine to hibernate. My script to hibernate is this:

date --rfc-3339=seconds echo Syncing sync date --rfc-3339=seconds echo "synced. Now screensaver" xscreensaver-command -lock sleep 3 #sudo chvt 10 #sleep 1 sudo /usr/local/sbin/beep sleep 1

#systemctl hibernate sudo /usr/bin/systemctl hibernate sleep 3 sudo /usr/local/sbin/beep #date --rfc-3339=seconds echo

Well, at 19 hours it was still going at it:

Telcontar:~ # hibernate 2021-10-23 15:23:17+02:00 Syncing

It had been attempting to sync the filesystem for 4 hours, unsuccessfully.

I do a separate sync previous to hibernating, because otherwise the hibernate stalls for long time not giving a hint of what is going on.

What is going on? Well, the problem seems to be syncing the metadata of partition sdc9 (reiserfs, rotating rust), which holds /var/spool/news/. It can be a few millions of small files. Not really a news server, just the leafnode proxy. I know it takes very long after it runs /etc/cron.daily/leafnode, which calls "/usr/sbin/texpire":

logger -p cron.warning -t texpire "CER: running leafnode's texpire without ionice" test -x /usr/sbin/texpire && su - news -c "/usr/sbin/texpire" logger -p cron.warning -t texpire "CER: finished texpire" sync -f /var/spool/news/ logger -p cron.warning -t texpire "CER: and synced -f"

That sync can take half an hour normally, but that was not the time it runs:

<9.4> 2021-10-22T23:45:01.361524+02:00 Telcontar texpire - - - CER: running leafnode's texpire without ionice ... <9.4> 2021-10-23T00:35:19.929058+02:00 Telcontar texpire - - - CER: finished texpire <9.4> 2021-10-23T00:37:09.833697+02:00 Telcontar texpire - - - CER: and synced -f

So it should have not interfered.

So what?

Another possibility is that there is a cronjob that every 4 minutes tries to fetch news. So what I have done is disabling that job, and after a while, sync finished.

So now my hibernate script will also need to stop news fetching.

But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most?

Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :) I would suggest to try running $ strace synce and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

Anton Aylward

22:13

On 2021-10-23 16:30, Dave Howorth wrote:

...

On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." wrote:

...
Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :)

I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I have ReiserFS # mount |grep reiserfs | wc -l 7 Actually there are more .... # mount |grep autofs | wc -l 8 and even worse # mount |grep x-systemd.automount | wc -l 3 Nevertheless: # times sync 0m0.110s 0m0.082s 0m0.576s 0m0.268s -- “Reality is so complex, we must move away from dogma, whether it’s conspiracy theories or free-market,” -- James Glattfelder. http://jth.ch/jbg

Carlos E. R.

24 Oct 24 Oct

02:25

On 23/10/2021 22.30, Dave Howorth wrote:

...

On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." <> wrote:

...
Hi,

...

...
But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most?

Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :)

But my /var/spool/news/ has 1,678,066 KiB in 659668 files, and some news processes change the access time of the inodes, which can be all of them. The current implemantion stores all those change in ram, and dumps them to disk when doing a sync (halt or hibernate implies a sync).

...

I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I doubt that is viable, but I can try. -- Cheers / Saludos, Carlos E. R. (from 15.2 x86_64 at Telcontar)

Dave Howorth

10:27

On Sun, 24 Oct 2021 04:25:13 +0200 "Carlos E. R." wrote:

...

On 23/10/2021 22.30, Dave Howorth wrote:

...
On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." <> wrote:

...
Hi,

...
...
But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most?

Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :)

But my /var/spool/news/ has 1,678,066 KiB in 659668 files, and some news processes change the access time of the inodes, which can be all of them.

Hmm, I mount all my filesystems with noatime (yes, I know modern people use relatime but just call me old-fashioned). I used to run a system that had loads of directories with millions of files in each one. Initially I used reiserfs for that but eventually had to change it for some reason. I remember ext4 was lousy for that application, but xfs worked well. Not as space efficient as reiserfs but it did perform reasonably.

...

The current implemantion stores all those change in ram, and dumps them to disk when doing a sync (halt or hibernate implies a sync).

You mean you have a tmpfs or something? Or just the kernel's caching?

...

...
I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I doubt that is viable, but I can try.

Why wouldn't it be viable?

Carlos E. R.

12:18

On 24/10/2021 12.27, Dave Howorth wrote:

...

On Sun, 24 Oct 2021 04:25:13 +0200 "Carlos E. R." <> wrote:

...
On 23/10/2021 22.30, Dave Howorth wrote:

...
On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." <> wrote:

...
Hi,

...
...
But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most?

Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :)

But my /var/spool/news/ has 1,678,066 KiB in 659668 files, and some news processes change the access time of the inodes, which can be all of them.

Hmm, I mount all my filesystems with noatime (yes, I know modern people use relatime but just call me old-fashioned).

News in particular have traditionally used those time stamps.

...

I used to run a system that had loads of directories with millions of files in each one. Initially I used reiserfs for that but eventually had to change it for some reason. I remember ext4 was lousy for that application, but xfs worked well. Not as space efficient as reiserfs but it did perform reasonably.

...
The current implemantion stores all those change in ram, and dumps them to disk when doing a sync (halt or hibernate implies a sync).

You mean you have a tmpfs or something? Or just the kernel's caching?

No, it is an effect of relatime, which is default nowdays IIRC. "something" in the filesystem stack tries to write the access time, but the kernel in fact stores that change in RAM. Can stay there for days, apparently. At some point it actually writes them to disk. My hypothesis is that reiserfs, which sees barely no maintenance, is slow when doing that, specially on rotating rust. In fact, I see the hard disk LED solid "on" while the sync is going on. Now that I think... I have free space in my /dev/nvme0n1, I can add a small reiserfs there and test. I see 3.7 gigs in use, so 12 gigs would be more than enough.

...

...
...
I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I doubt that is viable, but I can try.

Why wouldn't it be viable?

If it goes on on 100000 files... the trace can be enormous. Anyway, operation yesterday night was fast, the strace was active. 43 lines. Huh, we will see nothing, the gist is a single line: ... open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=26244, ...}) = 0 mmap(NULL, 26244, PROT_READ, MAP_SHARED, 3, 0) = 0x7f829bbbe000 close(3) = 0 sync() = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++ -- Cheers / Saludos, Carlos E. R. (from 15.2 x86_64 at Telcontar)

Anton Aylward

14:37

On 2021-10-24 08:18, Carlos E. R. wrote:

...

My hypothesis is that reiserfs, which sees barely no maintenance, is slow when doing that, specially on rotating rust. In fact, I see the hard disk LED solid "on" while the sync is going on.

It sees no maintenance because, unlike other ill designed s/w and file systems, it don't need it. The big downside of ReiserFS, and why we should be investing in Reiser4FS, is that it is single-threaded. That's a big downer if you have more than one ReiserFS mounted. On the plus side, ReiserFS is true B-tree FS. Ext4 only pretends to be, it still has that crazy UNIX V5/6/7 model of having a separate and predefined 'inode space' and inodes stored on disk as an array. Well OK, BtrFS is also a true B-tree FS, but it is over-ambitious in many respects and is, always has been riddled with problems. And an awkward and difficult to understand set of configurations options (though Ext4/mkfs is worse in that respect). Reiser is a straight forward B-tree FS. It's simple. There's not much you can fiddle with. "It just works". In that, and in it's lack of _need_ for maintenance, it's not a lot of fun. I get to wonder, perhaps I should search for a paper on this, about what happens with B-tree systems (in general) when they get more than half (or X%) full? Is the cost of rebalancing the tree as a result of whatever activity too great? Is that what you are seeing? It's worth considering https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1933172 If you attempt to balance a btrfs filesystem that is nearly full, and this filesystem has had a lot of small, medium and large files created and deleted, such that the b-tree needs to be rotated, when the balance fails due to not having enough free space, the kernel oops, and the btrfs filesystem hangs. Rotating and rebalancing a large (as in nearly full disk) is a fair bit of work, lots of rewriting to disk, demands on free space, hence thrashing to swap. -- “Reality is so complex, we must move away from dogma, whether it’s conspiracy theories or free-market,” -- James Glattfelder. http://jth.ch/jbg

jdd＠dodin.org

14:44

Le 24/10/2021 à 16:37, Anton Aylward a écrit :

...

If you attempt to balance a btrfs filesystem that is nearly full,

if manually done, it's an error. It's very easy to expand a btrfs file syste (even with external usb3 ssd) jdd -- http://dodin.org http://valeriedodin.com

Carlos E. R.

19:02

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Sunday, 2021-10-24 at 10:37 -0400, Anton Aylward wrote:

...

On 2021-10-24 08:18, Carlos E. R. wrote:

...
My hypothesis is that reiserfs, which sees barely no maintenance, is slow when doing that, specially on rotating rust. In fact, I see the hard disk LED solid "on" while the sync is going on.

It sees no maintenance because, unlike other ill designed s/w and file systems, it don't need it.

I'm unsure of that, specially related to the "relatime" mount feature.

...

The big downside of ReiserFS, and why we should be investing in Reiser4FS, is that it is single-threaded. That's a big downer if you have more than one ReiserFS mounted.

Yep. The issue here is that this partition takes normally 30..45 minutes to sync the time stamps (atime), that happened during the previous hours, possibly a day. The stamps remain in RAM till I try to halt, hibernate, or sync the machine. I have just migrated the partition to SSD (nvme, actually). Telcontar:~ # time rsync --archive --acls --xattrs --hard-links --sparse --stats --human-readable /data/Lareiserfs/var_spool_news/ /data/LareiserfsOnSSD/var_spool_news Number of files: 1,337,060 (reg: 1,335,949, dir: 1,111) Number of created files: 1,337,059 (reg: 1,335,949, dir: 1,110) Number of deleted files: 0 Number of regular files transferred: 659,960 Total file size: 3.80G bytes Total transferred file size: 2.03G bytes Literal data: 2.03G bytes Matched data: 0 bytes File list size: 43.73M File list generation time: 0.001 seconds File list transfer time: 0.000 seconds Total bytes sent: 2.14G Total bytes received: 45.64M sent 2.14G bytes received 45.64M bytes 1.07M bytes/sec total size is 3.80G speedup is 1.74 real 34m6.318s user 0m19.447s sys 1m7.471s Telcontar:~ # Meanwhile, I asked for a sync of the old partition (on rotating rust), and it is taking longer than writing this post. +++............. the command was issued at 16:53 hours. Now it is 20:43 and is still running. It is taking hours to run. Not finished at the moment of sending this email, at 21:01 .............++- I see on the strace that it is "stuck" here (expected): openat(AT_FDCWD, "/data/Lareiserfs/", O_RDONLY|O_NONBLOCK) = 3 fcntl(3, F_GETFL) = 0x8800 (flags O_RDONLY|O_NONBLOCK|O_LARGEFILE) fcntl(3, F_SETFL, O_RDONLY|O_LARGEFILE) = 0 syncfs(3 The command is this, I'll wait for completion before posting. Telcontar:~ # time strace -o /tmp/hibernate_old.strace \ sync -f /data/Lareiserfs/ atop was saying: PRC | sys 0.25s | user 0.75s | #proc 594 | #tslpu 2 | #zombie 0 | no procacct | CPU | sys 7% | user 22% | irq 0% | idle 1054% | wait 117% | ipc notavail | CPL | avg1 4.68 | avg5 5.57 | avg15 4.67 | csw 41808 | intr 14058 | numcpu 12 | MEM | tot 31.3G | free 9.9G | cache 6.0G | buff 2.9G | slab 2.3G | hptot 0.0M | SWP | tot 100.0G | free 95.9G | | | vmcom 26.4G | vmlim 115.7G | DSK | sdc | busy 95% | read 5 | write 124 | MBw/s 0.2 | avio 22.0 ms | <== in red DSK | nvme0n1 | busy 0% | read 0 | write 2 | MBw/s 0.0 | avio 6.00 ms | NET | transport | tcpi 16 | tcpo 16 | udpi 0 | udpo 0 | tcpao 1 | NET | network | ipi 17 | ipo 16 | ipfrw 0 | deliv 17 | icmpo 0 | NET | eth0 0% | pcki 17 | pcko 16 | sp 1000 Mbps | si 6 Kbps | so 3 Kbps | Sometimes "DSK" goes busy over 125%. But another gadget says it is not writing more than 400K/S (gkrellm), sometimes only 4K/S and still busy at 100%. iotop said: Total DISK READ : 0.00 B/s | Total DISK WRITE : 68.15 K/s Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 62.27 K/s TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND 7375 be/4 root 0.00 B/s 1203.11 B/s 0.00 % 95.35 % [kworker/u64:3+flush-8:32] 10268 be/4 cer 0.00 B/s 3.52 K/s 0.00 % 87.98 % firefox -P Small [glean.dispatche] 1475 be/3 root 0.00 B/s 1203.11 B/s 0.00 % 71.73 % [jbd2/sdc5-8] 484 be/3 root 0.00 B/s 18.80 K/s 0.00 % 0.27 % [jbd2/nvme0n1p5-] 12125 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.09 % [kworker/3:1-events] 9683 be/4 cer 0.00 B/s 19.97 K/s 0.00 % 0.00 % firefox -P Small [Permission] 9709 be/4 cer 0.00 B/s 3.52 K/s 0.00 % 0.00 % firefox -P Small [Cache2 I/O] 9866 be/4 cer 0.00 B/s 18.80 K/s 0.00 % 0.00 % firefox -P Small [localStorage DB] 18562 be/4 nscd 0.00 B/s 1203.11 B/s 0.00 % 0.00 % nscd top said - notice buff/cache size: top - 19:04:11 up 5 days, 22:01, 1 user, load average: 2,55, 2,88, 3,40 Tasks: 596 total, 2 running, 594 sleeping, 0 stopped, 0 zombie %Cpu(s): 1,3 us, 0,3 sy, 0,0 ni, 91,4 id, 6,9 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem : 32821868 total, 12361052 free, 8736108 used, 11724708 buff/cache KiB Swap: 10485760+total, 10098549+free, 3872100 used. 23040036 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 9650 cer 20 0 12,657g 2,860g 630904 655252 S 5,373 9,138 327:43.07 firefox 9902 cer 20 0 3956072 477800 122412 28472 S 3,284 1,456 16:25.98 Web Content 9833 cer 20 0 3962788 793676 76448 49600 S 2,388 2,418 111:43.34 Web Content - --- 20:45 hours. Notice that the partition where this happens is not mounted currently. fstab defines it this way: LABEL=c_data_reiser /data/Lareiserfs reiserfs acl,user_xattr,barrier=flush,lazytime 1 3 #/data/Lareiserfs/gamedata /usr/gamedata none bind 0 0 /data/Lareiserfs/gamedata/flightgear /usr/share/flightgear none bind 0 0 /data/Lareiserfs/gamedata/terrasync /home/cer/terrasync none bind 0 0 #/data/Lareiserfs/var_spool_news /var/spool/news none bind 0 0 Notice that "/data/Lareiserfs/var_spool_news" is not active. The new partition is: LABEL=LaReiserOnSSD /data/LareiserfsOnSSD reiserfs acl,user_xattr,barrier=flush,lazytime 1 3 /data/LareiserfsOnSSD/var_spool_news /var/spool/news none bind 0 0 Confirmed by "mount" command output: cer@Telcontar:~> mount | grep -i reiser /dev/sdc9 on /data/Lareiserfs type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /data/homedvl type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/src type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /home/cer/terrasync type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/share/flightgear type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/nvme0n1p6 on /data/LareiserfsOnSSD type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/nvme0n1p6 on /var/spool/news type reiserfs (rw,relatime,lazytime,user_xattr,acl) cer@Telcontar:~> I have renamed the old mount point, in order to break symlinks to it if they exist: Telcontar:~ # l /data/Lareiserfs/ total 6 drwxr-xr-x 11 root root 280 Oct 24 19:07 ./ drwxr-xr-x 26 root root 4096 Oct 24 14:12 ../ drwxr-xr-x 2 root root 160 Jan 20 2018 MoveReiser/ drwxr-xr-x 3 root root 72 Mar 2 2014 data_homedvl/ drwxr-xr-x 7 root root 240 Jan 14 2019 gamedata/ drwxrwxr-x 7 root root 168 Oct 23 15:03 pruebas/ drwxr-xr-x 2 root root 72 Feb 2 2018 scripts/ drwxr-xr-x 21 root root 1240 Oct 15 23:24 usr_src/ drwxrwxr-x 15 news news 472 Oct 23 14:16 var_spool_news.no/ <===== Telcontar:~ # The leafnode processes and sockets are stopped. Telcontar:~ # ps afxu | grep news cer 6415 0.1 0.2 1313520 90208 ? Sl Oct18 12:13 \_ xfce4-terminal --geometry=191x27 --display :0.0 --role=xfce4-terminal-1624817654-2757480848 --show-menubar --show-borders --hi root 23438 0.0 0.0 7432 924 pts/56 S+ 20:54 0:00 | | \_ grep --color=auto news cer 27337 0.0 0.0 13624 2960 pts/77 Ss+ 13:22 0:00 | \_ /bin/bash /home/cer/bin/terminales_one /var/log/news/news.debug cer 27338 0.0 0.0 4740 756 pts/77 S+ 13:22 0:00 | \_ tail -F -n 1000 /var/log/news/news.debug These are the reiserfs processes active: Telcontar:~ # ps afxu | grep -i reiser root 1501 0.0 0.0 0 0 ? I< Oct18 0:00 \_ [reiserfs/sdc9] root 31114 0.0 0.0 0 0 ? I< 14:12 0:00 \_ [reiserfs/nvme0n] root 10234 0.0 0.0 23496 3560 pts/23 S+ 16:53 0:00 | | \_ strace -o /tmp/hibernate_old.strace sync -f /data/Lareiserfs/ root 10237 0.0 0.0 4664 752 pts/23 D+ 16:53 0:00 | | \_ sync -f /data/Lareiserfs/ cer 7996 0.0 0.0 51460 8424 pts/32 S+ Oct23 0:00 | | \_ /usr/bin/mc -P /tmp/mc-cer/mc.pwd.7158 /data/Lareiserfs/ root 23485 0.0 0.0 7432 888 pts/56 S+ 20:55 0:00 | | \_ grep --color=auto -i reiser Telcontar:~ # Used files in the old partition: elcontar:~ # lsof /data/Lareiserfs lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. lsof: WARNING: can't stat() fuse.portal file system /run/user/1000/doc Output information may be incomplete. COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME bash 6581 cer cwd DIR 8,41 1688 1995125 /data/homedvl/cer/Mail/alpine-2.24/pico bash 6585 cer cwd DIR 8,41 1120 1488445 /data/homedvl/cer/Mail/alpine-2.24 bash 7068 cer cwd DIR 8,41 224 1488295 /data/homedvl/cer/Mail/alpine-2.24/debug mc 7996 cer cwd DIR 8,41 168 916318 /data/Lareiserfs/pruebas bash 7998 cer cwd DIR 8,41 168 916318 /data/Lareiserfs/pruebas sync 10237 root 3r DIR 8,41 280 2 /data/Lareiserfs Telcontar:~ # Clearing them, now: Telcontar:~ # lsof /data/Lareiserfs lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. lsof: WARNING: can't stat() fuse.portal file system /run/user/1000/doc Output information may be incomplete. COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME sync 10237 root 3r DIR 8,41 280 2 /data/Lareiserfs Telcontar:~ # That's the sync process itself. I can not think of anything else to do :-( - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXWtuRwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfVxgAAmQGRlWUZU8YAym8JgBZH EgSXDq4TAJwKC7a3jn4Uve/FbVTDCFIlcyRgdg== =LU6W -----END PGP SIGNATURE-----

Carlos E. R.

22:50

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Sunday, 2021-10-24 at 21:02 +0200, Carlos E. R. wrote:

...

On Sunday, 2021-10-24 at 10:37 -0400, Anton Aylward wrote:

...
On 2021-10-24 08:18, Carlos E. R. wrote:

...

Meanwhile, I asked for a sync of the old partition (on rotating rust), and it is taking longer than writing this post.

+++............. the command was issued at 16:53 hours.

Now it is 20:43 and is still running.

It is taking hours to run. Not finished at the moment of sending this email, at 21:01

.............++-

Still running at 00:49

...

top said - notice buff/cache size:

top - 19:04:11 up 5 days, 22:01, 1 user, load average: 2,55, 2,88, 3,40 Tasks: 596 total, 2 running, 594 sleeping, 0 stopped, 0 zombie %Cpu(s): 1,3 us, 0,3 sy, 0,0 ni, 91,4 id, 6,9 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem : 32821868 total, 12361052 free, 8736108 used, 11724708 buff/cache KiB Swap: 10485760+total, 10098549+free, 3872100 used. 23040036 avail Mem

PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 9650 cer 20 0 12,657g 2,860g 630904 655252 S 5,373 9,138 327:43.07 firefox 9902 cer 20 0 3956072 477800 122412 28472 S 3,284 1,456 16:25.98 Web Content 9833 cer 20 0 3962788 793676 76448 49600 S 2,388 2,418 111:43.34 Web Content

top - 00:37:23 up 6 days, 3:34, 1 user, load average: 4,96, 4,73, 4,39 Tasks: 609 total, 1 running, 608 sleeping, 0 stopped, 0 zombie %Cpu(s): 1,6 us, 0,5 sy, 0,0 ni, 76,6 id, 21,3 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem : 32821868 total, 5574216 free, 7266244 used, 19981408 buff/cache KiB Swap: 10485760+total, 10257884+free, 2278756 used. 24292200 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 24052 cer 20 0 9210668 2,554g 687504 0 S 12,24 8,161 25:57.37 firefox 21842 cer 20 0 4277204 1,243g 173404 0 S 0,000 3,971 5:07.37 thunderbird-bin 24413 cer 20 0 3722176 421212 162176 0 S 0,000 1,283 2:06.71 Web Content buff/cache keeps increasing :-? I attempted a sync on the new partition, and was instant: Telcontar:~ # time sync -f /data/LareiserfsOnSSD/ real 0m0.071s user 0m0.001s sys 0m0.000s Telcontar:~ # I see in the log this, which is encouraging, the texpire run: <9.4> 2021-10-24T23:45:01.391204+02:00 Telcontar texpire - - - CER: running leafnode's texpire without ionice <4.5> 2021-10-24T23:45:01.423949+02:00 Telcontar su - - - (to news) root on none <10.6> 2021-10-24T23:45:01.645518+02:00 Telcontar su - - - pam_unix(su-l:session): session opened for user news by (uid=0) <10.6> 2021-10-24T23:45:48.297631+02:00 Telcontar su - - - pam_unix(su-l:session): session closed for user news <9.4> 2021-10-24T23:45:48.331276+02:00 Telcontar texpire - - - CER: finished texpire <9.4> 2021-10-24T23:45:51.547240+02:00 Telcontar texpire - - - CER: and synced -f It finished within a minute (but today there was not much "news" activity) Compare with a previous run on rotating disk: <9.4> 2021-10-23T23:45:01.272427+02:00 Telcontar texpire - - - CER: running leafnode's texpire without ionice <4.5> 2021-10-23T23:45:01.306239+02:00 Telcontar su - - - (to news) root on none <10.6> 2021-10-23T23:45:01.541270+02:00 Telcontar su - - - pam_unix(su-l:session): session opened for user news by (uid=0) <10.6> 2021-10-24T00:31:42.883991+02:00 Telcontar su - - - pam_unix(su-l:session): session closed for user news <9.4> 2021-10-24T00:31:42.918772+02:00 Telcontar texpire - - - CER: finished texpire <9.4> 2021-10-24T00:34:02.638221+02:00 Telcontar texpire - - - CER: and synced -f Took about 45 minutes (and just 3' to sync). So whatever it does is io bound, with seek (head positioning) slowness. The HD LED is solid on. - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXXjJRwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfVKJ4AnR+7OQAiWR2Df9XuYCrD RVGwwmg4AJ4zR85i9h5M3HEctHrinHdPv/8ZAw== =t/i9 -----END PGP SIGNATURE-----

Carlos E. R.

25 Oct 25 Oct

01:07

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Monday, 2021-10-25 at 00:50 +0200, Carlos E. R. wrote:

...

On Sunday, 2021-10-24 at 21:02 +0200, Carlos E. R. wrote:

...
On Sunday, 2021-10-24 at 10:37 -0400, Anton Aylward wrote:

...
On 2021-10-24 08:18, Carlos E. R. wrote:

...

...
Meanwhile, I asked for a sync of the old partition (on rotating rust), and it is taking longer than writing this post.

+++............. the command was issued at 16:53 hours.

Now it is 20:43 and is still running.

It is taking hours to run. Not finished at the moment of sending this email, at 21:01

.............++-

Still running at 00:49

Still running at 03:03 I just did this: Telcontar:~ # date --rfc-3339=seconds ; time umount -v /data/Lareiserfs 2021-10-25 03:01:46+02:00 umount: /data/Lareiserfs: target is busy. real 0m0.004s user 0m0.002s sys 0m0.000s Telcontar:~ # lsof /data/Lareiserfs lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. lsof: WARNING: can't stat() fuse.portal file system /run/user/1000/doc Output information may be incomplete. COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME sync 10237 root 3r DIR 8,41 280 2 /data/Lareiserfs Telcontar:~ # date --rfc-3339=seconds ; time umount -v --lazy /data/Lareiserfs 2021-10-25 03:02:08+02:00 umount: /data/Lareiserfs (/dev/sdc9) unmounted real 0m0.003s user 0m0.003s sys 0m0.000s Telcontar:~ # That way I'm sure nothing is writing to that partition. And leave sync running the sync during the night, let's see tomorrow. - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXYDTBwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfVjLQAn14N0da3SSlCc7KPrJkJ PZbOIohGAKCPJcTkfgSkvesKsx2aEm2pQijWOw== =n3mW -----END PGP SIGNATURE-----

Carlos E. R.

02:23

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Monday, 2021-10-25 at 03:07 +0200, Carlos E. R. wrote:

...

On Monday, 2021-10-25 at 00:50 +0200, Carlos E. R. wrote:

...
On Sunday, 2021-10-24 at 21:02 +0200, Carlos E. R. wrote:

...
On Sunday, 2021-10-24 at 10:37 -0400, Anton Aylward wrote:

...
On 2021-10-24 08:18, Carlos E. R. wrote:

...

...
Meanwhile, I asked for a sync of the old partition (on rotating rust), and it is taking longer than writing this post.

+++............. the command was issued at 16:53 hours.

Now it is 20:43 and is still running.

It is taking hours to run. Not finished at the moment of sending this email, at 21:01

.............++-

Still running at 00:49

Still running at 03:03

I just did this:

Telcontar:~ # date --rfc-3339=seconds ; time umount -v /data/Lareiserfs 2021-10-25 03:01:46+02:00 umount: /data/Lareiserfs: target is busy.

real 0m0.004s user 0m0.002s sys 0m0.000s Telcontar:~ # lsof /data/Lareiserfs lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. lsof: WARNING: can't stat() fuse.portal file system /run/user/1000/doc Output information may be incomplete. COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME sync 10237 root 3r DIR 8,41 280 2 /data/Lareiserfs Telcontar:~ # date --rfc-3339=seconds ; time umount -v --lazy Telcontar:~ /data/Lareiserfs 2021-10-25 03:02:08+02:00 umount: /data/Lareiserfs (/dev/sdc9) unmounted

real 0m0.003s user 0m0.003s sys 0m0.000s Telcontar:~ #

That way I'm sure nothing is writing to that partition.

And leave sync running the sync during the night, let's see tomorrow.

Wow, it finished! Telcontar:~ # time strace -o /tmp/hibernate_old.strace sync -f /data/Lareiserfs/ real 674m20.295s user 0m0.005s sys 0m0.092s Telcontar:~ # Telcontar:~ # date --rfc-3339=seconds 2021-10-25 04:15:00+02:00 Telcontar:~ # About 12 hours! Telcontar:~ # cat /tmp/hibernate_old.strace execve("/usr/bin/sync", ["sync", "-f", "/data/Lareiserfs/"], 0x7fff9baa1990 /* 72 vars */) = 0 brk(NULL) = 0x563d1dc32000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=346952, ...}) = 0 mmap(NULL, 346952, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f69c5198000 close(3) = 0 openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`D\2\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=2038464, ...}) = 0 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f69c5196000 mmap(NULL, 3909496, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f69c4c0d000 mprotect(0x7f69c4dbe000, 2097152, PROT_NONE) = 0 mmap(0x7f69c4fbe000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b1000) = 0x7f69c4fbe000 mmap(0x7f69c4fc4000, 14200, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f69c4fc4000 close(3) = 0 arch_prctl(ARCH_SET_FS, 0x7f69c5197500) = 0 mprotect(0x7f69c4fbe000, 12288, PROT_READ) = 0 mprotect(0x563d1c2e3000, 4096, PROT_READ) = 0 mprotect(0x7f69c51ed000, 4096, PROT_READ) = 0 munmap(0x7f69c5198000, 346952) = 0 brk(NULL) = 0x563d1dc32000 brk(0x563d1dc53000) = 0x563d1dc53000 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=2939, ...}) = 0 read(3, "# Locale name alias data base.\n#"..., 4096) = 2939 read(3, "", 4096) = 0 close(3) = 0 open("/usr/lib/locale/en_US.UTF-8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) open("/usr/lib/locale/en_US.utf8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=330604, ...}) = 0 mmap(NULL, 330604, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f69c519c000 close(3) = 0 open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=26244, ...}) = 0 mmap(NULL, 26244, PROT_READ, MAP_SHARED, 3, 0) = 0x7f69c518f000 close(3) = 0 openat(AT_FDCWD, "/data/Lareiserfs/", O_RDONLY|O_NONBLOCK) = 3 fcntl(3, F_GETFL) = 0x8800 (flags O_RDONLY|O_NONBLOCK|O_LARGEFILE) fcntl(3, F_SETFL, O_RDONLY|O_LARGEFILE) = 0 syncfs(3) = 0 close(3) = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++ Telcontar:~ # I see something writing every second or so to /dev/sdc9 (in gkrellm), even though umounted. There should be nothing writing to it. Hum, now it is gone... :-? Will try to hibernate and call it a day. - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHkEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXYVChwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfVFPgAnApzMfytwH78LZj0a1+k HD8un6WsAJdolhn6xORY/ilUiUYjbih3Isuo =YyWu -----END PGP SIGNATURE-----

Carlos E. R.

09:05

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Monday, 2021-10-25 at 04:23 +0200, Carlos E. R. wrote:

...

On Monday, 2021-10-25 at 03:07 +0200, Carlos E. R. wrote:

...
On Monday, 2021-10-25 at 00:50 +0200, Carlos E. R. wrote:

...
On Sunday, 2021-10-24 at 21:02 +0200, Carlos E. R. wrote:

...
On Sunday, 2021-10-24 at 10:37 -0400, Anton Aylward wrote:

...
On 2021-10-24 08:18, Carlos E. R. wrote:

...

...
Meanwhile, I asked for a sync of the old partition (on rotating rust), and it is taking longer than writing this post.

+++............. the command was issued at 16:53 hours.

Now it is 20:43 and is still running.

It is taking hours to run. Not finished at the moment of sending this email, at 21:01

.............++-

Still running at 00:49

Still running at 03:03

I just did this:

Telcontar:~ # date --rfc-3339=seconds ; time umount -v /data/Lareiserfs 2021-10-25 03:01:46+02:00 umount: /data/Lareiserfs: target is busy.

real 0m0.004s user 0m0.002s sys 0m0.000s Telcontar:~ # lsof /data/Lareiserfs lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. lsof: WARNING: can't stat() fuse.portal file system /run/user/1000/doc Output information may be incomplete. COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME sync 10237 root 3r DIR 8,41 280 2 /data/Lareiserfs Telcontar:~ # date --rfc-3339=seconds ; time umount -v --lazy Telcontar:~ /data/Lareiserfs 2021-10-25 03:02:08+02:00 umount: /data/Lareiserfs (/dev/sdc9) unmounted

real 0m0.003s user 0m0.003s sys 0m0.000s Telcontar:~ #

That way I'm sure nothing is writing to that partition.

And leave sync running the sync during the night, let's see tomorrow.

Wow, it finished!

Telcontar:~ # time strace -o /tmp/hibernate_old.strace sync -f Telcontar:~ /data/Lareiserfs/

real 674m20.295s user 0m0.005s sys 0m0.092s Telcontar:~ #

Telcontar:~ # date --rfc-3339=seconds 2021-10-25 04:15:00+02:00 Telcontar:~ #

About 12 hours!

Telcontar:~ # cat /tmp/hibernate_old.strace ... fcntl(3, F_SETFL, O_RDONLY|O_LARGEFILE) = 0 syncfs(3) = 0 close(3) = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++ Telcontar:~ #

I see something writing every second or so to /dev/sdc9 (in gkrellm), even though umounted. There should be nothing writing to it.

Hum, now it is gone... :-?

Will try to hibernate and call it a day.

It took an hour and a half to hibernate! Telcontar:~ # hibernate 2021-10-25 04:23:46+02:00 Checking news to send 2021-10-25 04:23:49+02:00 Syncing 2021-10-25 06:03:59+02:00 synced. Now screensaver xscreensaver-command: no screensaver is running on display :0.0 touch /var/lib/news/bin/cronscriptparafetchnews.enabled Telcontar:~ # I see write activity on /dev/sdc9, which is umounted, gkrellm is showing it. I'm going to reboot, maybe the kernel still has open inodes on it. ... Rebooted. Interesting, now I see that low intensity write activity on /dev/nvme0n1p6 instead, the new small reiserfs partition for news. See attached photo of gkrellm displaying the partition, labelled "nv 6". Each vertical line is about 14K/S write. News fetching is still disabled, but thunderbird might be reading them. Telcontar:~ # ps afxu | grep news ... news 10624 1.2 0.0 73324 9512 ? Ss 10:52 0:00 /usr/lib/systemd/systemd --user news 10625 0.0 0.0 268436 4396 ? S 10:52 0:00 \_ (sd-pam) After using thunderbird: news 10720 0.0 0.0 13492 5496 ? Ss 10:53 0:00 /usr/sbin/leafnode So Thunderbird was not still reading. The previous entry of systemd could be "leafnode.socket": Telcontar:~ # systemctl status leafnode.socket ● leafnode.socket - Leafnode NNTP server Loaded: loaded (/usr/lib/systemd/system/leafnode.socket; enabled; vendor preset: disabled) Active: active (listening) since Mon 2021-10-25 10:40:58 CEST; 14min ago Listen: [::]:119 (Stream) Accepted: 1; Connected: 1 Tasks: 0 CGroup: /leafnode.socket Oct 25 10:40:58 Telcontar systemd[1]: Listening on Leafnode NNTP server. Telcontar:~ # Ah, the write activity on /dev/nvme0n1p6 is gone, but instead I have it on /dev/sdc9! Can't be news related now: Telcontar:~ # mount | grep sdc9 /dev/sdc9 on /data/Lareiserfs type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/share/flightgear type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/src type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /data/homedvl type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /home/cer/terrasync type reiserfs (rw,relatime,lazytime,user_xattr,acl) Telcontar:~ # Even the bind mountpoint is renamed: Telcontar:~ # l /data/Lareiserfs total 6 drwxr-xr-x 11 root root 280 Oct 24 19:07 ./ drwxr-xr-x 26 root root 4096 Oct 24 14:12 ../ drwxr-xr-x 2 root root 160 Jan 20 2018 MoveReiser/ drwxr-xr-x 3 root root 72 Mar 2 2014 data_homedvl/ drwxr-xr-x 7 root root 240 Jan 14 2019 gamedata/ drwxrwxr-x 7 root root 168 Oct 23 15:03 pruebas/ drwxr-xr-x 2 root root 72 Feb 2 2018 scripts/ drwxr-xr-x 21 root root 1240 Oct 15 23:24 usr_src/ drwxrwxr-x 15 news news 472 Oct 23 14:16 var_spool_news.no/ Telcontar:~ # Telcontar:~ # lsof /dev/sdc9 lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs Output information may be incomplete. Telcontar:~ # Telcontar:~ # time sync -f /data/LareiserfsOnSSD/ real 0m0.016s user 0m0.001s sys 0m0.000s Telcontar:~ # time sync -f /data/Lareiserfs/ real 0m0.092s user 0m0.001s sys 0m0.000s Telcontar:~ # Now I see the write acctitivity on both /dev/nvme0n1p6 and /dev/sdc9. I wonder what is causing that write activity on sdc9. There should be nothing. - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXZzUhwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfV6bwAni3MhuLgmQj2mS7DGYHK RQ5xu73uAJ4vp9dTJlTjogd/PQm1KUo+C0vuzA== =TjHs -----END PGP SIGNATURE-----

Dave Howorth

24 Oct 24 Oct

16:21

On Sun, 24 Oct 2021 14:18:40 +0200 "Carlos E. R." wrote:

...

On 24/10/2021 12.27, Dave Howorth wrote:

...
On Sun, 24 Oct 2021 04:25:13 +0200 "Carlos E. R." <> wrote:

...
On 23/10/2021 22.30, Dave Howorth wrote:

...
On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." <> wrote:

...
Hi,

...
...
But how is it possible that sync is unable to cope and sync in time the metadata of a hundred new tiny files at most?

Is it some new problem with reiserfs?

Dunno, but I doubt it. I also have reiserfs partitions and my system syncs without trouble, plus I doubt there have been many changes in reiserfs recently (I stand to be corrected :)

But my /var/spool/news/ has 1,678,066 KiB in 659668 files, and some news processes change the access time of the inodes, which can be all of them.

Hmm, I mount all my filesystems with noatime (yes, I know modern people use relatime but just call me old-fashioned).

News in particular have traditionally used those time stamps.

...
I used to run a system that had loads of directories with millions of files in each one. Initially I used reiserfs for that but eventually had to change it for some reason. I remember ext4 was lousy for that application, but xfs worked well. Not as space efficient as reiserfs but it did perform reasonably.

...
The current implemantion stores all those change in ram, and dumps them to disk when doing a sync (halt or hibernate implies a sync).

You mean you have a tmpfs or something? Or just the kernel's caching?

No, it is an effect of relatime, which is default nowdays IIRC.

"something" in the filesystem stack tries to write the access time, but the kernel in fact stores that change in RAM. Can stay there for days, apparently. At some point it actually writes them to disk.

I did some quick reading around. It seems modern relatime should write at least once every twenty-four hours. I don't know if that matches your experience? Apparently there was something called lazytime also being developed. It never writes atimes to disk, but keeps them always in cache. I don't know whether that would be better for you, or even whether lazytime is actually implemented/available/default by now?

...

My hypothesis is that reiserfs, which sees barely no maintenance, is slow when doing that, specially on rotating rust. In fact, I see the hard disk LED solid "on" while the sync is going on.

Now that I think... I have free space in my /dev/nvme0n1, I can add a small reiserfs there and test. I see 3.7 gigs in use, so 12 gigs would be more than enough.

...
...
...
I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I doubt that is viable, but I can try.

Why wouldn't it be viable?

If it goes on on 100000 files... the trace can be enormous.

Anyway, operation yesterday night was fast, the strace was active. 43 lines.

Huh, we will see nothing, the gist is a single line:

... open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=26244, ...}) = 0 mmap(NULL, 26244, PROT_READ, MAP_SHARED, 3, 0) = 0x7f829bbbe000 close(3) = 0 sync() = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++

Yeah, sync() is a single call to the kernel. So whatever is slowing your system is something in the kernel rather than the application. Whether that's a kernel issue or just a 'big' filesystem in some sense, I don't know. NVMe should definitely help. Or change to some news software that doesn't use atime :)

Carlos E. R.

17:03

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Sunday, 2021-10-24 at 17:21 +0100, Dave Howorth wrote:

...

On Sun, 24 Oct 2021 14:18:40 +0200 "Carlos E. R." <> wrote:

...
On 24/10/2021 12.27, Dave Howorth wrote:

...
On Sun, 24 Oct 2021 04:25:13 +0200 "Carlos E. R." <> wrote:

...
On 23/10/2021 22.30, Dave Howorth wrote:

...
On Sat, 23 Oct 2021 20:52:59 +0200 (CEST) "Carlos E. R." <> wrote:

...
Hi,

...

...
...
You mean you have a tmpfs or something? Or just the kernel's caching?

No, it is an effect of relatime, which is default nowdays IIRC.

"something" in the filesystem stack tries to write the access time, but the kernel in fact stores that change in RAM. Can stay there for days, apparently. At some point it actually writes them to disk.

I did some quick reading around. It seems modern relatime should write at least once every twenty-four hours. I don't know if that matches your experience?

Apparently there was something called lazytime also being developed. It never writes atimes to disk, but keeps them always in cache. I don't know whether that would be better for you, or even whether lazytime is actually implemented/available/default by now?

They are the default, I think. In any case, I'm using them: Telcontar:~ # mount | grep reiser /dev/sdc9 on /data/Lareiserfs type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /data/homedvl type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/src type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /home/cer/terrasync type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/sdc9 on /usr/share/flightgear type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/nvme0n1p6 on /data/LareiserfsOnSSD type reiserfs (rw,relatime,lazytime,user_xattr,acl) /dev/nvme0n1p6 on /var/spool/news type reiserfs (rw,relatime,lazytime,user_xattr,acl) Telcontar:~ # If I disable them, sync goes faster or is not needed, but instead the normal operation during the day is very slow.

...

...
My hypothesis is that reiserfs, which sees barely no maintenance, is slow when doing that, specially on rotating rust. In fact, I see the hard disk LED solid "on" while the sync is going on.

Now that I think... I have free space in my /dev/nvme0n1, I can add a small reiserfs there and test. I see 3.7 gigs in use, so 12 gigs would be more than enough.

...
...
...
I would suggest to try running

$ strace synce

and see what that shows. Is it hanging somewhere, or in an infinite loop? You might be able to see where.

I doubt that is viable, but I can try.

Why wouldn't it be viable?

If it goes on on 100000 files... the trace can be enormous.

Anyway, operation yesterday night was fast, the strace was active. 43 lines.

Huh, we will see nothing, the gist is a single line:

... open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=26244, ...}) = 0 mmap(NULL, 26244, PROT_READ, MAP_SHARED, 3, 0) = 0x7f829bbbe000 close(3) = 0 sync() = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++

Yeah, sync() is a single call to the kernel. So whatever is slowing your system is something in the kernel rather than the application. Whether that's a kernel issue or just a 'big' filesystem in some sense, I don't know. NVMe should definitely help. Or change to some news software that doesn't use atime :)

Oh, there is no alternative to leafnode, it is unique. I have migrated my partition to SSD, but I tried a sync on the old one (that is not in operation) and it is taking hours. I have a half written post on it, waiting for the sync to complete and write the report. - -- Cheers, Carlos E. R. (from openSUSE 15.2 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHIEARECADIWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCYXWR1BQccm9iaW4ubGlz dGFzQGdteC5lcwAKCRC1MxgcbY1H1fn9AJ4l9T/R8Akmkf5kapzsdzfyiaXcsACe KEzbT1y7+9V60+GLT0WVhL6X4Lw= =jtkr -----END PGP SIGNATURE-----

936

Age (days ago)

938

Last active (days ago)

List overview

Download

14 comments

5 participants

participants (5)

Anton Aylward
Carlos E. R.
Carlos E. R.
Dave Howorth
jdd＠dodin.org

[oS-en] Unending sync

tags

participants (5)