Mysql 5.5 InnoDB growing CPU – Going crazy

innodbmy.cnfMySQLmysql-5.5

Good morning,

I'm currently facing a problem where CPU usage keeps going up until the server crash.

I've tried multiple best practices proposed in this forum and on Percona, reinstalled the server twice already. Nothing seems to work.

The application is a small script that perform SELECT on range indexes, UPDATE on primary key and bulk insert on a UNIQUE keys in a very intensive way.

99.9% of the queries are running on a single InnoDB tables.

Following is the mysqltuner.pl output (which did not help me at all):

[--] Reads / Writes: 12% / 88%
[--] Total buffers: 4.2G global + 5.0M per thread (100 max threads)
[OK] Maximum possible memory usage: 4.7G (59% of installed RAM)
[OK] Slow queries: 0% (1/1M)
[OK] Highest usage of available connections: 42% (42/100)
[OK] Key buffer size / total MyISAM indexes: 128.0M/29.3M
[!!] Query cache is disabled
[OK] Sorts requiring temporary tables: 0% (0 temp sorts / 2 sorts)
[OK] Temporary tables created on disk: 19% (63 on disk / 327 total)
[OK] Thread cache hit rate: 58% (42 created / 102 connections)
[OK] Table cache hit rate: 38% (126 open / 325 opened)
[OK] Open file limit used: 3% (68/2K)
[OK] Table locks acquired immediately: 96% (1M immediate / 1M locks)
[OK] InnoDB buffer pool / data size: 4.0G/358.1M
[OK] InnoDB log waits: 0

My.cnf file is optimised to the best of my knowledge and what I've seen being used or adviced by pros:

# general tuning
# family of join_buffer_size ,sort_buffer_size, read_buffer_size, read_rnd_buffer_size
sort_buffer_size    = 4M
read_rnd_buffer_size    = 512K
table_cache             = 1024 
key_buffer_size     = 128M
#show global status like 'Max_used_connections'
max_connections        = 100 
#determine how many thread MySQL keep in memory to handle new conn
#100 - ((Threads_created/Connections)*100)
thread_cache_size       = 50 
#max size of what is being cached see SHOW GLOBAL STATUS LIKE 'Qc%'
#query_cache_limit  = 2M
query_cache_size        = 0 
query_cache_type        = 0

#innodb tuning

innodb_buffer_pool_size = 4G
innodb_buffer_pool_instances = 2
innodb_log_file_size    = 1G 
innodb_log_buffer_size  = 16MB
innodb_flush_log_at_trx_commit  = 2

innodb_file_per_table
innodb_flush_method = O_DIRECT 
innodb_read_io_threads = 64
innodb_write_io_threads = 64
innodb_thread_concurrency = 0

So far I've tried to:

1) Change query_cache_size to check in it had any impact on the CPU usage. Haven't been able to see any benefit from that so I disabled it.

2) Change thread_cache in order to get a better cache hit rate. There is no variation of Threads_created so I decided to let it at 50.

3) innodb_buffer_pool_size = 4G (out of 8G total)

Running rolando's queries:

SELECT CEILING(Total_InnoDB_Bytes*1.6/POWER(1024,3)) RIBPS FROM
 (SELECT SUM(data_length+index_length) Total_InnoDB_Bytes FROM 
 information_schema.tables WHERE engine='InnoDB') A;

return 2G in mycase.
So I decided to have 2 buffer pool instances with innodb_read_io_threads = 64 and innodb_write_io_threads = 64.

Got nothing out of this.

4) Adjust innodb_log_file_size to 25% of the pool and have trx_commit at 2.

Still no improvement.

