Sendmail slow?

[Knute Johnson]

Smoot Carl-Mitchell wrote:
> On Sat, 2009-02-14 at 17:15 -0800, Knute Johnson wrote:
>> Smoot Carl-Mitchell wrote:
>>> You might try running strace on the listening SMTP process with timer
>>> option to see where the delay is creeping in.  Something like
>>>
>>> sudo strace -f -p <pid> -o <output_file> -t
>>>
>>> You need the -f to pick up the forked processes as the listening
>>> sendmail handles the connections.  The -t will give you timestamps on
>>> each system call.
>> I sent the whole output but it was too big and rejected.  Anyway, this 
>> shows a 5 second gap but I don't know what it really means.  If you can 
>> decipher it, great!
>>
>> Thanks,
>>
> 
> Here is the blow by blow.
> 
> Read /etc/resolv.conf.  Likely getting the names of your nameservers.
>> 5092  17:05:19 stat64("/etc/resolv.conf", {st_mode=S_IFREG|0644, 
>> st_size=91, ...}) = 0
>> 5092  17:05:19 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 5
> 
> Connect to 207.181.0.10 (would not happen to be one of your
> nameservers?)  The connection descriptor is 5.
>> 5092  17:05:19 connect(5, {sa_family=AF_INET, sin_port=htons(53), 
>> sin_addr=inet_addr("207.181.0.10")}, 28) = 0
>> 5092  17:05:19 poll([{fd=5, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
> 
> Send a request to descriptor 5.  This does look like a DNS request.
>> 5092  17:05:19 send(5, 
>> "\331S\1\0\0\1\0\0\0\0\0\0\6knute2\faerioconnect"..., 41, MSG_NOSIGNAL) = 41
>> 5092  17:05:19 poll([{fd=5, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
>> 5092  17:05:19 ioctl(5, FIONREAD, [57]) = 0
> 
> Read the response.
>> 5092  17:05:19 recvfrom(5, 
>> "\331S\205\200\0\1\0\1\0\0\0\0\6knute2\faerioconnect"..., 1024, 0, 
>> {sa_family=AF_INET, sin_port=htons(53), 
>> sin_addr=inet_addr("207.181.0.10")}, [16]) = 57
> 
> Close the connection.
>> 5092  17:05:19 close(5)                 = 0
> 
> Now set up a socket on port 587 which is the submit port. This is using
> descriptor 8. What is host 216.240.58.140, BTW?
>> 5092  17:05:19 getsockname(8, {sa_family=AF_INET, sin_port=htons(587), 
>> sin_addr=inet_addr("216.240.58.140")}, [16]) = 0
> 
> Read /etc/services.
>> 5092  17:05:19 open("/etc/services", O_RDONLY|0x80000 /* O_??? */) = 5
>> 5092  17:05:19 fstat64(5, {st_mode=S_IFREG|0644, st_size=18449, ...}) = 0
>> 5092  17:05:19 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
>> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ed6000
>> 5092  17:05:19 read(5, "# Network services, Internet sty"..., 4096) = 4096
>> 5092  17:05:19 close(5)                 = 0
> 
> 
>> 5092  17:05:19 munmap(0xb7ed6000, 4096) = 0
>> 5092  17:05:19 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
>> 5092  17:05:19 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
>> 5092  17:05:19 time(NULL)               = 1234659919
>> 5092  17:05:19 rt_sigaction(SIGALRM, {0xb7f9e170, [], SA_RESTART}, 
>> {0xb7f9e170, [], SA_RESTART}, 8) = 0
> 
> Set an alarms for 5 seconds.
>> 5092  17:05:19 alarm(5)                 = 0
>> 5092  17:05:19 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0
> 
> New socket on descriptor 5.
>> 5092  17:05:19 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 5
> 
> Bind it to the address 216.240.58.140 which I assume is one of your
> local interface addresses.
>> 5092  17:05:19 bind(5, {sa_family=AF_INET, sin_port=htons(0), 
>> sin_addr=inet_addr("216.240.58.140")}, 16) = 0
> 
> And connect on descriptor 5.  This is connecting on port 113 which
> looking at /etc/services is the auth port. This trying to authenticate
> the sender of the email using the AUTH protocol. See RFC1413.  Your
> sendmail is trying to use AUTH to detemine the identity of the sender.
> You can disable this in your sendmail.mc file by adding
> 
> define(`confTO_IDENT',    `0s')dnl
> 
> to your sendmail.mc and yor submit.mc file after the include for
> debian-mta or debian-msp and redoing the make in /etc/mail.
>  
>> 5092  17:05:19 connect(5, {sa_family=AF_INET, sin_port=htons(113), 
>> sin_addr=inet_addr("216.240.58.138")}, 16 <unfinished ...>
> 
> 
> The alarm is triggered after 5 seconds which is the delay you are
> seeing.  So the AUTH protocol is the source of the delay.
>> 16288 17:05:24 <... select resumed> )   = 0 (Timeout)
> 

That's it!  No delay at all now.  Thanks very much for helping me figure 
this out.

-- 

Knute Johnson

"The urge to save humanity is almost always a false front for the urge 
to rule."

   H.L. Mencken