mysql_async: Conn::new sometimes fails to make progress under load
Try running the following test:
#[tokio::test(threaded_scheduler)]
async fn can_handle_the_pressure() {
use futures_util::stream::StreamExt;
{
let (tx, mut rx) = tokio::sync::mpsc::unbounded_channel::<()>();
for _ in 0..500 {
let tx = tx.clone();
tokio::spawn(async move {
let c = Conn::new(get_opts()).await.unwrap();
let c = c.drop_query("SELECT 1").await.unwrap();
c.disconnect().await.unwrap();
drop(tx);
});
}
drop(tx);
// see that all the tx's eventually complete
assert_eq!(rx.next().await, None);
}
eprintln!("MID");
{
let (tx, mut rx) = tokio::sync::mpsc::unbounded_channel::<()>();
for _ in 0..500 {
let tx = tx.clone();
tokio::spawn(async move {
eprintln!("GETCONN");
let c = Conn::new(get_opts()).await.unwrap();
eprintln!("GOTCONN");
let c = c.drop_query("SELECT 1").await.unwrap();
c.disconnect().await.unwrap();
drop(tx);
});
}
drop(tx);
// see that all the tx's eventually complete
assert_eq!(rx.next().await, None);
}
eprintln!("DONE");
}
Against a local MySQL with max_connections = 1000. It passes just fine. Now, run some CPU-heavy program that takes up most of the cores on the machine, and run the test again. It will frequently hang between printing MID and printing DONE. Digging a big deeper, you will see that GETCONN gets printed 500 times, but GOTCONN only N < 500 times (the exact value of N varies). Some further digging reveals that the issue lies in handle_handshake. Specifically, if you put a print statement above and below the call to read_packet().await, you’ll see that the print before gets printed 2*500-N times, and the print after 2*500-2*N times. The explanation for this is that every connection goes through Conn::new twice: once as a “plain” connection, and once as an “upgraded” socket connection. But some (500-N) plain connections get “stuck” on that .await. They therefore do not get upgraded, so they fail to hit the second print twice, and the first print once (as a socket).
In any case, the issue for the stuck connections is that read_packet().await never returns for plain connections. Reading through the code, it appears that there are only three ways this can happen: tokio::net::TcpStream is broken (unlikely), tokio_util::codec::Framed is broken (possible), or mysql_common::proto::codec::PacketCodec either blocks (unlikely) or returns None when it should return Some (a likely culprit). How any of these are related to load, I have no idea. Why it is necessary to first spin up and drop 500 connections, I also have no idea. But that’s what I’m seeing. Which sort of points at a tokio bug, but that seems weird too?
Well, I figured I should write up my findings no matter what, so that hopefully we can get to the bottom of it. I ran into this when running code on EC2 which is infamous for having a lot of scheduling noise, similar to that of a loaded machine, so it’s probably worth trying to fix.
About this issue
- Original URL
- State: closed
- Created 4 years ago
- Comments: 21 (20 by maintainers)
Note, that system-wide keepalive also fixes the issue 🙃:
Hi.
I was able to reproduce the issue using the test above. I’ve also tried synchronous mysql driver and it hangs after 5 minutes in my environment (arch+mariadb14 with max_connections=1). Direct UNIX socket connections (using
OptsBuilder::socket) are not affected by this issue as far as i can see.Looks like this issue goes away for both synchronous and asynchronous drivers if keepalive is enabled using
OptsBuilder::tcp_keepalive. I’ve measured the delay between invocations ofdatefor1and10seconds keepalive. That shows, that keepalive messages somehow wakes hanged connections up. Here are the histograms for delays:histograms
delays for 1sec keepalive
delays for 10sec keepalive
Stack traces:
stack trace for `mysql_async`
stack trace for `mysql`
TBH i don’t know why this is happening. I’ll try to hang c++ connector just to make sure that it’s not on mysql side.
This seems strange, because i wasn’t able to reproduce the issue with
max_connections > n.Any thoughts?
Here’s another: for runs of the test that succeed, after
MID, I observe 18000 calls toPacketCodec::decode, and 5000 calls toPacketCodec::encode. That is 36 decodes per connection (roughly 18 each for plain and socket presumably), and 10 encodes per connection. On a run that hangs, I see36 * Hfewer calls todecode, andH/2more calls toencode, whereHis the number of hangingConn::new. This suggests to me that maybedecodeis never called for the hanging connections (how could that be?). I have no idea whyencodewould be called more.@blackbeam I may need your knowledge of the protocol here to figure out what might be causing this hang. Can you replicate the hang on a computer you control?