Re: Filesystem operations slower in 13.0 than 12.2

[Mark Millard via freebsd-stable]

Konstantin Belousov kostikbel at gmail.com wrote on
Fri Mar 5 23:12:13 UTC 2021 :

> On Sat, Mar 06, 2021 at 12:27:55AM +0200, Christos Chatzaras wrote:
. . .
> > Command: /usr/bin/time -l portsnap extract (these tests done with 2 
> > different idle servers but with same 4TB HDDs models)
> > 
> > FreeBSD 12.2p4
> > 
> >99.45 real34.90 user59.63 sys
> >   100.00 real34.91 user59.97 sys
> >82.95 real35.98 user60.68 sys
> > 
> > FreeBSD 13.0-RC1
> > 
> >   217.43 real75.67 user   110.97 sys
> >   125.50 real63.00 user96.47 sys
> >   118.93 real62.91 user96.28 sys
> . . .
> In the portsnap results for 13RC1, the variance is too high to conclude
> anything, I think.

I'll note that there are other reports of wide variance
in transfer rates observed during an overall operation
such as "make extract". The one I'm thinking of is:

https://lists.freebsd.org/pipermail/freebsd-stable/2021-March/093251.html

which is an update to earlier reports, but based on more recent
stable/13. https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=253968
comment 4 has some more notes about the context. The "make extract"
for firefox likely is not as complicated as the portsnap extract
example's execution structure.

Might be something to keep an eye on if there are on-going
examples of over time.

===
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)

___
freebsd-stable@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to "freebsd-stable-unsubscr...@freebsd.org"

Re: Filesystem operations slower in 13.0 than 12.2

[Christos Chatzaras]

Hello Konstantin,

> On 6 Mar 2021, at 01:12, Konstantin Belousov  wrote:
> 
> There was (is) bugs in FreeBSD UFS SU < 13
> - some LoR existed in SU code, where it needed to lock a containing directory
>  to provide posix guarantees for fsync(), while owning the vnode lock.  I
>  do not believe it is observable in a real-world uses

If you are talking about these changes:

https://svnweb.freebsd.org/base?view=revision=367672 


then only during doing Prestashop translations, and after clicking on "Save" it 
removes and recreates Prestashop cache in /var/cache/prod directory could 
trigger a "processes hanging in ufs state". I use FreeBSD since 6.x and it was 
the first time I could trigger it (maybe it's related to specific Prestashop 
version too).

> - in some situations UFS SU in < 13 did not performed necessary fsync()
>  of the directory, related to the previous item
> The end result was that after sucessfull fsync() followed by a system
> failure e.g. power or panic, the parent directory for the synced
> vnode would not be synced and the vnode dirent' is not written to the
> permanent store. This volatiles posix requirement that after fsync, the
> data can be read, since you plain cannot open the file.
> 
> During the development of the patch to fix both LoR and related
> ommission of fsync, a mistake was made resulting in much more aggessive
> syncing of directories. It was not exactly that, but approximately, on
> most of metadata operations that created or removed directory entry,
> the directory was fully synced. This resulted in the significant slow
> down, which was eliminated around BETA4..RC1. I.e. most of fixes come to
> BETA4, but minor parts were only discovered later and ready for RC1.

I ask these questions to better understand how a FreeBSD developer works (and 
more specifically when a bug is not reported).

1) How you discover about this LoR / fsync ommission bug? Someone else found it 
and report it (I couldn't find a PR for this)? Is it discovered by a test 
suite? You found it by doing other work in this part of the code?

2) When I report the slowdown with BETA2 few weeks ago, you replied that this 
is a known bug and it will be fixed in BETA3 or BETA4.
After the initial patches that made more aggessive syncing of directories, how 
did you discover the slowdown?

> There are still more fsync(dir) in 13RC1 than it is in any 12, by the nature
> of the bug and its fix, but the current belief is that all fsync calls left
> in the flow are required for correctness.

Thank you for explaining these changes.
___
freebsd-stable@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to "freebsd-stable-unsubscr...@freebsd.org"

Re: Filesystem operations slower in 13.0 than 12.2

