From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: Dmitry Gutov Newsgroups: gmane.emacs.bugs Subject: bug#64735: 29.0.92; find invocations are ~15x slower because of ignores Date: Sun, 30 Jul 2023 04:35:49 +0300 Message-ID: References: <1fd5e3ed-e1c3-5d6e-897f-1d5d55e379fa@gutov.dev> <87wmyupvlw.fsf@localhost> <5c4d9bea-3eb9-b262-138a-4ea0cb203436@gutov.dev> <87tttypp2e.fsf@localhost> <87r0p030w0.fsf@yahoo.com> <83sf9f6wm0.fsf@gnu.org> <83sf9eub9d.fsf@gnu.org> <2d844a34-857d-3d59-b897-73372baac480@gutov.dev> <83bkg2tsu6.fsf@gnu.org> <83bd4246-ac41-90ec-1df3-02d0bd59ca44@gutov.dev> <834jlttv1p.fsf@gnu.org> <937c3b8e-7742-91b7-c2cf-4cadd0782f0c@gutov.dev> <83a5vlsanw.fsf@gnu.org> <69a98e2a-5816-d36b-9d04-8609291333cd@gutov.dev> <87351cs8no.fsf@localhost> <35163e56-607d-9c5b-e3e8-5d5b548b3cb7@gutov.dev> <878rb3m43b.fsf@localhost> <83v8e6lyi4.fsf@gnu.org> <35f8b664-0241-9f96-1aa0-20ca51b2d34c@gutov.dev> <59c30342-a7e0-d83b-a128-0faae4cbd633@gutov.dev> <83pm4bi6qa.fsf@gnu.org> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="21357"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.13.0 Cc: luangruo@yahoo.com, sbaugh@janestreet.com, yantar92@posteo.net, 64735@debbugs.gnu.org To: Eli Zaretskii Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Sun Jul 30 03:38:49 2023 Return-path: Envelope-to: geb-bug-gnu-emacs@m.gmane-mx.org Original-Received: from lists.gnu.org ([209.51.188.17]) by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1qPvOS-0005Pz-Hc for geb-bug-gnu-emacs@m.gmane-mx.org; Sun, 30 Jul 2023 03:38:49 +0200 Original-Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1qPvMn-0008Ac-4F; Sat, 29 Jul 2023 21:37:05 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1qPvMl-0008AT-3o for bug-gnu-emacs@gnu.org; Sat, 29 Jul 2023 21:37:03 -0400 Original-Received: from debbugs.gnu.org ([2001:470:142:5::43]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1qPvMk-0001NQ-Dj for bug-gnu-emacs@gnu.org; Sat, 29 Jul 2023 21:37:02 -0400 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1qPvMj-0001Er-Mu for bug-gnu-emacs@gnu.org; Sat, 29 Jul 2023 21:37:01 -0400 X-Loop: help-debbugs@gnu.org Resent-From: Dmitry Gutov Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Sun, 30 Jul 2023 01:37:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 64735 X-GNU-PR-Package: emacs Original-Received: via spool by 64735-submit@debbugs.gnu.org id=B64735.16906809624695 (code B ref 64735); Sun, 30 Jul 2023 01:37:01 +0000 Original-Received: (at 64735) by debbugs.gnu.org; 30 Jul 2023 01:36:02 +0000 Original-Received: from localhost ([127.0.0.1]:49110 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1qPvLl-0001DU-Kb for submit@debbugs.gnu.org; Sat, 29 Jul 2023 21:36:02 -0400 Original-Received: from out2-smtp.messagingengine.com ([66.111.4.26]:44143) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1qPvLi-0001D9-Mf for 64735@debbugs.gnu.org; Sat, 29 Jul 2023 21:35:59 -0400 Original-Received: from compute3.internal (compute3.nyi.internal [10.202.2.43]) by mailout.nyi.internal (Postfix) with ESMTP id 747DF5C009A; Sat, 29 Jul 2023 21:35:53 -0400 (EDT) Original-Received: from mailfrontend1 ([10.202.2.162]) by compute3.internal (MEProxy); Sat, 29 Jul 2023 21:35:53 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gutov.dev; h=cc :cc:content-transfer-encoding:content-type:content-type:date :date:from:from:in-reply-to:in-reply-to:message-id:mime-version :references:reply-to:sender:subject:subject:to:to; s=fm2; t= 1690680953; x=1690767353; bh=YgxU7i11/XCn0vDsz5JhY3gGnIHKv6/VfGQ 6I0trznE=; b=VvKi7r4z/9L5coIKMDCVXvr2+rVOq3hH1Fa/5+L/9blEMwDS9b6 nkv5yZBBufAn1t1kNY9NiNzkGFKXcaQAEz9YuMpbAWg+vpt+9IEdYXTdXQv3ALv5 Z7xM1M4b5h9PTeqf2i88/hfTIKh1XCxpx/fDLEy/vltlfIu8cnU7F++BzRi2aE25 tBr/p8BzhcPUUOpDi4ZxEcyLUPHRcW2e1b2iRvWLkZCjQzou5HRmFtOzzP3PdRyR ed58C+TlvctmE/MKX2R21dZjHfCguUdLFj01ZAhehrOtGthJnQ0xns6jek8QwuvN 65i4j2PZWkKmXvkIKjeCbx+AXa07SnC6oZA== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=cc:cc:content-transfer-encoding :content-type:content-type:date:date:feedback-id:feedback-id :from:from:in-reply-to:in-reply-to:message-id:mime-version :references:reply-to:sender:subject:subject:to:to:x-me-proxy :x-me-proxy:x-me-sender:x-me-sender:x-sasl-enc; s=fm3; t= 1690680953; x=1690767353; bh=YgxU7i11/XCn0vDsz5JhY3gGnIHKv6/VfGQ 6I0trznE=; b=yn7ctk9vTJeIXvLKYh7VfMfLSWHGPu9Wu/NqkvziZuacn2bGchO LoL236dS7gzG295xQiGCmLugTK7yiII4yvlw5RQe1o2Rx7/d9k5DdcpBSzmCN9zX U7HZjlws/vOwDsW/mGw5nSzd7jEtYIPayxJ6oe0rJ7ZCdsdt5TtEXY/YKeKBPd1J n+G8BPtU19ecm8o4XpCJWhcbWG8wUVBoDTKZEx9JDS8rlr69f9W48pje2vuk/yQB zvXlPkBw0k85gA6C5IDRArWQYb2f5K/sAqcpnBhgHUOG/sVElaB/UP5t/iein7wF utEk1IcQuG+1F58No+BfSKzAb1mSd27nJNg== X-ME-Sender: X-ME-Received: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedviedrieelgdegjecutefuodetggdotefrodftvf curfhrohhfihhlvgemucfhrghsthforghilhdpqfgfvfdpuffrtefokffrpgfnqfghnecu uegrihhlohhuthemuceftddtnecusecvtfgvtghiphhivghnthhsucdlqddutddtmdenuc fjughrpefkffggfgfuvfevfhfhjggtgfesthejredttdefjeenucfhrhhomhepffhmihht rhihucfiuhhtohhvuceoughmihhtrhihsehguhhtohhvrdguvghvqeenucggtffrrghtth gvrhhnpeeigfetveehveevffehledtueekieeikeeufeegudfgfeeghfdulefgfeevledv veenucevlhhushhtvghrufhiiigvpedtnecurfgrrhgrmhepmhgrihhlfhhrohhmpegumh hithhrhiesghhuthhovhdruggvvh X-ME-Proxy: Feedback-ID: i0e71465a:Fastmail Original-Received: by mail.messagingengine.com (Postfix) with ESMTPA; Sat, 29 Jul 2023 21:35:51 -0400 (EDT) Content-Language: en-US In-Reply-To: <83pm4bi6qa.fsf@gnu.org> X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-gnu-emacs@gnu.org List-Id: "Bug reports for GNU Emacs, the Swiss army knife of text editors" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Original-Sender: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Xref: news.gmane.io gmane.emacs.bugs:266346 Archived-At: On 29/07/2023 09:15, Eli Zaretskii wrote: >> Date: Sat, 29 Jul 2023 03:12:34 +0300 >> From: Dmitry Gutov >> Cc: luangruo@yahoo.com, sbaugh@janestreet.com, yantar92@posteo.net, >> 64735@debbugs.gnu.org >> >> It seems like per-chunk overhead is non-trivial, and affects GC somehow >> (but not in a way that just any string would). >> >> In this test, by default, the output produces ~6000 strings and passes >> them to the filter function. Meaning, read_and_dispose_of_process_output >> is called about 6000 times, producing the overhead of roughly 0.2s. >> Something in there must be producing extra work for the GC. >> >> This line seems suspect: >> >> list3 (outstream, make_lisp_proc (p), text), >> >> Creates 3 conses and one Lisp object (tagged pointer). But maybe I'm >> missing something bigger. > > I don't understand what puzzles you here. You need to make your > descriptions more clear to allow others to follow your logic. You use > terms you never explain: "junk objects", "number of strings in the > heap", "per-chunk overhead" (what is "chunk"?), which is a no-no when > explaining complex technical stuff to others. In this context, junks objects are objects that will need to be collected by garbage collector very soon because they are just a byproduct of a function's execution (but aren't used in the return value, for example). The more of them a function creates, the more work it will be, supposedly, for the GC. Heap is perhaps the wrong term (given that C has its own notion of heap), but I meant the memory managed by the Lisp runtime. And chunks are the buffered strings that get passed to the process filter. Chunks of the process' output. By default, these chunks are 4096 characters long, but the comparisons tweak that value by 10x and 100x. > If I read what you wrote superficially, without delving into the > details (which I can't understand), you are saying that the overall > amount of consing is roughly the same. What is "amount of consing"? Is it just the number of objects? Or does their size (e.g. string length) affect GC pressure as well? > This is consistent with the > fact that the GC times change only very little. So I don't think I > see, on this level, what puzzles you in this picture. Now that you pointed that out, the picture is just more puzzling. While 0.1s in GC is not insignificant (it's 10% of the whole runtime), it does seem to have been more of a fluke, and on average the fluctuations in GC time are smaller. Here's an extended comparison: (("with-find 4096" . "Elapsed time: 1.737742s (1.019624s in 28 GCs)") ("with-find 40960" . "Elapsed time: 1.515376s (0.942906s in 26 GCs)") ("with-find 409600" . "Elapsed time: 1.458987s (0.948857s in 26 GCs)") ("with-find 1048576" . "Elapsed time: 1.363882s (0.888599s in 24 GCs)") ("with-find-p 4096" . "Elapsed time: 1.202522s (0.745758s in 19 GCs)") ("with-find-p 40960" . "Elapsed time: 1.005221s (0.640815s in 16 GCs)") ("with-find-p 409600" . "Elapsed time: 0.855483s (0.591208s in 15 GCs)") ("with-find-p 1048576". "Elapsed time: 0.825936s (0.623876s in 16 GCs)") ("with-find-sync 4096" . "Elapsed time: 0.848059s (0.272570s in 7 GCs)") ("with-find-sync 409600"."Elapsed time: 0.912932s (0.339230s in 9 GCs)") ("with-find-sync 1048576"."Elapsed time: 0.880479s (0.303047s in 8 GCs)" )) What was puzzling for me, overall, is that if we take "with-find 409600" (the fastest among the asynchronous runs without parallelism) and "with-find-sync", the difference in GC time (which is repeatable), 0.66s, almost covers all the difference in performance. And as for "with-find-p 409600", it would come out on top! Which it did in Ihor's tests when GC was disabled. But where does the extra GC time come from? Is it from extra consing in the asynchronous call's case? If it is, it's not from all the chunked strings, apparently, given that increasing max string's size (and decreasing their number by 2x-6x, according to my logging) doesn't affect the reported GC time much. Could the extra time spent in GC just come from the fact that it's given more opportunities to run, maybe? call_process stays entirely in C, whereas make-process, with its asynchronous approach, goes between C and Lisp even time it receives input. The report above might indicate so: with-find-p have ~20 garbage collection cycles, whereas with-find-sync - only ~10. Or could there be some other source of consing, unrelated to the process output string, and how finely they are sliced? Changing process-adaptive-read-buffering to nil didn't have any effect here. If we get back to increasing read-process-output-max, which does help (apparently due to reducing the number we switch between reading from the process and doing... whatever else), the sweet spot seems to be 1048576, which is my system's maximum value. Anything higher - and the perf goes back to worse -- I'm guessing something somewhere resets the value to default? Not sure why it doesn't clip to the maximum allowed, though. Anyway, it would be helpful to be able to decide on as high as possible value without manually reading from /proc/sys/fs/pipe-max-size. And what of other OSes?