Not the answer you need?
Register and ask your own question!

percona server 5.5 query end status

liangyu5017liangyu5017 ContributorInactive User Role Novice
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
# [email protected]: 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.

Comments

Sign In or Register to comment.

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright ©2005 - 2020 Percona LLC. All rights reserved.