[Konstantin Belousov]

On Sat, Mar 06, 2021 at 12:27:55AM +0200, Christos Chatzaras wrote:
> I did some more tests. Finally I see similar results (with the exception of 
> one "portsnap extract" test). Also with 13.0 I can't trigger a bug that I 
> describe here:
> 
> https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=250576
> 
> --
> 
> Command: /usr/bin/time -l rm -fr /usr/ports /usr/src (these tests done with 
> exactly the same hardware - I upgrade 12.2p4 to 13.0-RC1 for the 2nd test)
> 
> FreeBSD 12.2p4
> 
>12.67 real 0.36 user 1.94 sys
>13.18 real 0.41 user 1.81 sys
>12.16 real 0.36 user 1.85 sys

> FreeBSD 13.0-RC1
> 
>16.71 real 0.63 user 3.02 sys
>14.53 real 0.48 user 2.98 sys
>13.97 real 0.70 user 2.85 sys
> 
> Command: /usr/bin/time -l tar xf src.tar (these tests done with 2 different 
> idle servers but with same 4TB HDDs models)
> 
> FreeBSD 12.2p4
> 
>37.35 real 1.03 user 3.34 sys
> 
> FreeBSD 13.0-RC1
> 
>44.97 real 1.15 user 3.34 sys
> 
> --
> 
> Command: /usr/bin/time -l tar xf ports.tar (these tests done with 2 different 
> idle servers but with same 4TB HDDs models)
> 
> FreeBSD 12.2p4
> 
>50.80 real 1.55 user 4.62 sys
> 
> FreeBSD 13.0-RC1
> 
>59.93 real 1.69 user 4.73 sys
> 
> --
> 
> 
> Command: /usr/bin/time -l portsnap extract (these tests done with 2 different 
> idle servers but with same 4TB HDDs models)
> 
> FreeBSD 12.2p4
> 
>99.45 real34.90 user59.63 sys
>   100.00 real34.91 user59.97 sys
>82.95 real35.98 user60.68 sys
> 
> FreeBSD 13.0-RC1
> 
>   217.43 real75.67 user   110.97 sys
>   125.50 real63.00 user96.47 sys
>   118.93 real62.91 user96.28 sys
I trimmed the data above to show the interesting numbers more compact.
In the portsnap results for 13RC1, the variance is too high to conclude
anything, I think.

There was (is) bugs in FreeBSD UFS SU < 13
- some LoR existed in SU code, where it needed to lock a containing directory
  to provide posix guarantees for fsync(), while owning the vnode lock.  I
  do not believe it is observable in a real-world uses
- in some situations UFS SU in < 13 did not performed necessary fsync()
  of the directory, related to the previous item
The end result was that after sucessfull fsync() followed by a system
failure e.g. power or panic, the parent directory for the synced
vnode would not be synced and the vnode dirent' is not written to the
permanent store. This volatiles posix requirement that after fsync, the
data can be read, since you plain cannot open the file.

During the development of the patch to fix both LoR and related
ommission of fsync, a mistake was made resulting in much more aggessive
syncing of directories. It was not exactly that, but approximately, on
most of metadata operations that created or removed directory entry,
the directory was fully synced. This resulted in the significant slow
down, which was eliminated around BETA4..RC1. I.e. most of fixes come to
BETA4, but minor parts were only discovered later and ready for RC1.

There are still more fsync(dir) in 13RC1 than it is in any 12, by the nature
of the bug and its fix, but the current belief is that all fsync calls left
in the flow are required for correctness.
___
freebsd-stable@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to "freebsd-stable-unsubscr...@freebsd.org"

Re: Filesystem operations slower in 13.0 than 12.2

[Christos Chatzaras]

I did some more tests. Finally I see similar results (with the exception of one 
"portsnap extract" test). Also with 13.0 I can't trigger a bug that I describe 
here:

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=250576

--

Command: /usr/bin/time -l rm -fr /usr/ports /usr/src (these tests done with 
exactly the same hardware - I upgrade 12.2p4 to 13.0-RC1 for the 2nd test)

