Application startup time

Fri Oct 6 14:17:50 UTC 2017

On Fri, 2017-10-06 at 08:37 -0400, Janos Dohanics wrote:
> On Fri, 06 Oct 2017 22:25:16 +1030
> Wayne Sierke <ws at au.dyndns.ws> wrote:
> 
> > On Thu, 2017-10-05 at 13:33 -0400, Janos Dohanics wrote:
> > > Greetings,
> > > 
> > > I have a fairly recently built computer: i7-4790K CPU @ 4.00GHz,
> > > 32GB RAM, GeForce GT 730, FreeBSD 10.4-BETA2.
> > > 
> > > On this computer, I have thunderbird-52.3.0_3, installed from
> > > ports.
> > > 
> > > Thunderbird takes 38 seconds to start up, that is, from clicking
> > > the
> > > icon until Thunderbird offers a login prompt.
> > > [...]
> > 
> > Hi Janos,
> > 
> > Best guess is that 38s includes 30s of "network issue" (probably
> > dns)
> > delay time. Given that the Windows TB client doesn't appear to
> > suffer
> > from the same problem - and assuming that it is configured to
> > access
> > the same mail servers - that may help you isolate a network
> > configuration problem. A good place to start would be to compare
> > the
> > DNS configuration in FreeBSD vs the Windows VM.
> > 
> > The "freezes" are a bit curious. If they're repeatable (i.e. occur
> > in
> > response to a specific action) you could put TB into "offline" mode
> > and see if the freezes still occur. If they don't then they are
> > probably related to the same network issue.
> 
> Hi Wayne,
> 
> DNS doesn't seem to be the bottleneck:
> 
> $ time drill imap.telissant.net
> ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 49359
> ;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
> ;; QUESTION SECTION:
> ;; imap.telissant.net.	IN	A
> 
> ;; ANSWER SECTION:
> imap.telissant.net.	23887	IN	A	104.225.1.170
> 
> ;; AUTHORITY SECTION:
> 
> ;; ADDITIONAL SECTION:
> 
> ;; Query time: 0 msec
> ;; SERVER: 10.61.70.7
> ;; WHEN: Fri Oct  6 08:26:38 2017
> ;; MSG SIZE  rcvd: 52
> 
> real	0m0.029s
> user	0m0.001s
> sys	0m0.001s
> 
> 10.61.70.7 is the FreeBSD computer with the troublesome Thunderbird and
> also is the host for the Win7 virtual machine, which looks up
> 10.61.70.7 for DNS resolution.
> 
> However, I ran truss(1) which showed errors like:
> 
> 0.054980624 recvmsg(0x4,0x7fffffffdd40,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055094665 recvmsg(0x4,0x7fffffffddd0,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055193841 recvmsg(0x4,0x7fffffffdcc0,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055211203 recvmsg(0x4,0x7fffffffdcc0,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055297486 recvmsg(0x4,0x7fffffffdd60,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055314573 recvmsg(0x4,0x7fffffffdd60,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055435337 recvmsg(0x4,0x7fffffffddf0,0x0)      ERR#35 'Resource temporarily unavailable'
> 0.055452586 recvmsg(0x4,0x7fffffffddf0,0x0)      ERR#35 'Resource temporarily unavailable'
> 
> and many like these:
> 
> 0.657764282 _umtx_op(0x8013151a0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffddfccce8) ERR#60 'Operation timed out'
> 0.672757944 _umtx_op(0x8013152f0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdc3bec98) ERR#60 'Operation timed out'
> 0.688696796 _umtx_op(0x8013152f0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdc3bec98) ERR#60 'Operation timed out'
> 0.706338501 _umtx_op(0x8013152f0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdc3bec98) ERR#60 'Operation timed out'
> 
> and
> 
> 1.905534690 getpeername(40,0x7fffdfdfc778,0x7fffdfdfc744) ERR#57 'Socket is not connected'
> 1.967428986 getpeername(51,0x7fffdfdfc7a8,0x7fffdfdfc774) ERR#57 'Socket is not connected'
> 1.967580715 getpeername(51,0x7fffdfdfc970,0x7fffdfdfc934) ERR#57 'Socket is not connected'
> 1.997209982 getpeername(51,0x7fffdfdfc970,0x7fffdfdfc934) ERR#57 'Socket is not connected'
> 
> and
> 
> 6.783927993 _umtx_op(0x8013153e0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) ERR#4 'Interrupted system call'
> 6.784120019 sigreturn(0x7fffdafb3500)            ERR#4 'Interrupted system call'
> 103.644696383 _umtx_op(0x8013153e0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) ERR#4 'Interrupted system call'
> 103.644887820 sigreturn(0x7fffdafb3f40)          ERR#4 'Interrupted system call'
> 108.663319712 _umtx_op(0x8013153e0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) ERR#4 'Interrupted system call'
> 108.663460460 sigreturn(0x7fffdafb3f40)          ERR#4 'Interrupted system call'
> 113.668752752 _umtx_op(0x8013153e0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) ERR#4 'Interrupted system call'
> 
> Perhaps a bug in Thunderbird?

While hardly a thorough comparison I can tell you that I get what
appears to be a strikingly similar set of messages from truss with my
Thunderbird. Un(?)fortunately I would say those messages are probably
not significant.

Below are some events whose timing in particular might make for an
interesting comparison.

First dns server connection:
0.194129868 open("/etc/resolv.conf",O_CLOEXEC,0666) = 13 (0xd)
0.194383797 open("/etc/nsswitch.conf",O_CLOEXEC,0666) = 13 (0xd)
0.196764530 open("/etc/hosts",O_CLOEXEC,0666)	 = 13 (0xd)
0.197027552 connect(14,{ AF_INET 172.17.17.42:53 },16) = 0 (0x0)
0.197582820 recvfrom(14,"\f\M-:\M^E\M^@\0\^A\0\^A\0\^A\0"...,65536,0x0,{ AF_INET 172.17.17.42:53 },0x7fffffffb8dc) = 93 (0x5d)
0.320484741 connect(16,{ AF_INET 172.17.17.42:53 },16) = 0 (0x0)
0.321022309 recvfrom(16,"|\^]\M^E\M^@\0\^A\0\^A\0\^A\0\^A"...,65536,0x0,{ AF_INET 172.17.17.42:53 },0x7fffffffb86c) = 93 (0x5d)

First imap server connection and send/recv:
3.613094209 connect(46,{ AF_INET 172.17.17.142:993 },16) ERR#36 'Operation now in progress'
3.613132454 getpeername(46,0x7fffdf9fa970,0x7fffdf9fa934) ERR#57 'Socket is not connected'
3.614344524 sendto(46,"\^V\^C\^A\0\M^Q\^A\0\0\M^M\^C\^C"...,150,0x0,NULL,0x0) = 150 (0x96)
3.614382113 recvfrom(46,0x825157a80,5,0x0,0x0,0x0) ERR#35 'Resource temporarily unavailable'
3.687505051 recvfrom(46,"\^V\^C\^A\0005",5,0x0,NULL,0x0) = 5 (0x5)