The innodb status output in normal operation mode is (trying to paste it in a readable fashion).

 mysql> show engine innodb status\G
 *************************** 1. row ***************************
   Type: InnoDB
   Name: 
 Status: 
 =====================================
 140420 15:41:43 INNODB MONITOR OUTPUT
 =====================================
 Per second averages calculated from the last 38 seconds
 -----------------
 BACKGROUND THREAD
 -----------------
 srv_master_thread loops: 62 1_second, 61 sleeps, 6 10_second, 1 background, 1 flush
 srv_master_thread log flush and writes: 62
 ----------
 SEMAPHORES
 ----------
 OS WAIT ARRAY INFO: reservation count 722, signal count 2177
 Mutex spin waits 351436, rounds 271903, OS waits 201
 RW-shared spins 1069, rounds 12114, OS waits 242
 RW-excl spins 479, rounds 10793, OS waits 234
 Spin rounds per wait: 0.77 mutex, 11.33 RW-shared, 22.53 RW-excl
 ------------
 TRANSACTIONS
 ------------
 Trx id counter A6BFB
 Purge done for trx's n:o < A373C undo n:o < 0
 History list length 8780
 LIST OF TRANSACTIONS FOR EACH SESSION:
 ---TRANSACTION A6BB0, not started
 MySQL thread id 80, OS thread handle 0x7f4fb7c69700, query id 149238 localhost data
 ---TRANSACTION A6BD2, not started
 MySQL thread id 86, OS thread handle 0x7f4fb7ae3700, query id 149642 localhost data
 ---TRANSACTION A6BC9, not started
 MySQL thread id 78, OS thread handle 0x7f4fb7ceb700, query id 149544 localhost data
 ---TRANSACTION A6BB8, not started
 MySQL thread id 70, OS thread handle 0x7f4fb7ef3700, query id 149353 localhost data
 ---TRANSACTION A6BD6, not started
 MySQL thread id 73, OS thread handle 0x7f4fb7e30700, query id 149674 localhost data
 ---TRANSACTION A6BBB, not started
 MySQL thread id 79, OS thread handle 0x7f4fb7caa700, query id 149298 localhost data
 ---TRANSACTION A6BC0, not started
 MySQL thread id 84, OS thread handle 0x7f4fb7b65700, query id 149379 localhost data
 ---TRANSACTION A6BCF, not started
 MySQL thread id 63, OS thread handle 0x7f4fb80ba700, query id 149574 localhost data
 ---TRANSACTION A6BCC, not started
 MySQL thread id 61, OS thread handle 0x7f5112b16700, query id 149616 localhost data
 ---TRANSACTION A6BC6, not started
 MySQL thread id 58, OS thread handle 0x7f5112bd9700, query id 149498 localhost data
 ---TRANSACTION 0, not started
 MySQL thread id 47, OS thread handle 0x7f5112c1a700, query id 149675 localhost savas
 show engine innodb status
 ---TRANSACTION A6BF9, ACTIVE 0 sec
 mysql tables in use 1, locked 0
 MySQL thread id 62, OS thread handle 0x7f5112ad5700, query id 149649 localhost data Sending data
 SELECT id FROM tracker WHERE domain_id=2 AND visited='Y' AND stop_visit='N' AND NOW()>=addtime(updated,sec_to_time('43200')) limit 100
 Trx read view will not see trx with id >= A6BFA, sees < A3706
 ---TRANSACTION A6BF3, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 81, OS thread handle 0x7f4fb7c28700, query id 149612 localhost data
 Trx read view will not see trx with id >= A6BF4, sees < A3706
 ---TRANSACTION A6BEE, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 75, OS thread handle 0x7f4fb7dae700, query id 149515 localhost data
 Trx read view will not see trx with id >= A6BEF, sees < A3706
 ---TRANSACTION A6BEB, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 82, OS thread handle 0x7f4fb7be7700, query id 149465 localhost data
 Trx read view will not see trx with id >= A6BEC, sees < A3706
 ---TRANSACTION A6BE8, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 60, OS thread handle 0x7f5112b57700, query id 149449 localhost data
 Trx read view will not see trx with id >= A6BE9, sees < A3706
 ---TRANSACTION A6BE5, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 59, OS thread handle 0x7f5112b98700, query id 149419 localhost data
 Trx read view will not see trx with id >= A6BE6, sees < A3706
 ---TRANSACTION A6BE4, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 83, OS thread handle 0x7f4fb7ba6700, query id 149420 localhost data
 Trx read view will not see trx with id >= A6BE5, sees < A3706
 ---TRANSACTION A6BDC, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 71, OS thread handle 0x7f4fb7eb2700, query id 149327 localhost data
 Trx read view will not see trx with id >= A6BDD, sees < A3706
 ---TRANSACTION A6BD9, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 65, OS thread handle 0x7f4fb8038700, query id 149312 localhost data
 Trx read view will not see trx with id >= A6BDA, sees < A3706
 ---TRANSACTION A6BB7, ACTIVE 0 sec
 2 lock struct(s), heap size 376, 1 row lock(s)
 MySQL thread id 68, OS thread handle 0x7f4fb7f75700, query id 149058 localhost data
 Trx read view will not see trx with id >= A6BB8, sees < A3706
 ---TRANSACTION A3727, ACTIVE 63 sec
 MySQL thread id 96, OS thread handle 0x7f4fb7859700, query id 48112 localhost data
 Trx read view will not see trx with id >= A3728, sees < A3700
 ---TRANSACTION A3726, ACTIVE 63 sec
 MySQL thread id 97, OS thread handle 0x7f4fb7818700, query id 47827 localhost data
 Trx read view will not see trx with id >= A3727, sees < A3700
 ---TRANSACTION A3725, ACTIVE 63 sec
 MySQL thread id 95, OS thread handle 0x7f4fb789a700, query id 47424 localhost data
 Trx read view will not see trx with id >= A3726, sees < A3700
 ---TRANSACTION A3724, ACTIVE 63 sec
 MySQL thread id 85, OS thread handle 0x7f4fb7b24700, query id 47707 localhost data
 Trx read view will not see trx with id >= A3725, sees < A3700
 ---TRANSACTION A3723, ACTIVE 63 sec
 MySQL thread id 89, OS thread handle 0x7f4fb7a20700, query id 47625 localhost data
 Trx read view will not see trx with id >= A3724, sees < A3700
 ---TRANSACTION A3722, ACTIVE 63 sec
 MySQL thread id 92, OS thread handle 0x7f4fb795d700, query id 48674 localhost data
 Trx read view will not see trx with id >= A3723, sees < A3700
 ---TRANSACTION A3721, ACTIVE 63 sec
 MySQL thread id 93, OS thread handle 0x7f4fb791c700, query id 47449 localhost data
 Trx read view will not see trx with id >= A3722, sees < A3700
 ---TRANSACTION A3720, ACTIVE 63 sec
 MySQL thread id 90, OS thread handle 0x7f4fb79df700, query id 48764 localhost data
 Trx read view will not see trx with id >= A3721, sees < A3700
 ---TRANSACTION A371F, ACTIVE 63 sec
 MySQL thread id 94, OS thread handle 0x7f4fb78db700, query id 48320 localhost data
 Trx read view will not see trx with id >= A3720, sees < A3700
 ---TRANSACTION A371E, ACTIVE 63 sec
 MySQL thread id 91, OS thread handle 0x7f4fb799e700, query id 48109 localhost data
 Trx read view will not see trx with id >= A371F, sees < A3700
 ---TRANSACTION A371D, ACTIVE 63 sec
 MySQL thread id 76, OS thread handle 0x7f4fb7d6d700, query id 48220 localhost data
 Trx read view will not see trx with id >= A371E, sees < A3700
 ---TRANSACTION A3718, ACTIVE 63 sec
 MySQL thread id 88, OS thread handle 0x7f4fb7a61700, query id 48238 localhost data
 Trx read view will not see trx with id >= A3719, sees < A3700
 ---TRANSACTION A3716, ACTIVE 63 sec
 MySQL thread id 87, OS thread handle 0x7f4fb7aa2700, query id 48036 localhost data
 Trx read view will not see trx with id >= A3717, sees < A3700
 ---TRANSACTION A3711, ACTIVE 63 sec
 MySQL thread id 77, OS thread handle 0x7f4fb7d2c700, query id 48232 localhost data
 Trx read view will not see trx with id >= A3712, sees < A3700
 ---TRANSACTION A370E, ACTIVE 63 sec
 MySQL thread id 72, OS thread handle 0x7f4fb7e71700, query id 47602 localhost data
 Trx read view will not see trx with id >= A370F, sees < A3700
 ---TRANSACTION A370C, ACTIVE 63 sec
 MySQL thread id 74, OS thread handle 0x7f4fb7def700, query id 48101 localhost data
 Trx read view will not see trx with id >= A370D, sees < A3700
 ---TRANSACTION A370B, ACTIVE 63 sec
 MySQL thread id 69, OS thread handle 0x7f4fb7f34700, query id 48102 localhost data
 Trx read view will not see trx with id >= A370C, sees < A3700
 ---TRANSACTION A3708, ACTIVE 63 sec
 MySQL thread id 67, OS thread handle 0x7f4fb7fb6700, query id 48748 localhost data
 Trx read view will not see trx with id >= A3709, sees < A3700
 ---TRANSACTION A3707, ACTIVE 63 sec
 MySQL thread id 66, OS thread handle 0x7f4fb7ff7700, query id 48263 localhost data
 Trx read view will not see trx with id >= A3708, sees < A3700
 ---TRANSACTION A3706, ACTIVE 63 sec
 MySQL thread id 64, OS thread handle 0x7f4fb8079700, query id 48314 localhost data
 Trx read view will not see trx with id >= A3707, sees < A3700
 --------
 FILE I/O
 --------
 I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
 I/O thread 1 state: waiting for completed aio requests (log thread)
 I/O thread 2 state: waiting for completed aio requests (read thread)
 I/O thread 3 state: waiting for completed aio requests (read thread)
 I/O thread 4 state: waiting for completed aio requests (read thread)
 I/O thread 5 state: waiting for completed aio requests (read thread)
 I/O thread 6 state: waiting for completed aio requests (read thread)
 I/O thread 7 state: waiting for completed aio requests (read thread)
 I/O thread 8 state: waiting for completed aio requests (read thread)
 I/O thread 9 state: waiting for completed aio requests (read thread)
 I/O thread 10 state: waiting for completed aio requests (read thread)
 I/O thread 11 state: waiting for completed aio requests (read thread)
 I/O thread 12 state: waiting for completed aio requests (read thread)
 I/O thread 13 state: waiting for completed aio requests (read thread)
 I/O thread 14 state: waiting for completed aio requests (read thread)
 I/O thread 15 state: waiting for completed aio requests (read thread)
 I/O thread 16 state: waiting for completed aio requests (read thread)
 I/O thread 17 state: waiting for completed aio requests (read thread)
 I/O thread 18 state: waiting for completed aio requests (read thread)
 I/O thread 19 state: waiting for completed aio requests (read thread)
 I/O thread 20 state: waiting for completed aio requests (read thread)
 I/O thread 21 state: waiting for completed aio requests (read thread)
 I/O thread 22 state: waiting for completed aio requests (read thread)
 I/O thread 23 state: waiting for completed aio requests (read thread)
 I/O thread 24 state: waiting for completed aio requests (read thread)
 I/O thread 25 state: waiting for completed aio requests (read thread)
 I/O thread 26 state: waiting for completed aio requests (read thread)
 I/O thread 27 state: waiting for completed aio requests (read thread)
 I/O thread 28 state: waiting for completed aio requests (read thread)
 I/O thread 29 state: waiting for completed aio requests (read thread)
 I/O thread 30 state: waiting for completed aio requests (read thread)
 I/O thread 31 state: waiting for completed aio requests (read thread)
 I/O thread 32 state: waiting for completed aio requests (read thread)
 I/O thread 33 state: waiting for completed aio requests (read thread)
 I/O thread 34 state: waiting for completed aio requests (read thread)
 I/O thread 35 state: waiting for completed aio requests (read thread)
 I/O thread 36 state: waiting for completed aio requests (read thread)
 I/O thread 37 state: waiting for completed aio requests (read thread)
 I/O thread 38 state: waiting for completed aio requests (read thread)
 I/O thread 39 state: waiting for completed aio requests (read thread)
 I/O thread 40 state: waiting for completed aio requests (read thread)
 I/O thread 41 state: waiting for completed aio requests (read thread)
 I/O thread 42 state: waiting for completed aio requests (read thread)
 I/O thread 43 state: waiting for completed aio requests (read thread)
 I/O thread 44 state: waiting for completed aio requests (read thread)
 I/O thread 45 state: waiting for completed aio requests (read thread)
 I/O thread 46 state: waiting for completed aio requests (read thread)
 I/O thread 47 state: waiting for completed aio requests (read thread)
 I/O thread 48 state: waiting for completed aio requests (read thread)
 I/O thread 49 state: waiting for completed aio requests (read thread)
 I/O thread 50 state: waiting for completed aio requests (read thread)
 I/O thread 51 state: waiting for completed aio requests (read thread)
 I/O thread 52 state: waiting for completed aio requests (read thread)
 I/O thread 53 state: waiting for completed aio requests (read thread)
 I/O thread 54 state: waiting for completed aio requests (read thread)
 I/O thread 55 state: waiting for completed aio requests (read thread)
 I/O thread 56 state: waiting for completed aio requests (read thread)
 I/O thread 57 state: waiting for completed aio requests (read thread)
 I/O thread 58 state: waiting for completed aio requests (read thread)
 I/O thread 59 state: waiting for completed aio requests (read thread)
 I/O thread 60 state: waiting for completed aio requests (read thread)
 I/O thread 61 state: waiting for completed aio requests (read thread)
 I/O thread 62 state: waiting for completed aio requests (read thread)
 I/O thread 63 state: waiting for completed aio requests (read thread)
 I/O thread 64 state: waiting for completed aio requests (read thread)
 I/O thread 65 state: waiting for completed aio requests (read thread)
 I/O thread 66 state: waiting for completed aio requests (write thread)
 I/O thread 67 state: waiting for completed aio requests (write thread)
 I/O thread 68 state: waiting for completed aio requests (write thread)
 I/O thread 69 state: waiting for completed aio requests (write thread)
 I/O thread 70 state: waiting for completed aio requests (write thread)
 I/O thread 71 state: waiting for completed aio requests (write thread)
 I/O thread 72 state: waiting for completed aio requests (write thread)
 I/O thread 73 state: waiting for completed aio requests (write thread)
 I/O thread 74 state: waiting for completed aio requests (write thread)
 I/O thread 75 state: waiting for completed aio requests (write thread)
 I/O thread 76 state: waiting for completed aio requests (write thread)
 I/O thread 77 state: waiting for completed aio requests (write thread)
 I/O thread 78 state: waiting for completed aio requests (write thread)
 I/O thread 79 state: waiting for completed aio requests (write thread)
 I/O thread 80 state: waiting for completed aio requests (write thread)
 I/O thread 81 state: waiting for completed aio requests (write thread)
 I/O thread 82 state: waiting for completed aio requests (write thread)
 I/O thread 83 state: waiting for completed aio requests (write thread)
 I/O thread 84 state: waiting for completed aio requests (write thread)
 I/O thread 85 state: waiting for completed aio requests (write thread)
 I/O thread 86 state: waiting for completed aio requests (write thread)
 I/O thread 87 state: waiting for completed aio requests (write thread)
 I/O thread 88 state: waiting for completed aio requests (write thread)
 I/O thread 89 state: waiting for completed aio requests (write thread)
 I/O thread 90 state: waiting for completed aio requests (write thread)
 I/O thread 91 state: waiting for completed aio requests (write thread)
 I/O thread 92 state: waiting for completed aio requests (write thread)
 I/O thread 93 state: waiting for completed aio requests (write thread)
 I/O thread 94 state: waiting for completed aio requests (write thread)
 I/O thread 95 state: waiting for completed aio requests (write thread)
 I/O thread 96 state: waiting for completed aio requests (write thread)
 I/O thread 97 state: waiting for completed aio requests (write thread)
 I/O thread 98 state: waiting for completed aio requests (write thread)
 I/O thread 99 state: waiting for completed aio requests (write thread)
 I/O thread 100 state: waiting for completed aio requests (write thread)
 I/O thread 101 state: waiting for completed aio requests (write thread)
 I/O thread 102 state: waiting for completed aio requests (write thread)
 I/O thread 103 state: waiting for completed aio requests (write thread)
 I/O thread 104 state: waiting for completed aio requests (write thread)
 I/O thread 105 state: waiting for completed aio requests (write thread)
 I/O thread 106 state: waiting for completed aio requests (write thread)
 I/O thread 107 state: waiting for completed aio requests (write thread)
 I/O thread 108 state: waiting for completed aio requests (write thread)
 I/O thread 109 state: waiting for completed aio requests (write thread)
 I/O thread 110 state: waiting for completed aio requests (write thread)
 I/O thread 111 state: waiting for completed aio requests (write thread)
 I/O thread 112 state: waiting for completed aio requests (write thread)
 I/O thread 113 state: waiting for completed aio requests (write thread)
 I/O thread 114 state: waiting for completed aio requests (write thread)
 I/O thread 115 state: waiting for completed aio requests (write thread)
 I/O thread 116 state: waiting for completed aio requests (write thread)
 I/O thread 117 state: waiting for completed aio requests (write thread)
 I/O thread 118 state: waiting for completed aio requests (write thread)
 I/O thread 119 state: waiting for completed aio requests (write thread)
 I/O thread 120 state: waiting for completed aio requests (write thread)
 I/O thread 121 state: waiting for completed aio requests (write thread)
 I/O thread 122 state: waiting for completed aio requests (write thread)
 I/O thread 123 state: waiting for completed aio requests (write thread)
 I/O thread 124 state: waiting for completed aio requests (write thread)
 I/O thread 125 state: waiting for completed aio requests (write thread)
 I/O thread 126 state: waiting for completed aio requests (write thread)
 I/O thread 127 state: waiting for completed aio requests (write thread)
 I/O thread 128 state: waiting for completed aio requests (write thread)
 I/O thread 129 state: waiting for completed aio requests (write thread)
 Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
  ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
 Pending flushes (fsync) log: 0; buffer pool: 0
 1381 OS file reads, 6437 OS file writes, 98 OS fsyncs
 0.47 reads/s, 16384 avg bytes/read, 103.02 writes/s, 1.55 fsyncs/s
 -------------------------------------
 INSERT BUFFER AND ADAPTIVE HASH INDEX
 -------------------------------------
 Ibuf: size 1, free list len 3, seg size 5, 1 merges
 merged operations:
  insert 7, delete mark 0, delete 0
 discarded operations:
  insert 0, delete mark 0, delete 0
 Hash table size 8850461, node heap has 9 buffer(s)
 129480.12 hash searches/s, 1874.61 non-hash searches/s
 ---
 LOG
 ---
 Log sequence number 2208664963
 Log flushed up to   2208626326
 Last checkpoint at  2206051147
 0 pending log writes, 0 pending chkp writes
 6364 log i/o's done, 101.63 log i/o's/second
 ----------------------
 BUFFER POOL AND MEMORY
 ----------------------
 Total memory allocated 4395630592; in additional pool allocated 0
 Dictionary memory allocated 109470
 Buffer pool size   262143
 Free buffers       260626
 Database pages     1508
 Old database pages 556
 Modified db pages  447
 Pending reads 0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1359, created 149, written 66
 0.47 reads/s, 3.53 creates/s, 1.18 writes/s
 Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 1508, unzip_LRU len: 0
 I/O sum[0]:cur[26], unzip sum[0]:cur[0]
 ----------------------
 INDIVIDUAL BUFFER POOL INFO
 ----------------------
 ---BUFFER POOL 0
 Buffer pool size   131072
 Free buffers       130261
 Database pages     806
 Old database pages 315
 Modified db pages  242
 Pending reads 0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 759, created 47, written 34
 0.42 reads/s, 0.84 creates/s, 0.61 writes/s
 Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 806, unzip_LRU len: 0
 I/O sum[0]:cur[13], unzip sum[0]:cur[0]
 ---BUFFER POOL 1
 Buffer pool size   131071
 Free buffers       130365
 Database pages     702
 Old database pages 241
 Modified db pages  205
 Pending reads 0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 600, created 102, written 32
 0.05 reads/s, 2.68 creates/s, 0.58 writes/s
 Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 702, unzip_LRU len: 0
 I/O sum[0]:cur[13], unzip sum[0]:cur[0]
 --------------
 ROW OPERATIONS
 --------------
 0 queries inside InnoDB, 0 queries in queue
 31 read views open inside InnoDB
 Main thread process no. 14441, id 139980400486144, state: sleeping
 Number of rows inserted 0, updated 6750, deleted 0, read 352960
 0.00 inserts/s, 108.23 updates/s, 0.00 deletes/s, 5625.48 reads/s
 ----------------------------
 END OF INNODB MONITOR OUTPUT
 ============================

