Re: Filesystem operations slower in 13.0 than 12.2

[Mark Millard via freebsd-stable]

On 2021-Mar-22, at 22:51, Kevin Oberman  wrote:

> On Mon, Mar 22, 2021 at 8:19 AM Adrian Chadd  wrote:
>> On Mon, 15 Mar 2021 at 14:58, Kevin Oberman  wrote:
>> 
>> > >
>> > > It appears that the messages are associated with reading
>> > > the disk(s), not directly with writing them, where the
>> > > reads take more than "hz * 20" time units to complete.
>> > > (I'm looking at main (14) code.) What might contribute
>> > > to the time taken for the pending read(s)?
>> > >
>> > The reference to hz * 20 woke up a few sleeping memory cells. I forgot that
>> > I cleaned up my loader.conf. It was largely a copy of the one on my
>> > decade-old T520. I commented out "kern.hz=100". I don't recall the details,
>> > but I think it was actually from an even older system, my T42 from before I
>> > retired.
>> >
>> > In any case, restoring this setting has greatly improved the situation. I
>> > now have really bad disk I/O performance on large disk to disk activity
>> > (untarring the firefox distro) instead of terrible performance and the
>> > system freezes have vanished, though I do see pauses in response to clicks
>> > or text entry, but the display remains active and the pauses are short... 1
>> > to 15 seconds, I'd guess. No, I have no idea what this indicates.
>> 
>> ... which drive controller is this? Is it just a laptop ATA disk?
>> 
>> > I'm still not seeing the performance I was seeing back in February when 40
>> > MB/s for extended intervals was common and I once untarred firefox.tar.gz2
>> > in under a minute and performance seldom dropped below 1.4 MB/s.
>> 
>> Did you find a resolution?  I wonder if setting kern.hz is kicking
>> some process(es) to get some time more frequently due to bugs
>> elsewhere in the system (interrupts, IPI handling, wake-ups, etc)
>> 
>> 
>> 
>> -adrian

> No resolution. This is a Lenovo L15 ThinkPad with a 2TB ATAPI drive.

I've not found documentation indicating the "which drive
controller" answer. That may have to be answered from boot
messages or boot -v messages or other such on FreeBSD.
(I've no access to such a machine.)

You might want to put a copy of such a log someplace that
folks could look at it. There may be commands that some
folks would like to see the output of. (I'm not all that
likely to be one that could put such to use but other
folks might be able to.)

Intel® Celeron®? 10th Generation Intel CoreTM i3? i5? i7?

> The current drive is a Seagate.  All testing has been done since I got it 
> back from Lenovo in late January. I can read or write the drive at reasonable 
> rates that exceed 50 MB/s. Extracting a tar distribution file is painful. I 
> have had firefox extracts take over a half hour. Worse, if I do other 
> operations while the extract is taking place, I often see a 30 second (and, 
> occasionally 60 second) display freezes

I thought that you had reported that use of kern.hz=100
had lead to "the system freezes have vanished" and "pauses
are short... 1 to 15 seconds". Did more testing show that
to not be always the case?

> as well as log reports that of "swap_pager: indefinite wait buffer:"

Unfortunately, I do not know how to investigate what is leading to
those message being generated. Figuring that out would seem to be
important but I do not know what to monitor to at least potentially
eliminate some possibilities.

One possible thing to look at is something like "gstat -spod"
output spanning the time of the untar. It would at least
indicate if a large queue backlog was accumulating on the
device. And the ms/r and ms/w columns would give a clue if
commands are sitting in the queues for long periods. (The
"d" may be a waste: no BIO_DELETEs possible? Also, the r/s
vs. ms/r are not rescaled reciprocals but distinct
measurements. Similarly for: the w/s vs. ms/w.)

Given the "indefinite wait buffer" messages, I expect
the ms/r and/or ms/w figures to be large at least some
of the time. Knowing how large may be of use to someone.
But I can not eliminate anything with such information.

>  This is a bit odd as I have 20G of RAM and am pretty close to no swap space 
> activity, but, of course, paging does occur. 

With 20 GiBytes of RAM, what is going on at the time that
leads to paging activity? I'm thinking of just untarring
the firefox file, not building firefox or such. Can you
test such an untar in a context that is not otherwise
paging (nor swapping)? If yes, is the behavior different
in any readily noticeable way?

> This system is CometLake and graphics are not supported on 12. I am not 
> absolutely sure that there is not a hardware issue even though the main 
> board, the disk, and the keyboard/mouse pad have all been replace since I 
> received the system back last June. I now wonder what else could go wrong.
 

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

Re: Filesystem operations slower in 13.0 than 12.2

[Kevin Oberman]

On Mon, Mar 22, 2021 at 8:19 AM Adrian Chadd  wrote:

> On Mon, 15 Mar 2021 at 14:58, Kevin Oberman  wrote:
>
> > >
> > > It appears that the messages are associated with reading
> > > the disk(s), not directly with writing them, where the
> > > reads take more than "hz * 20" time units to complete.
> > > (I'm looking at main (14) code.) What might contribute
> > > to the time taken for the pending read(s)?
> > >
> > The reference to hz * 20 woke up a few sleeping memory cells. I forgot
> that
> > I cleaned up my loader.conf. It was largely a copy of the one on my
> > decade-old T520. I commented out "kern.hz=100". I don't recall the
> details,
> > but I think it was actually from an even older system, my T42 from
> before I
> > retired.
> >
> > In any case, restoring this setting has greatly improved the situation. I
> > now have really bad disk I/O performance on large disk to disk activity
> > (untarring the firefox distro) instead of terrible performance and the
> > system freezes have vanished, though I do see pauses in response to
> clicks
> > or text entry, but the display remains active and the pauses are
> short... 1
> > to 15 seconds, I'd guess. No, I have no idea what this indicates.
>
> ... which drive controller is this? Is it just a laptop ATA disk?
>
> > I'm still not seeing the performance I was seeing back in February when
> 40
> > MB/s for extended intervals was common and I once untarred
> firefox.tar.gz2
> > in under a minute and performance seldom dropped below 1.4 MB/s.
>
> Did you find a resolution?  I wonder if setting kern.hz is kicking
> some process(es) to get some time more frequently due to bugs
> elsewhere in the system (interrupts, IPI handling, wake-ups, etc)
>
>
>
> -adrian
>
No resolution. This is a Lenovo L15 ThinkPad with a 2TB ATAPI drive. The
current drive is a Seagate.  All testing has been done since I got it back
from Lenovo in late January. I can read or write the drive at reasonable
rates that exceed 50 MB/s. Extracting a tar distribution file is painful. I
have had firefox extracts take over a half hour. Worse, if I do other
operations while the extract is taking place, I often see a 30 second (and,
occasionally 60 second) display freezes as well as log reports that of
"swap_pager: indefinite wait buffer:" This is a bit odd as I have 20G of
RAM and am pretty close to no swap space activity, but, of course, paging
does occur.

This system is CometLake and graphics are not supported on 12. I am not
absolutely sure that there is not a hardware issue even though the main
board, the disk, and the keyboard/mouse pad have all been replace since I
received the system back last June. I now wonder what else could go wrong.
--
Kevin Oberman, Part time kid herder and retired Network Engineer
E-mail: rkober...@gmail.com
PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
___
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

[Adrian Chadd]

On Mon, 15 Mar 2021 at 14:58, Kevin Oberman  wrote:

> >
> > It appears that the messages are associated with reading
> > the disk(s), not directly with writing them, where the
> > reads take more than "hz * 20" time units to complete.
> > (I'm looking at main (14) code.) What might contribute
> > to the time taken for the pending read(s)?
> >
> The reference to hz * 20 woke up a few sleeping memory cells. I forgot that
> I cleaned up my loader.conf. It was largely a copy of the one on my
> decade-old T520. I commented out "kern.hz=100". I don't recall the details,
> but I think it was actually from an even older system, my T42 from before I
> retired.
>
> In any case, restoring this setting has greatly improved the situation. I
> now have really bad disk I/O performance on large disk to disk activity
> (untarring the firefox distro) instead of terrible performance and the
> system freezes have vanished, though I do see pauses in response to clicks
> or text entry, but the display remains active and the pauses are short... 1
> to 15 seconds, I'd guess. No, I have no idea what this indicates.

... which drive controller is this? Is it just a laptop ATA disk?

> I'm still not seeing the performance I was seeing back in February when 40
> MB/s for extended intervals was common and I once untarred firefox.tar.gz2
> in under a minute and performance seldom dropped below 1.4 MB/s.

Did you find a resolution?  I wonder if setting kern.hz is kicking
some process(es) to get some time more frequently due to bugs
elsewhere in the system (interrupts, IPI handling, wake-ups, etc)



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

[Mark Millard via freebsd-stable]

On 2021-Mar-15, at 14:57, Kevin Oberman  wrote:

> Responses in-line.
> 
> On Sun, Mar 14, 2021 at 3:09 PM Mark Millard  wrote:
> 
>> On 2021-Mar-14, at 11:09, Kevin Oberman  wrote:
>> 
>> > . . .
>> >  
>> > Seems to only occur on large r/w operations from/to the same disk. "sp
>> > big-file /other/file/on/same/disk" or tar/untar operations on large files.
>> > Hit this today updating firefox.
>> > 
>> > I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
>> > things while it was running slowly, the disk would appear to lock up. E.g.
>> > pwd(1) seemed to completely lock up the system, but I could still ping it
>> > and, after about 30 seconds, things came back to life. It was also not
>> > instantaneous. Disc activity dropped to <1MB/s for a few seconds before
>> > everything froze.
>> > 
>> > During the untar of firefox, I saw; this several times. I also looked at my
>> > console where I found these errors during :
>> > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
>> > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>> 
>> Does anyone know:
>> Are those messages normal "reading is taking a rather long
>> time" notices or is their presence more useful information
>> in some way about the type of problem or context for the
>> problem?
>> 
> As for the tests:
> Are these messages always present when near a time frame
> when the problem occurs? Never present in a near time
> frame to a period when the problem does not occur?
> In a large number of test, these errors have not repeated. They baffle me for 
> another reason. This system has 20G or RAM. Tyically, all swap space is 
> unused. ATM I see 16384M free out of 16384. Not sure that I have ever seen it 
> used, though it might have been while building rust. I have not built rust 
> for a month.
> 
> It appears that the messages are associated with reading
> the disk(s), not directly with writing them, where the
> reads take more than "hz * 20" time units to complete.
> (I'm looking at main (14) code.) What might contribute
> to the time taken for the pending read(s)?
> The reference to hz * 20 woke up a few sleeping memory cells. I forgot that I 
> cleaned up my loader.conf. It was largely a copy of the one on my decade-old 
> T520. I commented out "kern.hz=100". I don't recall the details, but I think 
> it was actually from an even older system, my T42 from before I retired.
> 
> In any case, restoring this setting has greatly improved the situation. I now 
> have really bad disk I/O performance on large disk to disk activity 
> (untarring the firefox distro) instead of terrible performance and the system 
> freezes have vanished, though I do see pauses in response to clicks or text 
> entry, but the display remains active and the pauses are short... 1 to 15 
> seconds, I'd guess. No, I have no idea what this indicates.

Interesting.

> I'm still not seeing the performance I was seeing back in February when 40 
> MB/s for extended intervals was common and I once untarred firefox.tar.gz2 in 
> under a minute and performance seldom dropped below 1.4 MB/s.
>  
>>> /*
>>>  * swap_pager_getpages() - bring pages in from swap
>>>  *
>>>  *  Attempt to page in the pages in array "ma" of length "count".  The
>>>  *  caller may optionally specify that additional pages preceding and
>>>  *  succeeding the specified range be paged in.  The number of such 
>>> pages
>>>  *  is returned in the "rbehind" and "rahead" parameters, and they will
>>>  *  be in the inactive queue upon return.
>>>  *
>>>  *  The pages in "ma" must be busied and will remain busied upon return.
>>>  */
>>> static int
>>> swap_pager_getpages_locked(vm_object_t object, vm_page_t *ma, int count,
>>> int *rbehind, int *rahead)
>>> {
>>> . . .
>>> /*
>>>  * Wait for the pages we want to complete.  VPO_SWAPINPROG is always
>>>  * cleared on completion.  If an I/O error occurs, SWAPBLK_NONE
>>>  * is set in the metadata for each page in the request.
>>>  */
>>> VM_OBJECT_WLOCK(object);
>>> /* This could be implemented more efficiently with aflags */
>>> while ((ma[0]->oflags & VPO_SWAPINPROG) != 0) {
>>> ma[0]->oflags |= VPO_SWAPSLEEP;
>>> VM_CNT_INC(v_intrans);
>>> if (VM_OBJECT_SLEEP(object, &object->handle, PSWP,
>>> "swread", hz * 20)) {
>>> printf(
>>> "swap_pager: indefinite wait buffer: bufobj: %p, blkno: %jd, size: %ld\n",
>>> bp->b_bufobj, (intmax_t)bp->b_blkno, 
>>> bp->b_bcount);
>>> }
>>> }
>>> VM_OBJECT_WUNLOCK(object);
>>> . . .
>>> 
>>> where:
>>> 
>>> #define VM_OBJECT_SLEEP(object, wchan, pri, wmesg, timo)\
>>> rw_sleep((wchan), &(object)->lock, (pri), (wmesg), (timo))
>>> 
>>> and:
>>> 
>>> #define rw_sleep(chan, rw, pri, wmesg, timo) 

Re: Filesystem operations slower in 13.0 than 12.2

[Kevin Oberman]

Responses in-line.

On Sun, Mar 14, 2021 at 3:09 PM Mark Millard  wrote:

>
>
> On 2021-Mar-14, at 11:09, Kevin Oberman  wrote:
>
> > . . .
> >
> > Seems to only occur on large r/w operations from/to the same disk. "sp
> > big-file /other/file/on/same/disk" or tar/untar operations on large
> files.
> > Hit this today updating firefox.
> >
> > I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
> > things while it was running slowly, the disk would appear to lock up.
> E.g.
> > pwd(1) seemed to completely lock up the system, but I could still ping it
> > and, after about 30 seconds, things came back to life. It was also not
> > instantaneous. Disc activity dropped to <1MB/s for a few seconds before
> > everything froze.
> >
> > During the untar of firefox, I saw; this several times. I also looked at
> my
> > console where I found these errors during :
> > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
> > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>
> Does anyone know:
> Are those messages normal "reading is taking a rather long
> time" notices or is their presence more useful information
> in some way about the type of problem or context for the
> problem?
>
> As for the tests:
> Are these messages always present when near a time frame
> when the problem occurs? Never present in a near time
> frame to a period when the problem does not occur?
>
In a large number of test, these errors have not repeated. They baffle me
for another reason. This system has 20G or RAM. Tyically, all swap space is
unused. ATM I see 16384M free out of 16384. Not sure that I have ever seen
it used, though it might have been while building rust. I have not built
rust for a month.

>
> It appears that the messages are associated with reading
> the disk(s), not directly with writing them, where the
> reads take more than "hz * 20" time units to complete.
> (I'm looking at main (14) code.) What might contribute
> to the time taken for the pending read(s)?
>
The reference to hz * 20 woke up a few sleeping memory cells. I forgot that
I cleaned up my loader.conf. It was largely a copy of the one on my
decade-old T520. I commented out "kern.hz=100". I don't recall the details,
but I think it was actually from an even older system, my T42 from before I
retired.

In any case, restoring this setting has greatly improved the situation. I
now have really bad disk I/O performance on large disk to disk activity
(untarring the firefox distro) instead of terrible performance and the
system freezes have vanished, though I do see pauses in response to clicks
or text entry, but the display remains active and the pauses are short... 1
to 15 seconds, I'd guess. No, I have no idea what this indicates.

I'm still not seeing the performance I was seeing back in February when 40
MB/s for extended intervals was common and I once untarred firefox.tar.gz2
in under a minute and performance seldom dropped below 1.4 MB/s.


>
> /*
>  * swap_pager_getpages() - bring pages in from swap
>  *
>  *  Attempt to page in the pages in array "ma" of length "count".  The
>  *  caller may optionally specify that additional pages preceding and
>  *  succeeding the specified range be paged in.  The number of such
> pages
>  *  is returned in the "rbehind" and "rahead" parameters, and they will
>  *  be in the inactive queue upon return.
>  *
>  *  The pages in "ma" must be busied and will remain busied upon
> return.
>  */
> static int
> swap_pager_getpages_locked(vm_object_t object, vm_page_t *ma, int count,
> int *rbehind, int *rahead)
> {
> . . .
> /*
>  * Wait for the pages we want to complete.  VPO_SWAPINPROG is
> always
>  * cleared on completion.  If an I/O error occurs, SWAPBLK_NONE
>  * is set in the metadata for each page in the request.
>  */
> VM_OBJECT_WLOCK(object);
> /* This could be implemented more efficiently with aflags */
> while ((ma[0]->oflags & VPO_SWAPINPROG) != 0) {
> ma[0]->oflags |= VPO_SWAPSLEEP;
> VM_CNT_INC(v_intrans);
> if (VM_OBJECT_SLEEP(object, &object->handle, PSWP,
> "swread", hz * 20)) {
> printf(
> "swap_pager: indefinite wait buffer: bufobj: %p, blkno: %jd, size: %ld\n",
> bp->b_bufobj, (intmax_t)bp->b_blkno,
> bp->b_bcount);
> }
> }
> VM_OBJECT_WUNLOCK(object);
> . . .
>
> where:
>
> #define VM_OBJECT_SLEEP(object, wchan, pri, wmesg, timo)\
> rw_sleep((wchan), &(object)->lock, (pri), (wmesg), (timo))
>
> and:
>
> #define rw_sleep(chan, rw, pri, wmesg, timo)\
> _sleep((chan), &(rw)->lock_object, (pri), (wmesg),  \
> tick_sbt * (timo), 0, C_HARDCLOCK)
>
> (I do not claim to be able to interpret the implications
> of the code that leads to the m

Re: Filesystem operations slower in 13.0 than 12.2

[Mark Millard via freebsd-stable]

On 2021-Mar-14, at 11:09, Kevin Oberman  wrote:

> . . .
>  
> Seems to only occur on large r/w operations from/to the same disk. "sp
> big-file /other/file/on/same/disk" or tar/untar operations on large files.
> Hit this today updating firefox.
> 
> I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
> things while it was running slowly, the disk would appear to lock up. E.g.
> pwd(1) seemed to completely lock up the system, but I could still ping it
> and, after about 30 seconds, things came back to life. It was also not
> instantaneous. Disc activity dropped to <1MB/s for a few seconds before
> everything froze.
> 
> During the untar of firefox, I saw; this several times. I also looked at my
> console where I found these errors during :
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096

Does anyone know:
Are those messages normal "reading is taking a rather long
time" notices or is their presence more useful information
in some way about the type of problem or context for the
problem?

As for the tests:
Are these messages always present when near a time frame
when the problem occurs? Never present in a near time
frame to a period when the problem does not occur?

It appears that the messages are associated with reading
the disk(s), not directly with writing them, where the
reads take more than "hz * 20" time units to complete.
(I'm looking at main (14) code.) What might contribute
to the time taken for the pending read(s)?

/*
 * swap_pager_getpages() - bring pages in from swap
 *
 *  Attempt to page in the pages in array "ma" of length "count".  The
 *  caller may optionally specify that additional pages preceding and
 *  succeeding the specified range be paged in.  The number of such pages
 *  is returned in the "rbehind" and "rahead" parameters, and they will
 *  be in the inactive queue upon return.
 *
 *  The pages in "ma" must be busied and will remain busied upon return.
 */
static int
swap_pager_getpages_locked(vm_object_t object, vm_page_t *ma, int count,
int *rbehind, int *rahead)
{
. . .
/*
 * Wait for the pages we want to complete.  VPO_SWAPINPROG is always
 * cleared on completion.  If an I/O error occurs, SWAPBLK_NONE
 * is set in the metadata for each page in the request.
 */
VM_OBJECT_WLOCK(object);
/* This could be implemented more efficiently with aflags */
while ((ma[0]->oflags & VPO_SWAPINPROG) != 0) {
ma[0]->oflags |= VPO_SWAPSLEEP;
VM_CNT_INC(v_intrans);
if (VM_OBJECT_SLEEP(object, &object->handle, PSWP,
"swread", hz * 20)) {
printf(
"swap_pager: indefinite wait buffer: bufobj: %p, blkno: %jd, size: %ld\n",
bp->b_bufobj, (intmax_t)bp->b_blkno, bp->b_bcount);
}
}
VM_OBJECT_WUNLOCK(object);
. . .

where:

#define VM_OBJECT_SLEEP(object, wchan, pri, wmesg, timo)\
rw_sleep((wchan), &(object)->lock, (pri), (wmesg), (timo))

and:

#define rw_sleep(chan, rw, pri, wmesg, timo)\
_sleep((chan), &(rw)->lock_object, (pri), (wmesg),  \
tick_sbt * (timo), 0, C_HARDCLOCK)

(I do not claim to be able to interpret the implications
of the code that leads to the messages. But seeing some
of the code might prompt a thought by someone that knows
the code's context and operation.)

> . . .
> Backing off to Mar. 4 was not an improvement. My untar did seem better for a 
> couple of minutes, but then the display froze again for 30 seconds and disk 
> performance dropped to <1M.

You were able to see the disk performance drop while
the display was frozen?

It might not be the best for monitoring but I'll ask
this in terms of top output: Does Inact, Laundry,
Wired, Free, or other such show anything fairly unique
for around the problematical time frame(s)?

> then things got really bad and behaved in a manner that was baffling to me. 
> The screen froze again, but stayed frozen after half a minute. I clicked on a 
> couple of buttons in Firefox to no effect and then hit ctrl-q to quit. After 
> the long pause, I pressed the power button to try to force a shutdown. 
> Suddenly, it started unwinding everything I had done during the freeze. My 
> browser did the updates from my mouse clicks including quitting. It then 
> switched to a different workspace from ctrl-alt-right and did a clean 
> shutdown.  
> 
> Do I also have a graphics issue? Examining log files show no indication that 
> anything was happening. SMART shows no errors and reasonable values for 
> everything. No indication of a HW problem. The system performs well unless I 
> do something that tries a bulk disk data move. Building world takes about 75 
> minutes. I just have a very hard time building big

Re: Filesystem operations slower in 13.0 than 12.2

[Kevin Oberman]

On Sat, Mar 13, 2021 at 9:43 PM Kevin Oberman  wrote:

> No improvement with stable/13-n244880-cec3990d347.  It may be worse.
> worse. An attempt to unpack firefox-86.0.1,2 saw disk rates in the range
> of 800K to 2 MB/s range and with repeated 30 second freezes. I have no idea
> what made it so much worse, but I'm forced to start wondering if it could
> be a hardware issue. The disk drive was already replaced once due to a bad
> bearing. Went from a WD Black to a Seagate. Since it just keeps getting
> worse, I must consider that possibility. It is odd, though, that it was
> suddenly worse with the updated system.
>
> I think I will try going back to n244765-a00bf7d9bba (March 4) and see if
> it improves. If it does, I can likely eliminate bad hardware.
> --
> Kevin Oberman, Part time kid herder and retired Network Engineer
> E-mail: rkober...@gmail.com
> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>
>
> On Sat, Mar 13, 2021 at 6:00 PM Warner Losh  wrote:
>
>>
>>
>> On Sat, Mar 13, 2021 at 6:37 PM Kevin Oberman 
>> wrote:
>>
>>> I have been dealing with this for a long time since head back in
>>> September through 13-stable of Mar-4. I have seen no improvement over this
>>> time. It seems (my perception without supporting data) that it got worse in
>>> the timeframe of BETA-3 tag. I was running stable, so not quite BETA-3. It
>>> also does not help that I have also been bitten by the P-State related
>>> freeze issue which has some similarities. disabling p-states has almost
>>> eliminated this issue, though, with only three occurrences since I disabled
>>> them in late January.
>>>
>>>  As a result, I don't think it is a recent change, but a problem that
>>> has existed for at least 3 months. This was made worse by two hardware
>>> issues that kept the system unavailable for most of the time between buying
>>> it last spring and getting the keyboard replaced in January. (Both the
>>> mainboard and the disk drive had already been replaced.)  There was another
>>> slow I/O issue that I had assumed was the same as mine, but was reportedly
>>> fixed with BETA-4. A few are still seeing slow I/O, so I assume that there
>>> were different issues with I/O. Since CometLake systems seem pretty
>>> uncommon, it might be related to that.
>>>
>>
>> It was a change from last fall, or set of changes. RC1 or defintely RC2
>> has fixes to regain performance lost. If BETA4 was the last one you
>> evaluated, perhaps you could do a couple tests with RC2 now that it's out
>> to see if it is the same thing?
>>
>> Warner
>>
>>
>>> Kevin Oberman, Part time kid herder and retired Network Engineer
>>> E-mail: rkober...@gmail.com
>>> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>>>
>>>
>>> On Sat, Mar 13, 2021 at 4:36 PM Warner Losh  wrote:
>>>


 On Sat, Mar 13, 2021 at 5:33 PM Kevin Oberman 
 wrote:

> Just spent a little time looking at my issue and have a few more notes:
>

 What version did you evaluate? There's a number of changes lately that
 could have a big impact on this...

 Warner


> Seems to only occur on large r/w operations from/to the same disk. "sp
> big-file /other/file/on/same/disk" or tar/untar operations on large
> files.
> Hit this today updating firefox.
>
> I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
> things while it was running slowly, the disk would appear to lock up.
> E.g.
> pwd(1) seemed to completely lock up the system, but I could still ping
> it
> and, after about 30 seconds, things came back to life. It was also not
> instantaneous. Disc activity dropped to <1MB/s for a few seconds before
> everything froze.
>
> During the untar of firefox, I saw; this several times. I also looked
> at my
> console where I found these errors during :
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>
> I should note that some operations continue just fine while this is
> going
> on until I do something that freezes the system. I assume that this
> eliminates the disk drive and low-level driver. Is vfs a possible
> issue. It
> had some serious work in the past few months by markj. That does not
> explain why more people are not seeing this.
>
> I have been seeing this since at least September 2020, so it goes back
> a
> way. As this CometLake system will not run graphics on 12, I can't
> confirm
> operation before 13.
> --
> Kevin Oberman, Part time kid herder and retired Network Engineer
> E-mail: rkober...@gmail.com
> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>
>
> On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
> freebsd-stable@freebsd.org> wrote:
>
> >
> > Konstantin Belousov kostikbel at gmail.com w

Re: Filesystem operations slower in 13.0 than 12.2

[Kevin Oberman]

No improvement with stable/13-n244880-cec3990d347.  It may be worse. worse.
An attempt to unpack firefox-86.0.1,2 saw disk rates in the range of 800K
to 2 MB/s range and with repeated 30 second freezes. I have no idea what
made it so much worse, but I'm forced to start wondering if it could be a
hardware issue. The disk drive was already replaced once due to a bad
bearing. Went from a WD Black to a Seagate. Since it just keeps getting
worse, I must consider that possibility. It is odd, though, that it was
suddenly worse with the updated system.

I think I will try going back to n244765-a00bf7d9bba (March 4) and see if
it improves. If it does, I can likely eliminate bad hardware.
--
Kevin Oberman, Part time kid herder and retired Network Engineer
E-mail: rkober...@gmail.com
PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683


On Sat, Mar 13, 2021 at 6:00 PM Warner Losh  wrote:

>
>
> On Sat, Mar 13, 2021 at 6:37 PM Kevin Oberman  wrote:
>
>> I have been dealing with this for a long time since head back in
>> September through 13-stable of Mar-4. I have seen no improvement over this
>> time. It seems (my perception without supporting data) that it got worse in
>> the timeframe of BETA-3 tag. I was running stable, so not quite BETA-3. It
>> also does not help that I have also been bitten by the P-State related
>> freeze issue which has some similarities. disabling p-states has almost
>> eliminated this issue, though, with only three occurrences since I disabled
>> them in late January.
>>
>>  As a result, I don't think it is a recent change, but a problem that has
>> existed for at least 3 months. This was made worse by two hardware issues
>> that kept the system unavailable for most of the time between buying it
>> last spring and getting the keyboard replaced in January. (Both the
>> mainboard and the disk drive had already been replaced.)  There was another
>> slow I/O issue that I had assumed was the same as mine, but was reportedly
>> fixed with BETA-4. A few are still seeing slow I/O, so I assume that there
>> were different issues with I/O. Since CometLake systems seem pretty
>> uncommon, it might be related to that.
>>
>
> It was a change from last fall, or set of changes. RC1 or defintely RC2
> has fixes to regain performance lost. If BETA4 was the last one you
> evaluated, perhaps you could do a couple tests with RC2 now that it's out
> to see if it is the same thing?
>
> Warner
>
>
>> Kevin Oberman, Part time kid herder and retired Network Engineer
>> E-mail: rkober...@gmail.com
>> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>>
>>
>> On Sat, Mar 13, 2021 at 4:36 PM Warner Losh  wrote:
>>
>>>
>>>
>>> On Sat, Mar 13, 2021 at 5:33 PM Kevin Oberman 
>>> wrote:
>>>
 Just spent a little time looking at my issue and have a few more notes:

>>>
>>> What version did you evaluate? There's a number of changes lately that
>>> could have a big impact on this...
>>>
>>> Warner
>>>
>>>
 Seems to only occur on large r/w operations from/to the same disk. "sp
 big-file /other/file/on/same/disk" or tar/untar operations on large
 files.
 Hit this today updating firefox.

 I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
 things while it was running slowly, the disk would appear to lock up.
 E.g.
 pwd(1) seemed to completely lock up the system, but I could still ping
 it
 and, after about 30 seconds, things came back to life. It was also not
 instantaneous. Disc activity dropped to <1MB/s for a few seconds before
 everything froze.

 During the untar of firefox, I saw; this several times. I also looked
 at my
 console where I found these errors during :
 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096

 I should note that some operations continue just fine while this is
 going
 on until I do something that freezes the system. I assume that this
 eliminates the disk drive and low-level driver. Is vfs a possible
 issue. It
 had some serious work in the past few months by markj. That does not
 explain why more people are not seeing this.

 I have been seeing this since at least September 2020, so it goes back a
 way. As this CometLake system will not run graphics on 12, I can't
 confirm
 operation before 13.
 --
 Kevin Oberman, Part time kid herder and retired Network Engineer
 E-mail: rkober...@gmail.com
 PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683


 On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
 freebsd-stable@freebsd.org> wrote:

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

Re: Filesystem operations slower in 13.0 than 12.2

[Warner Losh]

On Sat, Mar 13, 2021 at 6:37 PM Kevin Oberman  wrote:

> I have been dealing with this for a long time since head back in September
> through 13-stable of Mar-4. I have seen no improvement over this time. It
> seems (my perception without supporting data) that it got worse in the
> timeframe of BETA-3 tag. I was running stable, so not quite BETA-3. It also
> does not help that I have also been bitten by the P-State related freeze
> issue which has some similarities. disabling p-states has almost eliminated
> this issue, though, with only three occurrences since I disabled them in
> late January.
>
>  As a result, I don't think it is a recent change, but a problem that has
> existed for at least 3 months. This was made worse by two hardware issues
> that kept the system unavailable for most of the time between buying it
> last spring and getting the keyboard replaced in January. (Both the
> mainboard and the disk drive had already been replaced.)  There was another
> slow I/O issue that I had assumed was the same as mine, but was reportedly
> fixed with BETA-4. A few are still seeing slow I/O, so I assume that there
> were different issues with I/O. Since CometLake systems seem pretty
> uncommon, it might be related to that.
>

It was a change from last fall, or set of changes. RC1 or defintely RC2 has
fixes to regain performance lost. If BETA4 was the last one you evaluated,
perhaps you could do a couple tests with RC2 now that it's out to see if it
is the same thing?

Warner


> Kevin Oberman, Part time kid herder and retired Network Engineer
> E-mail: rkober...@gmail.com
> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>
>
> On Sat, Mar 13, 2021 at 4:36 PM Warner Losh  wrote:
>
>>
>>
>> On Sat, Mar 13, 2021 at 5:33 PM Kevin Oberman 
>> wrote:
>>
>>> Just spent a little time looking at my issue and have a few more notes:
>>>
>>
>> What version did you evaluate? There's a number of changes lately that
>> could have a big impact on this...
>>
>> Warner
>>
>>
>>> Seems to only occur on large r/w operations from/to the same disk. "sp
>>> big-file /other/file/on/same/disk" or tar/untar operations on large
>>> files.
>>> Hit this today updating firefox.
>>>
>>> I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
>>> things while it was running slowly, the disk would appear to lock up.
>>> E.g.
>>> pwd(1) seemed to completely lock up the system, but I could still ping it
>>> and, after about 30 seconds, things came back to life. It was also not
>>> instantaneous. Disc activity dropped to <1MB/s for a few seconds before
>>> everything froze.
>>>
>>> During the untar of firefox, I saw; this several times. I also looked at
>>> my
>>> console where I found these errors during :
>>> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
>>> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>>>
>>> I should note that some operations continue just fine while this is going
>>> on until I do something that freezes the system. I assume that this
>>> eliminates the disk drive and low-level driver. Is vfs a possible issue.
>>> It
>>> had some serious work in the past few months by markj. That does not
>>> explain why more people are not seeing this.
>>>
>>> I have been seeing this since at least September 2020, so it goes back a
>>> way. As this CometLake system will not run graphics on 12, I can't
>>> confirm
>>> operation before 13.
>>> --
>>> Kevin Oberman, Part time kid herder and retired Network Engineer
>>> E-mail: rkober...@gmail.com
>>> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>>>
>>>
>>> On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
>>> freebsd-stable@freebsd.org> wrote:
>>>
>>> >
>>> > 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 

Re: Filesystem operations slower in 13.0 than 12.2

[Kevin Oberman]

I have been dealing with this for a long time since head back in September
through 13-stable of Mar-4. I have seen no improvement over this time. It
seems (my perception without supporting data) that it got worse in the
timeframe of BETA-3 tag. I was running stable, so not quite BETA-3. It also
does not help that I have also been bitten by the P-State related freeze
issue which has some similarities. disabling p-states has almost eliminated
this issue, though, with only three occurrences since I disabled them in
late January.

 As a result, I don't think it is a recent change, but a problem that has
existed for at least 3 months. This was made worse by two hardware issues
that kept the system unavailable for most of the time between buying it
last spring and getting the keyboard replaced in January. (Both the
mainboard and the disk drive had already been replaced.)  There was another
slow I/O issue that I had assumed was the same as mine, but was reportedly
fixed with BETA-4. A few are still seeing slow I/O, so I assume that there
were different issues with I/O. Since CometLake systems seem pretty
uncommon, it might be related to that.

Kevin Oberman, Part time kid herder and retired Network Engineer
E-mail: rkober...@gmail.com
PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683


On Sat, Mar 13, 2021 at 4:36 PM Warner Losh  wrote:

>
>
> On Sat, Mar 13, 2021 at 5:33 PM Kevin Oberman  wrote:
>
>> Just spent a little time looking at my issue and have a few more notes:
>>
>
> What version did you evaluate? There's a number of changes lately that
> could have a big impact on this...
>
> Warner
>
>
>> Seems to only occur on large r/w operations from/to the same disk. "sp
>> big-file /other/file/on/same/disk" or tar/untar operations on large files.
>> Hit this today updating firefox.
>>
>> I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
>> things while it was running slowly, the disk would appear to lock up. E.g.
>> pwd(1) seemed to completely lock up the system, but I could still ping it
>> and, after about 30 seconds, things came back to life. It was also not
>> instantaneous. Disc activity dropped to <1MB/s for a few seconds before
>> everything froze.
>>
>> During the untar of firefox, I saw; this several times. I also looked at
>> my
>> console where I found these errors during :
>> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
>> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>>
>> I should note that some operations continue just fine while this is going
>> on until I do something that freezes the system. I assume that this
>> eliminates the disk drive and low-level driver. Is vfs a possible issue.
>> It
>> had some serious work in the past few months by markj. That does not
>> explain why more people are not seeing this.
>>
>> I have been seeing this since at least September 2020, so it goes back a
>> way. As this CometLake system will not run graphics on 12, I can't confirm
>> operation before 13.
>> --
>> Kevin Oberman, Part time kid herder and retired Network Engineer
>> E-mail: rkober...@gmail.com
>> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>>
>>
>> On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
>> freebsd-stable@freebsd.org> wrote:
>>
>> >
>> > 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
>> 

Re: Filesystem operations slower in 13.0 than 12.2

[Warner Losh]

On Sat, Mar 13, 2021 at 5:33 PM Kevin Oberman  wrote:

> Just spent a little time looking at my issue and have a few more notes:
>

What version did you evaluate? There's a number of changes lately that
could have a big impact on this...

Warner


> Seems to only occur on large r/w operations from/to the same disk. "sp
> big-file /other/file/on/same/disk" or tar/untar operations on large files.
> Hit this today updating firefox.
>
> I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
> things while it was running slowly, the disk would appear to lock up. E.g.
> pwd(1) seemed to completely lock up the system, but I could still ping it
> and, after about 30 seconds, things came back to life. It was also not
> instantaneous. Disc activity dropped to <1MB/s for a few seconds before
> everything froze.
>
> During the untar of firefox, I saw; this several times. I also looked at my
> console where I found these errors during :
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
> swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096
>
> I should note that some operations continue just fine while this is going
> on until I do something that freezes the system. I assume that this
> eliminates the disk drive and low-level driver. Is vfs a possible issue. It
> had some serious work in the past few months by markj. That does not
> explain why more people are not seeing this.
>
> I have been seeing this since at least September 2020, so it goes back a
> way. As this CometLake system will not run graphics on 12, I can't confirm
> operation before 13.
> --
> Kevin Oberman, Part time kid herder and retired Network Engineer
> E-mail: rkober...@gmail.com
> PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683
>
>
> On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
> freebsd-stable@freebsd.org> wrote:
>
> >
> > 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
> "
> >
> ___
> 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"
>
___
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

[Kevin Oberman]

Just spent a little time looking at my issue and have a few more notes:

Seems to only occur on large r/w operations from/to the same disk. "sp
big-file /other/file/on/same/disk" or tar/untar operations on large files.
Hit this today updating firefox.

I/O starts at >40MB/s. Dropped to about 1.5MB/s. If I tried doing other
things while it was running slowly, the disk would appear to lock up. E.g.
pwd(1) seemed to completely lock up the system, but I could still ping it
and, after about 30 seconds, things came back to life. It was also not
instantaneous. Disc activity dropped to <1MB/s for a few seconds before
everything froze.

During the untar of firefox, I saw; this several times. I also looked at my
console where I found these errors during :
swap_pager: indefinite wait buffer: bufobj: 0, blkno: 55043, size: 8192
swap_pager: indefinite wait buffer: bufobj: 0, blkno: 51572, size: 4096

I should note that some operations continue just fine while this is going
on until I do something that freezes the system. I assume that this
eliminates the disk drive and low-level driver. Is vfs a possible issue. It
had some serious work in the past few months by markj. That does not
explain why more people are not seeing this.

I have been seeing this since at least September 2020, so it goes back a
way. As this CometLake system will not run graphics on 12, I can't confirm
operation before 13.
--
Kevin Oberman, Part time kid herder and retired Network Engineer
E-mail: rkober...@gmail.com
PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683


On Fri, Mar 5, 2021 at 10:47 PM Mark Millard via freebsd-stable <
freebsd-stable@freebsd.org> wrote:

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

[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&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 inp

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"

Re: Filesystem operations slower in 13.0 than 12.2

[Mark Millard via freebsd-stable]

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

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

(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 input operations
> 621229  block output operations
>   4412  messages sent
>2536379  messages received
>  0  signals received
>1004790  voluntary context switches
>251  involuntary context switches
> 
> --
> 
> FreeBSD 13.0-BETA4 (2021-02-26)
> 
>   163.81 real71.93 user   107.32 sys
>  49032  maximum resident set size
> 21  average shared memory size
>  3  average unshared data size
> 89  average unshared stack size
>   12288156  page reclaims
>  5  page faults
>  0  swaps
>716  block input operations
>868  block output operations
>   4412  messages sent
>2536379  messages received
>  0  signals received
> 355244  voluntary context switches
>277  involuntary context switches
> 
> --
> 
> FreeBSD 14-CURRENT (2021-03-04)
> 
>   255.43 real74.94 user   148.90 sys
>  49032  maximum resident set size
> 23  average shared memory size
>  3  average unshared data size
> 96  average unshared stack size
>   12288156  page reclaims
> 23  page faults
>  0  swaps
>  31207  block input operations
>175  block output operations
>   4412  messages sent
>2536379  messages received
>  0  signals received
> 385527  voluntary context switches
>369  involuntary context switches
> 
> --
> 
> Differences between 13.0 and 14-CURRENT maybe related to debugging features.
> 
> But 13.0-BETA4 is slower than 12.2. Does someone have more in