Hi Wietse,
Following up with a cleaner test of the DNS theory.
I wrote a small bpftrace script that hooks the relevant kernel functions
directly (system-wide, rather than attaching to a particular PID list),
so it also captures newly spawned workers:
*
|locks_lock_inode_wait| — the same accept-lock wait we have been
measuring all along.
*
|udp_recvmsg|, filtered to sockets connected to port 53 — the kernel
receive path for UDP DNS responses.
The script runs cleanly on plain upstream kernels and does not depend on
anything AL-specific.
I ran this continuously, automatically triggering a 60-second capture
whenever the smtpd process count crossed a threshold. Today it caught a
real event, with smtpd peaking at 417 processes and cleanup at 354.
From that exact capture window:
|mean p95 p99 max >=1s >=5s cleanup lock 3611.1ms 17826ms 18498ms
18498ms 35.4% 27.3% smtpd lock 230.6ms 1994ms 5019ms 5694ms 6.2% 1.0%
cleanup dns n=0 smtpd dns n=10496 mean=0.0ms p95=0ms p99=0ms max=0ms
>=1s: 0 >=5s: 0 |
Cleanup never calls into DNS in this path; it canonicalizes/enqueues a
message that smtpd has already accepted, so there are no
recipient/client DNS checks there.
For smtpd, we observed 10,496 UDP DNS receive calls during the capture
window. None took even 1 ms according to this instrumentation. In other
words, the DNS waits were below the measurement resolution throughout
the event.
This makes DNS look very unlikely to be a contributor to this particular
incident.
For context, here are the plain process counts over the same 60-second
capture window (13:36:05–13:37:05), from a separate poller running
independently of bpftrace:
|13:36:02 smtpd=395 cleanup=328 13:36:32 smtpd=414 cleanup=354 13:37:02
smtpd=412 cleanup=354 |
The complete bpftrace output for this capture is here:
autocap_bpftrace_full_t400_133605.log :
https://drive.google.com/drive/folders/1W5iuptm0Efzgk2seDTVcvwgrdLAvvLJ9
So at this point, we seem to have ruled out the two explanations we know
how to test so far:
1.
Traffic volume — we confirmed that traffic was equal between the
fleets during a divergent event.
2.
DNS — the DNS receive path showed no measurable waits during this event.
What remains is the lock itself. During the same event, smtpd
experienced accept-lock waits of up to 5.7 seconds, while cleanup
experienced waits of up to 18.5 seconds.
Given this, is there any additional data that would help diagnose what
is causing the lock contention, or is there another angle you think we
should investigate?
We now have the box fully instrumented and can capture the next real
event within a couple of minutes of it starting, so I am happy to run
any additional tracing or collect any other kernel/Postfix data that
would be useful.
Thanks again for engaging with this.
Rajesh Mishra
On 28/08/26 8:53 pm, Wietse Venema via Postfix-users wrote:
Postfix daemons waiting for a lock on queue_directory/pid/smtpd
and queue_directory/pid/smtpd are a symptom: there are more smtpd
and cleanup service daemon processes than the number of connections
to the smtpd and cleanup service at that point in time. The idle
processes are the residue of a recent burst in traffic. They do not
slow down Postfix.
The number of processes will peak at a number that depends on traffic
volume (duh) AND on the time to service an SMTP client.
My educated guess is that Postfix is taking more time in DNS
lookups: in the SMTP daemon doing in FCRDNS checks; or in anti-spam
software, doing DNS reputation lookups.
See also:https://en.wikipedia.org/wiki/Forward-confirmed_reverse_DNS
Wietse
_______________________________________________
Postfix-users mailing list [email protected]
To unsubscribe send an email [email protected]
_______________________________________________
Postfix-users mailing list -- [email protected]
To unsubscribe send an email to [email protected]
