[MDEV-9743] long "query end" stage on a simple update sql Created: 2016-03-16  Updated: 2016-05-09  Resolved: 2016-05-09

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Update
Affects Version/s: 10.1.12
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: chen yuanyuan Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

Centos 7

Attachments: File my.cnf     Text File pt-query-digest.txt     File stmt1.sql     File stmt2.sql     File test.sql    

 Description   

Using the follwing test sql:

DROP DATABASE IF EXISTS `my_test`;
 
CREATE DATABASE `my_test`;
 
USE `my_test`;
 
 
 
DROP TABLE IF EXISTS `test`;
 
CREATE TABLE `test` (
 
        `id` TINYINT UNSIGNED NOT NULL AUTO_INCREMENT,
 
        `size` INT UNSIGNED NOT NULL,
 
        PRIMARY KEY (`id`)
 
)ENGINE=Innodb;
 
insert into my_test.test values(0,100);


SET profiling = 1;
 
#this update has short query end 
update my_test.test set size=100 where id=1;
 
#this update has long query end 
update my_test.test set size=size+100 where id=1;
 
SHOW PROFILE for query 1;
 
SHOW PROFILE for query 2;

I find that update my_test.test set size=size+100 where id=1; has a very log "query end" stage:

    [root@localhost code]# /usr/local/mysql/bin/mysql < test.sql | grep "query end"
 
query end	0.000007
 
query end	0.005163

I have used the same test.sql on mysql 5.1 ,and no such thing happaned:

[root@localhost ~]# mysql < test.sql | grep "query end"
 
query end	0.000003
 
query end	0.000002

Of course,the config files of mariadb 10.1.12 and mysql 5.1.73 are different.But the update sql is so simple that I don't think the difference in config files can cause this huge performance slowdown.But I have upload my mariadb config file.

=============updated in 2016/03/17=================
Sorry for my brief description yesterday.Now I rerun the test.sql in my virtualbox centos 7 machine and check the full stages,the result is the same:

[root@localhost code]#  /usr/local/mysql/bin/mysql < test.sql 
Status	Duration
 
starting	0.000084
 
checking permissions	0.000012
 
Opening tables	0.000017
 
After opening tables	0.000006
 
System lock	0.000004
 
Table lock	0.000006
 
init	0.000131
 
updating	0.000059
 
end	0.000010
 
query end	0.000009
 
closing tables	0.000004
 
Unlocking tables	0.000008
 
freeing items	0.000013
 
updating status	0.000011
 
cleaning up	0.000004
 
 
 
Status	Duration
 
starting	0.000036
 
checking permissions	0.000006
 
Opening tables	0.000012
 
After opening tables	0.000005
 
System lock	0.000004
 
Table lock	0.000005
 
init	0.000037
 
updating	0.000073
 
end	0.000007
 
Waiting for query cache lock	0.000003
 
end	0.000009
 
query end	0.003902
 
closing tables	0.000012
 
Unlocking tables	0.000012
 
freeing items	0.000010
 
updating status	0.000025
 
cleaning up	0.000004

Actually,I have tried to batch exec the "update my_test.test set size=100 where id=1;" 10000 times and "update my_test.test set size=size+100 where id=1;" 10000 times,and got the following results:

[root@localhost code]# time /usr/local/mysql/bin/mysql < stmt1.sql 
 
 
real	0m0.667s
 
user	0m0.037s
 
sys	0m0.102s
 
[root@localhost code]# time /usr/local/mysql/bin/mysql < stmt2.sql 
 
 
real	0m56.015s
 
user	0m0.187s
 
sys	0m0.316s
 
[root@localhost code]# wc -l stmt1.sql  stmt2.sql 
 10000 stmt1.sql
 
 10000 stmt2.sql
 
 20000 total

I found this problem because in our performance testing , I used pt-query-digest to analyze the slow query log and found the exce time of a simply update sql is 88% of the overall exec time:

# Profile
 
# Rank Query ID           Response time   Calls R/Call V/M   Item
 
# ==== ================== =============== ===== ====== ===== =============
 
#    1 0x919A71601652CD9C 1880.7490 88.8%  1000 1.8807  0.21 UPDATE uisdb.maildir
 
#    2 0x6A6BF8323EF9A924   64.4834  3.0%  1000 0.0645  0.03 INSERT UPDATE uisdb.mail_entity
 
