[CentOS] Re: slow SMTP-AUTH

[Ugo Bellavance]

Ray Van Dolson wrote:
> On Wed, Jul 25, 2007 at 07:35:58PM -0400, Ugo Bellavance wrote:
>> Ugo Bellavance wrote:
>>> Brett Schroeder wrote:
>>>> Ugo Bellavance wrote:
>>>>> Hi,
>>>>>
>>>>>    I installed sendmail on a centos-4 openvz VM.  I set up SMTP-AUTH
>>>>> and when I try to send mail using this server, there is a big delay in
>>>>> which my e-mail client (Mozilla Thunderbird) just hangs.  The server, on
>>>>> the other hand, is idle at the same time.  It does that no matter if I
>>>>> use no encryption, TLS, or SSL.  When the client is 'hung' sendmail, on
>>>>> the server side haven't logged anything yet for this connection.
>>>>>
>>>>> Any idea?
>>>> Since nothing is logged on the server, it sounds like there is a 
>>>> firewall (or
>>>> other networking problem) in the way. You should use WireShark (or 
>>>> tcpdump) on
>>>> the client to capture the network traffic.
>> I disabled the firewall on the server, no luck.  I tried sniffing, I see 
>> nothing weird.
>>
>>   5.512292 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [PSH, 
>> ACK] Seq=350 Ack=10923 Win=17461 Len=53
>>   5.512984 72.55.149.51 -> 74.59.221.180 TCP submission > 17274 [PSH, 
>> ACK] Seq=10923 Ack=403 Win=7504 Len=277
>>   5.724172 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [ACK] 
>> Seq=403 Ack=11200 Win=17184 Len=0
>>  22.884013 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [PSH, 
>> ACK] Seq=403 Ack=11200 Win=17184 Len=53
>>  22.884918 72.55.149.51 -> 74.59.221.180 TCP submission > 17274 [PSH, 
>> ACK] Seq=11200 Ack=456 Win=7504 Len=85
>>  22.970714 74.59.221.180 -> 72.55.149.51 TLSv1 Application Data
>>  22.971120 72.55.149.51 -> 74.59.221.180 TLSv1 Application Data
>>
> 
> Can you run strace on sendmail during a connection and see what it's
> doing?  DNS is often the culprit when delays are concerned, so look for
> anything along those lines.
> 
> Ray

Here is an interesting part, but I can't tell why it took 2.292863 
seconds to do that:

09:07:47 time(NULL)                     = 1185455267 <0.000007>
09:07:47 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0 <0.000008>
09:07:47 select(8, [4 5 6 7], NULL, NULL, {5, 0}) = 1 (in [6], left {2, 
707000}) <2.292863>
09:07:49 accept(6, {sa_family=AF_INET, sin_port=htons(25919), 
sin_addr=inet_addr("74.59.221.180")}, [16]) = 9 <0.000023>
09:07:49 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000010>
09:07:49 time(NULL)                     = 1185455269 <0.000007>
09:07:49 pipe([10, 11])                 = 0 <0.000021>
09:07:49 rt_sigprocmask(SIG_BLOCK, [CHLD], [ALRM], 8) = 0 <0.000008>
09:07:49 clone(Process 16312 attached

Some operations are unfinished like this one:

[pid 31853] 09:07:49 select(8, [4 5 6 7], NULL, NULL, {5, 0} <unfinished 
...>


There is a 5-second gap here (from one PID to the other, weird):

[pid 16312] 09:07:49 time(NULL)         = 1185455269 <0.000010>
[pid 16312] 09:07:49 read(9, 0x8968260, 5) = -1 EAGAIN (Resource 
temporarily unavailable) <0.000012>
[pid 16312] 09:07:49 time(NULL)         = 1185455269 <0.000009>
[pid 16312] 09:07:49 select(10, [9], NULL, [9], {3600, 0} <unfinished ...>
[pid 31853] 09:07:54 <... select resumed> ) = 0 (Timeout) <4.999631>
[pid 31853] 09:07:54 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000008>
[pid 31853] 09:07:54 time(NULL)         = 1185455274 <0.000008>
[pid 31853] 09:07:54 open("/proc/loadavg", O_RDONLY) = 9 <0.000037>
[pid 31853] 09:07:54 fstat64(9, {st_mode=S_IFREG|0444, st_size=0, ...}) 
= 0 <0.000008>
[pid 31853] 09:07:54 read(9, "0.01 0.02 0.00 3/49 16395\n", 1024) = 26 
<0.000015>
[pid 31853] 09:07:54 close(9)           = 0 <0.000013>
[pid 31853] 09:07:54 time(NULL)         = 1185455274 <0.000007>
[pid 31853] 09:07:54 open("/proc/loadavg", O_RDONLY) = 9 <0.000015>