6

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
  • 1
    This is 'normal'. Look down the list a short ways; you may find some slow query inside the transaction. – Rick James Oct 2 '16 at 5:01
  • Hi Rick, as you can see in the rank the query #2 it only uses 2.1% of the time. Is there any way to pt-query-digest or log only Transactions? Thanks! – LeG Oct 2 '16 at 12:06
  • Well, let's check some other things. How much RAM? What is the value of innodb_buffer_pool_size? – Rick James Oct 2 '16 at 19:26
  • Rick, server has 8Gb RAM, innodb_buffer_pool_size=5G – LeG Oct 2 '16 at 20:56
  • Please post the output of grep innodb /etc/my.cnf – RolandoMySQLDBA Oct 6 '16 at 17:16
1

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.
  • Rick, is there any way I can log all transactions excluding non transactions queries in order to identify how they are working and how to optimize them? – LeG Oct 2 '16 at 21:00
  • I don't think there is a way to do that. Suggest you stare at the source code. Anyway, how much of a problem is COMMIT apparently causing? – Rick James Oct 2 '16 at 21:02
  • 1
    "61.74 QPS, 0.17x concurrency" sounds like there is very little trouble. And so little concurrency that one transaction is rarely hitting another. – Rick James Oct 2 '16 at 21:06
  • Actually not that much, I've started with the following: # 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 But I was just wondering how could I further improve. – LeG Oct 2 '16 at 22:00
0

In short

Use SHOW ENGINE INNODB STATUS to get more information.

Long version

This means your COMMIT taking lots of time. There are serveral issues might cause it:

  • CPU bound or I/O bound.

    In this case, you can find out which transaction is slow, and then you can optimize it.

  • InnoDB locks.

    In this case, you can find out what kind of locks are acquired, and possible deadlocks (which might not be detected by InnoDB), and then optimize it.

  • Hi Gslin, what should I look for in the ´SHOW ENGINE INNODB STATUS´? Thanks! – LeG Oct 2 '16 at 12:10

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.