Best Answer

I'm going to explain how I solved the performance problem that I was fighting with for weeks. Feel free to criticize, the result can only be better for people in need.

First I read the book "High Performance MySQL". It is a great book because they expose the ways of profiling right from the start. Basically when you are done reading the first 2-3 chapters, you have enough tools to start digging. I wasn't aware of most of the profiling methods and I learned a lot.

I decided to start digging from the query_log by setting query_log_time=0. Then i picked the query that was causing trouble. In fact there was only one choice possible since all the queries were indexed, but this particular one was working on a large table. Went through everything here.

The target table was:

+------------+---------------+------+-----+-------------------+----------------+
| Field      | Type          | Null | Key | Default           | Extra          |
+------------+---------------+------+-----+-------------------+----------------+
| id         | int(11)       | NO   | PRI | NULL              | auto_increment |
| domain_id  | int(11)       | NO   | MUL | NULL              |                |
| url        | varchar(250)  | NO   | UNI | 0                 |                |
| visited    | enum('Y','N') | NO   |     | N                 |                |
| updated    | timestamp     | NO   |     | CURRENT_TIMESTAMP |                |
| hits       | smallint(6)   | NO   |     | 0                 |                |
| stop_visit | enum('Y','N') | NO   |     | N                 |                |
+------------+---------------+------+-----+-------------------+----------------+

