In daily development or online operation and maintenance, we often encounter various database exceptions, such as timeouts, deadlocks, etc. But some problems seem ordinary on the surface, but there are unexpected reasons behind them.
Share it once todayMySQL acquisition lock timeout issue caused by server time jumpThe investigation process.
Problem phenomenon: A large number of lock timeout logs appear
One day, the following error messages suddenly appeared in the system log:
The acquisition lock timeout causes the transaction to fail.
Preliminary analysis: deadlock?
It may be that there is a deadlock, so the problem code is located according to the exception stack, but it is found that the method is simple in logic and only modify one entity, similar to the following. (Not real business code)
//Update only the last access time of the user (()); (user);
Forced analysis (conjecture), this modification will be changed by each request. Since within the request transaction, the transaction will be locked until the request is completed.
But for a long-term and stable project, the request is unlikely to suddenly slow down
In-depth investigation: no abnormalities appeared in the slow log
If a deadlock occurs, then there must be records in the slow log. However, the actual troubleshooting comes, and there is no User-related slow query for slow logs.
Clues: Uncommon logs
- HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m26s857ms76µs413ns).
Looking through the log, I found an exception record of clock leap detected. So I verified the server time and found that it was more than 40 seconds faster than the local environment.
The truth is revealed: Server time jump causes misjudgment
When MySQL performs lock waiting and transaction timeout, it depends on the system timestamp for judgment. When the system time suddenly jumps to future time, MYSQL misjudgment.
As for the reason for the jump, it is speculated that the NTP client performed a forced stepping operation after detecting the time drift, and instantly fastened the time for dozens of seconds.
One step closer: What operations will cause the acquisition lock to timeout?
Under the premise that MySQL uses the InnoDB engine,Lock timeout（Lock wait timeout exceeded) usually has two main causes:
1. Deadlock
The most common reason isDeadlock. Deadlocks often have the same resources modified in different orders, and hold the locks needed by each other, causing each other to wait for each other and never be released.
for example:
-
Transaction A The modification order is: first change the user, then change the order;
-
Transaction B The modification order is: first change the order, then change the user;
-
Both parties each hold a lock and want to obtain the other party's, but it ends up deadlocking.
MySQL detects a deadlock and proactively interrupts one of the transactions. (At this time, a Dealock error will appear in the log)
In fact, as long as the order of modification of Entity is uniformly stipulated in the project, most deadlocks can be avoided.
2. Locks caused by long transactions are not released in time
In InnoDB, the transaction is not committed during the periodAlways hold the lock. If the transaction is executed for too long, it will cause other concurrent requests to block for a long time, and eventually throw a lock waiting timeout exception.
Transaction execution is too long, common reasons include:
-
Entity too much modification
For example, modify and save one by one in a loop, each timesave(), repeatedly brush SQL. -
Time-consuming operations are included in the transaction
For example, calling external services, HTTP interfaces, microservice RPCs, etc., especially when there is no timeout control for slow interfaces. -
There is an explicit wait in the transaction
like()It is used for debugging, speed limiting and other scenarios, and the lock will not be released during the period.