Extreme Slowdown when Using TRAMP

[bsdf]

When using TRAMP to browse remote filesystems, selectrum slows down to the point of being unusable. The behaviour is observed both with and without prescient-mode. The remote machine is on my LAN so network latency is not an issue here.

Please see the following GIF which demonstrates the behaviour in both selectrum vs counsel-find-file (no, the GIF didn't stop-- it's that slow):

Also attached is a profiler log

[clemera]

Thanks for the report, this is related to #205. I don't know what exactly is causing the misbehaviour maybe we have to look how ivy/icomplete handles tramp prompts. Any help investigating this further is greatly appreciated.

[clemera]

This is weird to reproduce. It seems the problem only comes up when there is already an existing connection via tramp (in other words a *tramp...* buffer exists.

[bkhl]

I'm having this as well. I notice that there's no problem with the /sudo: or /sftp: connection methods, so it appears to be specific to the /ssh: method.

Regrettably I need to use the ssh method for multi-hop situations, so I'll keep an eye on this and try to do some digging myself.

[emacsomancer]

Same issue here as well.

(To ease the situation for myself, while continuing to use selectrum as my default selection interface, I just set up a convenience function+binding for using counsel's counsel-find-file for tramp /ssh: things:

(defun bms/ssh-find-file ()
  "Use counsel to make ssh connections via TRAMP."
  (interactive)
  (counsel-find-file "/ssh:"))
(global-set-key (kbd "C-x T") 'bms/ssh-find-file)

)

[clemera]

#277 may improve things on this issue as well?

[plattfot]

I'm also have this issue. But in my case the connection to the remote machines have some serious latency and on top of that the disk I/O on those machines are terrible (slower than normal HDD). Only completion framework that works for me is emacs' default as that doesn't do completion until you hit tab. Which allows me to avoid running completion on certain directories that takes a long time to complete.

To compare I tested to navigate to one of those slow directories using emacs' default, counsel-find-file and selectrum. The slow directory isn't massive or anything like that, it contains 6945 directories with relative short names. Not sure about the underlying topology for the disks but it's mounted over nfs to the remote machine.

• emacs' default took around 5s to generate the completion buffer for that directory. I don't need to call the completion for the rest as I know the path.
• counsel-find-file about the same but you get the completion lag on each directory you hit while navigating to the slow directory.
• selectrum I would say about the same lag as counsel-find-file while navigating but when I entered the slow directory it just froze. It took more than 15 minutes for it to complete the completion list. Navigating to one of it's subdirectories and back again and I have to wait roughly the same time (timed it to ~18 min).

This makes selectrum unusable for me for file navigation. And I don't like the way counsel handles the file navigation so cannot use @emacsomancer's workaround.

But I still want to use selectrum as it works really well for other completions. As a workaround I tried restoring read-file-name-function to read-file-name-default but that broke the completion completely for find-file. Anyone know a way to just disable the file navigation but keep the rest?

I'm testing this with commit f5f2329 from master.

[clemera]

@plattfot Thanks for the detailed description. It is strange that the default is so much faster with default completion because we just use the default file table to compute candidates. I will have a look if there is some special tramp handling that we somehow miss. I remember I have seen some special tramp handling in counsel code as well which we should also look at to get more insight.

Regarding you question you could use the following to fallback to default completion for files (the code is a bit convoluted to make it work best with recursive minibuffer sessions, too):

(defun selectrum-read-file-name-default+ (&rest args)
  (let* ((completion-in-region-function 
          (lambda (&rest args)
            (apply (if (eq minibuffer-completing-file-name t)
                       #'completion--in-region 
                     #'selectrum-completion-in-region) args)))
         (completing-read-function (lambda (&rest args)
				     (setq-local minibuffer-completing-file-name
						 minibuffer-completing-file-name)
                                     (setq completing-read-function #'selectrum-completing-read)
                                     (apply #'completing-read-default args))))
    (apply #'read-file-name-default args)))

[plattfot]

@clemera hmm yeah that sounds strange. I'll have some free time tomorrow so I'll see if I can profile the code and see what takes it so long.

Thanks for the code! I made some slight modifications to just use the emacs' default file completion. And that works perfectly for me.

(defun selectrum-read-file-name-default+ (&rest args)
  (let* ((completion-in-region-function
          (lambda (&rest args)
            (apply #'completion--in-region args)))
         (completing-read-function (lambda (&rest args)
                                     (setq-local minibuffer-completing-file-name
                                                 minibuffer-completing-file-name)
                                     (setq completing-read-function #'completing-read-default)
                                     (apply #'completing-read-default args))))
    (apply #'read-file-name-default args)))
(setf read-file-name-function 'selectrum-read-file-name-default+)

[clemera]

I'll have some free time tomorrow so I'll see if I can profile the code and see what takes it so long.

That would be great!

[plattfot]

First runs of profiling and it seems the slow down might be due completion-file-name-table calling file-exists-p, the last selectrum function I can see before this call is selectrum--minibuffer-post-command-hook but I ran it with byte-compiled selectrum code so a bunch of things are stripped out. Currently rerunning it with none byte code to see if I can get a better overview what is calling what.

Also it seems there's some issue when trying to write out the profiler report when selectrum is loaded. The report that is saved to disk is not the same as the initial report. Not sure if it's due to selectrum or big profiles.

Repro:
Run emacs -Q and in the scratch buffer eval

(require 'selectrum "/path/to/clone/selectrum/selectrum.el")
(selectrum-mode +1)

Then enable profiler-start, open up find-file and /ssh:remote-machine:/slow/directory. Wait until the completion list shows up, hit C-g and then run profiler-report.

First runs of profiling and it seems the slow down might be due completion-file-name-table calling file-exists-p, the last selectrum function I can see before this call is selectrum--minibuffer-post-command-hook.

Repro:
Run emacs -Q and in the scratch buffer eval

(require 'selectrum "/path/to/clone/selectrum/selectrum.el")
(selectrum-mode +1)

Then enable profiler-start, open up find-file and /ssh:remote-machine:/slow/directory/. Wait until the completion list shows up, hit C-g and then run profiler-report.

Also it seems there's some issue when trying to write out the profiler report. The report that is saved to disk is not the same as the initial report. I've pasted what I see instead of attaching the profile:

- command-execute                                                                          6984  64%
 - call-interactively                                                                      6979  64%
  - funcall-interactively                                                                  6974  63%
   - execute-extended-command                                                              6395  58%
    - command-execute                                                                      6380  58%
     - call-interactively                                                                  6380  58%
      - byte-code                                                                          6374  58%
       - completing-read                                                                   6196  56%
        - selectrum-completing-read                                                        6196  56%
         - selectrum-read                                                                  6196  56%
          - let*                                                                           6196  56%
           - progn                                                                         6196  56%
            - progn                                                                        6196  56%
             - let                                                                         6196  56%
              - if                                                                         6196  56%
               - let                                                                       6196  56%
                - unwind-protect                                                           6196  56%
                 - progn                                                                   6196  56%
                  - let*                                                                   6196  56%
                   - read-from-minibuffer                                                  6194  56%
                    - selectrum--minibuffer-post-command-hook                              6187  56%
                     - if                                                                  6187  56%
                      - let                                                                6187  56%
                       - if                                                                6175  56%
                        - let                                                              6131  56%
                         - if                                                              6131  56%
                          - progn                                                          6131  56%
                           - setq                                                          6131  56%
                            - cond                                                         6131  56%
                             - let*                                                        6081  55%
                              - funcall                                                    6081  55%
                               - #<lambda -0xb347b9250d9bcad>                              6069  55%
                                - let*                                                     6068  55%
                                 - cond                                                    6068  55%
                                  - condition-case                                         6068  55%
                                   - funcall                                               6068  55%
                                    - read-file-name-internal                              6068  55%
                                     - completion--some                                    6068  55%
                                      - #<compiled 0x78b8a1>                               6068  55%
                                       - complete-with-action                              6068  55%
                                        - completion--file-name-table                      6068  55%
                                         - all-completions                                 6036  55%
                                          - completion-file-name-table                     6034  55%
                                           - #<lambda -0x73fed7b1850b0e>                   5575  51%
                                            - and                                          5573  51%
                                             - or                                          5566  51%
                                              - funcall                                    5561  50%
                                               - file-exists-p                             5467  50%
                                                - tramp-file-name-handler                  5443  49%
                                                 + apply                                   3387  31%
                                                 + tramp-find-foreign-file-name-handler    1728  15%
                                                 + tramp-dissect-file-name                  219   2%
                                                   tramp-tramp-file-p                        40   0%
                                                 + tramp-replace-environment-variables       10   0%
                                                   #<compiled 0xbe5bf1>                       2   0%
                                                   #<compiled 0x964f29>                       1   0%

*Edit: Forgot to mention, use:

(setf (caar profiler-report-cpu-line-format) 120)

to change the width of the cpu line in the report. Otherwise you'll have trouble seeing the full stack. From emacs.stackexchange.com. I have modified the width before pasting it here so it would fit the post.

[plattfot]

And here is a run when using emacs' default find-file
Similar repro:
Run emacs -Q, run profiler-start, run find-file, type in /ssh:remote-machine:/slow/directory/, hit tab and wait for it to complete. Hit C-g then run profiler-report.

- ...                                                   72  54%
   Automatic GC                                         49  37%
 - complete-with-action                                 18  13%
  - completion--file-name-table                         18  13%
   - substitute-in-file-name                            17  12%
    - tramp-file-name-handler                           17  12%
     - apply                                            17  12%
      - tramp-sh-file-name-handler                      17  12%
       - apply                                          17  12%
        - tramp-handle-substitute-in-file-name          17  12%
         - file-local-name                              12   9%
          - file-remote-p                               12   9%
           - tramp-file-name-handler                    12   9%
            + apply                                      9   6%
            + tramp-find-foreign-file-name-handler       3   2%
         - file-remote-p                                 5   3%
          - tramp-file-name-handler                      5   3%
           + apply                                       4   3%
           + tramp-find-foreign-file-name-handler        1   0%
   + test-completion                                     1   0%
 + #<compiled 0xfe9619>                                  5   3%
- command-execute                                       59  44%
 - call-interactively                                   59  44%
  - byte-code                                           56  42%
   - find-file-read-args                                49  37%
    - read-file-name                                    49  37%
     - read-file-name-default                           49  37%
      - completing-read                                 49  37%
       - completing-read-default                        49  37%
        - read-from-minibuffer                          42  31%
         - command-execute                              20  15%
          - call-interactively                          20  15%
           - funcall-interactively                      20  15%
            + minibuffer-complete                       17  12%
            + self-insert-command                        1   0%
              delete-backward-char                       1   0%
         + rfn-eshadow-update-overlay                   16  12%
           tooltip-hide                                  1   0%
         + timer-event-handler                           1   0%
   + read-extended-command                               7   5%
  + funcall-interactively                                3   2%
+ timer-event-handler                                    1   0%

[clemera]

#335 Should also have improved the situation for this one?

[emacsomancer]

#335 Should also have improved the situation for this one?

It seems to for me. (Also local navigation feels faster in directories with large numbers of contents.)

[bsdf]

much improved here as well. great work!

[clemera]

Great news! Seems the file completion problems we had are gone then :)