Re: Faster start-file-process?

[Philipp Stephani]

Am Di., 10. März 2020 um 13:54 Uhr schrieb Michael Albinus
<address@hidden>:
>
> Philipp Stephani <address@hidden> writes:
>
> Hi Philipp,
>
> > t and "-o ControlMaster=auto -o ControlPath='tramp.%%C' -o
> > ControlPersist=no" (i.e. the defaults).
> >
> >> Could you set `tramp-verbose' to 6 and verify, whether these options are
> >> used? You could send the traces to me for analyzing, if you prefer.
> >
> > They seem to be used, the output is:
> >
> > Tramp: Opening connection for HOSTNAME using ssh...
> > Tramp: Sending command ‘exec ssh -q   -o ControlMaster=auto -o
> > ControlPath='tramp.%C' -o ControlPersist=no -e none HOSTNAME’
> > Tramp: Waiting for prompts from remote shell...done
> > Tramp: Found remote shell prompt on ‘HOSTNAME’
> > Tramp: Opening connection for HOSTNAME using ssh...done
>
> Yes. So we don't need to care about ControlMaster; Tramp does everything
> what's possible here.

Yes, almost :)
I'd actually prefer for my own use case if it left out the options
because I already set them in my ~/.ssh/config (with a different
ControlPath). But that's a minor thing that I can fix myself.

>
> > The form I've evaluated is just
> > (let ((default-directory "/ssh:HOSTNAME:/"))
> >     (start-file-process "" nil "true"))
> >
> > This takes 2 seconds per invocation on my machine:
> > (benchmark-run 10
> >   (let ((default-directory "/ssh:HOSTNAME:/"))
> >     (start-file-process "" nil "true")))
> > (21.287248981 78 6.104474747000001)
>
> There is a difference wrt verbosity level. See:
>
> (benchmark-run 10
>   (let ((tramp-verbose 10)
>         (default-directory "/ssh::/"))
>     (start-file-process "" nil "true")))
> (8.524027585 16 3.5059282540000005)
>
> (benchmark-run 10
>   (let ((tramp-verbose 3)
>         (default-directory "/ssh::/"))
>     (start-file-process "" nil "true")))
> (6.871181527 9 2.210354418999998)
>
> (benchmark-run 10
>   (let ((tramp-verbose 0)
>         (default-directory "/ssh::/"))
>     (start-file-process "" nil "true")))
> (3.986375167 6 1.6585357770000044)
>
> This is with Tramp 2.5.0-pre from git master. All these numbers are
> taken after I had open /ssh::/ already in another buffer. For better
> comparision, you might set tramp-verbose to 0.
>
> > If you're interested, I've profiled Tramp with ELP (on Emacs master),
> > here's the report:
>
> Thanks. What was the code you have profiled with? Just the same as for
> the benchmark? 48 sec sounds very long compared to the benchmark results.

I've just used something like (start-file-process "true") again. Note
the 48 includes the total time of all file handlers combined. I'm not
sure whether the other invocations come from, they might be background
processes. The figures for tramp-handle-start-file-process are a bit
closer. (I've run the test form 11 times in total.)

>
> > tramp-file-name-handler                            79
> > 48.196645538  0.6100841207
> > tramp-sh-file-name-handler                         59
> > 47.933230473  0.8124276351
> > tramp-handle-start-file-process                    11
> > 23.966547321  2.1787770292
> > tramp-sh-handle-make-process                       11
> > 23.916336605  2.1742124187
> > tramp-maybe-open-connection                        77
> > 23.538912846  0.3057001668
> > tramp-process-actions                              11
> > 16.095361023  1.4632146384
>
> Well, tramp-process-actions runs the handshaking (checking for passwords
> and other things to set up). Maybe we shall investigate in more detail
> where the time is spent.
>
> > tramp-check-for-regexp                             27300
> > 13.363068022  0.0004894896
> > tramp-search-regexp                                27520
> > 8.4726394889  0.0003078720
>
> tramp-check-for-regexp takes only negligible time per call. But applying
> it 27300 times sounds too much to me. tramp-search-regexp is mainly
> called in tramp-check-for-regexp.
>
> > tramp-send-command                                 198
> > 7.0239918969  0.0354747065
> > tramp-wait-for-output                              176
> > 6.898226061   0.0391944662
> > tramp-accept-process-output                        2955
> > 6.8919202430  0.0023322911
> > tramp-wait-for-regexp                              187
> > 6.8587603229  0.0366778626
> > tramp-open-connection-setup-interactive-shell      11
> > 6.817871086   0.6198064623
>
> Well, tramp-open-connection-setup-interactive-shell is needed for
> interactive shells. But in start-file-process, some of its actions might
> be skipped I believe.
>
> > tramp-get-connection-property                      56391
> > 2.8474465550  5.049...e-05
> > tramp-send-command-and-check                       44
> > 1.8092037689  0.0411182674
> > tramp-barf-unless-okay                             33
> > 1.345802245   0.0407818862
> > tramp-send-command-and-read                        33
> > 1.3418833959  0.0406631332
> > tramp-debug-message                                785
> > 1.1342730509  0.0014449338
> > tramp-open-shell                                   11
> > 1.106302197   0.1005729269
> > tramp-get-hash-table                               56732
> > 0.7261888440  1.280...e-05
> > [...]
>
> These calls do not take too much time per call. However,
> tramp-get-connection-property is called 56391 times. Maybe i change it
> to be a defsubst?
>
> > I'm not sure what the culprit is, but my method (that doesn't use
> > Tramp's connections) is reliably 500 times faster.
>
> 500 times faster is remarkable. But Tramp needs some overhead for setup
> and writing traces. Anyway, I'll play with it; maybe I could speed it up
> somehow.

Thanks for looking into it!
I don't think that with the current approach (standing connections)
Tramp can become much faster. It'll just take too long sending and
parsing output over the SSH connection. The big problem is that this
needs to be synchronous, while my method is entirely asynchronous. The
latter is the crucial point: for things like Flymake or LSP to work
over Tramp, start-file-process has to finish in a few milliseconds.
Everything else adds unacceptable latency.

I've now experimented a bit more with my approach, and the results are
somewhat mixed:
- Visiting a 512 KiB file is 20% faster.
- Reading it without visiting is 30% faster. (The difference is that
visiting also needs to read the mtime of the file.)
- A test like file-exists-p is 50 times slower. Since this operation
is extremely fast on the remote machine, the overhead of starting the
SSH process is now significant.
- Running /bin/true synchronously (process-file) is 4 times slower.
- start-file-process is still 500 times faster.

This uses the current master of Tramp. All these results are
statistically significant (on my machine, that is). I think at least
start-file-process and make-process should definitely switch to the
connectionless approach (or at least offer it as option), that would
make language servers or Flymake backends over SSH possible.
I'm also happy to contribute patches!