Re: Faster start-file-process?

[Michael Albinus]

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.

> 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.

> 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.

Best regards, Michael.