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

[Dmitry Gutov <dmitry@gutov.dev>]

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

On 10/09/2023 08:33, Eli Zaretskii wrote:
>> Date: Sun, 10 Sep 2023 04:30:24 +0300
>> Cc: luangruo@yahoo.com, sbaugh@janestreet.com, yantar92@posteo.net,
>>   64735@debbugs.gnu.org
>> From: Dmitry Gutov <dmitry@gutov.dev>
>>
>> On 08/09/2023 09:35, Eli Zaretskii wrote:
>>> I think you'd need to expose consing_until_gc to Lisp, and then you
>>> can collect the data from Lisp.
>>
>> I can expose it to Lisp and print all three from post-gc-hook, but the
>> result just looks like this:
>>
>> gc-pct 0.1 gc-thr 800000 cugc 4611686018427387903
>>
>> Perhaps I need to add a hook which runs at the beginning of GC? Or of
>> maybe_gc even?
> 
> 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. What we could perhaps do is 
add another hook (or a printer) at the beginning of maybe_gc, but either 
would result in lots and lots of output.

>> Alternatively, (memory-use-counts) seems to retain some counters which
>> don't get erased during garbage collection.
> 
> Maybe using those will be good enough, indeed.

I added this instrumentation:

(defvar last-mem-counts '(0 0 0 0 0 0 0))

(defun gc-record-after ()
   (let* ((counts (memory-use-counts))
          (diff (cl-map 'list
                        (lambda (old new) (- new old))
                        last-mem-counts counts)))
     (setq last-mem-counts counts)
     (message "counts diff %s" diff)))

(add-hook 'post-gc-hook #'gc-record-after)

so that after each garbage collection we print the differences in all 
counters (CONSES FLOATS VECTOR-CELLS SYMBOLS STRING-CHARS INTERVALS 
STRINGS).

And a message call when the process finishes.

And made those recordings during the benchmark runs of two different 
listing methods (one using make-process, another using process-file) to 
list all files in a large directory (there are ~200000 files there).

The make-process one I also ran with a different (large) value of 
read-process-output-max. Results attached.

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?

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.

So there is also a second recording for 
find-directory-files-recursively-2 with read-process-output-max=409600. 
It does improve the performance significantly (and reduce the number of 
GC pauses). I guess what I'm still not clear on, is whether the number 
of GC pauses is fewer because of less consing (the only column that 
looks significantly different is the 3rd: VECTOR-CELLS), or because the 
process finishes faster due to larger buffers, which itself causes fewer 
calls to maybe_gc.

And, of course, what else could be done to reduce the time spent in GC 
in the asynchronous case.

[-- Attachment #2: gcs2.txt --]
[-- Type: text/plain, Size: 2184 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
counts diff (75840 13 31177 60 343443 3496 4748)
counts diff (41946 1 460 0 1226494 0 8425)
counts diff (43165 1 450 0 1284214 0 8951)
counts diff (43513 1 364 0 1343316 0 10125)
counts diff (43200 1 384 0 1479048 0 9766)
counts diff (46220 1 428 0 1528863 0 10242)
counts diff (43125 1 462 0 1767068 0 8790)
counts diff (49118 1 458 0 1723271 0 10832)
counts diff (53156 1 572 0 1789919 0 10774)
counts diff (57755 1 548 0 1783286 0 12600)
counts diff (62171 1 554 0 1795216 0 13995)
counts diff (62020 1 550 0 1963255 0 13996)
counts diff (54559 1 616 0 2387308 0 10700)
counts diff (56428 1 634 0 2513219 0 11095)
counts diff (62611 1 658 0 2510756 0 12864)
counts diff (67560 1 708 0 2574312 0 13899)
counts diff (78154 1 928 0 2572273 0 14714)
counts diff (86794 1 976 0 2520915 0 17004)
counts diff (78112 1 874 0 2943548 0 15367)
counts diff (79443 1 894 0 3138948 0 15559)
counts diff (81861 1 984 0 3343764 0 15260)
counts diff (87724 1 1030 0 3430969 0 16650)
counts diff (88532 1 902 0 3591052 0 18487)
counts diff (92083 1 952 0 3769290 0 19065)
<finished\n>
Elapsed time: 1.344422s (0.747126s in 24 GCs)

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

start now
counts diff (57967 1 4040 1 981912 106 7731)
counts diff (32075 1 20 0 1919096 0 10560)
counts diff (43431 1 18 0 2259314 0 14371)
counts diff (46335 1 18 0 2426290 0 15339)
counts diff (31872 1 18 0 2447639 0 10518)
counts diff (46527 1 18 0 2328042 0 15403)
counts diff (42468 1 18 0 2099976 0 14050)
counts diff (48648 1 18 0 2302713 0 16110)
counts diff (50404 1 20 0 3260921 0 16669)
counts diff (40147 1 20 0 3264463 0 13251)
counts diff (48118 1 20 0 3261725 0 15908)
counts diff (60732 1 282 0 2791003 0 16785)
counts diff (71329 1 506 0 2762237 0 17487)
counts diff (61455 1 342 0 3192771 0 16271)
counts diff (49035 1 30 0 3663715 0 16085)
counts diff (58651 1 236 0 3783888 0 16683)
counts diff (57132 1 24 0 4557688 0 18862)
counts diff (71319 1 24 0 4769891 0 23591)
<finished\n>
Elapsed time: 0.890710s (0.546486s in 18 GCs)

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

find-directory-files-recursively-3

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

start now
<process finished, now parsing>
counts diff (62771 5 26629 63 458211 3223 8038)
counts diff (17045 1 12 0 1288153 0 16949)
counts diff (18301 1 12 0 1432165 0 18205)
counts diff (17643 1 12 0 1716294 0 17547)
counts diff (21917 1 12 0 1726462 0 21821)
counts diff (25888 1 12 0 1777371 0 25792)
counts diff (21743 1 12 0 2345143 0 21647)
counts diff (24035 1 12 0 2561491 0 23939)
counts diff (30028 1 12 0 2593069 0 29932)
counts diff (29627 1 12 0 3041307 0 29531)
counts diff (30140 1 12 0 3479209 0 30044)
counts diff (35181 1 12 0 3690480 0 35085)
Elapsed time: 0.943090s (0.351799s in 12 GCs)