Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] heisenbug about commit hang, possible race condition in ProxySQL? #1939

Closed
carsonip opened this issue Mar 6, 2019 · 15 comments

Comments

Projects
None yet
2 participants
@carsonip
Copy link
Contributor

commented Mar 6, 2019

As it is more reproducible at my end and more evidence is pointing to ProxySQL as the source of the misbehavior, I am moving the Google groups thread to GitHub. I believe this is a ProxySQL bug.

ProxySQL version: 1.4.13
ProxySQL config: started with --idle-threads

Setup:
Python program using mysqlclient (MySQLdb) driver, with sqlalchemy.
ProxySQL running on the same machine.
Python program connects to ProxySQL via UNIX socket.
ProxySQL connects to Amazon RDS backend.

Some ProxySQL variables I use:
SET mysql-max_connections=25000;
SET mysql-free_connections_pct=2;
SET mysql-max_stmts_per_connection=500;
SET mysql-ping_interval_server_msec=3000;
SET mysql-monitor_enabled=0;

Bug description:
ProxySQL using 4 threads and idle-threads options, with 3000 client connections.
Python program retrieves a 1000-row result set, then perform a commit (which is empty, so it should return almost immediately).
To reproduce, I wrap the read call and the commit in

This specific commit may hang with a certain probability. Usually can be reproduced within 1 hour. But it only happens in my production environment (the server is busy).
Traceback shows that the hang occurs at:
File "venv/local/lib/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2531, in do_commit\n dbapi_connection.commit()\n

I digged into mysqlclient's code and it is just a very thin wrapper over libmysqlclient-dev's mysql_commit. The hang occurs in mysql_commit.

In another version of the code which uses mysql_send_query and mysql_read_query_result, the mysql_send_query call returns. So I am quite sure the query goes through. But I cannot confirm.

