MySQL Bugs: #45509: Better SHOW ENGINE INNODB STATUS parsing

Bug #45509	Better SHOW ENGINE INNODB STATUS parsing
Submitted:	15 Jun 2009 20:27	Modified:	24 Jan 2011 22:47
Reporter:	Mark Leith	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Enterprise Monitor: Agent	Severity:	S3 (Non-critical)
Version:	2.x	OS:	Any
Assigned to:	Mark Leith	CPU Architecture:	Any
Tags:	Agent, innodb status, mem

Description:
Currently SHOW ENGINE INNODB STATUS truncates at 64K - so if there are lots of transactions, or lock details printed in deadlock output, the lower variables that we rely on parsing for graphs and rules are not available, warnings are printed to the log (if level = warning), and we don't collect anything. 

The best way to not have truncated output currently, without flooding the log file, is to poll the innodb_status.<pid> file in the data directory, created with the innodb_status_file option:

http://dev.mysql.com/doc/refman/5.1/en/innodb-parameters.html#option_mysqld_innodb_status_...

We should try and parse this status file first if it exists, and then fall back to the typical SHOW ENGINE INNODB STATUS parsing afterwards. 

Further to this, there is a lot of information which we are simply throwing away - thread information, foreign key errors and deadlock information. To complete this "overall feature request", we should also parse each of these "dynamic" sections, and send them as appropriate data collections. 

See also related bugs: Bug#38129, Bug#19825

How to repeat:
N/A

Suggested fix:
N/A

Changing to S3 as this doesn't seem like a feature request as it affects a core functionality. Ie monitoring buffer pool information obtained from this output, potential advisors/graphs affected by this (from docs advisor / graph reference):

InnoDB Adaptive Hash Index Memory
InnoDB Adaptive Hash Index Searches
InnoDB Buffer Pool
InnoDB OS File Access
InnoDB Row Details
InnoDB Semaphores
InnoDB Transaction History

Mark Leith writes: 
Patch pushed to trunk (2.3):

1894 Mark Leith	2010-06-22
     Bug#45509 / EM-3367 - Better SHOW ENGINE INNODB STATUS parsing
       - post review fixes
       - move init of gerr in to the while loop so it is reset each time
       - free / reset innodb_status if we have to loop

   modified:
     src/job_collect_mysql.c
1893 Mark Leith	2010-06-22
     Bug#45509 / EM-3367 - Better SHOW ENGINE INNODB STATUS parsing
      - As InnoDB does not lock the file, retry reading the file 5 times, if mtime changes whilst reading it

And advisor items have been updated (advisor trunk):

revno: 355
committer: Mark Leith <mark.leith@oracle.com>
branch nick: trunk
timestamp: Wed 2010-06-23 12:51:04 +0100
message:
  EM-4561 - Add regex parsing for the new InnoDB Plugin SHOW INNODB STATUS output's extra sections
    - Adding the extra dc items to items-innodb-status.xml

Mark Leith writes: 
Available in build 2.3.0.2016

The workaround for the large deadlock part of the problem is to deliberately create a small deadlock, like this:

Connection1:
create table t1(a int)engine=innodb;
start transaction;
insert into t1 values (1),(2),(3);

Connection2:
start transaction;
delete from t1 where a=1; #will hang

Connection1:
update t1 set a=2 where a=1;

At this point Connection2 will deadlock, and the SHOW ENGINE INNODB STATUS should be visible again.

Carsten Segieth writes: 
checked OK with 2.3.0.2036

Just a comment to hopefully help others who had the same problem as me:  

The MySQL Enterprise Monitor will show blank InnoDB graphs if the SHOW INNODB STATUS command returns > 64k of data, as is mentioned in other bugs.  The trick shown above, to clear out the last deadlock with a small one, worked for me to get the INNODB status to fit in 64k and now my graphs work again!

Hopefully this comment will get picked up by the search engines and help the next person who has this problem.

Justin,

Glad it worked for you. Some people still have trouble after that and find that truncate table for the mysql.inventory table fixes the problem.