FreeBSD 12.2p4

   12.67 real 0.36 user 1.94 sys
  5652  maximum resident set size
 8  average shared memory size
 4  average unshared data size
   139  average unshared stack size
   950  page reclaims
 0  page faults
 0  swaps
 49120  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 49258  voluntary context switches
 0  involuntary context switches

   13.18 real 0.41 user 1.81 sys
  5896  maximum resident set size
 8  average shared memory size
 4  average unshared data size
   132  average unshared stack size
  1074  page reclaims
 0  page faults
 0  swaps
 19463  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 19617  voluntary context switches
 7  involuntary context switches

   12.16 real 0.36 user 1.85 sys
  5884  maximum resident set size
 7  average shared memory size
 3  average unshared data size
   125  average unshared stack size
  1046  page reclaims
 0  page faults
 0  swaps
 18942  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 19096  voluntary context switches
 8  involuntary context switches

FreeBSD 13.0-RC1

   16.71 real 0.63 user 3.02 sys
  5580  maximum resident set size
 7  average shared memory size
 3  average unshared data size
   124  average unshared stack size
   956  page reclaims
 0  page faults
 0  swaps
 24420  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 24596  voluntary context switches
 8  involuntary context switche

   14.53 real 0.48 user 2.98 sys
  5572  maximum resident set size
 7  average shared memory size
 3  average unshared data size
   123  average unshared stack size
   954  page reclaims
 0  page faults
 0  swaps
 19426  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 19599  voluntary context switches
13  involuntary context switches

   13.97 real 0.70 user 2.85 sys
  5580  maximum resident set size
 8  average shared memory size
 4  average unshared data size
   130  average unshared stack size
   956  page reclaims
 0  page faults
 0  swaps
 18310  block input operations
   136  block output operations
 0  messages sent
 0  messages received
 0  signals received
 18477  voluntary context switches
25  involuntary context switches

--


Command: /usr/bin/time -l tar xf src.tar (these tests done with 2 different 
idle servers but with same 4TB HDDs models)

FreeBSD 12.2p4

   37.35 real 1.03 user 3.34 sys
  8644  maximum resident set size
36  average shared memory size
 4  average unshared data size
   129  average unshared stack size
   773  page reclaims
16  page faults
 0  swaps
60  block input operations
  4042  block output operations
 0  messages sent
 0  messages received
 0  signals received
   874  voluntary context switches
18  involuntary context switches

FreeBSD 13.0-RC1

   44.97 real 1.15 user 3.34 sys
  8840  maximum resident set size
35  average shared memory size
 3  average unshared data size
   127  average unshared stack size
   768  page reclaims
 0  page faults
 0  swaps
 2  block input operations
   422  block output operations
 0  messages sent
 0  messages received
 0  signals received
   304  voluntary context switches
43  involuntary context switches

Re: Filesystem operations slower in 13.0 than 12.2

[Mark Millard via freebsd-stable]

On 2021-Mar-4, at 14:16, Mark Millard  wrote:

> Christos Chatzaras chris at cretaforce.gr wrote on
> Thu Mar 4 21:41:01 UTC 2021 :
> 
> 
>> After finding slow filesystem operations with 13.0-BETA2 I did more tests.
>> 
>> All tests done with same hardware (Seagate ST4000NM0245 4TB HDD - 2 disks 
>> with RAID-1 using gmirror).
>> 
>> Filesystem mounted with noatime.
>> 
>> Command used:
>> 
>> /usr/bin/time -l portsnap extract
>> 
>> but similar differences I see with "/usr/bin/time -l rm -fr /usr/ports"
> 
> I doubt that "rm -fr" gets large differences of the
> type:
> 
> (from 12.2p4:)
> 0  messages sent
> 0  messages received
> vs. (13.0-BETA4 and 14.0-CURRENT:)
>  4412  messages sent
>   2536379  messages received

The more I think above the above figures, the more
it seems like 12.2 probably just does not track
messsages sent and received, especially given the
lack of huge "voluntary context switches" differences
vs. 13.0-BETA4 and 14.0-CURRENT. (I expect the message
sends/receives to context switch, but I might be
wrong.)

