Bug 243531
| Summary: | Unstable ena and nvme on AWS | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Base System | Reporter: | Leif Pedersen <leif> | ||||||||
| Component: | kern | Assignee: | freebsd-virtualization (Nobody) <virtualization> | ||||||||
| Status: | Closed FIXED | ||||||||||
| Severity: | Affects Some People | CC: | cperciva, imp, tomas | ||||||||
| Priority: | --- | ||||||||||
| Version: | 12.1-RELEASE | ||||||||||
| Hardware: | amd64 | ||||||||||
| OS: | Any | ||||||||||
| Attachments: |
|
||||||||||
|
Description
Leif Pedersen
2020-01-22 23:28:22 UTC
I haven't been able to reproduce this yet... any more tips on how to replicate your environment? I'm at a bit of a loss to come up with anything particularly helpful. A few thoughts, although mostly naive observations and wild speculation - It kind of seems like when one machine has a problem, several others do also. This suggests that it could be triggered by a shared event in the host's networking or EBS. (None of our instances have local storage.) I don't have enough machines or samples to show that it's not just a coincidence though. The nvme errors are always (or almost always?) accompanied by ena errors, but ena errors happen without nvme errors sometimes. That suggests it might be triggered by a network event in the AWS hosting infrastructure, like a network topology change or something. I'll attach a /var/log/all.log and the screenshot from a crash that happened today. Probably nothing new there. This time, the machine did not panic, but rather wedged after Nagios reported its CPU load at 9. There's nothing running on this one besides the hourly zfs snapshot transfers, so I think the load from processes piled up waiting for IO. The timing of error messages stretches out over many minutes, starting with ena errors at 02:20:16, and nvme errors finally happen at 02:28:06. Seems odd, like a problem that ramps up rather slowly rather than an abrupt crash. It's also interesting that these messages on the console screenshot made it into syslog, so IO must have recovered, if only briefly. Created attachment 211805 [details]
console screenshot of crash on 2020-02-21
Created attachment 211806 [details]
syslog from crash on 2020-02-21
Hi Leif, Can you tell me the instance ID from that one? And is that timestamp in UTC? Another request: Can you provide a verbose boot? We're wondering if there's something funky going on with interrupt routing. Created attachment 212007 [details]
syslog from verbose boot on 2020-02-27
(In reply to Colin Percival from comment #6) Sorry, I didn't notice your message sooner. :( The instance id of extra1-dev is i-0ce4598513b3acbb2. I attached the log from a verbose boot. My timestamps are in America/Chicago (-0600 now/-0500 summer) I believe that this patch should fix the underlying problem, which is in the ENA driver: https://reviews.freebsd.org/D24546 If you're able to build a custom kernel, please test that patch and report results in that review or via email (cperciva@). A commit references this bug: Author: mw Date: Thu May 7 11:28:41 UTC 2020 New revision: 360777 URL: https://svnweb.freebsd.org/changeset/base/360777 Log: Optimize ENA Rx refill for low memory conditions Sometimes, especially when there is not much memory in the system left, allocating mbuf jumbo clusters (like 9KB or 16KB) can take a lot of time and it is not guaranteed that it'll succeed. In that situation, the fallback will work, but if the refill needs to take a place for a lot of descriptors at once, the time spent in m_getjcl looking for memory can cause system unresponsiveness due to high priority of the Rx task. This can also lead to driver reset, because Tx cleanup routine is being blocked and timer service could detect that Tx packets aren't cleaned up. The reset routine can further create another unresponsiveness - Rx rings are being refilled there, so m_getjcl will again burn the CPU. This was causing NVMe driver timeouts and resets, because network driver is having higher priority. Instead of 16KB jumbo clusters for the Rx buffers, 9KB clusters are enough - ENA MTU is being set to 9K anyway, so it's very unlikely that more space than 9KB will be needed. However, 9KB jumbo clusters can still cause issues, so by default the page size mbuf cluster will be used for the Rx descriptors. This can have a small (~2%) impact on the throughput of the device, so to restore original behavior, one must change sysctl "hw.ena.enable_9k_mbufs" to "1" in "/boot/loader.conf" file. As a part of this patch (important fix), the version of the driver was updated to v2.1.2. Submitted by: cperciva Reviewed by: Michal Krawczyk <mk@semihalf.com> Reviewed by: Ido Segev <idose@amazon.com> Reviewed by: Guy Tzalik <gtzalik@amazon.com> MFC after: 3 days PR: 225791, 234838, 235856, 236989, 243531 Differential Revision: https://reviews.freebsd.org/D24546 Changes: head/sys/dev/ena/ena.c head/sys/dev/ena/ena.h head/sys/dev/ena/ena_sysctl.c head/sys/dev/ena/ena_sysctl.h A commit references this bug: Author: mw Date: Tue May 12 18:44:42 UTC 2020 New revision: 360985 URL: https://svnweb.freebsd.org/changeset/base/360985 Log: MFC r360777: Optimize ENA Rx refill for low memory conditions Sometimes, especially when there is not much memory in the system left, allocating mbuf jumbo clusters (like 9KB or 16KB) can take a lot of time and it is not guaranteed that it'll succeed. In that situation, the fallback will work, but if the refill needs to take a place for a lot of descriptors at once, the time spent in m_getjcl looking for memory can cause system unresponsiveness due to high priority of the Rx task. This can also lead to driver reset, because Tx cleanup routine is being blocked and timer service could detect that Tx packets aren't cleaned up. The reset routine can further create another unresponsiveness - Rx rings are being refilled there, so m_getjcl will again burn the CPU. This was causing NVMe driver timeouts and resets, because network driver is having higher priority. Instead of 16KB jumbo clusters for the Rx buffers, 9KB clusters are enough - ENA MTU is being set to 9K anyway, so it's very unlikely that more space than 9KB will be needed. However, 9KB jumbo clusters can still cause issues, so by default the page size mbuf cluster will be used for the Rx descriptors. This can have a small (~2%) impact on the throughput of the device, so to restore original behavior, one must change sysctl "hw.ena.enable_9k_mbufs" to "1" in "/boot/loader.conf" file. As a part of this patch (important fix), the version of the driver was updated to v2.1.2. Submitted by: cperciva PR: 225791, 234838, 235856, 236989, 243531 Changes: _U stable/12/ stable/12/sys/dev/ena/ena.c stable/12/sys/dev/ena/ena.h Hello, today I had service outage on 12.1-RELEASE-p5. After cca. 10 minutes system and all services went back to normal. Here is output of /var/log/messages: Jun 5 08:58:37 mail kernel: ena0: The number of lost tx completion is above the threshold (129 > 128). Reset the device Jun 5 08:58:37 mail kernel: ena0: Trigger reset is on Jun 5 08:58:37 mail kernel: ena0: device is going DOWN Jun 5 08:58:37 mail kernel: swap_pager: indefinite wait buffer: bufobj: 0, blkno: 475845, size: 28672 Jun 5 08:58:37 mail kernel: ena0: free uncompleted tx mbuf qid 0 idx 0x8eena0: free uncompleted tx mbuf qid 1 idx 0x0swap_pager: indefinite wait buffer: bufobj: 0, blkno: 295657, size: 28672 Jun 5 08:58:38 mail kernel: ena0: ena0: device is going UP Jun 5 08:58:38 mail kernel: link is UP What can I do to confirm relation to this bug? (In reply to Tomáš Čiernik from comment #13) Hi Tomáš, That definitely looks like the same issue. Does `sysctl dev.ena | grep mbuf_alloc_fail` show nonzero values? (If no, it's not the same issue; if yes, it probably is.) Colin Percival Hello,
sorry for my late anwer. It seems it's different issue.
% sysctl dev.ena | grep mbuf_alloc_fail
dev.ena.0.queue1.rx_ring.mbuf_alloc_fail: 0
dev.ena.0.queue0.rx_ring.mbuf_alloc_fail: 0
Many thanks for your input - now I know I should focus to another point ("just" to find it ...).
This issue has been fixed in current and MFC'd to stable/12. Since the other report turned out not to be this, I'm closing this bug as fixed. |
