Slow Prewrite Request Occurs During DELETE

Translated
1

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: DELETE的时候出现slow prewrite request

| username: anly_zhang

[TiDB Usage Environment] Production Environment
[TiDB Version] 6.2.0 DMR
[Reproduction Path] Cannot reproduce
[Encountered Issue]: Synchronizing data using CloudCanal from MySQL to TiDB, but there is a significant delay when executing DELETE operations, which are based on composite primary keys.
[Resource Configuration]
[Attachments: Logs]
tidb_10.170.0.26_4000.zip (4.0 KB)
tidb_10.170.0.27_4000.zip (3.9 KB)
tidb_10.170.0.28_4000.zip (4.9 KB)
tikv_10.170.0.29_20160.zip (6.6 KB)
tikv_10.170.0.30_20160.zip (5.4 KB)
tikv_10.170.0.31_20160.zip (6.1 KB)

CloudCanal task logs are as follows:

com.clougence.cloudcanal.base.service.task.exception.runtime.ApplierHandlerException: parallel handle increment event failed
	at com.clougence.cloudcanal.tidb.worker.writer.Incre.TiDBIncreBatchApplyNoTxHandler.handle(TiDBIncreBatchApplyNoTxHandler.java:179)
	at com.clougence.cloudcanal.tidb.worker.writer.Incre.TiDBIncreBatchApplyNoTxHandler.handle(TiDBIncreBatchApplyNoTxHandler.java:55)
	at com.clougence.cloudcanal.task.applier.incre.IncrementDisruptorApplyHandler.onEvent(IncrementDisruptorApplyHandler.java:25)
	at com.clougence.cloudcanal.task.applier.incre.IncrementDisruptorApplyHandler.onEvent(IncrementDisruptorApplyHandler.java:12)
	at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
	at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.util.concurrent.ExecutionException: com.clougence.cloudcanal.base.service.task.exception.runtime.ApplierHandlerException: apply batch data error.msg:SocketTimeoutException: Read timed out
	at java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.util.concurrent.FutureTask.get(FutureTask.java:192)
	at com.clougence.cloudcanal.tidb.worker.writer.Incre.TiDBIncreBatchApplyNoTxHandler.handle(TiDBIncreBatchApplyNoTxHandler.java:164)
	... 6 more
Caused by: com.clougence.cloudcanal.base.service.task.exception.runtime.ApplierHandlerException: apply batch data error.msg:SocketTimeoutException: Read timed out
	at com.clougence.cloudcanal.base.service.task.executor.RdbOneByOneExecutor.exec(RdbOneByOneExecutor.java:82)
	at com.clougence.cloudcanal.base.service.task.applier.RdbIncreMultiSqlApply$DmlWorker.run(RdbIncreMultiSqlApply.java:121)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	... 1 more
Caused by: com.clougence.cloudcanal.base.service.task.exception.runtime.ApplierHandlerException: {"db":null,"schema":"jy8","table":"tbl_game_record","eventType":"DELETE","pks":[["114929357","1669966573221"]]} error,msg:SocketTimeoutException: Read timed out
	at com.clougence.cloudcanal.base.service.task.exception.IncreExceptionHandler.logAndSkipExIfNecessary(IncreExceptionHandler.java:36)
	at com.clougence.cloudcanal.base.service.task.executor.RdbOneByOneExecutor.deleteOneRow(RdbOneByOneExecutor.java:200)
	at com.clougence.cloudcanal.base.service.task.executor.RdbOneByOneExecutor.delete(RdbOneByOneExecutor.java:132)
	at com.clougence.cloudcanal.base.service.task.executor.RdbOneByOneExecutor.exec(RdbOneByOneExecutor.java:72)
	... 6 more
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 60,062 milliseconds ago. The last packet sent successfully to the server was 60,064 milliseconds ago.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953)
	at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:370)
	at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:497)
	at com.clougence.cloudcanal.base.service.task.executor.RdbOneByOneExecutor.deleteOneRow(RdbOneByOneExecutor.java:192)
	... 8 more
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 60,062 milliseconds ago. The last packet sent successfully to the server was 60,064 milliseconds ago.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
	at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:546)
	at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:710)
	at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:649)
	at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:951)
	at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1075)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:930)
	... 11 more
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
	at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
	at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
	at java.io.FilterInputStream.read(FilterInputStream.java:133)
	at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
	at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
	at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
	at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
	at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:540)
	... 16 more
2
| username: 我是咖啡哥 | Original post link

Is the delete SQL slow on TiDB?

3
| username: anly_zhang | Original post link

In the dashboard, I see that this DELETE operation takes a long time, at least 24 seconds, and up to 1.4 minutes. But this is deleting data based on the primary key, which is problematic;

delete from `dbn`.`tbl_game_record` where `id` = ? and `bet_time` = ? limit ?

id and bet_time are composite primary keys.

4
| username: 裤衩儿飞上天 | Original post link

How is the overall load of the cluster when deleting a timestamp?

5
| username: anly_zhang | Original post link

The images you provided are not visible. Please provide the text content for translation.

6
| username: h5n1 | Original post link

Check the execution time consumption of this slow SQL in the dashboard to see which parts are taking the most time.

7
| username: buddyyuan | Original post link

Your logs contain many lock conflicts causing timeouts.

8
| username: anly_zhang | Original post link

I also saw this, but theoretically, there shouldn’t be a lock conflict when deleting a primary key.

9
| username: 我是咖啡哥 | Original post link

Is it because multiple tasks are being executed simultaneously, leading to lock conflicts? You can try reducing concurrency, it might be faster.

10
| username: system | Original post link

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.