Updates and deletes are hanging for ~900 seconds

[NadavkOptimalQ]

Describe the bug
We are running using sqlalchemy 1.3.4 with pymysql 0.10.0 on python 2.7.18. Our code runs with multiprocessing without gevent on AKS.

Along the day some of our updates and deletes take around 900 seconds before finishing. This doesn't happen all the time and we are not able to find the reason this happens

Expected behavior
All updates and deletes should take the same time without large spikes

To Reproduce
Not really sure how to reproduce this but I can provide logs as requested

Versions.

• OS: ubuntu 16.04
• Python: 2.7.18
• SQLAlchemy: 1.3.4
• Database: MySQL 5.7
• DBAPI: pymysql 0.10.0

This has been happening for a few weeks now and is very badly affecting our production
Any help would be much appreciated

[zzzeek]

Well the good news is 900 seconds is plenty of time to look around and see where things are blocked.

this is a problem that would likely have to do with your database status and/or network. 900 seconds == 15 minutes which does seem like a human -coded timeout of some time.

so top level questions:

1. when did this start happening and did some change in the code precipitate it?

2. did the problem appear gradually and is becoming more frequent?

3. when the hang occurs, is it all work being frozen at the same time? or are there lots of processes doing their thing just fine and one particualr proc occasionally gets blocked?

4. is it the same, or similar, UPDATE/DELETE with the problem, and others succeed without issue?

5. when the 900 second thing happens, what can you learn from the proceslist table? https://dev.mysql.com/doc/refman/8.0/en/information-schema-processlist-table.html does this show the UPDATE/DELETE in progress?

6. when the 900 second thing happens, can you log in and see if other statements like SELECT, INSERT etc work fine? does UPDATE/DELETE on other tables with relatively small numbers of rows succeed w/o issue? database is reponsive? can you run UPDATE/DELETE on the target table in question while it's happening?

7. is this UPDATE/DELETE affecting tens of thousands of rows? MySQL is known to not be very good at this use case. if your data size has grown, you will want to look into reorganizing such statements to batch among groups of rows at a time, say 1000 rows at a time. this is a well known issue we have in the openstack world. an SO answer involving this issue: https://stackoverflow.com/questions/22783945/mysql-deleting-rows-from-innodb-is-very-slow/22784306

8. are the UPDATE/DELETE usign a WHERE clause against unindexed columns? does the DB need indexing?

9. is this a hosted database or you have access to server tuning? do you have good settings for the following variables: innodb_pool_size , innodb_log_file_size, innodb_flush_log_at_trx_commit etc. good overview of the important ones at https://www.percona.com/blog/2013/09/20/innodb-performance-optimization-basics-updated/

hopefully these are some areas to get you started.

[NadavkOptimalQ]

Hi,
thanks for the quick reply.

1. Can't really say a specific code change caused this. I think us increasing our scale (data in db + number of pods running) might be what started it all
2. Again not sure but I think it just started one day when we increased scale
3. No. It just randomly one process once in a while gets stuck
4. Basically all the actions that this affects are from one process that updates/deletes from a specific table
5. We ran a da long script that saved the full processlist but we don't see any long process there
6. Like stated in point 5 we don't actually see the slowness in the database process itself
7. That updates and deletes are very small. 1-100 lines from a table with less than 1 mil lines.
8. All of our actions are using the primary key of the table
9. The database is managed on azure. Most of the params you stated are not available in the azure portal. Could I get them form inside the database?

[zzzeek]

so is that "900 seconds" number pretty constant? that's 15 minutes exactly. Look around to see what you have set up that times out in 15 minutes. Did the examination of processlist show the UPDATE/DELETE statement in question itself taking a long time? you want to see the actual statement in there. otherwise, if the program is just hanging for 900 seconds and is not actually emitting a statement you might want to see if it's waiting on the conneciton pool. did you set pool_timeout to 900 seconds or something like that?

[NadavkOptimalQ]

After some investigation with the azure AKS team, we found that our requests were going to the SQL's public IP instead of utilizing the private link. The issue they saw was we were reaching the limit of SNAT connections.
We moved to a private link and the problem doesn't occur nearly as often but it still does happen so we are still investigating.

As for your questions, our timeouts both in the database and in our use of sqlAlchemy are higher. We are working with a connection pool that has 250 connections and recycle time of 3600.

[zzzeek]

in my experience, when a major cause for a problem is found and resolved, the issues that still remain should be examined closely to make sure they are still the same issue and are not some slightly different symptom that is either unrelated, or perhaps a part of the first issue that still wasn't resolved, such as you have one worker or something still going to the wrong interface.

anyway glad you found a major part ot it!