percona server 5.5 query end status

MySQL & MariaDB Percona Server for MySQL 5.6
1

Recently, I have had some very simple update statements that take a very long time to execute, up to about 6 seconds.
percona-server:5.5.53
table_rows:7374453
primary_key:user_id
sql:
update user_info SET recommend_votes_num = recommend_votes_num - 4 WHERE user_id = 4124593 AND recommend_votes_num >= 4
(user_id is primarykey)

binlog info:

at 867369173

#190708 14:46:23 server id 6163699 end_log_pos 867369252 Query thread_id=9221135 exec_time=0 error_code=0
SET TIMESTAMP=1562568383/!/;
BEGIN
/!/;

at 867369252

#190708 14:46:23 server id 6163699 end_log_pos 867369455 Query thread_id=9221135 exec_time=0 error_code=0
SET TIMESTAMP=1562568383/!/;
update user_info SET recommend_votes_num = recommend_votes_num - 4 WHERE user_id = 4124593 AND recommend_votes_num >= 4
/!/;

at 867369455

#190708 14:46:23 server id 6163699 end_log_pos 867369482 Xid = 1260093514
COMMIT/!/;

(both exec_itme is 0)

slow_log info:

Time: 190708 14:46:27

User@Host: db_zh_user1[db_zh_user1] @ [172.26.0.75]

Thread_id: 9221135 Schema: zongheng_user_1 Last_errno: 0 Killed: 0

Query_time: 4.202410 Lock_time: 0.000038 Rows_sent: 0 Rows_examined: 1 Rows_affected: 1 Rows_read: 1

Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0

Profile_starting: 0.000026 Profile_starting_cpu: 0.000026 Profile_checking_permissions: 0.000003 Profile_checking_permissions_cpu: 0.000003 Profile_Opening_tables: 0.000008 Profile_Ope

ning_tables_cpu: 0.000009 Profile_System_lock: 0.000009 Profile_System_lock_cpu: 0.000009 Profile_init: 0.000060 Profile_init_cpu: 0.000061 Profile_Updating: 0.000096 Profile_Updating_cp
u: 0.000095 Profile_end: 0.000003 Profile_end_cpu: 0.000003 Profile_Waiting_for_query_cache_lock: 0.000002 Profile_Waiting_for_query_cache_lock_cpu: 0.000002 Profile_end: 0.000012 Profil
e_end_cpu: 0.000012 Profile_query_end: 4.202146 Profile_query_end_cpu: 0.000069 Profile_closing_tables: 0.000021 Profile_closing_tables_cpu: 0.000020 Profile_freeing_items: 0.000028 Prof
ile_freeing_items_cpu: 0.000028 Profile_logging_slow_query: 0.000003 Profile_logging_slow_query_cpu: 0.000002

Profile_total: 4.202417 Profile_total_cpu: 0.000337

InnoDB_trx_id: 2912B40F

QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No

Filesort: No Filesort_on_disk: No Merge_passes: 0

InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000

InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000

InnoDB_pages_distinct: 20

SET timestamp=1562568387;
update user_info SET recommend_votes_num = recommend_votes_num - 4 WHERE user_id = 4124593 AND recommend_votes_num >= 4;

query_end: 4.202146!!!

Can someone help me explain why this update takes so much time in the query end status?
I hope percona experts can help me solve this problem or provide some ideas. This problem has been bothering me for several weeks. Thank you.

2

Looking for expert opinion, Any help will be appreciated

3

Hello liangyu5017

It may be that you will get some help with this from the user community, though I think it may be very specific to your environment. Did you see that we have a free-to-access webinar on troubleshooting performance issues? That might be worth you looking at. Sveta is one of our most experienced engineers, and will have valuable advice in that webinar:

[URL]Upcoming Webinars

There are also a few more resources that might help you resolve the issue yourself:

There is also a more recent webinar from our CEO, Peter Zaitsev, from last year [URL]Upcoming Webinars

See how you get on with those maybe and also do check out the blog for the Q&A follow ups for those posts.