Re: measuring swap partition speed

From: Mark Millard <marklmi_at_yahoo.com>
Date: Sun, 24 Dec 2023 21:31:37 UTC
void <void_at_f-m.fm> wrote on
Date: Sun, 24 Dec 2023 12:28:05 UTC :

> On Sat, Dec 23, 2023 at 11:55:43AM -0800, Mark Millard wrote:
> 
> >If you had the resources to test avoiding the encrypted
> >partition for your type of media, that might prove
> >interesting.
> 
> The problem remains even with UFS. It remains after any non-swap i/o
> load stops, even when swap is not otherwise in use. 
> 
> I took /dev/da0p5, formatted it with newfs -U and put it at /mnt.
> 
> then
> 
> root@pi4:/mnt# date && git clone https://git.freebsd.org/ports.git
> Sun Dec 24 12:06:50 GMT 2023
> Cloning into 'ports'...
> remote: Enumerating objects: 6044522, done.
> remote: Counting objects: 100% (941/941), done.
> remote: Compressing objects: 100% (125/125), done.
> remote: Total 6044522 (delta 923), reused 821 (delta 816), pack-reused 6043581
> Receiving objects: 100% (6044522/6044522), 1.16 GiB | 6.94 MiB/s, done.
> ^Csolving deltas: 2% (101172/3649394)
> 
> date && dd if=/dev/urandom of=/dev/da0p6 bs=8k conv=sync status=progress
> Sun Dec 24 12:06:52 GMT 2023
> ^C203841536 bytes (204 MB, 194 MiB) transferred 205.012s, 994 kB/s 
> 25009+0 records in
> 25008+0 records out
> 204865536 bytes transferred in 205.914885 secs (994904 bytes/sec)
> 
> cancelled both processes, checked swap
> 
> # date && swapinfo -h
> Sun Dec 24 12:11:56 GMT 2023
> Device Size Used Avail Capacity
> /dev/da0p2 2.0G 0B 2.0G 0%
> /dev/da0p4 2.0G 0B 2.0G 0%
> /dev/da0p6 2.0G 0B 2.0G 0%
> /dev/da0p8 2.0G 0B 2.0G 0%
> Total 8.0G 0B 8.0G 0%
> 
> while /dev/da0p6 is available as swap to the system
> 
> # date && dd if=/dev/urandom of=/dev/da0p6 bs=8k conv=sync status=progress
> Sun Dec 24 12:10:38 GMT 2023
> ^C78790656 bytes (79 MB, 75 MiB) transferred 96.008s, 821 kB/s 
> 9767+0 records in
> 9766+0 records out
> 80003072 bytes transferred in 96.986518 secs (824889 bytes/sec)
> 
> # swapoff /dev/da0p6
> 
> # date && dd if=/dev/urandom of=/dev/da0p6 bs=8k conv=sync status=progress
> Sun Dec 24 12:21:28 GMT 2023
> dd: /dev/da0p6: end of device2031 MiB) transferred 105.007s, 20 MB/s
> 
> 262145+0 records in
> 262144+0 records out
> 2147483648 bytes transferred in 105.837991 secs (20290291 bytes/sec)

Somewhat analogous swap-active vs. swap-inactive sequences follow.
I've updated to the new snaphot (that has a UFS limit increased
to be big enough to again allow "poudriere bulk -a" to finish).

Note that this was tried in a context with:

# sysctl dev.bcm2835_cpufreq.0.freq_settings dev.cpu.0.freq_levels dev.cpu.0.freq
dev.bcm2835_cpufreq.0.freq_settings: 1500/-1 600/-1
dev.cpu.0.freq_levels: 1500/-1 600/-1
dev.cpu.0.freq: 600

# sysctl hw.cpufreq.sdram_freq
hw.cpufreq.sdram_freq: 400000000

no powerd use or the like.

I may later do some of the activity with my usual settings
for such.

# gpart show -p
=>       63  468862065    da0  MBR  (224G)
         63       1985         - free -  (993K)
       2048     102400  da0s1  fat32lba  [active]  (50M)
     104448  468757680  da0s2  freebsd  (224G)

=>        0  468757680   da0s2  BSD  (224G)
          0        128          - free -  (64K)
        128  451979136  da0s2a  freebsd-ufs  (216G)
  451979264   16777216  da0s2b  freebsd-swap  (8.0G)
  468756480       1200          - free -  (600K)

# swapinfo -h
Device              Size     Used    Avail Capacity
/dev/label/growfs_swap     8.0G       0B     8.0G     0%

# dd if=/dev/urandom of=/dev/label/growfs_swap bs=8k conv=sync status=progress
^C506142720 bytes (506 MB, 483 MiB) transferred 31.001s, 16 MB/s
62278+0 records in
62277+0 records out
510173184 bytes transferred in 31.247613 secs (16326789 bytes/sec)

# dd if=/dev/urandom of=/dev/label/growfs_swap bs=8k conv=sync status=progress
^C783056896 bytes (783 MB, 747 MiB) transferred 48.001s, 16 MB/s
96653+0 records in
96652+0 records out
791773184 bytes transferred in 48.533448 secs (16313969 bytes/sec)

# swapoff /dev/label/growfs_swap

# dd if=/dev/urandom of=/dev/label/growfs_swap bs=8k conv=sync status=progress
^C749903872 bytes (750 MB, 715 MiB) transferred 46.037s, 16 MB/s
92085+0 records in
92084+0 records out
754352128 bytes transferred in 46.308913 secs (16289567 bytes/sec)

What I observe via "gstat -spod" is the likes of:

