[email protected] writes: > Sure Michael!,
Hi Miguel, > Here’s an example of running find-file: > (find-file > "/ssh:[email protected]|sudo:[email protected]|ssh:[email protected]|sudo:[email protected]:/usr/local/sbin/poll_backends.py") > > So 4 multihops. It is of course more slow but, even one seems to be slow. Thanks. This is good for analysis. The major help for analysis is going through the debug buffer, and inspect the messages related to debug level "(6)". Tese are all commands sent to remote, and what remote returns. Let's do it. --8<---------------cut here---------------start------------->8--- 14:18:02.107582 tramp-call-process (6) # ‘locale -a’ nil *temp* 14:18:02.114189 tramp-call-process (6) # 0 en_NZ nl_NL.UTF-8 ... 14:18:02.119271 tramp-maybe-open-connection (6) # /bin/sh -i 14:18:02.123494 tramp-wait-for-regexp (6) # #$ --8<---------------cut here---------------end--------------->8--- These are some local commands Tramp needs for warmup. The point is: the session starts 14:18:02.107582. --8<---------------cut here---------------start------------->8--- 14:18:02.124932 tramp-send-command (6) # exec ssh -l miguel -e none 172.28.3.249 14:18:04.567269 tramp-process-actions (6) # Linux automation.ec2.us-west-2.xpr.in 4.19.0-18-cloud-amd64 #1 SMP Debian 4.19.208-1 (2021-09-29) x86_64 Last login: Mon Mar 13 21:37:55 2023 from 172.28.0.238 -bash: warning: setlocale: LC_ALL: cannot change locale (en_US.UTF-8) miguel@automation:~$ 14:18:04.569597 tramp-send-command (6) # exec env SUDO_PROMPT=P""a""s""s""w""o""r""d"": sudo -u expression_aws -s -H /bin/sh -i 14:18:04.812422 tramp-process-actions (6) # /bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.UTF-8) $ 14:18:04.814883 tramp-send-command (6) # exec ssh -l admin -e none 172.28.0.87 14:18:05.322930 tramp-process-actions (6) # Linux loadbalancer02.ec2.us-west-2.xpr.in 4.19.0-21-cloud-amd64 #1 SMP Debian 4.19.249-2 (2022-06-30) x86_64 Last login: Sat Mar 11 00:18:42 2023 from 172.28.0.238 admin@loadbalancer02:~$ 14:18:05.325164 tramp-send-command (6) # exec env SUDO_PROMPT=P""a""s""s""w""o""r""d"": sudo -u root -s -H /bin/sh -i 14:18:05.551481 tramp-process-actions (6) # # --8<---------------cut here---------------end--------------->8--- Two "ssh" calls, two "sudo" calls, and you're there. It takes about 3 seconds, and only the first "ssh" call consumes some time due to network latency. --8<---------------cut here---------------start------------->8--- 14:18:05.552256 tramp-send-command (6) # exec env TERM='dumb' INSIDE_EMACS='28.2,tramp:2.5.3.28.2' ENV='' HISTFILE=~/.tramp_history PROMPT_COMMAND='' PS1=\#\$\ PS2='' PS3='' /bin/sh -i 14:18:05.740223 tramp-wait-for-regexp (6) # #$ 14:18:05.742881 tramp-send-command (6) # (cd ~/) 2>/dev/null; echo tramp_exit_status $? 14:18:05.930666 tramp-wait-for-regexp (6) # tramp_exit_status 0 #$ 14:18:05.933344 tramp-send-command (6) # set +o vi +o emacs 14:18:06.119327 tramp-wait-for-regexp (6) # #$ 14:18:06.120890 tramp-send-command (6) # set -o 14:18:06.308708 tramp-wait-for-regexp (6) # Current option settings errexit off noglob off ... 14:18:06.310090 tramp-send-command (6) # stty -inlcr -onlcr -echo kill '^U' erase '^H' 14:18:06.499667 tramp-wait-for-regexp (6) # #$ 14:18:06.501051 tramp-send-command (6) # echo foo 14:18:06.688265 tramp-wait-for-regexp (6) # foo #$ 14:18:06.690287 tramp-send-command (6) # PS1=///9e801e5981007e5308671e52a92cc9f5\#\$ PS2='' PS3='' PROMPT_COMMAND='' 14:18:06.879178 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:06.882853 tramp-send-command (6) # echo \"`uname -sr`\" 2>/dev/null; echo tramp_exit_status $? 14:18:07.073136 tramp-wait-for-regexp (6) # "Linux 4.19.0-21-cloud-amd64" tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:07.077645 tramp-send-command (6) # locale -a 14:18:07.693726 tramp-wait-for-regexp (6) # aa_DJ aa_DJ.utf8 ... 14:18:07.694968 tramp-send-command (6) # (echo foo ; echo bar) 14:18:07.880458 tramp-wait-for-regexp (6) # foo bar ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:07.884653 tramp-send-command (6) # echo \"`getconf PATH 2>/dev/null`\" 2>/dev/null; echo tramp_exit_status $? 14:18:08.076096 tramp-wait-for-regexp (6) # "/bin:/usr/bin" tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:08.080559 tramp-send-command (6) # test 0 2>/dev/null; echo tramp_exit_status $? 14:18:08.266701 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:08.269663 tramp-send-command (6) # test -d /bin 2>/dev/null; echo tramp_exit_status $? 14:18:08.456575 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:08.461471 tramp-send-command (6) # test -d /usr/bin 2>/dev/null; echo tramp_exit_status $? 14:18:08.648399 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:08.653265 tramp-send-command (6) # test -d /sbin 2>/dev/null; echo tramp_exit_status $? 14:18:08.840312 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:08.845103 tramp-send-command (6) # test -d /usr/sbin 2>/dev/null; echo tramp_exit_status $? 14:18:09.031778 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.036810 tramp-send-command (6) # test -d /usr/local/bin 2>/dev/null; echo tramp_exit_status $? 14:18:09.223823 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.229301 tramp-send-command (6) # test -d /usr/local/sbin 2>/dev/null; echo tramp_exit_status $? 14:18:09.415314 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.419954 tramp-send-command (6) # test -d /local/bin 2>/dev/null; echo tramp_exit_status $? 14:18:09.606866 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.610695 tramp-send-command (6) # test -d /local/freeware/bin 2>/dev/null; echo tramp_exit_status $? 14:18:09.796931 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.801324 tramp-send-command (6) # test -d /local/gnu/bin 2>/dev/null; echo tramp_exit_status $? 14:18:09.987587 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:09.992234 tramp-send-command (6) # test -d /usr/freeware/bin 2>/dev/null; echo tramp_exit_status $? 14:18:10.175886 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:10.179550 tramp-send-command (6) # test -d /usr/pkg/bin 2>/dev/null; echo tramp_exit_status $? 14:18:10.364786 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:10.367611 tramp-send-command (6) # test -d /usr/contrib/bin 2>/dev/null; echo tramp_exit_status $? 14:18:10.552288 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:10.556393 tramp-send-command (6) # test -d /opt/bin 2>/dev/null; echo tramp_exit_status $? 14:18:10.742397 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:10.745868 tramp-send-command (6) # test -d /opt/sbin 2>/dev/null; echo tramp_exit_status $? 14:18:10.930537 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:10.933807 tramp-send-command (6) # test -d /opt/local/bin 2>/dev/null; echo tramp_exit_status $? 14:18:11.119002 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:11.125652 tramp-send-command (6) # getconf PIPE_BUF / 2>/dev/null || echo 4096 2>/dev/null; echo tramp_exit_status $? 14:18:11.314759 tramp-wait-for-regexp (6) # 4096 tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:11.318396 tramp-send-command (6) # PATH=/bin:/usr/bin:/sbin:/usr/sbin:/usr/local/bin:/usr/local/sbin && export PATH 14:18:11.503851 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:11.506873 tramp-send-command (6) # echo ~root 14:18:11.693233 tramp-wait-for-regexp (6) # /root ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:11.696785 tramp-send-command (6) # mesg n 2>/dev/null; biff n 2>/dev/null 14:18:11.885902 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:11.887236 tramp-send-command (6) # stty tab0 14:18:12.076369 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:12.078244 tramp-send-command (6) # stty iutf8 2>/dev/null 14:18:12.266286 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:12.270945 tramp-send-command (6) # echo \"`tty`\" 2>/dev/null; echo tramp_exit_status $? 14:18:12.464702 tramp-wait-for-regexp (6) # "/dev/pts/4" tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:12.468358 tramp-send-command (6) # stty -a 14:18:12.657080 tramp-wait-for-regexp (6) # speed 9600 baud; rows 0; columns 0; line = 0; ... 14:18:12.658542 tramp-send-command (6) # while read var val; do export $var="$val"; done <<'5738c90c53a989a543f306c1edbb814e' LC_ALL en_US.utf8 ENV '' TMOUT 0 LC_CTYPE '' PAGER cat 5738c90c53a989a543f306c1edbb814e 14:18:12.843994 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:12.844930 tramp-send-command (6) # unset CDPATH HISTORY MAIL MAILCHECK MAILPATH autocorrect correct 14:18:13.030757 tramp-wait-for-regexp (6) # ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:13.034709 tramp-send-command (6) # test 0 2>/dev/null; echo tramp_exit_status $? 14:18:13.221205 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ --8<---------------cut here---------------end--------------->8--- This is the Tramp initialization. About 8 seconds, which is slow due to the limited remote machine's power, and due to network latency. This will be applied for every first connection to the remote machine (as you have applied with find-file), it won't run again if you do other actions on that remote machine in the same Tramp session. Starting a remote process runs the same code, more or less. This could be reduced by changing caching timeouts (increase remote-file-name-inhibit-cache, or set it to nil). Resrs for the existence of a given directory shouldn't happen then. Furthermore, you could reduce the number of tests by removing unnecessary entries from tramp-remote-path. In your case, /local/bin, /local/freeware/bin, /local/gnu/bin, /usr/freeware/bin, /usr/pkg/bin, /usr/contrib/bin, /opt/bin, /opt/sbin, /opt/local/bin aren't needed. --8<---------------cut here---------------start------------->8--- 14:18:13.224815 tramp-send-command (6) # test -d /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:13.411223 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:13.545445 tramp-send-command (6) # which \readlink | wc -w 14:18:13.731474 tramp-wait-for-regexp (6) # 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:13.734889 tramp-send-command (6) # \readlink --canonicalize-missing / 2>/dev/null; echo tramp_exit_status $? 14:18:13.923062 tramp-wait-for-regexp (6) # / tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:13.927893 tramp-send-command (6) # \readlink --canonicalize-missing /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:14.114515 tramp-wait-for-regexp (6) # /usr/local/sbin/poll_backends.py tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:14.200054 tramp-send-command (6) # which \stat | wc -w 14:18:14.385641 tramp-wait-for-regexp (6) # 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:14.388555 tramp-send-command (6) # env QUOTING_STYLE=locale \stat -c '("%N" %s)' / 2>/dev/null; echo tramp_exit_status $? 14:18:14.579195 tramp-wait-for-regexp (6) # ("‘/’" 4096) tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:14.679635 tramp-send-command (6) # (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /usr/local/sbin/poll_backends.py | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') 2>/dev/null; echo tramp_exit_status $? 14:18:14.872758 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:14.876711 tramp-send-command (6) # test -e / 2>/dev/null; echo tramp_exit_status $? 14:18:15.066949 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:15.068063 tramp-send-command (6) # test -e /\ this\ file\ does\ not\ exist\ 2>/dev/null; echo tramp_exit_status $? 14:18:15.251305 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:15.253773 tramp-send-command (6) # test -e /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:15.439035 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:15.441951 tramp-send-command (6) # test -h /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:15.627686 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:15.645997 tramp-send-command (6) # test -e /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:15.833544 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:15.843382 tramp-send-command (6) # test -e /usr/local/sbin 2>/dev/null; echo tramp_exit_status $? 14:18:16.029737 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:16.036952 tramp-send-command (6) # test -e /USR/LOCAL/SBIN 2>/dev/null; echo tramp_exit_status $? 14:18:16.223513 tramp-wait-for-regexp (6) # tramp_exit_status 1 14:18:16.464307 tramp-send-command (6) # test -d /usr/local/sbin/ 2>/dev/null; echo tramp_exit_status $? 14:18:16.648634 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:16.680172 tramp-send-command (6) # test -w /usr/local/sbin/ 2>/dev/null; echo tramp_exit_status $? 14:18:16.865035 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:17.090359 tramp-send-command (6) # (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /usr/local/sbin/poll_backends.py | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') 2>/dev/null; echo tramp_exit_status $? 14:18:17.280162 tramp-wait-for-regexp (6) # tramp_exit_status 0 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:17.282433 tramp-send-command (6) # test -e /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:17.471199 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ 14:18:17.483460 tramp-send-command (6) # test -h /usr/local/sbin/poll_backends.py 2>/dev/null; echo tramp_exit_status $? 14:18:17.667553 tramp-wait-for-regexp (6) # tramp_exit_status 1 ///9e801e5981007e5308671e52a92cc9f5#$ --8<---------------cut here---------------end--------------->8--- Tramp tries to read poll_backends.py, which isn't possible, because this file doesn't exist. 4 seconds. However, this is just the initial time. Whenever Tramp wants to apply a remote command it hasn't used yet (readlink, stat, "test -e" in this case), it applies sanity checks whether the command is applicable. This happens only once, next time Tramp wants to call the command it does it immediately. For sure, there's place for improvements. But many sanity checks cannot be avoided, because Tramp supports so different remote architectures. Best regards, Michael.
