postfix takes 60-90ms to queue email -- normal?

We're seeing some (maybe?) strange delays when submitting individual emails to our local Postfix server.

To help diagnose the issue, I wrote a little test program which sends 5 emails:

get smtp 1ms   (  1 ms)
email 0 677ms  (676 ms)
email 1 802ms  (125 ms)
email 2 890ms  ( 88 ms)
email 3 973ms  ( 83 ms)
email 4 1088ms (115 ms)

Discounting the handshaking in the first email, that's about 90ms per email. These timings have also been corroborated with another test app written by someone else using a different codepath, so it appears to be server related.

I turned on detailed logging and I can see that the delay is between the end of message \r\n\r\n and the receive:

[16:31:29.95] [SEND] \r\n.\r\n
[16:31:30.05] [RECV] 250 2.0.0 Ok: queued as B128E1E063\r\n

[16:31:30.08] [SEND] \r\n.\r\n
[16:31:30.17] [RECV] 250 2.0.0 Ok: queued as 4A7DE1E06E\r\n

[16:31:30.19] [SEND] \r\n.\r\n
[16:31:30.27] [RECV] 250 2.0.0 Ok: queued as 68ACC1E072\r\n

[16:31:30.28] [SEND] \r\n.\r\n
[16:31:30.34] [RECV] 250 2.0.0 Ok: queued as 7EFFE1E079\r\n

[16:31:30.39] [SEND] \r\n.\r\n
[16:31:30.45] [RECV] 250 2.0.0 Ok: queued as 9793C1E07A\r\n

The time intervals tell the story (discounting the handshaking required for the initial email) -- each email is waiting about 60-90 milliseconds for postfix to queue!

This seems .. excessive .. to me. Is it "normal" for postfix to take 60-90 ms for every email you send it? Or do I just have unreasonable expectations? I would expect the local postfix server to queue the email in about 20ms, tops!

That sounds normal. If you run multiple connections in parallel submitting mail, do you still get 90ms per mail? This will let you easily raise your rate that you can submit mail.

I know that other MTAs (sendmail) will fsync() to ensure that the accepted mail is committed to disk before sending back the 250 response, so that email doesn't get dropped if the system crashes after accepting the mail. postfix probably does as well.

You could test this by putting the mail spool directory onto tmpfs temporarily and seeing how long it takes to accept mail.

Other things that it could be doing during that 90ms window are: virus scanning, blacklist checking, etc. But you'd probably know if they were configured.

Postfix best practices say that you should do most of the filtering before the initial queue to avoid:

1. wasting resources in messages you shouldn't accept in the first place;
2. avoid sending error messages back (therefore spending the resources for the original email and the error message);
3. avoiding sending error messages to wrong recipients.

So, queuing time is not optimized to save resources. If you disable all the checks in smtpd_recipient_restrictions in postfix's main.cf you can probably get faster queuing at the cost of more errors and getting more (wrong) error messages to users. That would be perfectly acceptable if it's only the egress server for an application, for instance.