> In other words, large variations in Inter-Process-Communiciation
> counts, especially "received".
> 
> It is not obvious that the "portsnap extract" issue
> is dominated by file system I/O vs IPC issues.
> 
> portsanp is a script and does something that looks
> like the following, with the "while read" happening
> over 29000 times:
> 
> . . . | while read FILE HASH; do
>echo ${PORTSDIR}/${FILE}
>if ! [ -s "${WORKDIR}/files/${HASH}.gz" ]; then
>echo "files/${HASH}.gz not found -- snapshot corrupt."
>return 1
>fi
>case ${FILE} in
>*/)
>rm -rf ${PORTSDIR}/${FILE%/}
>mkdir -p ${PORTSDIR}/${FILE}
>tar -xz --numeric-owner -f ${WORKDIR}/files/${HASH}.gz 
> \
>-C ${PORTSDIR}/${FILE}
>;;
>*)
>rm -f ${PORTSDIR}/${FILE}
>tar -xz --numeric-owner -f ${WORKDIR}/files/${HASH}.gz 
> \
>-C ${PORTSDIR} ${FILE}
>;;
>esac
>done; then
> 
> I expect that the "tar -xz . . . *.gz" sort of commands
> also involve internal IPC use. (It looked like the
> portsnap script has not changed noticeably since
> something like late 2016.)

I wonder if the large user and/or sys differences between
12.2 and 13.0-BETA4 might be in process creation given the
over 29000 repititions of the loop and the number of
processes created per loop iteration.

The block input and output figures make no clear
difference that I can tell:

29  block input operations
  2783  block output operations
vs.
   716  block input operations
   868  block output operations

There is also:

  11821398  page reclaims
vs.
  12288156  page reclaims

but none of that suggests that scale of differences in:

   98.18 real35.31 user59.31 sys
vs.
  163.81 real71.93 user   107.32 sys

So it might be that "time -l" just does not report
on what makes up much of the difference.

Given the scale of the differences, I'd not expect
the variations in the likes of "involuntary context
switches" or the like to explain much of the
observed differences.

(I avoid 14.0-CURRENT for this because of its debug
build status that was reported. I avoid 13.0-BETA2
because of know block input/output operation count
issues.)

> (13.0-BETA2 showed a large "voluntary context switches"
> difference as well, but I ignore that middle step in
> the version sequence here.)
> 
> So I expect publishing the "rm -fr /usr/ports" figures
> from "time -l" would be appropriate. I do not know if
> the reports should be via separate topic or not but I
> doubt the figures with large differences will be the
> same for most-modern vs. older: I do not expect notable
> IPC from "rm -fr".
> 
>> --
>> 
>> FreeBSD 12.2p4 
>> 
>>   98.18 real35.31 user59.31 sys
>> 49064  maximum resident set size
>>21  average shared memory size
>> 3  average unshared data size
>>86  average unshared stack size
>>  11821398  page reclaims
>> 0  page faults
>> 0  swaps
>>29  block input operations
>>  2783  block output operations
>> 0  messages sent
>> 0  messages received
>> 0  signals received
>>354648  voluntary context switches
>>   322  involuntary context switches
>> 
>> --
>> 
>> FreeBSD 13.0-BETA2 (2021-02-12)
>> 
>>  497.88 real76.06 user   120.03 sys
>> 49032  maximum resident set size
>>22  average shared memory size
>> 3  average unshared data size
>>91  average unshared stack size
>>  12288156  page reclaims
>>23  page faults
>> 0  swaps
>> 29890  block 

Re: Filesystem operations slower in 13.0 than 12.2

[Dewayne Geraghty]

Thanks Helge, there is a 10% increase in involuntary context switching
which suggests that other things were occurring on the testing platform
 during the 13.0B4 run or 13 has adversely changed?  (And I'd discount
the latter due to the voluntary CS being similar across runs)

I appreciate you taking the time to perform difference tests, but think
that your tests need to be run under identical conditions :)
___
freebsd-stable@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to "freebsd-stable-unsubscr...@freebsd.org"