-----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-----