dT: 1.004s  w: 1.000s
 L(q)  ops/s    r/s     kB   kBps   ms/r    w/s     kB   kBps   ms/w    d/s     kB   kBps   ms/d    o/s   ms/o   %busy Name
    1   1999      0      0      0    0.0   1999      8  15992    0.3      0      0      0    0.0      0    0.0   67.0| da0

Sometimes L(q) (length of queue) is 0 instead. The ops/s and w/s vary some
but 1999 looks to be the most frequent value. %busy also vary some.
ms/w seems rather stable once it gets going.

I'll note that ms/r counts how long it was in the queue
but w/s does not involve the in-queue time.

The above applies to both dd's.

FYI: in my RPi4B environment:

# find / -name "*.core" -mtime +2 -ls

lasts a few seconds at most but there are no source
trees or other significant additions to the snapshot
content.

The same goes for:

# periodic daily

So I may need to clone to populate a /usr/ports or some such.

. . .

# cd /usr
# pkg install git-lite
. . .
# git clone ssh://anongit@git.FreeBSD.org/ports.git
. . .
Updating files: 100% (156990/156990), done.

# swapinfo
Device          1K-blocks     Used    Avail Capacity
/dev/label/growfs_swap   8388604        0  8388604     0%

# dd if=/dev/urandom of=/dev/label/growfs_swap bs=8k conv=sync status=progress
^C554303488 bytes (554 MB, 529 MiB) transferred 34.000s, 16 MB/s
69046+0 records in
69045+0 records out
565616640 bytes transferred in 34.691537 secs (16304168 bytes/sec)

# swapoff /dev/label/growfs_swap

# dd if=/dev/urandom of=/dev/label/growfs_swap bs=8k conv=sync status=progress
^C553779200 bytes (554 MB, 528 MiB) transferred 34.001s, 16 MB/s
69145+0 records in
69145+0 records out
566435840 bytes transferred in 34.774020 secs (16289052 bytes/sec)

So I do not see the variability --including not in the
"gstat -spod" display updates.

I'll note that with /usr/ports/ populated:

# find / -name "*.core" -mtime +2 -ls

now takes more time when first tried. During it "gstat -spod"
showed the likes of:

dT: 1.066s  w: 1.000s
 L(q)  ops/s    r/s     kB   kBps   ms/r    w/s     kB   kBps   ms/w    d/s     kB   kBps   ms/d    o/s   ms/o   %busy Name
    0    506    506      4   2049    0.4      0      0      0    0.0      0      0      0    0.0      0    0.0   18.0| da0

(L(q) is 1 some of the time.)

But that is only for the 1st run. Rerunning afterwards
does little I/O (caching). Other forms of prior
activity could produce such variations. Adjusting
with swap on vs. off status does not change this
behavior.

Looks like a reboot or some such is required to have the
find do a bunch of I/O.

This likely messes up using periodic daily as well, until
a reboot or some such.


Note: so far I've not seen any "gstat -spod" information for
any of your types of experiments.



Below I instead use bs=4k . I also use "time -l"

# swapinfo
Device          1K-blocks     Used    Avail Capacity
/dev/label/growfs_swap   8388604        0  8388604     0%

# time -l dd if=/dev/urandom of=/dev/label/growfs_swap bs=4k conv=sync status=progress
^C598851584 bytes (599 MB, 571 MiB) transferred 63.000s, 9506 kB/s
147514+0 records in
147513+0 records out
604213248 bytes transferred in 63.563283 secs (9505696 bytes/sec)
time: command terminated abnormally
       63.56 real         0.46 user        14.32 sys
      2176  maximum resident set size
        16  average shared memory size
         4  average unshared data size
       134  average unshared stack size
       130  page reclaims
         0  page faults
         0  swaps
         0  block input operations
    147514  block output operations
         0  messages sent
         0  messages received
        64  signals received
    147516  voluntary context switches
        14  involuntary context switches

Example gstat -spod display:

dT: 1.004s  w: 1.000s
 L(q)  ops/s    r/s     kB   kBps   ms/r    w/s     kB   kBps   ms/w    d/s     kB   kBps   ms/d    o/s   ms/o   %busy Name
    1   2299      0      0      0    0.0   2299      4   9195    0.3      0      0      0    0.0      0    0.0   76.3| da0

# swapoff /dev/label/growfs_swap

# time -l dd if=/dev/urandom of=/dev/label/growfs_swap bs=4k conv=sync status=progress
^C579633152 bytes (580 MB, 553 MiB) transferred 61.001s, 9502 kB/s
141615+0 records in
141615+0 records out
580055040 bytes transferred in 61.045478 secs (9502015 bytes/sec)
time: command terminated abnormally
       61.05 real         0.48 user        13.73 sys
      2176  maximum resident set size
        16  average shared memory size
         4  average unshared data size
       135  average unshared stack size
       131  page reclaims
         0  page faults
         0  swaps
         0  block input operations
    141615  block output operations
         0  messages sent
         0  messages received
        62  signals received
    141618  voluntary context switches
        14  involuntary context switches


dT: 1.004s  w: 1.000s
 L(q)  ops/s    r/s     kB   kBps   ms/r    w/s     kB   kBps   ms/w    d/s     kB   kBps   ms/d    o/s   ms/o   %busy Name
    1   2328      0      0      0    0.0   2328      4   9311    0.3      0      0      0    0.0      0    0.0   76.7| da0


Note the "time -l" "block output operations" being just a little
smaller than "voluntary context switches" for each.

Also, it appears that bs=4k is limited by whatever contributes
to the ops/s being under, say, 2400 rather than being more like
2*1999 (1999 being from the 8k==2*4k dd context).


Another systematic difference in our contexts is my use of one
swap partition (the default for the small arm board snapshots
these days).


===
Mark Millard
marklmi at yahoo.com