Hello, I wanted to discuss what looks like a possible performance issue on newer kernels and get some pointers on what we can do to investigate or resolve it.
In an earlier thread: https://www.mail-archive.com/[email protected]/msg108229.html I had raised a query about the performance difference we were seeing between two Postfix/OS environments (al2 with postfix 3.5 and al3 with postfix 3.11.1). Initially, I suspected OpenSSL was reason(https://github.com/openssl/openssl/issues/17627 and https://www.haproxy.com/blog/state-of-ssl-stacks), but that discussion helped us to rule out its not for us atleast. Since then, we have investigated this in much more detail. I will try to summarise what we are seeing. Old Env: Aamzon linux 2 (al2) with postfix 3.5.3 , kernel version 4.14 New Env: Amazone linux 3 (al3) with postfix 3.11.1 , kernel version 6.1 The main issue is that the AL3 environment appears noticeably slower than AL2, even though the Postfix configuration, machine capacity, and workload are effectively the same. Please note that we have a fleet of servers handling production traffic, and based on our internal statistics the workload is very similar across the AL2 and AL3 machines. Because of this, we believe the workload itself is not the main reason for the difference. I understand that there is a large jump in both the Postfix version and the OS/kernel version, so there are many possible variables involved. However, one very visible symptom on AL3 is that we see a much higher number of smtpd and cleanup processes being spawned This becomes especially noticeable during large bursts of incoming email. Since message processing appears to be slower on AL3, the smtpd processes start piling up much faster compared with AL2. From what I understand, this behaviour looks unusual, so I tried to trace it fluding at the kernel level. Please note that I am not a kernel expert. I have used LLM assistance to help ces and kernel behaviour, so please correct me if my interpretation or debugging direction is wrong. What I tested: I ran a small automated script on both environments to capture additional statistics whenever the smtpd process count crossed a certain threshold. On AL3, I used bpftrace with kprobe/kretprobe on locks_lock_inode_wait. On AL2, where the same tracing approach was not available, I used strace -T. From these tests, I found two observations that seem particularly interesting: 1. First observation; Between 15:06 and 15:08 UTC, the AL2 server had around 109–137 smtpd processes.During the same period, the AL3 server peaked at 341 smtpd processes. At that point, at least 53% of the active smtpd processes were waiting in locks_lock_iaffic imbalance, I also compared the number of connections handled by bothservers. Both were at roughly 8.4K connections, with a difference of only 6 connections between them. So, despite handling almost identical traffic, AL3 had significantly more smtpd processes active, with more than half of them waiting on inode/file locking. 2. Second observation: On another day, between approximately 17:30 and 17:32 Uon both environments. On AL2: smtpd peaked at 502 processes, cleanup peaked at 160 processes while on AL3: smtpd peaked at 658 processes , cleanup peaked at 173 processes The more interesting part was what happened after the spike. On AL2, the process counts started recovering toward the normal baseline relatively quickly. On AL3, however, the condition persisted. A separate continuous wchan sampler showed that the lock-related waanother 10 minutes and was actually getting worse during that period, while AL2 was already recovering. This suggests that the difference is not only in how high the process count spikes, but may also in how quickly the system is able to return to normal state. Stats Time (UTC) al3 smtpd in lock-wait % al2 smtpd in lock-wait % 17:40:0x 650 580 89.2% 185 0 17:40:2x 650 557 85.7% 183 0 0% 17:40:4x 650 551 84.8% 179 0 17:41:0x 650 545 83.8% 175 0 0% AL3 stayed pinned at 650 (its process ceiling) with 84-89% of all smtpd processes stuck on the lock for over a minute straight, while AL2 had zero processes in any lock-wait state at the same moments. Lock-wait distribution captured over the same 60s window (17:31-17:32) on both: mean p95 p99 max >=1s >=5s AL3 (n=993) 498.1ms 2733ms 13621ms 17051ms 7.55% 3.63% AL2 (n=14682) 0.03ms 0.2ms 0.5ms 26.9ms 0.00% 0.00% Median wait is 0ms on both -- most acquisitions are instant either way. The entire effect is in the tail: p99 differs by roughly 27000x. Caveat on the two n values: these aren't from the same instrumentation, so the counts themselves aren't directly comparable. strace -T on AL2 logs every flock() call the traced PIDs make, including the large majority that succeed instantly, which is why n is large there. The bpftrace probe on AL3 is a kprobe/kretprobe pair on the kernel's locks_lock_inode_wait() specifically, a narrower instrument. However both samples show that in al3 we are seeing significant higher number of smtpd process waiting for locks_lock_inode_wait lock A strong suspect is this kernel change https://lkml.iu.edu/1811.1/04878.html ahaviour which is not there in 4.1 but is there in 6.1. Some of the times during same workload i have seen al2 machines number of cleahile at al3 its 195. This is definitely not desired. It just seemed that process spawned were not dying off after a burst. Also I want to highlight a strace sample for cleanup process from both al2 and al3 to show the topmost time taking calls and here's it like , notice how al3 process has spent just more times compared to al2 . I have no during multiple iterations and difference at al3 is higher sometimes up to 17seconds in lock. cleanup wait on al3(10 to 9 seconds ) 10.247989 15:00:48.055370 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 < 10.064018 15:00:45.086426 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <10.064018> 10.063977 15:00:46.027174 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 < 10.021630 15:00:43.881359 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <10.021630> 10.016903 15:00:48.465303 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 < 10.001068 15:00:45.558471 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <10.001068> 9.991035 15:00:45.537511 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <9 9.955916 15:00:43.950398 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <9.955916> 9.952210 15:00:48.429505 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <9 9.944282 15:00:43.432689 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <9.944282> on al2 (5 seconds) 5.702913 15:00:48.126163 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <5 5.648998 15:00:41.919395 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <5.648998> 4.669568 15:00:54.152966 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <4 4.123999 15:01:22.847226 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <4.123999> 3.994816 15:00:54.416867 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <3 3.857762 15:01:20.168726 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <3.857762> 3.280578 15:00:43.437143 flock(8</mailspool/pid/unix.cleanup>, LOCK_EX) = 0 <3 I wanted to ask * Has anyone else observed smtpd/cleanup accept-lock contention get materiallyny pointers to the specific kernel commit/behavior change * Is the current debug direction right ?How do we move ahead from here. Since I am more on the systems admin background and not a kernel expert, would appreciate on how to debug this further. * I can provide any relevant script/metrics/observations if the community feels should be checked here. Adding the scripts used and outputs: - autocap_al3.sh (bpftrace capture script, AL3): https://drive.google.com/filehWULrq56iF/view?usp=sharing - autocap_al2.sh (strace capture script, AL2): https://drive.google.com/file/d/1MVbBTBrNc18utCzD3TMUhiZIZkfVoieA/view?usp=sharing - snapshot_normal_al3.txt (normal/calm output, AL3): https://drive.google.com/PNrqG21GSmhuOp/view?usp=sharing - snapshot_normal_al2.txt (normal/calm output, AL2): https://drive.google.com/file/d/173jiQiHQUYr4YzUtHWAfTJlmDUuNRdP-/view?usp=sharing - snapshot_spike_al3.txt (spike output, AL3): https://drive.google.com/file/d/bk6g2tW/view?usp=sharing - snapshot_spike_al2.txt (spike output, AL2): https://drive.google.com/file/d/1lhi6S9KvYCxogwxbTeDZHwCAWNWayrIK/view?usp=sharing - wchan_continuous_1740.txt (continuation output, both AL2 and AL3): https://duodnmshkHCcjjYNI2TmCk9VJP41kPj/view?usp=sharing _______________________________________________ Postfix-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