#    3 0x0CFA48C3B4E6316C   60.1811  2.8%  1000 0.0602  0.02 INSERT uisdb.mail
 
#    4 0xB577AD2502F24975   49.4235  2.3%  1103 0.0448  0.02 SELECT uisdb.mail_entity
 
# MISC 0xMISC               63.1927  3.0% 44938 0.0014   0.0 <53 ITEMS>
 
 
 
# Query 1: 20.83 QPS, 39.18x concurrency, ID 0x919A71601652CD9C at byte 40584611
 
# This item is included in the report because it matches --limit.
 
# Scores: V/M = 0.21
 
# Time range: 2016-03-17 01:29:20 to 01:30:08
 
# Attribute    pct   total     min     max     avg     95%  stddev  median
 
# ============ === ======= ======= ======= ======= ======= ======= =======
 
# Count          2    1000
 
# Exec time     88   1881s    20ms      3s      2s      3s   628ms      2s
 
# Lock time     99   1833s    57us      3s      2s      3s   625ms      2s
 
# Rows sent      0       0       0       0       0       0       0       0
 
# Rows examine   3    1000       1       1       1       1       0       1
 
# Rows affecte  13    1000       1       1       1       1       0       1
 
# Query size     0  89.84k      92      92      92      92       0      92
 
# String:
 
# Hosts        localhost
 
# Users        uis
 
# Query_time distribution
 
#   1us
 
#  10us
 
# 100us
 
#   1ms
 
#  10ms  ##
 
# 100ms  #####
 
#    1s  ################################################################
 
#  10s+
 
# Tables
 
#    SHOW TABLE STATUS FROM `uisdb` LIKE 'maildir'\G
 
#    SHOW CREATE TABLE `uisdb`.`maildir`\G
 
update uisdb.maildir set next_uid=last_insert_id(next_uid)+1 where mb_id=12 and maildir_id=1\G
 
# Converted for EXPLAIN
 
# EXPLAIN /*!50100 PARTITIONS*/
 
select  next_uid=last_insert_id(next_uid)+1 from uisdb.maildir where  mb_id=12 and maildir_id=1\G

uisdb.maildir is a simple table with 3000+ rows and the "where condition" uses its primary key to search:

MariaDB [(none)]> explain select  next_uid=last_insert_id(next_uid)+1 from uisdb.maildir where  mb_id=12 and maildir_id=1\G
 
*************************** 1. row ***************************
 
           id: 1
 
  select_type: SIMPLE
 
        table: maildir
 
         type: const
 
possible_keys: PRIMARY,mb_id
 
          key: PRIMARY
 
      key_len: 12
 
          ref: const,const
 
         rows: 1
 
        Extra: 
1 row in set (0.30 sec)

Our servers are not particularly tuned for mariadb except in the my.cnf files.If you need more env config,please tell me.

PS:when I googled this problem,someone seemed to encount the same problem,at this link

 Comments   
Comment by Elena Stepanova [ 2016-03-16 ]

First of all, the duration of this stage can be very volatile, you need a special environment tuned for performance tests and numerous experiments to be reasonably sure you are getting valid results. Please see below examples from MySQL 5.6 and MariaDB 10.1, note that the queries which you identified as "short query end" and "long query end" are intermixed there:

