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#56342: TRAMP (sh) issues way too many commands, thus being very slow over high-ping networks Date: Mon, 20 May 2024 03:04:59 +0300 Message-ID: <901c1ee9-d942-4b8e-9c73-45f6c1388abf@gutov.dev> References: <8735fjh5ge.fsf@gmx.de> <87v8sefl2f.fsf@gmx.de> <874jzyc9u9.fsf@gmx.de> <87sfnhazvy.fsf@gmx.de> <87k08sc02z.fsf@gmx.de> <87r128gdob.fsf@gmx.de> <87mtcvhidx.fsf@gmx.de> <87o7x22089.fsf@gmx.de> 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="15707"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Mozilla Thunderbird Cc: 56342@debbugs.gnu.org To: Michael Albinus , Paul Pogonyshev Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Mon May 20 02:06:24 2024 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 1s8qXm-0003ra-Ol for geb-bug-gnu-emacs@m.gmane-mx.org; Mon, 20 May 2024 02:06:23 +0200 Original-Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1s8qXQ-0007pQ-Qk; Sun, 19 May 2024 20:06:00 -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 1s8qXO-0007ou-Vv for bug-gnu-emacs@gnu.org; Sun, 19 May 2024 20:05:59 -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 1s8qXO-000537-Fx for bug-gnu-emacs@gnu.org; Sun, 19 May 2024 20:05:58 -0400 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1s8qXS-0000L9-Ge for bug-gnu-emacs@gnu.org; Sun, 19 May 2024 20:06:02 -0400 X-Loop: help-debbugs@gnu.org Resent-From: Dmitry Gutov Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Mon, 20 May 2024 00:06:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 56342 X-GNU-PR-Package: emacs Original-Received: via spool by 56342-submit@debbugs.gnu.org id=B56342.17161635161290 (code B ref 56342); Mon, 20 May 2024 00:06:02 +0000 Original-Received: (at 56342) by debbugs.gnu.org; 20 May 2024 00:05:16 +0000 Original-Received: from localhost ([127.0.0.1]:38752 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1s8qWh-0000Kj-IK for submit@debbugs.gnu.org; Sun, 19 May 2024 20:05:16 -0400 Original-Received: from fhigh8-smtp.messagingengine.com ([103.168.172.159]:57787) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1s8qWf-0000Ka-8l for 56342@debbugs.gnu.org; Sun, 19 May 2024 20:05:14 -0400 Original-Received: from compute6.internal (compute6.nyi.internal [10.202.2.47]) by mailfhigh.nyi.internal (Postfix) with ESMTP id BC15511400A5; Sun, 19 May 2024 20:05:02 -0400 (EDT) Original-Received: from mailfrontend1 ([10.202.2.162]) by compute6.internal (MEProxy); Sun, 19 May 2024 20:05:02 -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:subject:subject:to:to; s=fm2; t=1716163502; x=1716249902; bh=iA1tdACcQ0COos/fqJIOylaP8Oc4urgNG/bVnoyHQlw=; b= NZvTrZvnQHn67XqVVmyl7ZE7Y+rhXbO1N/2AikMFvDha+p/k9vtbIf8HXXFeQm8i G2U5T/UhcpmjBk7Ku4ZK9QKwFTI5hAZ0yece7wufz8YkKHi4UH9TYsxFjCRQGsaU Njw5/E5ZQYhdaAws7m3VDn7IYbGUAaxcKcqV/cx/o9WuLaJTLazVyjAnOnmfFF6P Bfbzg11S9PGDQSLZexKZnuqeVrDnbbKk/+Npicu7Ry9FZwDEnAqfrMzjCv8W9/55 85vvSvWDHB11wsTdOJ9O2A8DzKye9Js/EHkvotBIlf+eg6jnntoXtUSNgbe3PFR8 zXQtnRPfXXFRoygq5jonfQ== 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:subject:subject:to:to:x-me-proxy:x-me-proxy :x-me-sender:x-me-sender:x-sasl-enc; s=fm1; t=1716163502; x= 1716249902; bh=iA1tdACcQ0COos/fqJIOylaP8Oc4urgNG/bVnoyHQlw=; b=C UH/vzTdCBgwSy8nVYoKfg20qw+qrwD0amGN643THVNNLnoSN7OSZ1zkr9mrkUJ3W l/FIrfqoAv5DlSK555x4PLlWn5xt1iHYU3aXl+O0IxYZREdLjmILKHYrK2b2PjHu IXYdY0DhW59o1cIe7RAoilgg0JgFv4CBosQpjouJ2oZ8FXSPlDiQKepINdUM0BBx AzQxmlWT2McdNcSwzUnXvDM8KjD2B5QUmOAfHU6qMPrlR8W3yG5yns6WnmjwgPGx I1tLKxsE4wJiBNBwITIt8XokexafIo2xHukoP6e/n982vDsNpOdJ/SC/8In5ZWsg 7Vgts1TH5rmoOdA4W5P9Q== X-ME-Sender: X-ME-Received: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedvledrvdehledgvdelucetufdoteggodetrfdotf fvucfrrhhofhhilhgvmecuhfgrshhtofgrihhlpdfqfgfvpdfurfetoffkrfgpnffqhgen uceurghilhhouhhtmecufedttdenucesvcftvggtihhpihgvnhhtshculddquddttddmne cujfgurhepkfffgggfuffvvehfhfgjtgfgsehtjeertddtvdejnecuhfhrohhmpeffmhhi thhrhicuifhuthhovhcuoegumhhithhrhiesghhuthhovhdruggvvheqnecuggftrfgrth htvghrnhepteduleejgeehtefgheegjeekueehvdevieekueeftddvtdevfefhvdevgedu jeehnecuvehluhhsthgvrhfuihiivgeptdenucfrrghrrghmpehmrghilhhfrhhomhepug hmihhtrhihsehguhhtohhvrdguvghv X-ME-Proxy: Feedback-ID: i0e71465a:Fastmail Original-Received: by mail.messagingengine.com (Postfix) with ESMTPA; Sun, 19 May 2024 20:05:01 -0400 (EDT) Content-Language: en-US In-Reply-To: <87o7x22089.fsf@gmx.de> 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:285454 Archived-At: Hi Michael and Paul, I've found this report to be relevant, since the original scenario looks fairly similar to the pain point I'm seeing (which is the synchronized delay during 'save-buffer'. C-x C-s is something I hit pretty regularly, so I think it's one of the scenarios to optimize first. Almost 2 years have passed since the last message in this thread, so maybe you'll want to give an update, if you have particular changes in mind. I'd like to offer some profiler output with the latest Tramp and maybe a few suggestions. On 02/08/2022 17:23, Michael Albinus wrote: >> E.g. in the traces you have attached this can be seen. The following >> two commands repeat twice: > I haven't investigated this special case yet, but last days I'm working > on exact this problem. Flushing caches shouldn't be a sledge hammer, but > fine grained, selecting the needed properties to be flushed. Let's see > where we land. I was wondering whether the cache in question was useful for the case where we regularly change the contents and update the modification time. But perhaps it is, if going by the profiler output below. Anyway, the scenario is: 1. (setq remote-file-name-inhibit-locks t) ; big QoL improvement 2. visit some file on a remote host, via /ssh: 3. insert char (e.g. by pressing RET) 4. save buffer 5. repeat steps 3 and 4 10-15 times quickly, without pause The profiler report: 6341 77% - command-execute 6341 77% - call-interactively 6341 77% - apply 6341 77% - call-interactively@ido-cr+-record-current-command 6341 77% - apply 6341 77% - # 6150 75% - funcall-interactively 6134 75% - save-buffer 6132 75% - basic-save-buffer 3592 43% - basic-save-buffer-1 3592 43% - basic-save-buffer-2 3260 39% - write-region 3260 39% - tramp-file-name-handler 3260 39% - apply 3260 39% - tramp-sh-file-name-handler 3260 39% - apply 3260 39% - tramp-sh-handle-write-region 1771 21% - tramp-barf-unless-okay 1771 21% + tramp-send-command-and-check 1299 15% - file-attributes 1299 15% - tramp-file-name-handler 1299 15% - apply 1299 15% - tramp-sh-file-name-handler 1299 15% - apply 1299 15% - tramp-sh-handle-file-attributes 1299 15% + tramp-do-file-attributes-with-stat 171 2% + file-truename 7 0% + # 4 0% + expand-file-name 4 0% write-region 4 0% + tramp-message 332 4% + file-writable-p 2536 31% - verify-visited-file-modtime 2536 31% - tramp-file-name-handler 2536 31% - apply 2536 31% - tramp-sh-file-name-handler 2536 31% - apply 2536 31% - tramp-sh-handle-verify-visited-file-modtime 2536 31% - file-attributes 2536 31% - tramp-file-name-handler 2536 31% - apply 2536 31% - tramp-sh-file-name-handler 2536 31% - apply 2536 31% - tramp-sh-handle-file-attributes 2528 30% + tramp-do-file-attributes-with-stat 4 0% + tramp-get-file-property What I see here is a few things: 1. First we look at the file in verify-visited-file-modtime and then in write-region. It might be more economical to combine that in some script sent to the remote host to be executed. But that seems hard (even aside the coding required - it'd need a new file handler, I guess, one that would basically do the whole job of basic-save-buffer). 2. There are tramp-sh-handle-file-attributes calls in different branches that a fair amount of time gets spent in. Could those be cached, to only issue one call? Could a binding for 'process-file-side-effects' help? 3. The file-truename call. Curiously, it's only called by tramp-sh-handle-write-region. Does the handler really need to know the canonical file name? It seems like it'd be okay if it wrote to one of the symlinked names instead. Ah, looking at tramp-skeleton-write-region, this seems to have something to do with locking. Could we optimize this at least for the case when remote-file-name-inhibit-locks is set to t? Here's also some filtered output from the Tramp debug log from *one* save-buffer call: 02:39:44.488432 tramp-send-command (6) # tramp_stat_file_attributes /home/d/dgutov/git-test/b/c/caca 2>/dev/null; echo tramp_exit_status $? 02:39:44.688011 tramp-send-command (6) # test -e /home/d/dgutov/git-test/b/c/ 2>/dev/null; echo tramp_exit_status $? 02:39:44.890427 tramp-send-command (6) # test -w /home/d/dgutov/git-test/b/c/ 2>/dev/null; echo tramp_exit_status $? 02:39:45.097458 tramp-send-command (6) # (if test -h "/srv/data/home/d/dgutov/git-test/b/c/caca"; then echo t; else echo nil; fi) && \readlink --canonicalize-missing /srv/data/home/d/dgutov/git-test/b/c/caca 2>/dev/null; echo tramp_exit_status $? 02:39:45.303095 tramp-send-command (6) # tramp_stat_file_attributes /home/d/dgutov/git-test/b/c/caca 2>/dev/null; echo tramp_exit_status $? 02:39:45.508024 tramp-send-command (6) # base64 -d -i >/home/d/dgutov/git-test/b/c/caca <<'45aa0e36081f9f2cbcfda421e708711e' 2>/dev/null; echo tramp_exit_status $? 02:39:45.708813 tramp-send-command (6) # tramp_stat_file_attributes /home/d/dgutov/git-test/b/c/caca 2>/dev/null; echo tramp_exit_status $? It seems to stat the file (with tramp_stat_file_attributes) 3 times. One of these is from verify-visited-file-modtime, and two others - from other branches of execution. And another verify-visited-file-modtime call (with another tramp-do-file-attributes-with-stat) happens whenever you type the first character after saving the buffer. Which also contributes to perceived latency. Could these be cached by adding some new process-file-side-effects bindings? Other things we see above is several separate 'test' calls. Not sure if those could be combined (by having a command return all the data together, and then have it cached?), but that'd be nice.