Re: Tramp Debugging and Network Performance

[Michael Albinus]

suarezmiguelc@icloud.com writes:

> Sure Michael!,

Hi Miguel,

> Here’s an example of running find-file:
> (find-file
> "/ssh:miguel@172.28.3.249|sudo:expression_aws@172.28.3.249|ssh:admin@172.28.0.87|sudo:root@172.28.0.87:/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.