The suspicious query was:

SELECT id FROM tracker WHERE updated<=NOW() and domain_id=2 and stop_visit='N' LIMIT 1;

There was a BTREE index on (updated,domain_id,stop_visit) so the explain plan gave nothing out. Then I tried querying the profiling like this:

 SET profiling=1;
 SHOW profiles;
 SET @query_id=1
 SELECT STATE, SUM(DURATION) AS Total_R,
 ROUND(
 100 * SUM(DURATION) /
 (SELECT SUM(DURATION)
 FROM INFORMATION_SCHEMA.PROFILING
 WHERE QUERY_ID = @query_id
 ), 2) AS Pct_R,
 COUNT(*) AS Calls,
 SUM(DURATION) / COUNT(*) AS "R/Call"
 FROM INFORMATION_SCHEMA.PROFILING
 WHERE QUERY_ID = @query_id
 GROUP BY STATE
 ORDER BY Total_R DESC;

Nothing wrong was observed and the query was executing with timings under 0.001. No temporary tables, indexes are used... Everything looks OK but obviously there is a underlying problem that I knew it was there.

SHOW STATUS and FLUSH STATUS showed something really weird:

 FLUSH status;
 SELECT id FROM tracker WHERE updated<=NOW() and domain_id=2 and stop_visit='N' LIMIT 1;
 show status where variable_name like 'Created%' or variable_name like 'Handler%';