The weird thing is:
No hang with PyMySQL (pure python mysql driver), probably because it is slightly slower and did not trigger the race condition.
No hang when I add some print statements around the mysql_commit in C code. (At least it didn't hang in a few hours)
No hang when I use strace to trace system calls with the same hanging setup.
No hang when I use socat to capture the data flowing through the UNIX socket.

I suspect it is some race condition issue which depends on precise timing or some memory issue in ProxySQL.

I am still collecting info about this. I have been scratching my head for almost a week. But I couldn't do hardcore debugging on production servers easily. I'm posting to see whether anyone has an idea how to debug this or which section of ProxySQL code would contribute to this issue. idle-threads option is not widely used out there, is it possible that it is related? Is there anything I missed or I should investigate?

TODO:

  1. Check if it happens with TCP/IP on localhost instead of UNIX socket. (I doubt it would happen with TCP/IP)
  2. Enable logging on ProxySQL and see if that specific 'COMMIT' is received by ProxySQL. (Haven't done that yet because production server has a few K QPS, therefore a lot of noise. Have to isolate that specific connection)
  3. Check if it is a known / fixed issue of ProxySQL.
  4. Check if it happens without idle-threads option.
@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 6, 2019

New discovery:

  1. Wrote another Python version without sqlalchemy and uses MySQLdb directly. It hangs at commit.
  2. Wrote a C client which connects to ProxySQL through UNIX socket. It hangs almost immediately. When the C client connects to ProxySQL through TCP/IP or connects to Amazon RDS (the backend) directly, it does not hang. It is very easily reproducible.

And it only hangs on commit. Anything after mysql_commit is not executed when hang.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 6, 2019

It is hard to provide clear steps of reproducing the issue because it is highly dependent on the environment. It has to be busy enough and the client code has to execute quickly. But all the evidence is pointing at the setup of ProxySQL with idle-threads and UNIX socket. Please let me know how could I help to debug this.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 10, 2019

This is very reproducible before I restarted the machine. I don't have a good explanation for the bug disappearing after a restart. Any thoughts?

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 11, 2019

Good news: I can still reproduce it although it took more time (10mins - 1hr).

@renecannao

This comment has been minimized.

Copy link
Contributor

commented Mar 11, 2019

Can you provide a reproducible test case?

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 11, 2019

It is always reproducible on my production machine. I cannot reproduce it in other environments yet. The bug is highly dependent on the server load, query pattern and the client speed.

I have tried very hard to isolate the bug. Either it is the OS / unix socket's issue, or ProxySQL's issue.

@renecannao

This comment has been minimized.

Copy link
Contributor

commented Mar 11, 2019

Have you consider that maybe it is not a bug, but you are exhausting some resources, like number of file descriptors, or number of unix domain socket?

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 11, 2019

Have you consider that maybe it is not a bug, but you are exhausting some resources, like number of file descriptors, or number of unix domain socket?

I don't think so. I have 2 versions of the code. One in Python, using sqlalchemy + mysqlclient / mysqlclient only. One in C++ using libmysqlclient. As far as I can tell, I am using the same connection throughout the program. It runs the query successfully (i.e. the UNIX socket is working) for a while (a few minutes - a few hours) until one "COMMIT" hangs indefinitely.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 13, 2019

I confirm that there is no problem without --idle-threads.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 13, 2019

My 2 PRs #1945 #1948 cannot fix this issue. I'll build a custom version that traces specific sessions. I'll get back when I have some concrete debugging info such that we could lock down the area with bug.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 14, 2019

@renecannao
Good news! It is confirmed that the bug is due to ProxySQL --idle-threads and I have identified the root cause.

I've got some concrete debugging info for you, please look at https://gist.github.com/carsonip/da65093997b00c69538422f028bcef47 for the logs. The early parts of the logs are not useful. It is just for your reference that how the logs look like during normal times. Problematic part starts with line 965.
Here's the modified code for debugging (It listens to a TRACE ME SQL query so that it only logs the events of that session): https://github.com/carsonip/proxysql/tree/ca8fef7f8dfe6d5e6f7e47fb12c6b9ae2743fe1f

The nightmare starts with the large result (the query which will yield large result set before COMMIT) and throttling (thanks to fast UNIX socket).

Line 965 is the line changing session->pause_until (corresponding source). pause_until > curtime will set poll event=0, effectively polling for nothing. This will keep going for a short time until it is idle for too long that the session will go to the epoll thread.

When epoll thread adopts the session, it will only epoll for EPOLLIN (corresponding source). But it is actually waiting for data out before it became idle). In the log attached, it actually got awake once with 1 POLLIN event (not really sure why), the session got back to poll thread but got remove_pollout again due to pause_until, then it got idle and moved to epoll thread again. Finally the session never wakes up because epoll thread only epolls with EPOLLIN.

Solution:

  1. When epoll thread adopts the idle session, don't just epoll with EPOLLIN. Instead, do something like MySQL_Data_Stream::set_pollout() which conditionally epoll with either IN or IN|OUT. Or we could simply just hardcode EPOLLIN | EPOLLOUT to make sure we don't lose anything. (edit: I suppose we cannot hardcode EPOLLIN | EPOLLOUT because in usual cases the socket is always available for write) Please let me know which way you prefer.

Other suggestions:

  1. Throttle rate is too low for UNIX socket, which will trigger a mess like this. It will involve overhead of moving sessions around and probably more syscall. Since the default is already INT_MAX, INT is not enough. Consider types like unsigned long long and set a higher default, or provide a way to disable the throttling altogether.

Please let me know your thoughts. I would love to work on the fix.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 14, 2019

Side note: this also explains why this is a heisenbug. When I try to intercept the traffic / trace the syscall of the client, it couldn't reach a rate that would throttle the session. It only happens with --idle-threads because the bug is in the epoll thread code.

@renecannao

This comment has been minimized.

Copy link
Contributor

commented Mar 14, 2019

@carsonip : very good debugging!
This was impossible to debug without reproducing it.

Although I disagree with the solution (#1951).
If a session has still data to be sent to the client, it is not an idle session.
Therefore, the problem is that the session is marked as idle (while it is not) and moved to idle thread.
This is the bug: the session is moved TO idle-thread while it shouldn't.
Data streams in idle-threads should never have EPOLLOUT : they are not supposed to send data. They are waiting for data: this is why EPOLLIN is hardcoded.

I believe a better solution is to add a check here : if the data stream is paused, it shouldn't be considered idle.
Thoughts?

About the other suggestion, I would suggest that an easy solution is:
if throttle_max_bytes_per_second_to_client is INT_MAX (the default), disable throttling altogether.

@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 14, 2019

I was having dinner and I didn't comment soon enough. I was thinking the same thing, which is to not move sessions with pending data out to epoll thread, because it is dumb to keep moving the session between poll thread and epoll thread (because pause_until - curtime is quite a long time). I'll change the PR soon.

carsonip added a commit to carsonip/proxysql that referenced this issue Mar 14, 2019

Do not move throttled session to epoll
Epoll thread does not poll for EPOLLOUT. If a throttled session with
pending data out is moved to epoll thread, the session will stay in
epoll thread indefinitely, causing a hang observed by client. Fix by not
moving throttled session to epoll thread.

Fix sysown#1939

carsonip added a commit to carsonip/proxysql that referenced this issue Mar 14, 2019

Do not move throttled session to epoll
Epoll thread does not poll for EPOLLOUT. If a throttled session with
pending data out is moved to epoll thread, the session will stay in
epoll thread indefinitely, causing a hang observed by client. Fix by not
moving throttled session to epoll thread.

Fix sysown#1939
@carsonip

This comment has been minimized.

Copy link
Contributor Author

commented Mar 14, 2019

About the other suggestion, I would suggest that an easy solution is:
if throttle_max_bytes_per_second_to_client is INT_MAX (the default), disable throttling altogether.

I suppose 0 is a better value to denote "No limit" as it matches the mysql convention. INT_MAX is not as good because users may be surprised to realize the value of INT_MAX and INT_MAX-1 does not mean a difference of 1 byte/second. Please see #1953 for the PR.

carsonip added a commit to carsonip/proxysql that referenced this issue Mar 19, 2019

Do not move throttled session to epoll
Epoll thread does not poll for EPOLLOUT. If a throttled session with
pending data out is moved to epoll thread, the session will stay in
epoll thread indefinitely, causing a hang observed by client. Fix by not
moving throttled session to epoll thread.

Fix sysown#1939
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.