MySQL 5.6.28

 
MySQL [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.04 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 1;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000070 |
 
| checking permissions | 0.000012 |
 
| Opening tables       | 0.000025 |
 
| init                 | 0.000025 |
 
| System lock          | 0.000053 |
 
| updating             | 0.000093 |
 
| end                  | 0.000010 |
 
| query end            | 0.040792 |
 
| closing tables       | 0.000036 |
 
| freeing items        | 0.000082 |
 
| cleaning up          | 0.000026 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.02 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 2;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000070 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000025 |
 
| init                 | 0.000027 |
 
| System lock          | 0.000053 |
 
| updating             | 0.000181 |
 
| end                  | 0.000012 |
 
| query end            | 0.024010 |
 
| closing tables       | 0.000043 |
 
| freeing items        | 0.000102 |
 
| cleaning up          | 0.000030 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.01 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.30 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 3;                   
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000070 |
 
| checking permissions | 0.000012 |
 
| Opening tables       | 0.000045 |
 
| init                 | 0.000028 |
 
| System lock          | 0.000055 |
 
| updating             | 0.000094 |
 
| end                  | 0.000011 |
 
| query end            | 0.298782 |
 
| closing tables       | 0.000034 |
 
| freeing items        | 0.000097 |
 
| cleaning up          | 0.000026 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.24 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 4;                        
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000087 |
 
| checking permissions | 0.000013 |
 
| Opening tables       | 0.000026 |
 
| init                 | 0.000027 |
 
| System lock          | 0.000054 |
 
| updating             | 0.000097 |
 
| end                  | 0.000132 |
 
| query end            | 0.239300 |
 
| closing tables       | 0.000043 |
 
| freeing items        | 0.000098 |
 
| cleaning up          | 0.000028 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.04 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 5;                        
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000071 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000027 |
 
| init                 | 0.000027 |
 
| System lock          | 0.000054 |
 
| updating             | 0.000115 |
 
| end                  | 0.000011 |
 
| query end            | 0.040915 |
 
| closing tables       | 0.000035 |
 
| freeing items        | 0.000088 |
 
| cleaning up          | 0.000028 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.24 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 6;                   
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000076 |
 
| checking permissions | 0.000012 |
 
| Opening tables       | 0.000026 |
 
| init                 | 0.000027 |
 
| System lock          | 0.000054 |
 
| updating             | 0.000095 |
 
| end                  | 0.000010 |
 
| query end            | 0.238425 |
 
| closing tables       | 0.000034 |
 
| freeing items        | 0.000099 |
 
| cleaning up          | 0.000027 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.04 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MySQL [my_test]> SHOW PROFILE for query 7;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000069 |
 
| checking permissions | 0.000050 |
 
| Opening tables       | 0.000029 |
 
| init                 | 0.000025 |
 
| System lock          | 0.000054 |
 
| updating             | 0.000093 |
 
| end                  | 0.000010 |
 
| query end            | 0.041034 |
 
| closing tables       | 0.000036 |
 
| freeing items        | 0.000083 |
 
| cleaning up          | 0.000027 |
 
+----------------------+----------+
 
11 rows in set, 1 warning (0.00 sec)
 
 
 
MySQL [my_test]> select @@version, @@version_comment;
 
+-----------+------------------------------+
 
| @@version | @@version_comment            |
 
+-----------+------------------------------+
 
| 5.6.28    | MySQL Community Server (GPL) |
 
+-----------+------------------------------+
 
1 row in set (0.00 sec)

MariaDB 10.1.12

 
MariaDB [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.08 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 1;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000103 |
 
| checking permissions | 0.000016 |
 
| Opening tables       | 0.000022 |
 
| After opening tables | 0.000010 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000011 |
 
| init                 | 0.000050 |
 
| updating             | 0.000090 |
 
| end                  | 0.000012 |
 
| query end            | 0.078313 |
 
| closing tables       | 0.000024 |
 
| Unlocking tables     | 0.000020 |
 
| freeing items        | 0.000012 |
 
| updating status      | 0.000092 |
 
| cleaning up          | 0.000012 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.24 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 2;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000071 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000023 |
 
| After opening tables | 0.000010 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000011 |
 
| init                 | 0.000051 |
 
| updating             | 0.000090 |
 
| end                  | 0.000011 |
 
| query end            | 0.240071 |
 
| closing tables       | 0.000022 |
 
| Unlocking tables     | 0.000020 |
 
| freeing items        | 0.000013 |
 
| updating status      | 0.000094 |
 
| cleaning up          | 0.000012 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.24 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 3;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000070 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000004 |
 
| After opening tables | 0.000325 |
 
| System lock          | 0.000010 |
 
| Table lock           | 0.000012 |
 
| init                 | 0.000053 |
 
| updating             | 0.000091 |
 
| end                  | 0.000012 |
 
| query end            | 0.243168 |
 
| closing tables       | 0.000023 |
 
| Unlocking tables     | 0.000021 |
 
| freeing items        | 0.000013 |
 
| updating status      | 0.000096 |
 
| cleaning up          | 0.000012 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.05 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 4;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000070 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000022 |
 
| After opening tables | 0.000010 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000010 |
 
| init                 | 0.000053 |
 
| updating             | 0.000106 |
 
| end                  | 0.000013 |
 
| query end            | 0.046337 |
 
| closing tables       | 0.000025 |
 
| Unlocking tables     | 0.000020 |
 
| freeing items        | 0.000013 |
 
| updating status      | 0.000093 |
 
| cleaning up          | 0.000012 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.02 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 5;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000073 |
 
| checking permissions | 0.000012 |
 
| Opening tables       | 0.000022 |
 
| After opening tables | 0.000010 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000016 |
 
| init                 | 0.000052 |
 
| updating             | 0.000091 |
 
| end                  | 0.000011 |
 
| query end            | 0.019229 |
 
| closing tables       | 0.000022 |
 
| Unlocking tables     | 0.000020 |
 
| freeing items        | 0.000012 |
 
| updating status      | 0.000088 |
 
| cleaning up          | 0.000011 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.47 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 6;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000071 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000022 |
 
| After opening tables | 0.000011 |
 
| System lock          | 0.000009 |
 
| Table lock           | 0.000011 |
 
| init                 | 0.000050 |
 
| updating             | 0.000121 |
 
| end                  | 0.000013 |
 
| query end            | 0.467121 |
 
| closing tables       | 0.000024 |
 
| Unlocking tables     | 0.000026 |
 
| freeing items        | 0.000013 |
 
| updating status      | 0.000095 |
 
| cleaning up          | 0.000012 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.45 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MariaDB [my_test]> show profile for query 7;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000071 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000022 |
 
| After opening tables | 0.000010 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000011 |
 
| init                 | 0.000049 |
 
| updating             | 0.000100 |
 
| end                  | 0.000013 |
 
| query end            | 0.449001 |
 
| closing tables       | 0.000023 |
 
| Unlocking tables     | 0.000020 |
 
| freeing items        | 0.000013 |
 
| updating status      | 0.000095 |
 
| cleaning up          | 0.000013 |
 
+----------------------+----------+
 
15 rows in set (0.00 sec)
 
 
 
MariaDB [my_test]> select @@version, @@version_comment;
 
+-----------------+-------------------+
 
| @@version       | @@version_comment |
 
+-----------------+-------------------+
 
| 10.1.12-MariaDB | MariaDB Server    |
 
+-----------------+-------------------+
 
1 row in set (0.00 sec)

Secondly, your comparison to MySQL 5.1 is taken out of context (because of the grep). If you look at the whole output, the picture might be quite different:

MySQL 5.1.73

 
MySQL [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.45 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 1;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000060 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000014 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000009 |
 
| init                 | 0.000054 |
 
| Updating             | 0.000053 |
 
| end                  | 0.000009 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.449943 |
 
| logging slow query   | 0.000015 |
 
| cleaning up          | 0.000006 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.05 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 2;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000064 |
 
| checking permissions | 0.000010 |
 
| Opening tables       | 0.000014 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000010 |
 
| init                 | 0.000041 |
 
| Updating             | 0.000053 |
 
| end                  | 0.000010 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.050710 |
 
| logging slow query   | 0.000017 |
 
| cleaning up          | 0.000006 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.05 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 3;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000059 |
 
| checking permissions | 0.000010 |
 
| Opening tables       | 0.000016 |
 
| System lock          | 0.000008 |
 
| Table lock           | 0.000009 |
 
| init                 | 0.000039 |
 
| Updating             | 0.000050 |
 
| end                  | 0.000009 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.044139 |
 
| logging slow query   | 0.000015 |
 
| cleaning up          | 0.000006 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.09 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 4;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000061 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000014 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000010 |
 
| init                 | 0.000040 |
 
| Updating             | 0.000052 |
 
| end                  | 0.000009 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.082375 |
 
| logging slow query   | 0.000015 |
 
| cleaning up          | 0.000006 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=size+100 where id=1;
 
Query OK, 1 row affected (0.04 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 5;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000060 |
 
| checking permissions | 0.000009 |
 
| Opening tables       | 0.000015 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000009 |
 
| init                 | 0.000041 |
 
| Updating             | 0.000066 |
 
| end                  | 0.000010 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.042251 |
 
| logging slow query   | 0.000016 |
 
| cleaning up          | 0.000007 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;     
Query OK, 1 row affected (0.05 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 6;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000060 |
 
| checking permissions | 0.000011 |
 
| Opening tables       | 0.000015 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000010 |
 
| init                 | 0.000037 |
 
| Updating             | 0.000050 |
 
| end                  | 0.000009 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.041421 |
 
| logging slow query   | 0.000015 |
 
| cleaning up          | 0.000006 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]> update my_test.test set size=100 where id=1;
 
Query OK, 0 rows affected (0.09 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
MySQL [my_test]> show profile for query 7;
 
+----------------------+----------+
 
| Status               | Duration |
 
+----------------------+----------+
 
| starting             | 0.000196 |
 
| checking permissions | 0.000013 |
 
| Opening tables       | 0.000014 |
 
| System lock          | 0.000007 |
 
| Table lock           | 0.000010 |
 
| init                 | 0.000038 |
 
| Updating             | 0.000049 |
 
| end                  | 0.000007 |
 
| query end            | 0.000006 |
 
| freeing items        | 0.084687 |
 
| logging slow query   | 0.000021 |
 
| cleaning up          | 0.000009 |
 
+----------------------+----------+
 
12 rows in set (0.00 sec)
 
 
 
MySQL [my_test]>  select @@version, @@version_comment;
 
+-----------+------------------------------+
 
| @@version | @@version_comment            |
 
+-----------+------------------------------+
 
| 5.1.73    | MySQL Community Server (GPL) |
 
+-----------+------------------------------+
 
1 row in set (0.00 sec)

Indeed, the query end phase takes no time, but the very next phase, freeing items, behaves the same way as query end in higher versions. A lot of logic changed between 5.1 and 5.6/10.1, I suppose some steps might be marked differently now. It could have been investigated why exactly it happened, but does it serve any practical purpose? Why is the query end stage particularly important for you? Do you observe the overall performance degradation, or is it just how the total execution time is split into phases that bothers you?

Comment by Elena Stepanova [ 2016-03-17 ]

cyy,
Regarding your description update of '2016/03/17'.
My comments above related to a single execution or mixed executions of these two statements with default server settings.

Your last test results, where you execute the same statement 10,000 times in a row, are irrelevant on an entirely different reason.
In your server you have log_bin=ON and binlog_format=ROW.
So, when you execute update my_test.test set size=size+100 where id=1, every time it actually modifies the value, and the event is written into the binary log, which of course takes a lot of time comparing to the query itself.
But when you execute update my_test.test set size=100 where id=1 repeatedly, it does not modify anything, so it's never written into binlog. Naturally, it's instant comparing to the actual update.

If you want real results, please modify your stmt1.sql so that it always uses a different constant.

Comment by chen yuanyuan [ 2016-03-18 ]

Elena Stepanova,
Thank you for your comment.You are right,my test cases are too simple to represent the real cases.
But in the pt-query-digest result posed before,there are 1000 uisdb.maildir (innodb table) updates,and 1000 inserts to a innodb table,and again 1000 inserts to a innodb table with blob cols.their results are all written to the binary log,I couldn't understand why the update statements occupied so much time.
Bellow are definitions of there tables:

CREATE TABLE `maildir` (
 
        `mb_id` BIGINT UNSIGNED NOT NULL,
 
        `maildir_id` INT UNSIGNED NOT NULL,
 
        `name` VARCHAR(62) NOT NULL,
 
        `name_pinyin` VARCHAR(362) COLLATE utf8mb4_general_ci NOT NULL,
 
        `pwd` VARCHAR(64) COLLATE latin1_bin NULL,
 
        `next_uid` INT UNSIGNED NOT NULL,
 
        `is_subscribed` TINYINT UNSIGNED NOT NULL,
 
        `type` TINYINT UNSIGNED NOT NULL,
 
        `pop3_show_days` TINYINT UNSIGNED NOT NULL,
 
        `mail_reside_days` TINYINT UNSIGNED NOT NULL,
 
        `last_expire_mail_time` BIGINT UNSIGNED NOT NULL,
 
        `deleted_time` BIGINT UNSIGNED NULL,
 
        `deleted_method` TINYINT UNSIGNED NULL,
 
        `status` TINYINT UNSIGNED NOT NULL,
 
        PRIMARY KEY (`mb_id`,`maildir_id`),
 
        UNIQUE KEY (`mb_id`,`name`)
 
)ENGINE=Innodb,COLLATE=utf8mb4_bin;
 
 
 
CREATE TABLE `mail` (
 
        `mb_id` BIGINT UNSIGNED NOT NULL,
 
        `maildir_id` INT UNSIGNED NOT NULL,
 
        `uid` INT UNSIGNED NOT NULL,
 
        `orig_maildir_id` INT UNSIGNED NOT NULL,
 
        `entity_id` BIGINT UNSIGNED NOT NULL,
 
        `keyword_id` BIGINT UNSIGNED NOT NULL,
 
        `size` INT UNSIGNED NOT NULL,
 
        `system_flags` TINYINT UNSIGNED NOT NULL,
 
        `webmail_flags` BIGINT UNSIGNED NOT NULL,
 
        `sent_time` BIGINT UNSIGNED NOT NULL,
 
        `sent_timezone` SMALLINT NOT NULL,
 
        `from_display_name_pinyin` VARCHAR(384) COLLATE utf8mb4_general_ci NOT NULL,
 
        `to_display_name_pinyin` VARCHAR(384) COLLATE utf8mb4_general_ci NOT NULL,
 
        `received_time` BIGINT UNSIGNED NOT NULL,
 
        `subject_pinyin` VARCHAR(384) COLLATE utf8mb4_general_ci NOT NULL,
 
        PRIMARY KEY (`mb_id`,`maildir_id`,`uid`),
 
        INDEX (`entity_id`)
 
)ENGINE=Innodb,COLLATE=utf8mb4_bin;
 
 
 
CREATE TABLE `mail_entity` (
 
        `id` BIGINT UNSIGNED NOT NULL AUTO_INCREMENT,
 
        `xmid` CHAR(48) COLLATE latin1_bin NOT NULL,
 
        `is_shared` TINYINT UNSIGNED NOT NULL,
 
        `mis_ref_flag` TINYINT UNSIGNED NOT NULL,
 
        `hash` CHAR(64) COLLATE latin1_bin NOT NULL,
 
        `smtp_sender_mail_addr` VARCHAR(129) COLLATE latin1_bin NULL,
 
        `header` LONGBLOB NOT NULL,
 
        `main_text` LONGBLOB NULL,
 
        `from_mail_addrs` LONGBLOB NULL,
 
        `from_display_names` LONGBLOB NULL,
 
        `to_mail_addrs` LONGBLOB NULL,
 
        `to_display_names` LONGBLOB NULL,
 
        `cc_mail_addrs` LONGBLOB NULL,
 
        `cc_display_names` LONGBLOB NULL,
 
        `bcc_mail_addrs` LONGBLOB NULL,
 
        `bcc_display_names` LONGBLOB NULL,
 
        `subject` LONGBLOB NOT NULL,
 
        `message_id` LONGBLOB NULL,
 
        `is_encrypted` TINYINT UNSIGNED NOT NULL,
 
        `bodystructure` LONGBLOB NOT NULL,
 
        `mail_index` LONGTEXT COLLATE latin1_bin NOT NULL,
 
        `mail_attachment_index` LONGBLOB NULL,
 
        `mail_image_index` LONGBLOB NULL,
 
        `tfs_key` CHAR(18) COLLATE latin1_bin NOT NULL,
 
        `deleted_time` BIGINT UNSIGNED NULL,
 
        PRIMARY KEY (`id`),
 
        UNIQUE KEY (`xmid`),
 
        INDEX (`is_shared`,`mis_ref_flag`),
 
        INDEX (`deleted_time`)
 
)ENGINE=Innodb,COLLATE=utf8mb4_bin,ROW_FORMAT=COMPRESSED;

As You can see, the other two tables are more large (both in row number and col number) than the maildir table.
I have uploaded the pt-query-digest result as an attachment.
How to analyze in such a situation?

Comment by Elena Stepanova [ 2016-04-08 ]

cyy,

It can be analyzed further I suppose, but how is it related to the original problem you reported? I don't see here any indication that update spends time in 'query end', and you are comparing two completely different queries – UPDATE which searches for values based on a condition and uses a function, with INSERT which inserts a simple set of values.

Comment by Elena Stepanova [ 2016-05-09 ]

Please comment to re-open if you have further information on the issue.

Generated at Thu Feb 08 07:36:59 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.