On Wednesday, 27 March 2019 20:01:49 CET Viktor Dukhovni wrote: > On Wed, Mar 27, 2019 at 03:36:28PM +0100, Juliana Rodrigueiro wrote: > > However, during a benchmark, we realized 3.3.2 was 5 times slower than the > > version before. > > This is misleading. Postfix is not 5 times slower, your benchmark > appears to be measuring the LMTP delivery rate to a single sink > mailbox, and this artificial work-load may be slower under some > adverse conditions (below...). >
Although the benchmark produces a very large artificial work-load, this scenario is still a very valid use case, even more considering that 20 emails are enough to clog up deliveries. The stark difference between the LMTP server (cyrus 2.4) log messages is that most deliveries reuse the same session id when running postfix <= 2.11.0: Mar 28 10:22:22 localdomain lmtpunix[4881]: auditlog: append sessionid=<localdomain.com-4881-1553764942-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28047> guid=<521e5e4a35095385881941a77f3035f6087c8942> Mar 28 10:22:22 localdomain lmtpunix[4881]: Delivered: <20190328092221.f2f6...@localdomain.com> to mailbox: user.dst Mar 28 10:22:22 localdomain lmtpunix[4881]: USAGE dst user: 0.000000 sys: 0.000000 Mar 28 10:22:22 localdomain lmtpunix[4926]: auditlog: append sessionid=<localdomain.com-4926-1553764942-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28048> guid=<baa35444706bddf1963624e672905db77cce131a> Mar 28 10:22:22 localdomain lmtpunix[4926]: Delivered: <20190328092222.0044...@localdomain.com> to mailbox: user.dst ... ... Mar 28 10:22:22 localdomain lmtpunix[4926]: auditlog: append sessionid=<localdomain.com-4926-1553764942-5> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28060> guid=<0dc9e922f8b8cfc01ccc5bfeafa8220812adf8fa> Mar 28 10:22:22 localdomain lmtpunix[4926]: Delivered: <20190328092222.0da1...@localdomain.com> to mailbox: user.dst Mar 28 10:22:22 localdomain lmtpunix[4926]: USAGE dst user: 0.000000 sys: 0.004000 Mar 28 10:22:22 localdomain lmtpunix[6449]: auditlog: append sessionid=<localdomain.com-6449-1553764942-5> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28061> guid=<781d02ef98dde39e03461a60aa18beb858f8a5d2> Mar 28 10:22:22 localdomain lmtpunix[6449]: Delivered: <20190328092222.0ea9...@localdomain.com> to mailbox: user.dst In the other hand, for version >= 2.11.1, the sessions are used once per process. Mar 28 10:04:06 localdomain lmtpunix[4273]: Delivered: <20190328090404.7cf8...@localdomain.com> to mailbox: user.dst Mar 28 10:04:06 localdomain lmtpunix[4273]: USAGE dst user: 0.004000 sys: 0.000000 Mar 28 10:04:06 localdomain lmtpunix[4292]: auditlog: append sessionid=<localdomain.com-4292-1553763846-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28032> guid=<165f88d841750f2cc9a59a74e777ada4c884dae3> Mar 28 10:04:06 localdomain lmtpunix[4292]: Delivered: <20190328090404.7dee...@localdomain.com> to mailbox: user.dst Mar 28 10:04:06 localdomain lmtpunix[4292]: USAGE dst user: 0.000000 sys: 0.000000 Mar 28 10:04:06 localdomain lmtpunix[4295]: auditlog: append sessionid=<localdomain.com-4295-1553763846-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28033> guid=<f8c75569e69424c3b529a6e5c228e416518c48d5> ... ... Mar 28 10:04:10 localdomain lmtpunix[4295]: auditlog: append sessionid=<localdomain.com-4295-1553763850-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28041> guid=<7ba5808ec13795785ab5a5737cfef97ff24d307a> Mar 28 10:04:10 localdomain lmtpunix[4295]: Delivered: <20190328090404.87ac...@localdomain.com> to mailbox: user.dst Mar 28 10:04:10 localdomain lmtpunix[4295]: USAGE dst user: 0.000000 sys: 0.004000 Mar 28 10:04:12 localdomain lmtpunix[4273]: auditlog: append sessionid=<localdomain.com-4273-1553763852-1> mailbox=<user.dst> uniqueid=<3aab65ba5c98d020> uid=<28042> guid=<8ee41c08e69e9cdf9be61b2f2bad1a2d2c590f12> Mar 28 10:04:12 localdomain lmtpunix[4273]: Delivered: <20190328090404.88ae...@localdomain.com> to mailbox: user.dst > > 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 > This delivery spent 6s waiting in the active queue and 2s to complete > a connection. Why are connections to the LMTP server so expensive? > Is your syslog service logging synchronously? Perhaps logging of > connection establishment (in the LMTP server) is causing congestion > at LMTP connect? What is the LMTP server doing in connect and LHLO > processing? > Unlikely, the LMTP server doesn't log any more or less than it did before. > > -#define HAVE_NEXTHOP_STATE(state) > > (STR((state)->iterator->request_nexthop) != 0) > > +#define HAVE_NEXTHOP_STATE(state) > > (STR((state)->iterator->request_nexthop)[0] != 0) > That's a necessary bugfix, without it the test is always true. > I understand the necessary fix, and that is why I was puzzled by the behaviour change. > > Questions: > > > > (1) Does it mean that the lmtp connections via socket are never cached or > > reused? > There is no caching by nexthop domain, since there is no nexthop > domain for unix-domain LMTP sockets. All there is is a nexthop > socket address. So session caching, if any, would naturally be > just by endpoint address. However, in 2.11 the smtp_connect_local() > function also changed: > > > https://github.com/vdukhovni/postfix/commit/072fa2d1f7beaf41756c30a69ef96cb > 611461cec#diff-24650cb98191c311688117b61626fffbR506 > > to use smtp_reuse_nexthop() rather than smtp_reuse_addr(), so that > SASL authenticated connections might be re-used, but this looks > like a mistake, since we're therefore creating cached sessions that > will never be re-used, but that tie up LMTP server resources, > possibly leading to subsequent congestion under load. > It would then make sense that the LMTP server is busy with the open connections until it is finally closed after an inactivity timeout (probably the 2 seconds we see). Also, in my setup there are maximum 4 LMTP process, which then caps the deliveries by 2 emails per second. On Wednesday, 27 March 2019 20:24:29 CET Wietse Venema wrote: > > What kind of LMTP server are you using? > I'm using cyrus 2.4. > > To get rid of the 2s delays: > > /etc/postfix/main.cf: > lmtp_connection_cache_on_demand = no > > Please let us know if that helps. Meanwhile we can develop a proper fix. And yes, it worked, that helped a lot. Although not as fast as before, but now I see only reasonable delays. Thank you very much for looking into it!!! Julie.
