Re: Tramp Debugging and Network Performance

[suarezmiguelc]

Thank you for the amazingly detailed response, I’m impressed by the technical 
details here, as I’m interested in elisp and tramp itself.

Right now I’ve made some improvements as to set key file authentication, which 
I’m sure it has to improve this process. I will test the same find-file with 
the variable tweaks you mentioned.

Now, the thing where I’m most concerned is the 8 seconds of the initialisation, 
due to the network latency and the limited remote machine cpu. The destination 
remote server itself isn’t slow, but the VPN connection itself is done through 
a t2.micro server with PritunlVPN, would be safe to say that this is one of the 
main culprits?

As this is a corporate connection, I would need to come with a technical 
explanation and proof of this, would these calls be enough, or can I debug 
further? <- I’m the only one using Emacs and Tramp, so I’m a specific case.

> 14/3/23 17:57、Michael Albinus <michael.albinus@gmx.de>のメール:
> 
> 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.