MySQL slow log and COMMIT

Question

MySQL

I collected a log of slow requests, set the Perkon toolkit on it and got a wonderful report.

# 11.1s user time, 60ms system time, 37.28M rss, 114.69M vsz
# Current date: Mon Nov 26 09:00:15 2012
# Hostname: dbm01b
# Files: /tmp/slow.log
# Overall: 26.64k total, 253 unique, 0.31 QPS, 0.81x concurrency _____
# Time range: 2012-11-25 09:00:07 to 2012-11-26 08:59:45
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time         69753s      1s   2393s      3s      7s     15s      1s
# Lock time           357s       0      1s    13ms    48ms    23ms    27us
# Rows sent        600.53M       0 153.65M  23.08k    9.83   1.38M       0
# Rows examine       2.59G       0 153.65M 102.08k   1.09M   1.41M       0
# Rows affecte       3.93k       0      98    0.15    0.99    0.89       0
# Rows read        600.53M       0 153.65M  23.08k    9.83   1.38M       0
# Bytes sent        13.50G       0   2.69G 531.35k   1.96k  27.19M   51.63
# Merge passes           5       0       1    0.00       0    0.01       0
# Tmp tables         1.97k       0       4    0.08    0.99    0.30       0
# Tmp disk tbl          18       0       1    0.00       0    0.03       0
# Tmp tbl size     795.48M       0 200.99M  30.58k 123.85k   1.19M       0
# Query size         7.42M       6  18.99k  291.98   1.26k  542.45   76.28
# InnoDB:
# IO r bytes        11.48G       0   3.98G 865.77k  15.96k  41.26M       0
# IO r ops           1.17M       0 434.90k   88.30    0.99   4.40k       0
# IO r wait          3220s       0   2151s   232ms     8ms     18s       0
# pages distin      33.94M       0  63.79k   2.50k  15.96k   6.07k    4.96
# queue wait        30099s       0     17s      2s     11s      3s      1s
# rec lock wai          5s       0      1s   336us       0    12ms       0
# Boolean:
# Filesort       6% yes,  93% no
# Filesort on    0% yes,  99% no
# Full join      0% yes,  99% no
# Full scan     10% yes,  89% no
# Tmp table      6% yes,  93% no
# Tmp table on   0% yes,  99% no

# Profile
# Rank Query ID           Response time    Calls R/Call    Apdx V/M   Item
# ==== ================== ================ ===== ========= ==== ===== ====
#    1 0x813031B8BBC3B329 17471.3170 25.0% 12713    1.3743 0.56  0.09 COMMIT
#    2 0xD96E5125DDE561B1 11197.7439 16.1%  2555    4.3827 0.32  2.82 SELECT config
#    3 0x308989BE50A05867  7507.2040 10.8%  1821    4.1226 0.34  2.94 SELECT user
#    4 0x1C1CE7739FFBE68D  3427.3964  4.9%   820    4.1798 0.34  2.85 SELECT user
#    5 0x933552E69A3D4786  3283.6093  4.7%  1155    2.8430 0.43  2.75 UPDATE user
#    6 0xD73A57A12165993A  2736.5430  3.9%   918    2.9810 0.49  0.15 SELECT user user_photo
#    7 0x80E467E273FF53A9  2406.3752  3.4%   995    2.4185 0.47  2.59 UPDATE user_info

and then it starts on demand. And the first paragraph is

# Query 1: 0.15 QPS, 0.21x concurrency, ID 0x813031B8BBC3B329 at byte 15331863
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.56 [1.0], V/M = 0.09
# Query_time sparkline: |      ^ |
# Time range: 2012-11-25 09:02:35 to 2012-11-26 08:39:47
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         47   12713
# Exec time     25  17471s      1s      3s      1s      2s   353ms      1s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Rows read      0       0       0       0       0       0       0       0
# Bytes sent     0 136.57k      11      11      11      11       0      11
# Merge passes   0       0       0       0       0       0       0       0
# Tmp tables     0       0       0       0       0       0       0       0
# Tmp disk tbl   0       0       0       0       0       0       0       0
# Tmp tbl size   0       0       0       0       0       0       0       0
# Query size     0  74.49k       6       6       6       6       0       6
# InnoDB:
# String:
# Databases    user
# Hosts
# Last errno   0
# Users        user (12557/98%), user_1... (139/1%)... 1 more
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
commit\G

you understand - zero useful, and takes a quarter of the entire load.

in the slolog

# Time: 121121  9:01:48
# [email protected]: user[user] @  [192.168.2.83]
# Thread_id: 310269650  Schema: user  Last_errno: 0  Killed: 0
# Query_time: 1.298979  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0  Rows_read: 0
# Bytes_sent: 11  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# 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
# No InnoDB statistics available for this query
SET timestamp=1353474108;
commit;

how to understand what to commit there?

Answer 1

It looks like there is a problem with committing operations to disk. Try experimenting with the innodb_flush_log_at_trx_commit configuration option . Try values ​​2 or 0.

Answer 2

Is there a big cycle somewhere and a commit at the end?
It will be more efficient if you commit in blocks of several records 100-1000 at a time. Because The DBMS has to keep a large amount of intermediate uncommitted data.
Of course, if it does not go against the logic of the application.