Well I've started trying to diagnose this, I'm less sure now that it
only happens across the ssh connection, that may be a red herring.
I've changed the main disk drive on my dekstop system (where mutt
runs) from a 1TB spinning hard disk to a 1TB SSD and I *think* the
slowness may be related to this.
With the SSD some things are *much* faster, e.g. loading a 5000
message mbox (my 'sent' mailbox) is almost instant now whereas it used
to take several seconds. So the SSD is faster in general, a *lot*
faster.
I have the recommended trace running and the only significant delays I
can see are:-
...
...
...
12:40:19.110589 write(1, "\r\33[J\33[H\33[30m\33[46m---Mutt: ~/Mail"...,
3622) = 3622
12:40:19.110737 rt_sigaction(SIGINT, {sa_handler=0x55bca4ac2440,
sa_mask=[], sa_flags=SA_RESTORER, sa_restor er=0x7f00502f1470}, NULL, 8) = 0
12:40:19.110791 write(1, "\33[?1h\33=", 7) = 7
12:40:19.110826 poll([{fd=0, events=POLLIN}], 1, 15000) = 1 ([{fd=0,
revents=POLLIN}])
12:40:25.110942 read(0, "c", 1) = 1
12:40:25.111099 rt_sigaction(SIGINT, {sa_handler=0x55bca4ac2440,
sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART , sa_restorer=0x7f00502f1470},
NULL, 8) = 0
12:40:25.111211 write(1, "\33[?12l\33[?25h", 12) = 12
12:40:25.111433 stat("/home/chris/Mail/In/inbox", {st_mode=S_IFREG|0600,
st_size=3065472, ...}) = 0
12:40:25.111575 stat("/var/mail/chris", {st_mode=S_IFREG|0600, st_size=726,
...}) = 0
12:40:25.111649 stat("/home/chris/Mail/In/inbox", {st_mode=S_IFREG|0600,
st_size=3065472, ...}) = 0
12:40:25.111712 stat("/home/chris/Mail/Li/alug", {st_mode=S_IFREG|0600,
st_size=298691, ...}) = 0
...
...
...
12:40:25.115157 stat("/home/chris/Mail/In/odin", {st_mode=S_IFREG|0600,
st_size=1083391, ...}) = 0
12:40:25.115348 write(1, "\r\33[60dOpen mailbox ('?' for list"..., 55) = 55
12:40:25.115450 rt_sigaction(SIGINT, {sa_handler=0x55bca4ac2440,
sa_mask=[], sa_flags=SA_RESTORER, sa_restor er=0x7f00502f1470}, NULL, 8) = 0
12:40:25.115552 read(0, "\r", 1) = 1
12:40:27.765854 rt_sigaction(SIGINT, {sa_handler=0x55bca4ac2440,
sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART , sa_restorer=0x7f00502f1470},
NULL, 8) = 0
12:40:27.766147 write(1, "\33[60;13H: \33[K\33(B\33[m", 19) = 19
12:40:27.766445 write(1, "~/Mail/Li/x2go\33(B\33[m", 20) = 20
12:40:27.766650 stat("/home/chris/Mail/Li/x2go", {st_mode=S_IFREG|0600,
st_size=264290, ...}) = 0
...
...
...
12:40:27.766999 utime("/home/chris/Mail/Li/x2go", {actime=1577968429 /*
2020-01-02T12:33:49+0000 */, modtime =1577968434 /* 2020-01-02T12:33:54+0000
*/}) = 0
12:40:27.767127 write(1, "\r\33[32mMailbox is unchanged.\33[39m"..., 41) =
41
12:40:27.767183 stat("/home/chris/Mail/In/inbox", {st_mode=S_IFREG|0600,
st_size=3065472, ...}) = 0
12:40:27.767243 utime("/home/chris/Mail/In/inbox", {actime=1577968819 /*
2020-01-02T12:40:19+0000 */, modtim e=1577966702 /* 2020-01-02T12:05:02+0000
*/}) = 0
12:40:27.767325 close(3) = 0
12:40:27.767468 nanosleep({tv_sec=1, tv_nsec=0}, 0x7fff86fc8060) = 0
12:40:28.767837 lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
12:40:28.768113 lstat("/home/chris", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
...
...
...
I *think* the one that is the delay I'm seeing is that two and a half
second delay after read(0, "\r", 1). I guess the long delays after
poll(...) are what one would expect as it's mutt waiting for me to do
something, and the one second delay at nanosleep() is as coded.
So, what's that read() doing that takes so long?
--
Chris Green
