Subject: Re: bug#56342: TRAMP (sh) issues way too many commands, thus being very slow over high-ping networks

From: Dmitry Gutov <[email-masked]>
Date: Mon, 20 May 2024 03:04:59 +0300

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%      - #<primitive-function call-interactively>
         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%                  + #<byte-code-function 3D6>
            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.