Take the 2-minute tour ×
Server Fault is a question and answer site for system and network administrators. It's 100% free, no registration required.

We'd like to deploy a high-volume SMTP server (double opt-in lists), but discovered two of our Ubuntu servers take about 1s to send a single message.

When sending an email by hand, the delay occurs after closing off the data section of the message (between L#3 & L#4, see below) and appears to us as if Postfix is sluggish in adding the item to the active queue.

DATA
354 End data with <CR><LF>.<CR><LF>
Message goes here
.
250 2.0.0 Ok: queued as 0DB032015E

I'm not familiar with Postfix and would appreciate any help. Our servers are a freshly installed pair of Ubuntu 9.10 boxes with RAID1 drives that report about 60mb/sec with hdparam. We've fooled around with settings like in_flow_delay, but arne't having much luck.

Additional Information

Thanks for the tips. It appeared that disk speed was a limiting factor for other people, so I wanted to cover that first.

As for DNS, the server is setup with a proper FQDN and reverse. No DNS server to begin with, and bind setup as a local caching server hasn't improved much. And as a note, I do notice a line in the log reading: delay=0.79, if that gives anyone any ideas.

postconf -n

alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
config_directory = /etc/postfix
debug_peer_list = octane.to
inet_interfaces = all
inet_protocols = ipv4
mailbox_command = procmail -a "$EXTENSION"
mailbox_size_limit = 0
mydestination = inferno.octane.to.local, octane.to.local, localhost
myhostname = inferno.octane.to
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128
myorigin = /etc/mailname
readme_directory = no
recipient_delimiter = +
relayhost =
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu)
smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
smtpd_tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes

mail.log, cleaned up

smtpd[3413]: improper command pipelining after HELO from localhost[127.0.0.1]
smtpd[3413]: 3CFEB20160: client=localhost[127.0.0.1]
cleanup[3417]: 3CFEB20160: message-id=<20091118231505.3CFEB20160@inferno.octane.to>
qmgr[3392]: 3CFEB20160: from=<tyler@octane.to>, size=360, nrcpt=1 (queue active)
smtpd[3413]: disconnect from localhost[127.0.0.1]
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 220 hotrod.octane.to ESMTP Sendmail 8.13.8/8.13.8; Wed, 18 Nov 2009 18:15:05 -0500
smtp[3418]: > mail.octane.to[76.74.234.28]:25: EHLO inferno.octane.to
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-hotrod.octane.to Hello inferno.octane.to [76.74.234.11], pleased to meet you
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-ENHANCEDSTATUSCODES
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-PIPELINING
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-8BITMIME
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-SIZE
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-DSN
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-ETRN
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250-DELIVERBY
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250 HELP
smtp[3418]: server features: 0x900f size 0
smtp[3418]: Using ESMTP PIPELINING, TCP send buffer size is 4096
smtp[3418]: > mail.octane.to[76.74.234.28]:25: MAIL FROM:<tyler@octane.to> SIZE=360
smtp[3418]: > mail.octane.to[76.74.234.28]:25: RCPT TO:<test@octane.to> ORCPT=rfc822;test@octane.to
smtp[3418]: > mail.octane.to[76.74.234.28]:25: DATA
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250 2.1.0 <tyler@octane.to>... Sender ok
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250 2.1.5 <test@octane.to>... Recipient ok
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 354 Enter mail, end with "." on a line by itself
smtp[3418]: > mail.octane.to[76.74.234.28]:25: .
smtp[3418]: > mail.octane.to[76.74.234.28]:25: QUIT
smtp[3418]: < mail.octane.to[76.74.234.28]:25: 250 2.0.0 nAINF5wx003171 Message accepted for delivery
smtp[3418]: 3CFEB20160: to=<test@octane.to>, relay=mail.octane.to[76.74.234.28]:25, delay=0.79, delays=0.45/0/0.04/0.3, dsn=2.0.0, status=sent (250 2.0.0 nAINF5wx003171 Message accepted for delivery)
smtp[3418]: name_mask: resource
smtp[3418]: name_mask: software
qmgr[3392]: 3CFEB20160: removed

Checking two machines -- screencast

I have two machines with near identical configurations. Setup Ironhide, a clone of Inferno (the machine that's giving me problems.). Here's a screencast walking through a batch deployment, logs and some basic configuration.

Screencast ((Link Removed))

share|improve this question
    
"double opt-in" is spammer-speak. –  womble Nov 18 '09 at 20:46
    
Cranking up the logging and including what those say during/around the delay would be helpful. –  blahdiblah Nov 18 '09 at 22:41

1 Answer 1

Unless other symptoms on the box in question point to IO, I'm not sure why you're checking the hard drives and related config.

My first guess is DNS-related, as everything postfix does as an MTA is tied to DNS. However, guessing is not very productive - perhaps showing us your current settings would be helpful. Run the following command:

# postconf -n

And paste the output for those reading this question - obviously sanitise as necessary, the Internet being what it is. FYI, per the postconf man page, the -n flag prints "parameter settings that are not left at their built-in default value, because they are explicitly specified in main.cf"

@womble: "double opt-in" is also Marketing-speak.

UPDATE

From the screencast, only thing of interest I noted was the "delays=" bit in the logs. According to the release notes:

Postfix logs additional delay information as "delays=a/b/c/d" where a=time before queue manager, including message transmission; b=time in queue manager; c=connection setup time including DNS, HELO and TLS; d=message transmission time.

Seems messages from inferno have the largest portion of their delay in a, whereas messages from ironhide have theirs in d... which according to the notes above translates as inferno's message spending the majority of its time before the queue manager (including message transmission), and ironhide's message spending the majority of its time in message transmission.

Not sure what this means, but hope it helps in your search. :)

share|improve this answer
    
Without timestamps in your log snippet, it's difficult to theorise, but I would suggest getting a larger sampling of mails, sending to various MX servers, to see if the problem originates within your own network or not. And the delay=xx is the measurement in seconds of the amount of time spent inside the postfix queue. 0.79 seems okay for a single message - would the average of many different recipients be higher or lower? –  Zayne S Halsall Nov 21 '09 at 14:47
    
I'm leaning towards a networking issue, but I can't discover what for the life of me would simply delay the messages. I've added a link to a screen cast to the message, that's my last straw for troubleshooting... –  rooney Nov 23 '09 at 19:23
    
FYI, due to character limit in comments, added feedback to my original "answer"... hth. –  Zayne S Halsall Nov 29 '09 at 11:17

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.