Mysql – COMMIT on top of the pt-query-digest output

MySQLmysql-5.5perconapercona-toolsperformanceslow-log

I've been optimizing my MySQL server and after tweaking a few queries, I ended up with the COMMIT item on top of the pt-query-digest output, as shown in the extract below:

# 322s user time, 770ms system time, 71.75M rss, 223.13M vsz
# Current date: Sat Oct  1 11:12:58 2016
# Hostname: XXXX
# Files: /home/tools/Slow10.log
# Overall: 1.08M total, 1.47k unique, 61.74 QPS, 0.17x concurrency _______
# Time range: 2016-10-01 06:15:09 to 11:06:35
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          2913s     1us     14s     3ms    15ms    27ms   194us
# Lock time           123s       0      2s   113us   167us     3ms    42us
# Rows sent        1019.81k       0   8.58k    0.97    0.99   26.59       0
# Rows examine     314.86M       0   2.13M  305.82  234.30   7.13k       0
# Query size       321.03M       6  14.64k  311.81   1.14k  743.10   88.31

# Profile
# Rank Query ID           Response time   Calls  R/Call V/M   Item
# ==== ================== =============== ====== ====== ===== ============
#    1 0x813031B8BBC3B329 1676.7355 57.6%  70006 0.0240  0.02 COMMIT
#    2 0xBC10C51A724ECD57   61.8928  2.1%    211 0.2933  0.08 SELECT users

And the query is shown as:

# Query 1: 4.00 QPS, 0.10x concurrency, ID 0x813031B8BBC3B329 at byte 462955973
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: 2016-10-01 06:15:09 to 11:06:34
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6   70006
# Exec time     57   1677s     9us      2s    24ms    56ms    24ms    16ms
# 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
# Query size     0 410.19k       6       6       6       6       0       6
# String:
# Databases    XXX_XX... (9419/13%)... 40 more
# Hosts        localhost
# Query_time distribution
#   1us  #
#  10us  #
# 100us  #
#   1ms  ####
#  10ms  ################################################################
# 100ms  #
#    1s  #
#  10s+
commit\G

Any word on how can I optimize this?

If further information is required please let me know!

Thanks in advance!

EDIT 2016-02-10: The first analysis before any query optimization looked like:

# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================ ======= ====== ===== ==========
# 1 0x62057CDB69C17D23 18377.2125 46.3% 139328 0.1319 0.15 SELECT AAAA
# 2 0xEC77079791A0E274 6992.0443 17.6% 127446 0.0549 0.09 SELECT BBBB
# 3 0xB8A934DECC36D811 6283.1217 15.8% 247595 0.0254 0.03 UPDATE users_sessions
# 4 0x813031B8BBC3B329 2042.6094 5.1% 89046 0.0229 0.04 COMMIT

Server has 8Gb RAM with innodb_buffer_pool_size=5G with about 70 databases with 140 tables each.

EDIT 2016-10-06:

# grep innodb /etc/my.cnf
innodb_flush_method=O_DIRECT
innodb_buffer_pool_size=5G
innodb_log_buffer_size=4M

Best Answer

Forensics...

  • Median time for your COMMITs: 16ms.
  • Typical time for spinning disk write: 10ms.
  • Default setting of innodb_flush_log_at_trx_commit: 1, meaning flush to disk on every commit.

Conclusion: The killer used the candlestick in the library. Or.. Most of what you are doing is very rapidly committing transactions.

Possible ways to speed up:

  • innodb_flush_log_at_trx_commit = 2 -- This flushes once per second instead of once per transaction. That is less 'safe', but for some users, the tradeoff is worth it.
  • Batch you actions. Instead of one INSERT per COMMIT, do lots of INSERTs. The main cost in COMMIT is flushing one write to the rollback log, regardless of how much went on in the transaction.
  • Hardware -- SSD - drops the 10ms to 1ms (or something like that); RAID with battery backed write cache - makes writes take virtually 0 ms, even without loss of safety.
  • Since a few COMMITs are taking over 1 second, you could look for them and see if their transactions can be improved.
Related Question