InnoDB has a good source of information about its status which can be requested every time you need to know “what’s up” with that in your environment. The SHOW ENGINE INNODB STATUS will inform you the last x seconds of its operation, leveraging system or database administrator with the best – as possible – position about what is happening with data pages which are being manipulated in a sense of maintain those in the Buffer Pool as more as possible.

$ mysql -u  -p -e 'SHOW ENGINE INNODB STATUS\G' > file

Buffer Pool is the privileged main memory area where InnoDB will maintain all the last recently used data pages, regardless of the page’s size, in rotation, based on LRU algorithm. This area will serve well for SELECT, UPDATE and DELETE, SQL commands which will use more data from memory than that on disk. Pages will be cycling between young and old status, more used and less used, respectively…

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 79121448960; in additional pool allocated 0
Dictionary memory allocated 776119
Buffer pool size   4718590
Free buffers       4682063
Database pages     36395
Old database pages 13627
Modified db pages  23223
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 672, not young 0
2.90 youngs/s, 0.00 non-youngs/s
Pages read 36066, created 329, written 323
75.09 reads/s, 1.50 creates/s, 0.00 writes/s
Buffer pool hit rate 985 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 5.00/s
LRU len: 36395, unzip_LRU len: 0
I/O sum[0]:cur[80], unzip sum[0]:cur[0]

As you can see above, the total allocated main memory for Buffer Pool is 79121448960, with some space for the InnoDB’s dictionary, the actual size of the buffer pool, the amount of space, that is, 4682063, what is 292629 in terms of data pages, considering 16kb pages, the amount of old pages the remains in the buffer pool and all the modified or dirty pages – those that were modified by an UPDATE, for example, and haven’t flushed to disk yet. Pending reads and writes indicates the amount of pages which were written to the buffer pool and haven’t flushed yet as the flush list and the amount in terms of pages.

A good point that called my attention was the read ahead and evictions noticed by the output above. “The read ahead request is an I/O request to prefetch multiple pages in the buffer pool asynchronously, in anticipation that these pages will be needed soon”. This will tell us how many pages were copied into the buffer pool and were evicted without being accessed anytime. I think it costs a little bit to get more pages than necessary into the buffer pool as the mechanism must discard pages which are not being accessed, even being this process asynchronous.

Recently, I’ve got very curious about the spin rounds behavior and I realized that if you have many transactions in sleep state inside InnoDB, waiting to be executed, perhaps it may be a spin round problem. The output of SHOW ENGINE INNODB STATUS will show you that…

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 13701
--Thread 140549419812608 has waited at log0log.ic line 321 for 0.00 seconds the semaphore:
Mutex at 0x7c10f4b8 created file log0log.cc line 737, lock var 1
waiters flag 1
OS WAIT ARRAY INFO: signal count 15206
Mutex spin waits 607605, rounds 3114855, OS waits 8383
RW-shared spins 9396, rounds 101453, OS waits 1626
RW-excl spins 6569, rounds 137971, OS waits 3191
Spin rounds per wait: 5.13 mutex, 10.80 RW-shared, 21.00 RW-excl

What does it mean, so?

• Mutex spin waits 607605 is the number of times a thread tried to get a mutex and it wasn’t available, so it waited in a spin-wait;
• rounds 3114855 is the number of times threads looped in the spin-wait cycle, checking the mutex.
• OS waits 8383 is the number of times the thread gave up spin-waiting and went to sleep state instead.

In the SEMAPHORES output above we can observe a case of a fine tuning is needed to avoid context switches. It costs lots of computational resources to maintain information about the actual executing status to restore it as soon as possible. The RW-shared is high, but this is not the real problem. The real problem is happening around RW-excl which acquires locks and make the amount of rounds higher even on the OS level. The final result, 21 waits in the last five seconds.

I will comment more about it soon, cheers!

You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.