Juliana Rodrigueiro:
> Excerpt of maillog version > 2.11.1:
> Mar 27 14:46:50 localdomain postfix/lmtp[24750]: 6CEFF61:
> to=<d...@localdomain.com>, orig_to=<dst@localhost>,
> relay=localdomain.com[/var/
> imap/socket/lmtp], delay=0.02, delays=0.01/0/0.01/0, dsn=2.1.5, status=sent
> (250 2.1.5 Ok SESSIONID=<localdomain.com-24421-1553694410-1>)
> Mar 27 14:46:50 localdomain postfix/lmtp[24752]: 6E8CE63:
> to=<d...@localdomain.com>, orig_to=<dst@localhost>,
> relay=localdomain.com[/var/
> imap/socket/lmtp], delay=0.02, delays=0/0/0.01/0.01, dsn=2.1.5, status=sent
> (250 2.1.5 Ok SESSIONID=<localdomain.com-24753-1553694410-1>)
> Mar 27 14:46:50 localdomain postfix/qmgr[24339]: 6E8CE63: removed
The a/b/c/d delays logging shows:
a = time from message arrival to last active queue entry
b = time from last active queue entry to connection setup
c = time in connection setup, including DNS, EHLO and STARTTLS
d = time in message transmission
Here the delays are 0.01s or less.
> Mar 27 14:46:52 localdomain postfix/lmtp[24752]: 764A06A:
> to=<d...@localdomain.com>, orig_to=<dst@localhost>,
> relay=localdomain.com[/var/
> imap/socket/lmtp], delay=2, delays=0/2/0/0, dsn=2.1.5, status=sent (250 2.1.5
> Ok SESSIONID=<localdomain.com-24757-1553694412-1>)
The message had to wait 2s until a delivery agent became available, for
reasons that will become clear later.
> Mar 27 14:46:54 localdomain postfix/lmtp[24750]: 778DC61:
> to=<d...@localdomain.com>, orig_to=<dst@localhost>,
> relay=localdomain.com[/var/
> imap/socket/lmtp], delay=4, delays=0.01/2/2/0.02, dsn=2.1.5, status=sent (250
> 2.1.5 Ok SESSIONID=<localdomain.com-24421-1553694414-1>)
The message had to wait 2s until a delivery agent became available,
and then it spent 2s in connection setup (including DNS lookup).
> Mar 27 14:46:58 localdomain postfix/lmtp[24750]: 7CFDE72:
> to=<d...@localdomain.com>, orig_to=<dst@localhost>,
> relay=localdomain.com[/var/
> imap/socket/lmtp], delay=8.1, delays=0/6/2/0.02, dsn=2.1.5, status=sent (250
> 2.1.5 Ok SESSIONID=<localdomain.com-24421-1553694418-1>)
This message had to wait 6s until a delivery agent became available,
and then it spent 2s in connection setup (including DNS lookup).
There is a clear pattern in here: under load, the LMTP client spends
2s in connection setup (including DNS lookup).
Also, the connections are not reused, which may be the result of a
Postfix change that I will look into.
But connection reuse is an optimization; it should never take 2s
to set up an LMTP connection, not even if the LMTP server is on the
other side of the world.
The core problem is that under load, it takes 2s to set up an LMTP
connection. If you can fix that, then Postfix will perform fine
with or without connection reuse.
What kind of LMTP server are you using?
Wietse
