bug#64735: 29.0.92; find invocations are ~15x slower because of ignores

[Dmitry Gutov <dmitry@gutov.dev>]

[-- Attachment #1: Type: text/plain, Size: 2757 bytes --]

On 11/09/2023 14:57, Eli Zaretskii wrote:
>> Date: Mon, 11 Sep 2023 03:02:55 +0300
>> Cc: luangruo@yahoo.com, sbaugh@janestreet.com, yantar92@posteo.net,
>>   64735@debbugs.gnu.org
>> From: Dmitry Gutov <dmitry@gutov.dev>
>>
>>> You could record its value in a local variable at the entry to
>>> garbage_collect, and the expose that value to Lisp.
>>
>> That also doesn't seem to give much, given that the condition for
>> entering 'maybe_garbage_collect' is (consing_until_gc < 0). I.e. we wait
>> until it's down to 0, then garbage-collect.
> 
> No, we don't wait until it's zero, we perform GC on the first
> opportunity that we _notice_ that it crossed zero.  So examining how
> negative is the value of consing_until_gc when GC is actually
> performed could tell us whether we checked the threshold with high
> enough frequency, and comparing these values between different runs
> could tell us whether the shorter time spend in GC means really less
> garbage or less frequent checks for the need to GC.

Good point, I'm attaching the same outputs with "last value of 
consing_until_gc" added to every line.

There are some pretty low values in the "read-process-output-max 409600" 
part of the experiment, which probably means runtime staying in C 
accumulating the output into the (now larger) buffer? Not sure.

>> What's in there? First of all, for find-directory-files-recursively-3,
>> there are 0 garbage collections between the beginning of the function
>> and when we start parsing the output (no GCs while the process is
>> writing to the buffer synchronously). I guess inserting output in a
>> buffer doesn't increase consing, so there's nothing to GC?
> 
> No, we just don't count increasing size of buffer text in the "consing
> since GC" counter.  Basically, buffer text is never "garbage", except
> when a buffer is killed.

That makes sense. Perhaps it hints at a faster design for calling 
process asynchronously as well (more on another experiment later).

>> Next: for find-directory-files-recursively-2, the process only finishes
>> at the end, when all GC cycles are done for. I suppose that also means
>> we block the process's output while Lisp is running, and also that
>> whatever GC events occur might coincide with the chunks of output coming
>> from the process, and however many of them turn out to be in total.
> 
> We don't block the process when GC runs.  We do stop reading from the
> process, so if and when the pipe fills, the OS will block the process.

Right. But the effect is almost the same, including the potential 
side-effect that (IIUC) when a process is waiting like that, it's just 
suspended and not rushing ahead using the CPU/disk/etc resources to the 
max. That's an orthogonal train of thought, sorry.

[-- Attachment #2: gcs2b.txt --]
[-- Type: text/plain, Size: 3284 bytes --]

find-directory-files-recursively-2

Uses make-process and :filter to parse the output
concurrently with the process.

With (read-process-output-max 4096):

start now
cugc -2560 counts diff (42345 3 14097 2 408583 1966 4479)
cugc -4449 counts diff (24599 1 342 0 883247 0 6266)
cugc -100 counts diff (24070 1 354 0 977387 0 6009)
cugc -116 counts diff (27266 1 278 0 940723 0 7485)
cugc -95 counts diff (27486 1 270 0 1014591 0 7586)
cugc -117 counts diff (27157 1 294 0 1121065 0 7329)
cugc -146 counts diff (28233 1 316 0 1185527 0 7562)
cugc -143 counts diff (30597 1 354 0 1217320 0 8147)
cugc -4807 counts diff (25925 1 380 0 1474618 0 6407)
cugc -127 counts diff (33344 1 368 0 1341453 0 8965)
cugc -177 counts diff (34785 1 478 0 1434432 0 8842)
cugc -2801 counts diff (37069 1 464 0 1477825 0 9675)
cugc -23 counts diff (40817 1 448 0 1478445 0 10999)
cugc -1215 counts diff (44526 1 500 0 1503604 0 11964)
cugc -4189 counts diff (42305 1 468 0 1701989 0 11354)
cugc -4715 counts diff (36644 1 532 0 2036778 0 9082)
cugc -85 counts diff (38234 1 542 0 2131756 0 9535)
cugc -861 counts diff (41632 1 578 0 2188186 0 10474)
cugc -117 counts diff (46029 1 580 0 2211685 0 11921)
cugc -38 counts diff (50353 1 728 0 2280388 0 12568)
cugc -2537 counts diff (57168 1 888 0 2286381 0 13974)
cugc -3676 counts diff (61570 1 924 0 2341402 0 15246)
cugc -174 counts diff (56504 1 924 0 2689300 0 13502)
cugc -1001 counts diff (57066 1 842 0 2855028 0 14098)
cugc -146 counts diff (57716 1 916 0 3063238 0 13891)
cugc -148 counts diff (62868 1 982 0 3139111 0 15244)
cugc -1730 counts diff (64809 1 856 0 3283855 0 16535)
cugc -162 counts diff (69183 1 870 0 3394031 0 17902)
<finished\n>
total chunks 6652
Elapsed time: 1.233016s (0.668819s in 28 GCs)

And here's with (read-process-output-max 409600):

start now
cugc -12 counts diff (59160 5 22547 116 155434 2046 2103)
cugc -154001 counts diff (18671 1 16 0 1034538 0 6172)
cugc -100 counts diff (20250 1 14 0 1003966 0 6708)
cugc -190294 counts diff (19623 1 16 0 1244441 0 6489)
cugc -58 counts diff (26160 1 14 0 1015128 0 8678)
cugc -293067 counts diff (22737 1 16 0 1426874 0 7527)
cugc -92 counts diff (28308 1 14 0 1160213 0 9394)
cugc -25 counts diff (21620 1 16 0 1535686 0 7153)
cugc -21 counts diff (23251 1 16 0 1554720 0 7698)
cugc -143 counts diff (29988 1 16 0 1462639 0 9943)
cugc -117 counts diff (28827 1 16 0 1622562 0 9556)
cugc -26 counts diff (33959 1 16 0 1606815 0 11266)
cugc -17 counts diff (37476 1 16 0 1639853 0 12439)
cugc -250992 counts diff (31345 1 18 0 2081663 0 10383)
cugc -289142 counts diff (29904 1 18 0 2448410 0 9901)
cugc -290227 counts diff (30675 1 18 0 2448156 0 10159)
cugc -264315 counts diff (35418 1 18 0 2446508 0 11741)
cugc -32 counts diff (41741 1 18 0 2343900 0 13847)
cugc -2201 counts diff (44523 1 112 0 2478310 0 14239)
cugc -15673 counts diff (49622 1 170 0 2528221 0 15592)
cugc -40267 counts diff (41990 1 58 0 2972015 0 13693)
cugc -159 counts diff (41010 1 22 0 3177994 0 13580)
cugc -42 counts diff (47602 1 156 0 3259833 0 15009)
cugc -358884 counts diff (43740 1 34 0 3687145 0 14436)
cugc -22 counts diff (55598 1 20 0 3494190 0 18454)
cugc -1270 counts diff (60128 1 190 0 3683461 0 18980)
<finished\n>
total chunks 273
Elapsed time: 0.932625s (0.608713s in 26 GCs)

[-- Attachment #3: gcs3b.txt --]
[-- Type: text/plain, Size: 929 bytes --]

find-directory-files-recursively-3

Uses process-file, parses the buffer
with search-forward at the end.

start now
<process finished, now parsing>
cugc -129 counts diff (17667 1 1565 1 779081 93 10465)
cugc -139 counts diff (12789 1 12 0 912364 0 12696)
cugc -84 counts diff (13496 1 12 0 1028060 0 13403)
cugc -33 counts diff (14112 1 12 0 1168522 0 14019)
cugc -153 counts diff (14354 1 12 0 1347241 0 14261)
cugc -72 counts diff (17005 1 12 0 1401075 0 16912)
cugc -17 counts diff (20810 1 12 0 1403396 0 20717)
cugc -94 counts diff (18516 1 12 0 1792508 0 18423)
cugc -120 counts diff (17981 1 12 0 2108458 0 17888)
cugc -50 counts diff (22090 1 12 0 2169835 0 21997)
cugc -136 counts diff (26749 1 12 0 2231037 0 26656)
cugc -93 counts diff (25300 1 12 0 2687843 0 25207)
cugc -72 counts diff (26165 1 12 0 3046140 0 26072)
cugc -142 counts diff (30968 1 12 0 3205306 0 30875)
Elapsed time: 0.938180s (0.314630s in 14 GCs)