We will now print a warning to the agent log at message level if truncation happens when we read SHOW ENGINE INNODB STATUS:

g_warning("%s: SHOW ENGINE INNODB STATUS truncated for instance UUID '%s', enable innodb_status_file to allow non-truncated capture", G_STRLOC, uuid);

We now automatically try to read the innodb_status.<pid> file from the data directory if it exists, if it doesn't exist, we then fall back to executing SHOW ENGINE INNODB STATUS against the instance. 

Further to this, the subtask for adding extra InnoDB plugin parsing add the following new data collection items in the mysql::innodbstatus namespace::type:

innodb_main_thd_loops_one_sec - Count of one second loops the main thread has done
innodb_main_thd_loops_sleeps - Count of sleeps the main thread has done inside the one second loop
innodb_main_thd_loops_ten_sec - Count of ten second loops the main thread has done
innodb_main_thd_loops_background - Count of background loops the main thread has done
innodb_main_thd_loops_flush - Count of flush loops the main thread has done
innodb_main_thd_log_flush_writes - Count of log flushes initiated within the main thread loop
innodb_sem_spins_per_wait_mutex - Ratio of innodb_sem_mutex_rounds to innodb_sem_mutex_spin_waits
innodb_sem_spins_per_wait_rw_shared - Ratio of RW-Shared spin rounds to innodb_sem_shared_spins
innodb_sem_spins_per_wait_rw_excl - Ratio of RW-Exlusive spin rounds to innodb_sem_rw_excl_spins
innodb_trx_id_counter - Decoded decimal representation of the hex transaction ID counter in the latest InnoDB
innodb_trx_id_counter_str - The hex string based transaction ID counter in the latest InnoDB
innodb_ibuf_size - The Insert Buffer index tree size, in 16Kb pages
innodb_ibuf_free_list_len - The length of the free list for the Insert Buffer index
innodb_ibuf_seg_size - The Insert Buffer index header and tree size, in 16Kb pages
innodb_bp_dictionary_alloc - Size in bytes allocated to the data dictionary tables/indexes
innodb_bp_pages_young - The number of pages made young in the Buffer Pool LRU list
innodb_bp_pages_not_young - The number of pages made not young in the Buffer Pool LRU list
innodb_bp_pages_young_per_sec - The per second average of the pages made young in the Buffer Pool LRU list for the last 15 seconds
innodb_bp_pages_not_young_per_sec - The per second average of the pages made not young in the Buffer Pool LRU list for the last 15 seconds
innodb_bp_young_hit_rate - The rate at which pages have been made young for the past 15 seconds
innodb_bp_not_young_hit_rate - The rate at which pages have been made not young for the past 15 seconds
innodb_bp_pages_read_ahead_per_sec - The average of read ahead operations per second for the last 15 seconds
innodb_bp_pages_evicted_no_access_per_sec - The average number of pages evicted without being accessed for the last 15 seconds
innodb_bp_lru_len - The size in 16Kb pages of the Buffer Pool LRU list
innodb_bp_unzip_lru_len - The size in 16Kb pages of the Buffer Pool unzip_LRU list
innodb_bp_io_sum_pages - The number of Buffer Pool LRU list pages accessed total, for the last 50 seconds
innodb_bp_io_cur_pages - The number of Buffer Pool LRU list pages accessed total, for the last second
innodb_bp_io_unzip_sum_pages - The number of Buffer Pool unzip_LRU list pages accessed total, for the last 50 seconds
innodb_bp_io_unzip_cur_pages - The number of Buffer Pool unzip_LRU list pages accessed total, for the last second

Added to 2.3.0 change log:

If the output from the SHOW ENGINE INNODB STATUS command is truncated
because it exceeds the size limit, and MySQL Enterprise Monitor
cannot get information about all InnoDB transactions, now a message
is printed to the agent log. To avoid the possibility of the status
information being truncated, enable the innodb_status_file option.
MySQL Enterprise Monitor gets the status information from this file
if it is available. The status file is not subject to a maximum size
like the SHOW ENGINE INNODB STATUS output.