Parsing SHOW ENGINE INNODB STATUS in ruby with regex
https://stackoverflow.com/questions/8236772
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianQuestion
I'm trying to parse the output of SHOW ENGINE INNODB STATUS in ruby and break each section of the output into a hash. The input looks something like this:
=====================================
111122 21:44:14 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 343485 1_second, 343478 sleeps, 34330 10_second, 180 background, 180 flush
srv_master_thread log flush and writes: 347405
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 35569, signal count 35549
Mutex spin waits 568, rounds 16942, OS waits 122
RW-shared spins 34379, rounds 1031182, OS waits 33574
RW-excl spins 14, rounds 56280, OS waits 1870
Spin rounds per wait: 29.83 mutex, 29.99 RW-shared, 4020.00 RW-excl
--------
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 (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 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
174398 OS file reads, 1293893 OS file writes, 476099 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 1.00 writes/s, 1.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 413 merges
merged operations:
insert 619, delete mark 1172, delete 685
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 553193, node heap has 5 buffer(s)
1.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 18246430610
Log flushed up to 18246430610
Last checkpoint at 18246428493
Max checkpoint age 7782360
Checkpoint age target 7539162
Modified age 2117
Checkpoint age 2117
0 pending log writes, 0 pending chkp writes
395104 log i/o's done, 1.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 136216576; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
Adaptive hash index 2298852 (2212772 + 86080)
Page hash 69556 (buffer pool 0 only)
Dictionary cache 1316974 (553912 + 763062)
File system 58436 (41336 + 17100)
Lock system 167716 (166436 + 1280)
Recovery system 0 (0 + 0)
Dictionary memory allocated 763062
Buffer pool size 8191
Buffer pool size, bytes 134201344
Free buffers 0
Database pages 8186
Old database pages 3001
Modified db pages 18
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 166320, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 174314, created 16854, written 855084
0.00 reads/s, 0.00 creates/s, 0.00 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: 8186, unzip_LRU len: 0
I/O sum[110]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 3FB94D3
Read view up limit trx id 3FB94D3
Read view low limit trx id 3FB94D3
Read view individually stored trx ids:
-----------------
Main thread process no. 12245, id 2777058192, state: flushing log
Number of rows inserted 439964, updated 362023, deleted 794, read 4706858
0.00 inserts/s, 1.00 updates/s, 0.00 deletes/s, 1.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 3FB94D3
Purge done for trx's n:o < 3FB94D3 undo n:o < 0
History list length 3221
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 72085, OS thread handle 0xa4435b90, query id 1594101 anders.borg.lan 192.168.1.12 aaron
show engine innodb status
---TRANSACTION 0, not started
MySQL thread id 69032, OS thread handle 0xa833bb90, query id 1539435 anders.borg.lan 192.168.1.12 aaron
---TRANSACTION 3FB8DA3, not started
MySQL thread id 58893, OS thread handle 0xa839db90, query id 1590306 localhost pd
---TRANSACTION 3FB94D1, not started
MySQL thread id 2, OS thread handle 0xa85a8b90, query id 1594100 Slave has read all relay log; waiting for the slave I/O thread to update it
----------------------------
END OF INNODB MONITOR OUTPUT
============================
I want to get the headers BACKGROUND THREAD, SEMAPHORES, FILE I/O, as a key in a hash with the data below them as the value. I'm attempting to use regular expressions rather than a complex looping structure, but I'm open to elegant Enumerable options as well.
This extracts the keys:
ruby-1.9.2-p290 :011 > pp foo.scan /-{4,}\n([[:upper:][:space:][:punct:]]+)\n-{4,}\n/
[["BACKGROUND THREAD"],
["SEMAPHORES"],
["FILE I/O"],
["INSERT BUFFER AND ADAPTIVE HASH INDEX"],
["BUFFER POOL AND MEMORY"],
["ROW OPERATIONS"],
["LATEST DETECTED DEADLOCK"],
["TRANSACTIONS"]]
but when I attempt to get the value piece out, I'm unsuccessful. What I have tried (unsuccessfully) is
foo.scan /-{4,}\n([[:upper:][:space:][:punct:]]+)\n-{4,}\n(.*?)/m
=> [["BACKGROUND THREAD", ""], ["SEMAPHORES", ""], ["FILE I/O", ""], ["INSERT BUFFER AND ADAPTIVE HASH INDEX", ""], ["BUFFER POOL AND MEMORY", ""], ["ROW OPERATIONS", ""], ["TRANSACTIONS", ""]]
This still just gets the headers with blank values (I have tried with and without /m). When I make the second group greedy, it all goes to heck:
> pp foo.scan /-{4,}\n([[:upper:][:space:][:punct:]]+)\n-{4,}\n(.*)/m
[["BACKGROUND THREAD",
"srv_master_thread loops: 331475 1_second, 331470 sleeps, 33130 10_second, 171 background, 171 flush\nsrv_master_thread log flush and writes: 335234\n----------\nSEMAPHORES\n----------\nOS WAIT ARRAY INFO: reservation count 34304, signal count 34284\nMutex spin waits 525, rounds 15652, OS waits 111\nRW-shared spins 33171, rounds 994896, OS waits 32391\nRW-excl spins 14, rounds 54150, OS waits 1799\nSpin rounds per wait: 29.81 mutex, 29.99 RW-shared, 3867.86 RW-excl\n--------\nFILE I/O\n--------\nI/O thread 0 state: waiting for completed aio requests (insert buffer thread)\nI/O thread 1 state: waiting for completed aio requests (log thread)\nI/O thread 2 state: waiting for completed aio requests (read thread)\nI/O thread 3 state: waiting for completed aio requests (read thread)\nI/O thread 4 state: waiting for completed aio requests (read thread)\nI/O thread 5 state: waiting for completed aio requests (read thread)\nI/O thread 6 state: waiting for completed aio requests (write thread)\nI/O thread 7 state: waiting for completed aio requests (write thread)\nI/O thread 8 state: waiting for completed aio requests (write thread)\nI/O thread 9 state: waiting for completed aio requests (write thread)\nPending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,\n ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0\nPending flushes (fsync) log: 0; buffer pool: 0\n172201 OS file reads, 1243697 OS file writes, 457553 OS fsyncs\n0.00 reads/s, 0 avg bytes/read, 3.70 writes/s, 1.30 fsyncs/s\n-------------------------------------\nINSERT BUFFER AND ADAPTIVE HASH INDEX\n-------------------------------------\nIbuf: size 1, free list len 5, seg size 7, 399 merges\nmerged operations:\n insert 605, delete mark 1172, delete 685\ndiscarded operations:\n insert 0, delete mark 0, delete 0\nHash table size 553193, node heap has 4 buffer(s)\n1.00 hash searches/s, 0.00 non-hash searches/s\n---\nLOG\n---\nLog sequence number 18200393778\nLog flushed up to 18200393778\nLast checkpoint at 18200391595\nMax checkpoint age 7782360\nCheckpoint age target 7539162\nModified age 2183\nCheckpoint age 2183\n0 pending log writes, 0 pending chkp writes\n380952 log i/o's done, 1.10 log i/o's/second\n----------------------\nBUFFER POOL AND MEMORY\n----------------------\nTotal memory allocated 136216576; in additional pool allocated 0\nInternal hash tables (constant factor + variable factor)\n Adaptive hash index 2282468 \t(2212772 + 69696)\n Page hash 69556 (buffer pool 0 only)\n Dictionary cache 1316974 \t(553912 + 763062)\n File system 58436 \t(41336 + 17100)\n Lock system 167716 \t(166436 + 1280)\n Recovery system 0 \t(0 + 0)\nDictionary memory allocated 763062\nBuffer pool size 8191\nBuffer pool size, bytes 134201344\nFree buffers 0\nDatabase pages 8187\nOld database pages 3002\nModified db pages 18\nPending reads 0\nPending writes: LRU 0, flush list 0, single page 0\nPages made young 164135, not young 0\n0.00 youngs/s, 0.00 non-youngs/s\nPages read 172117, created 14087, written 822028\n0.00 reads/s, 0.00 creates/s, 2.50 writes/s\nBuffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000\nPages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s\nLRU len: 8187, unzip_LRU len: 0\nI/O sum[116]:cur[0], unzip sum[0]:cur[0]\n--------------\nROW OPERATIONS\n--------------\n0 queries inside InnoDB, 0 queries in queue\n1 read views open inside InnoDB\n---OLDEST VIEW---\nNormal read view\nRead view low limit trx n:o 3FB30F3\nRead view up limit trx id 3FB30F3\nRead view low limit trx id 3FB30F3\nRead view individually stored trx ids:\n-----------------\nMain thread process no. 12245, id 2777058192, state: sleeping\nNumber of rows inserted 332424, updated 349391, deleted 794, read 4555996\n0.00 inserts/s, 1.00 updates/s, 0.00 deletes/s, 1.00 reads/s\n------------\nTRANSACTIONS\n------------\nTrx id counter 3FB30F5\nPurge done for trx's n:o < 3FB30F3 undo n:o < 0\nHistory list length 3503\nLIST OF TRANSACTIONS FOR EACH SESSION:\n---TRANSACTION 0, not started\nMySQL thread id 69032, OS thread handle 0xa833bb90, query id 1539435 anders.borg.lan 192.168.1.12 aaron\nSHOW ENGINE INNODB STATUS\n---TRANSACTION 0, not started\nMySQL thread id 69030, OS thread handle 0xa4435b90, query id 1527567 anders.borg.lan 192.168.1.12 aaron\n---TRANSACTION 3FB23A6, not started\nMySQL thread id 58893, OS thread handle 0xa839db90, query id 1531687 localhost pd\n---TRANSACTION 3FB30F3, not started\nMySQL thread id 2, OS thread handle 0xa85a8b90, query id 1539435 Slave has read all relay log; waiting for the slave I/O thread to update it\n----------------------------\nEND OF INNODB MONITOR OUTPUT\n============================\n"]]
The keyboard shaped indent in my forehead is starting to chafe, so if anyone has thoughts, I would really appreciate it.
Thanks!
EDIT I'm almost there with the following regex, but it misses the final group in the output, TRANSACTIONS. I need to make the final non-capturing group optional, but adding ? after the final ) doesn't seem to do it:
> pp str.scan /-{4,}\n([[:upper:][:space:][:punct:]]+)\n-{4,}\n(.*?)(?=\n-{4,}\n[[:upper:][:space:][:punct:]]+\n-{4,})/m
[["BACKGROUND THREAD",
"srv_master_thread loops: 26645693 1_second, 26645613 sleeps, 266456 10_second, 455 background, 455 flush\nsrv_master_thread log flush and writes: 2937913"],
["SEMAPHORES",
"OS WAIT ARRAY INFO: reservation count 15790436, signal count 18650446\nMutex spin waits 6231859458, rounds 9218278203, OS waits 7750045\nRW-shared spins 7207433, OS waits 656673; RW-excl spins 97132, OS waits 408931\nSpin rounds per wait: 1.48 mutex, 10.35 RW-shared, 177.41 RW-excl"],
["FILE I/O",
"I/O thread 0 state: waiting for i/o request (insert buffer thread)\nI/O thread 1 state: waiting for i/o request (log thread)\nI/O thread 2 state: waiting for i/o request (read thread)\nI/O thread 3 state: waiting for i/o request (read thread)\nI/O thread 4 state: waiting for i/o request (read thread)\nI/O thread 5 state: waiting for i/o request (read thread)\nI/O thread 6 state: waiting for i/o request (write thread)\nI/O thread 7 state: waiting for i/o request (write thread)\nI/O thread 8 state: waiting for i/o request (write thread)\nI/O thread 9 state: waiting for i/o request (write thread)\nPending normal aio reads: 0, aio writes: 0,\n ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0\nPending flushes (fsync) log: 0; buffer pool: 0\n8702304 OS file reads, 249839013 OS file writes, 147614062 OS fsyncs\n0.59 reads/s, 16384 avg bytes/read, 62.21 writes/s, 31.38 fsyncs/s"],
["INSERT BUFFER AND ADAPTIVE HASH INDEX",
"Ibuf: size 1, free list len 1922, seg size 1924,\n725992 inserts, 725992 merged recs, 546813 merges\nHash table size 283212071, node heap has 1 buffer(s)\n0.00 hash searches/s, 30503.28 non-hash searches/s\n---\nLOG\n---\nLog sequence number 2723462238497\nLog flushed up to 2723462238497\nLast checkpoint at 2723462084076\nMax checkpoint age 3396675134\nCheckpoint age target 3290529037\nModified age 154421\nCheckpoint age 154421\n0 pending log writes, 0 pending chkp writes\n131000087 log i/o's done, 25.67 log i/o's/second"],
["BUFFER POOL AND MEMORY",
"Total memory allocated 140995723264; in additional pool allocated 0\nInternal hash tables (constant factor + variable factor)\n Adaptive hash index 2265717168 \t(2265696568 + 20600)\n Page hash 141606856\n Dictionary cache 569091839 \t(566425616 + 2666223)\n File system 195856 \t(82672 + 113184)\n Lock system 340161088 \t(339997048 + 164040)\n Recovery system 0 \t(0 + 0)\n Threads 449944 \t(406936 + 43008)\nDictionary memory allocated 2666223\nBuffer pool size 8388607\nBuffer pool size, bytes 137438937088\nFree buffers 1\nDatabase pages 8388605\nOld database pages 3096554\nModified db pages 594\nPending reads 0\nPending writes: LRU 0, flush list 0, single page 0\nPages made young 4784976, not young 0\n0.30 youngs/s, 0.00 non-youngs/s\nPages read 12326482, created 1997429, written 137433410\n0.59 reads/s, 0.14 creates/s, 41.24 writes/s\nBuffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000\nPages read ahead 0.00/s, evicted without access 0.00/s\nLRU len: 8388605, unzip_LRU len: 0\nI/O sum[1914]:cur[0], unzip sum[0]:cur[0]"],
["ROW OPERATIONS",
"0 queries inside InnoDB, 0 queries in queue\n11 read views open inside InnoDB\nMain thread process no. 28529, id 140437935073024, state: sleeping\nNumber of rows inserted 217582489, updated 81459757, deleted 20128876, read 500031405066\n8.59 inserts/s, 19.70 updates/s, 1.24 deletes/s, 86631.36 reads/s"],
["LATEST DETECTED DEADLOCK",
"111111 18:45:12\n*** (1) TRANSACTION:\nTRANSACTION 88D7813CC, ACTIVE 0 sec, process no 28529, OS thread id 140437815531264 starting index read\nmysql tables in use 1, locked 1\nLOCK WAIT 3 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1\nMySQL thread id 9633269, query id 3915648018 10.124.62.113 ideeli Updating\nUPDATE `skus` SET `updated_at` = '2011-11-11 18:45:12', `position` = 4 WHERE `id` = 6481750\n*** (1) WAITING FOR THIS LOCK TO BE GRANTED:\nRECORD LOCKS space id 26132 page no 23995 n bits 144 index `PRIMARY` of table `ideeli_production`.`skus` trx id 88D7813CC lock_mode X locks rec but not gap waiting\n*** (2) TRANSACTION:\nTRANSACTION 88D78109E, ACTIVE 2 sec, process no 28529, OS thread id 140437787576064 starting index read\nmysql tables in use 1, locked 1\n3 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 2\nMySQL thread id 9628857, query id 3915648065 10.124.62.114 ideeli Updating\nUPDATE `skus` SET `updated_at` = '2011-11-11 18:45:12', `position` = 5 WHERE `id` = 6481786\n*** (2) HOLDS THE LOCK(S):\nRECORD LOCKS space id 26132 page no 23995 n bits 176 index `PRIMARY` of table `ideeli_production`.`skus` trx id 88D78109E lock_mode X locks rec but not gap\n*** (2) WAITING FOR THIS LOCK TO BE GRANTED:\nRECORD LOCKS space id 26132 page no 23995 n bits 144 index `PRIMARY` of table `ideeli_production`.`skus` trx id 88D78109E lock_mode X locks rec but not gap waiting\n*** WE ROLL BACK TRANSACTION (1)"]]
EDIT 2 - I found the right expression. Also, I answered my question below:
Hash[status.scan /-+\n([[:upper:][:space:][:punct:]]+)\n-+\n(.*?)(?=\n-+\n[[:upper:][:space:][:punct:]]+\n)/m]
Solution 2
I found an expression that captures everything correctly. It seems a bit overly complex, but it gets the job done:
Hash[status.scan /-+\n([[:upper:][:space:][:punct:]]+)\n-+\n(.*?)(?=\n-+\n[[:upper:][:space:][:punct:]]+\n)/m]
There are a couple complete lines of dashes in the middle of the input, so I need to specify the CAPS text on the line following it in the lookahead.
OTHER TIPS
You need to make it non-greedy, but you need to specify how far it should go by appending more to the end of the regex (otherwise, it's non-greedy, and the regex is finished, so why should it grab anything?). In this case, you just need to make it stop at the beginning of the next section of dashes:
foo.scan /-{4,}\n([[:upper:][:space:][:punct:]]+)\n-{4,}\n(.*?)\n(?=-{4,})/m
Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
