Re: File path completions: strange speed discrepancy

[JD Smith]

OK I believe I’ve cracked it.  Spurred on by the process tracing I mentioned in the last message, I looked into the repeated spawning of 

zsh -c getconf DARWIN_USER_TEMP_DIR 

which occurs with both remote and local start (even more times for the remote start).  I found DARWIN_USER_TEMP_DIR mentioned in cus-start.el, and it is obviously mac specific.  There is the interesting related docstring:

temporary-file-directory is a compiled Lisp function in ‘files.el’.

(temporary-file-directory)

  Probably introduced at or before Emacs version 20.3.

The directory for writing temporary files.

In case of a remote ‘default-directory’, this is a directory for

temporary files on that remote host.  ...

For a non-remote and non-mounted ‘default-directory’, the value of

the variable ‘temporary-file-directory’ is returned.

So a canonical local vs remote difference, as you mentioned.  To investigate further, first I explicitly set my shell-file-name to “/bin/bash”.  This radically improves things: local and remote are much closer to the same speed now.  

But still, the issue remains, why is DARWIN_USER_TEMP_DIR being queried via shell-command-to-string so often?  This variable is just a startup constant, taken ONCE from the environment, or from getconf (as a backup in case getenv fails).  

The traceback is revealing:

  shell-command-to-string("getconf DARWIN_USER_TEMP_DIR")

  (progn (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR"))

  (condition-case nil (progn (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR")) (error nil))

  (ignore-errors (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR"))

  (let* (file-name-handler-alist (tmp (ignore-errors (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR")))) (and (stringp tmp) (setq tmp (replace-regexp-in-string "\n\\'" "" tmp)) (file-directory-p tmp) tmp))

  (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") (let* (file-name-handler-alist (tmp (ignore-errors (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR")))) (and (stringp tmp) (setq tmp (replace-regexp-in-string "\n\\'" "" tmp)) (file-directory-p tmp) tmp)) "/tmp")

  (cond ((memq system-type '(ms-dos windows-nt)) (or (getenv "TEMP") (getenv "TMPDIR") (getenv "TMP") "c:/temp")) ((eq system-type 'darwin) (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") (let* (file-name-handler-alist (tmp (ignore-errors (shell-command-to-string "getconf DARWIN_USER_TEMP_DIR")))) (and (stringp tmp) (setq tmp (replace-regexp-in-string "\n\\'" "" tmp)) (file-directory-p tmp) tmp)) "/tmp")) (t (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") "/tmp")))

  (file-name-as-directory (cond ((memq system-type '(ms-dos windows-nt)) (or (getenv "TEMP") (getenv "TMPDIR") (getenv "TMP") "c:/temp")) ((eq system-type 'darwin) (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") (let* (file-name-handler-alist (tmp (ignore-errors ...))) (and (stringp tmp) (setq tmp (replace-regexp-in-string "\n\\'" "" tmp)) (file-directory-p tmp) tmp)) "/tmp")) (t (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") "/tmp"))))

  eval((file-name-as-directory (cond ((memq system-type '(ms-dos windows-nt)) (or (getenv "TEMP") (getenv "TMPDIR") (getenv "TMP") "c:/temp")) ((eq system-type 'darwin) (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") (let* (file-name-handler-alist (tmp ...)) (and (stringp tmp) (setq tmp ...) (file-directory-p tmp) tmp)) "/tmp")) (t (or (getenv "TMPDIR") (getenv "TMP") (getenv "TEMP") "/tmp")))))

  tramp-sh-handle-expand-file-name("/ssh:tir:/home/jdsmith/code/python/scraps/Untitled..." nil)

  apply(tramp-sh-handle-expand-file-name ("/ssh:tir:/home/jdsmith/code/python/scraps/Untitled..." nil))

  tramp-sh-file-name-handler(expand-file-name "/ssh:tir:/home/jdsmith/code/python/scraps/Untitled..." nil)

  apply(tramp-sh-file-name-handler expand-file-name ("/ssh:tir:/home/jdsmith/code/python/scraps/Untitled..." nil))

  tramp-file-name-handler(expand-file-name "/ssh:tir:/home/jdsmith/code/python/scraps/Untitled..." nil)

Stepping through `tramp-sh-handle-expand-file-name', I noticed that, after the main SSH connection is established, every other invocation of `tramp-compat-temporary-file-directory’ spawns a new shell with getconf DARWIN_USER_TEMP_DIR.  

And, at long last, HERE we see the problem, in `tramp-compat-temporary-file-directory':

(eval (car (get 'temporary-file-directory 'standard-value)) t))

Why is this an issue?  That standard value of `temporary-file-directory' contains, for 'darwin systems:

(shell-command-to-string \"getconf DARWIN_USER_TEMP_DIR\"))))

So, to recap my understanding of this issue:

1. During file completion, tramp requests the temporary file directory many, many times, using its own compat function.
2. Because on remote hosts, the function `temporary-file-directory' returns a *remote* directory, tramp instead evaluates the standard value of the variable `temporary-file-directory' (defined in cus-start). 
3. For 'darwin systems, that standard value includes a shell command call to retrieve DARWIN_USER_TEMP_DIR.  
4. Tramp thus evals code which spawns a shell to getconf DARWIN_USER_TEMP_DIR hundreds of times per file completion. 
5. Some shells are slower than others to start.  For me zsh is much slower than bash (due to my config).
6. [not really relevant] For some unexplained reasons, starting zsh in a remote directory leads to faster local shell startups. Possibly environment variable setting is the culprit.

One thing I don’t understand is why tramp needs to re-evaluate the standard value of the variable `temporary-file-directory’ at all.  That variable doesn’t appear to change on remote hosts, or ever really.  What does change is the returned result of the identically-name function `temporary-file-directory’.  

A quick fix for me was simply to (see FIXED timing, below):

(defsubst tramp-compat-temporary-file-directory ()

  "Return name of directory for temporary files.

It is the default value of `temporary-file-directory'."

  temporary-file-directory)

With this, my tramp file browsing is blazingly fast, whether starting local or remote, with Emacs 27.2 and tramp 2.4.3-pre.  Some timing, from my earlier test:

Normal Tramp Local, zsh: 11.2 seconds

Normal Tramp Remote, zsh: 0.88s

Normal Tramp Local, bash: 1.48 seconds

Normal Tramp Remote, bash: 0.80s

Fixed Tramp Local, zsh: 0.76 seconds

Fixed Tramp Remote, zsh: 0.85 seconds

Fixed Tramp Local, bash: 0.74 seconds

Fixed Tramp Remote, bash: 0.80 seconds

I note that this remains an issue in Emacs 28.1 and Tramp v2.5.1.2.  I would not be at all surprised if this also underlies many of the complaints about tramp performance on MacOS (e.g. https://emacs.stackexchange.com/questions/16489/tramp-is-unbearably-slow-osx-ssh), for people who have slow-to-start shells. 

Thanks for your help with this (and as always, for Tramp, which is unique and incredibly useful).

Best,

JDS

On Sep 20, 2021, at 2:31 PM, JD Smith <jdtsmith@gmail.com> wrote:

Furthermore, I have switched to a remote machine in my LAN, because it
doesn't matter whether the machine is far away. So I have changed the
code snippet to

(progn
 (require 'tramp-sh)
 (defun my/test ()
   (interactive)
   (tramp-cleanup-all-connections)
   (elp-instrument-list
    (append
     '(completion-file-name-table
completion--sifn-requote
completion--file-name-table
completing-read
read-file-name-internal
read-file-name-default)
     (mapcar #'intern (all-completions "tramp-handle-" obarray 'functionp))
     (mapcar #'intern (all-completions "tramp-sh-handle-" obarray 'functionp))))
   (setq unread-command-events
 (mapcar 'identity "///ssh:detlef:/hom\talbin\tsr\temacs\t/lisp/\t\n"))
   (call-interactively #'find-file)
   (let ((elp-recycle-buffers-p nil))
     (elp-results)
     (elp-reset-all)))

 (dolist (df '("/ssh::" "/"))
   (let ((default-directory df))
     (my/test))))

Thanks for this.  The final bit of your updated test unfortunately does not work for me, as it tries and fails to open a connection to my local machine for some reason (“Could not resolve hostname”).

But just running my/test from *scratch*, and then again from a dired buffer on the remote host (another server this time, also wired), yields the attached results, in graphical form this time.  As you can see, in the worst case, the performance per call is >100x worse.

One additional bit of data: on my MacOS terminal, when a running process (here emacs -Q) spawns any sub-processes, the name of the sub-process appears in the terminal window title.  I have noticed that, while performing our test from *scratch*, the title flashes wildly for the full ~9 seconds of the test, mentioning “launchctl” and “date” and others, over and over.  These appear perhaps a dozen or more times.  Conversely, when running my/test from the remote dired buffer, it is updated almost not at all (maybe “gzip” for the final file transfer?... it goes by fast).

So I’d conjecture the root cause of the discrepancy here is that there’s some real difference in how and how often external processes are being spawned, between local and remote starting points.  

To check into this, I advised call-process, to report on which processes are being made.  But this looks… identical, except the fast version spawns my zsh shell to collect DARWIN_USER_TEMP_DIR even more often (134 times!)!  Somehow the processes have to be involved though...

<tramp_local_remote.pdf>