A customer opened a support issue to ask about some help determining why they were seeing a lot of Lock Wait Timeouts. I asked them to enable the InnoDB Lock Monitor so that I could get a look at what was going on in their transactions and whether there might be some locks held longer than necessary.
The customer sent in a 184MB MySQL error log with 4773836 lines. I started looking through it, but I could tell I was going to need a better way to get a better overview of the file than what I'd be able to piece together trying to poke through it and look for individual lines. I started piping the file through a variety of UNIX tools to narrow down what I was seeing.
I ended up with this mess:
< mysqld.err grep ACTIVE | cut -d' ' -f 2,4 | sort -rn -k 2 | perl -F, -ane 'print "$F[0] $F[1]" if not $v{$F[0]}; $v{$F[0]} = $F[1];' | head
It's hideous, but it's pretty helpful. Here's the output:
1EC080F1 24284 1EC84325 18196 1ECAC476 13430 1ED57B19 4880 1ECFF656 4198 1ED54BF5 1229 1ED59197 193 1ED58A84 164 1ED58A80 164 1ED50FDA 134
It's just a list of the longest-running transactions, showing the transaction ID and the time it's been active.
I decided to re-write it in perl, since I was already using perl in my pipeline and wanted the opportunity to get some other output in a slightly more reasonable way. Here's the perl version:
#!/usr/bin/perl -n
if ( /ACTIVE (\d+) sec/ ) {
@r = split(' ');
$t{substr($r[1],0,8)} = $r[3] if not defined $t{$r[1]} and $t{$r[1]}<$r[3];
}
END {
map {
print "$_ $t{$_}\n"
} (
sort {
$t{$b} <=> $t{$a}
} keys %t
)[0..9]
}
$ perl toptrans.pl < mysqld.err 1EC080F1 24284 1EC84325 18196 1ECAC476 13430 1ED57B19 4880 1ECFF656 4198 1ED54BF5 1229 1ED59197 193 1ED58A80 164 1ED58A84 164 1ED50FDA 134
That gives exactly the same output as the first version, but I figure it might be easier to change the criteria I'm looking for or the output contents/format.
But really parsing through InnoDB status or monitor information is not very much fun. I got lucky that all the information I was looking for was on a single line. If I want to get anything more, though, such as the number of locks being held, any information about the locks, the MySQL thread ID, et cetera, it'd be really nasty. I thought that there must be something better out there, and a bit of Google quickly reminded me that Baron Schwartz [http://www.xaprb.com] wrote a really excellent InnoDB status parser for use in innotop [http://code.google.com/p/innotop/].
The innotop script includes the InnoDBParser module inside of the file. You can just do a require to get access to the goods, then instantiate a new InnoDBParser. I ended up using Data::Dumper to make sense of the structure of the data:
#!/usr/bin/perl
use Data::Dumper;
require "innotop";
my $innodb_parser = new InnoDBParser;
my $contents;
{
local $INPUT_RECORD_SEPARATOR = undef;
$contents = ;
}
my $innodb_status = $innodb_parser->parse_status_text(
$contents,
0,
# Omit the following parameter to get all sections.
# { tx => 1 },
);
$Data::Dumper::Indent = 2;
print Dumper $innodb_status;
$ START=191; END=319; tail -n +$START < mysqld.err | head -n $(( $END - $START + 1 )) | perl txinfo.pl
$VAR1 = {
got_all => 1,
last_secs => '20',
sections => {
bp => {
add_pool_alloc => '0',
awe_mem_alloc => 0,
buf_free => '7822',
buf_pool_hit_rate => undef,
buf_pool_hits => undef,
buf_pool_reads => undef,
buf_pool_size => '8192',
complete => 1,
dict_mem_alloc => '41875',
page_creates_sec => '0.00',
page_reads_sec => '0.00',
page_writes_sec => '0.00',
pages_created => '1',
pages_modified => '0',
pages_read => '368',
pages_total => '369',
pages_written => '32',
reads_pending => '0',
total_mem_alloc => '137363456',
writes_pending => '0',
writes_pending_flush_list => 0,
writes_pending_lru => 0,
writes_pending_single_page => 0
},
bt => {
complete => 1,
fulltext => 'srv_master_thread loops: 4 1_second, 4 sleeps, 0 10_second, 6 background, 6 flush
srv_master_thread log flush and writes: 4'
},
ib => {
bufs_in_node_heap => undef,
complete => 1,
free_list_len => undef,
hash_searches_s => '0.00',
hash_table_size => undef,
inserts => undef,
merged_recs => undef,
merges => undef,
non_hash_searches_s => '0.00',
seg_size => undef,
size => undef,
used_cells => undef
},
io => {
avg_bytes_s => '0',
complete => 1,
flush_type => 'fsync',
fsyncs_s => '0.00',
os_file_reads => '379',
os_file_writes => '30',
os_fsyncs => '11',
pending_aio_writes => undef,
pending_buffer_pool_flushes => '0',
pending_ibuf_aio_reads => '0',
pending_log_flushes => '0',
pending_log_ios => '0',
pending_normal_aio_reads => undef,
pending_preads => 0,
pending_pwrites => 0,
pending_sync_ios => '0',
reads_s => '0.00',
threads => {
'0' => {
event_set => 0,
purpose => 'insert buffer thread',
state => 'waiting for i/o request',
thread => '0'
},
'1' => {
event_set => 0,
purpose => 'log thread',
state => 'waiting for i/o request',
thread => '1'
},
'2' => {
event_set => 0,
purpose => 'read thread',
state => 'waiting for i/o request',
thread => '2'
},
'3' => {
event_set => 0,
purpose => 'read thread',
state => 'waiting for i/o request',
thread => '3'
},
'4' => {
event_set => 0,
purpose => 'read thread',
state => 'waiting for i/o request',
thread => '4'
},
'5' => {
event_set => 0,
purpose => 'read thread',
state => 'waiting for i/o request',
thread => '5'
},
'6' => {
event_set => 0,
purpose => 'write thread',
state => 'waiting for i/o request',
thread => '6'
},
'7' => {
event_set => 0,
purpose => 'write thread',
state => 'waiting for i/o request',
thread => '7'
},
'8' => {
event_set => 0,
purpose => 'write thread',
state => 'waiting for i/o request',
thread => '8'
},
'9' => {
event_set => 0,
purpose => 'write thread',
state => 'waiting for i/o request',
thread => '9'
}
},
writes_s => '0.00'
},
lg => {
complete => 1,
last_chkp => '139205502',
log_flushed_to => '139205502',
log_ios_done => '12',
log_ios_s => '0.00',
log_seq_no => '139205502',
pending_chkp_writes => '0',
pending_log_writes => '0'
},
ro => {
complete => 0,
del_sec => '0.00',
ins_sec => '0.00',
main_thread_id => '4496171008',
main_thread_proc_no => 0,
main_thread_state => 'waiting for server activity',
n_reserved_extents => 0,
num_rows_del => '0',
num_rows_ins => '0',
num_rows_read => '12',
num_rows_upd => '0',
queries_in_queue => '0',
queries_inside => '0',
read_sec => '0.30',
read_views_open => '1',
upd_sec => '0.00'
},
sm => {
complete => 1,
mutex_os_waits => '0',
mutex_spin_rounds => '0',
mutex_spin_waits => '0',
reservation_count => '4',
rw_excl_os_waits => undef,
rw_excl_spins => undef,
rw_shared_os_waits => undef,
rw_shared_spins => undef,
signal_count => '4',
wait_array_size => 0,
waits => []
},
tx => {
complete => 1,
history_list_len => '105',
is_truncated => 0,
num_lock_structs => undef,
purge_done_for => '163A',
purge_undo_for => '0',
transactions => [
{
active_secs => 0,
has_read_view => 0,
heap_size => 0,
hostname => 'localhost',
ip => '',
lock_structs => 0,
lock_wait_status => '',
lock_wait_time => 0,
mysql_thread_id => '22',
os_thread_id => '4529143808',
proc_no => 0,
query_id => '339',
query_status => '',
query_text => '',
row_locks => 0,
tables_in_use => 0,
tables_locked => 0,
thread_decl_inside => 0,
thread_status => '',
txn_doesnt_see_ge => '',
txn_id => '0',
txn_sees_lt => '',
txn_status => 'not started',
undo_log_entries => 0,
user => 'root'
},
{
active_secs => '13',
has_read_view => 0,
heap_size => '376',
hostname => 'localhost',
ip => '',
lock_structs => '2',
lock_wait_status => '',
lock_wait_time => 0,
locks => [
{
db => 'test',
index => '',
insert_intention => 0,
lock_mode => 'IX',
lock_type => 'TABLE',
n_bits => 0,
page_no => 0,
space_id => 0,
special => '',
table => 't1',
txn_id => '1802',
waiting => 0
},
{
db => 'test',
index => 'PRIMARY',
insert_intention => 0,
lock_mode => 'X',
lock_type => 'RECORD',
n_bits => '80',
page_no => '386',
space_id => 0,
special => '',
table => 't1',
txn_id => '1802',
waiting => 0
}
],
mysql_thread_id => '21',
os_thread_id => '4528869376',
proc_no => 0,
query_id => '333',
query_status => '',
query_text => '',
row_locks => '7',
tables_in_use => 0,
tables_locked => 0,
thread_decl_inside => 0,
thread_status => '',
txn_doesnt_see_ge => '',
txn_id => '1802',
txn_sees_lt => '',
txn_status => 'ACTIVE',
undo_log_entries => 0,
user => 'root'
}
],
trx_id_counter => '1803'
}
},
timestring => '2011-12-22 18:48:26',
ts => [
2011,
12,
22,
18,
48,
26
]
};
The output of that is 278 lines just for a single transaction holding a couple row locks. After digging around the output for a while, I came up with this script that provides a pretty flexible way to print out various "fields" related to transactions that satisfy particular criteria (note that here I'm only getting the output of the "tx" section, which would give 115 lines of output in the Data::Dumper example above):
#!/usr/bin/perl
use Data::Dumper;
require "innotop";
$Data::Dumper::Indent = 2;
my $innodb_parser = new InnoDBParser;
my @fields = (
"txn_id",
"active_secs",
"lock_structs",
"row_locks",
"hostname"
);
my $contents;
{
local $INPUT_RECORD_SEPARATOR = undef;
$contents = ;
}
my $innodb_status = $innodb_parser->parse_status_text(
$contents,
0,
# Omit the following parameter to get all sections.
{ tx => 1 },
);
#print Dumper $innodb_status; exit;
for my $tx (@{$innodb_status->{sections}->{tx}->{transactions}}) {
if (
$tx->{active_secs} > 0
) {
print join( "\t",
map { $tx->{$_} } @fields
), "\n";
}
}
I ran that against another status snippet that includes a couple different transactions each with some locks. Here's the output (along with what might be a helpful way to extract just a single status output from among a file filled with them):
$ grep -hn 'INNODB MONITOR' mysqld.err | tail -n 2 1703104:111222 19:16:12 INNODB MONITOR OUTPUT 1741522:END OF INNODB MONITOR OUTPUT $ START=1703104; END=1741522; tail -n +$START < mysqld.err | head -n $(( $END - $START + 1 )) | perl txinfo.pl 1808 380 5 2003 localhost 1806 864 11 6206 localhost
Hey, that's pretty neat, we've actually got some nice info, somewhat programmatically and reliably retrieved from the InnoDB Lock Monitor. If you want to get additional fields from the parsed data structure, you can just add the names of the fields to the @fields array at the top of the program. I'll probably get carried away and add those as command-line options to this thing at some point. I'm looking forward to being able to use this the next time I've got almost 5 million lines of InnoDB status output to make sense of!
PlanetMySQL Voting: Vote UP / Vote DOWN