+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Created_tmp_disk_tables    | 0     |
| Created_tmp_files          | 6     |
| Created_tmp_tables         | 0     |
| Handler_commit             | 0     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 0     |
| Handler_read_last          | 0     |
| Handler_read_next          | 44687 |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 0     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 0     |
+----------------------------+-------+

Now I thought why is Handler_read_next so high when the index was tailored to be selective (or i thought so). Well it wasn't. And more importantly I still don't have an answer to this question. After a bunch of random tries I found out that the ENUM column (stop_visit) was causing this very high Handler_read_next value. Changing the datatype to tinyint [0,1] or char(1) ['Y','N'] rewarded me with nothing.

At this point, I decided to break everything and re-start from scratch with the knowledge acquired. This resulted in the following changes to the initial table:

+-----------+---------------------+------+-----+-------------------+----------------+
| Field     | Type                | Null | Key | Default           | Extra          |
+-----------+---------------------+------+-----+-------------------+----------------+
| id        | bigint(20) unsigned | NO   | PRI | NULL              | auto_increment |
| url_crc   | int(10) unsigned    | NO   | MUL | NULL              |                |
| updated   | timestamp           | NO   | MUL | CURRENT_TIMESTAMP |                |
| domain_id | tinyint(3) unsigned | NO   |     | NULL              |                |
| owner     | int(10) unsigned    | NO   | MUL | 0                 |                |
| url       | varchar(255)        | NO   |     | NULL              |                |
| hits      | tinyint(3) unsigned | NO   |     | 0                 |                |
+-----------+---------------------+------+-----+-------------------+----------------+

The previous multi-column index became a single column index ALTER table tracker add index idx_updated (updated).

The result was a query that did not do any Handler_read_next operations. Instead it was gracefully incrementing Handler_read_key and Handler_read_first by 1.

Another obscure problem was solved by using a method described in this book used to access VARCHAR datatypes. I had this UNIQUE index on the url column previously, and I used to INSERT IGNORE on this big table thinking that trusting the UNIQUE constraint was the way to go. So I thought, if Mysql has to go through all the rows to INSERT this new url it is gonna be painful. Reason is approximate 40 INSERT IGNORE every 0.001 (as soon as the first query finished) with average 50 concurrent clients.

So I changed this behavior by using a crc32 integer index. And then just doing a read like so:

  SELECT * from tracker WHERE url_crc=crc32('http://google.com') and url='http://google.com'

There is still 40 SELECT like those every 0.001 but at least I can easily profile them. So I decided to stick with this for the moment.

After all those changes were made, the time to validate all the work came.

Again from this great book 3 simple methods:

> while true; do sleep 1; mysql -e 'SHOW PROCESSLIST\G' | grep State: | sort | uniq -c | sort -rn; done

> mysqladmin ext -i1 | awk 'BEGIN{printf "%5s %5s %5s %5s %5s %5s %5s\n","QPS","Thcon","Thrun","Opentb","tmp_tbl","FreePages","Bytessent"}/Queries/{q=$4-qp;qp=$4}/Threads_connected/{tc=$4}/Created_tmp_disk_tables/{tmp=$4}/Opened_tables/{ot=$4}/Innodb_buffer_pool_pages_free/{pf=$4}/Bytes_sent/{bs=$4}/Threads_running/{printf "%5d %5d %5d %5d %5d %10d %10d\n",q,tc,$4,ot,tmp,pf,bs}'

> awk '/^# Time:/{print $3, $4, c;c=0}/^# User/{c++}' mysql-slow.log

The first command will help to spot those states that are not normal. It will be also the start of more advanced profiling, but I won't cover those aspects here. That command helped me to find out that the query cache was doing more harm than good.

The second command is made to check the STATUS of the server and see how it is evolving. A problem can be quickly spotted just by looking in the output:

QPS    Th_con Th_run Opened_files tmp_disk free_pages bytes_sent
466    22     7   276    54     120658   30110619
401    22     6   276    54     120657   30145343
405    22     9   276    54     120657   30179509
=>85    22     5   276    54     120658   30196291

The sudden drop of the QPS to 85 is an alert that something is going wrong. In my case, the query_log revealed a huge quantity of updates. That was caused by a caching table that wasn't flushing in a cool way for MySQL.

With all those improvements I managed to DoS my router kernel: [539677.201824] nf_conntrack: table full, dropping packet.. That was a first :p

So I think that is all, time to thank the authors of the great book 'High Performance MySQL' and the community here for all the relevant posts.