Header
这部分简单的打印,输出的时间,以及自从上次输出的间隔时间。
1 =====================================
2 07091310:31:48 INNODB MONITOR OUTPUT
3 =====================================
4 Persecond averages calculated from the last 49 seconds
SEMAPHORES
如果你有一个高并发的系统,你需要关注这一部分的输出。
它由两部分组成,event counters, 和可选项输出,即当前等待的事件(current waits)。
下面给出了一个示例输出。
1 ----------
2 SEMAPHORES
3 ----------
4 OSWAIT ARRAY INFO: reservation count 13569, signal count 11421
5 --Thread1152170336 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds
the semaphore:
6 Mutexat 0x2a957858b8 created file buf0buf.c line 517, lock var 0
7 waitersflag 0
8 waitis ending
9 --Thread1147709792 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds
the semaphore:
10 Mutexat 0x2a957858b8 created file buf0buf.c line 517, lock var 0
11 waitersflag 0
12 waitis ending
13 Mutexspin waits 5672442, rounds 3899888, OS waits 4719
14 RW-sharedspins 5920, OS waits 2918; RW-excl spins 3463, OS waits 3163
第4行表示,OS WAIT的信息,reservation count表示Innodb产生了多少次OS WAIT, signal count表示,进行OS WAIT的线程,接收到多少次信号(singal)被唤醒。
如果你看到signal的数值很大,通常是几十万,上百万。就表明,可能是很多I/O的等待,或是Innodb争用(contention)问题。关于争用问题,可能与OS的进程调度有关,你可尝试减少innodb_thread_concurrency参数。
在接下来,下面的介绍之前,有必要明白什么是OS Wait,什么是spin wait。
要明白这个,首先你要明白Innodb如何处理互斥量(Mutexes),以及什么是两步获得锁(two-step approach)。首先进程,试图获得一个锁,如果此锁被它人占用。它就会执行所谓的spin wait,即所谓循环的查询”锁被释放了吗?”。如果在循环过程中,一直未得到锁释放的信息,则其转入OS WAIT,即所谓线程进入挂起(suspended)状态。直到锁被释放后,通过信号(singal)唤醒线程。
Mutex spin waits 是线程无法获取锁,而进入的spin wait
rounds 是spin wait进行轮询检查Mutextes的次数
OS waits 是线程放弃spin-wait进入挂起状态
Spin wait的消耗远小于OS waits。Spinwait利用cpu的空闲时间,检查锁的状态,OS Wait会有所谓content switch,从CPU内核中换出当前执行线程以供其它线程使用。你可以通过innodb_sync_spin_loops参数来平衡spin wait和os wait。
http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_sync_spin_loops
5-12行,显示的是具体争用(contention)等待的事件,这个要求你对于MySQL的代码比较熟悉。
如示例,buf0buf.c实际上表示服务器有buffer pool争用的情况。
13-14显示了更详细的锁(Mutexes)的信息,如RW-shared表示共享锁,RW-excl表示排它锁
LATEST DETECTED DEADLOCK
当你服务器发生了死锁的情况时,这部分会显示出来。死锁通常的原因很复杂,但是这一部分只会显示最后两个发生死锁的事务,尽管可能也有其它事务也包含在死锁过程中。不过,尽管信息被删减了,通常你也能够通过这些信息找出死锁的原因。
下面给出了一个例子:
1 ------------------------
2 LATESTDETECTED DEADLOCK
3 ------------------------
4 07091311:14:21
5 ***(1) TRANSACTION:
6 TRANSACTION0 3793488, ACTIVE 2 sec, process no 5488, OS thread id 1141287232
startingindex read
7 mysqltables in use 1, locked 1
8 LOCKWAIT 4 lock struct(s), heap size 1216
9 MySQLthread id 11, query id 350 localhost baron Updating
10 UPDATEtest.tiny_dl SET a = 0 WHERE a <> 0
11 ***(1) WAITING FOR THIS LOCK TO BE GRANTED:
12 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table
`test/tiny_dl`trx id 0 3793488 lock_mode X waiting
13 Recordlock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
14 0:len 6; hex 000000000501 ...[ omitted ] ...
15
16 ***(2) TRANSACTION:
17 TRANSACTION0 3793489, ACTIVE 2 sec, process no 5488, OS thread id 1141422400
startingindex read, thread declared inside InnoDB 500
18 mysqltables in use 1, locked 1
19 4lock struct(s), heap size 1216
20 MySQLthread id 12, query id 351 localhost baron Updating
21 UPDATEtest.tiny_dl SET a = 1 WHERE a <> 1
22 ***(2) HOLDS THE LOCK(S):
23 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table
`test/tiny_dl`trx id 0 3793489 lock mode S
24 Recordlock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
25 0:... [ omitted ] ...
26
27 ***(2) WAITING FOR THIS LOCK TO BE GRANTED:
SHOW INNODB STATUS | 571
28 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table
`test/tiny_dl`trx id 0 3793489 lock_mode X waiting
29 Recordlock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
30 0:len 6; hex 000000000501 ...[ omitted ] ...
31
32 *** WE ROLL BACK TRANSACTION (2)
第4行显示了死锁发生的时间。第5-10行,显示了第一个死锁的第一个事务,下一节我会继续详细说明它的意思。
11-15行显示了死锁发生时事务1等待的锁。14行,可以忽略,显示的信息只有在调试Innodb时有用。重要的是12行,它说明了事务想获得test.tiny_dl 表的GEN_CLUST_INDEX* 索引对应的X 排它锁(有必要说明一下,Innodb的锁是与索引相关的,具体可以看我的博客关于Innodb锁的介绍)。
16-21行显示了事务2的状态,22-26显示了事务2获得的锁,27-31显示了事务2等待的锁。
Innodb不会显示当前事务所有获得的,以及等待的锁,但它给予了足够的信息,如当前查询使用的索引,它会帮助你定位问题以及如何避免死锁。当然,这类信息通常不是那么的直观,你可以通过打印出了SQL语句,以及索引等信息,找到问题代码,进行分析。
32行,显示了它选择哪一个事务回滚,以避免无限期的死锁等待。关于这点,Innodb有一个内在的死锁检测机制,当死锁等待超过一定时间后,就会回滚其中一个事务。innodb_lock_wait_timeout可配置死锁的等待超时时间。
TRANSACTIONS
这一部分包含Innodb 事务(transactions)的统计信息,还有当前活动的事务列表。
接下来,先介绍开始的统计部分
1 ------------
2 TRANSACTIONS
3 ------------
4 Trx id counter 080157601
5 Purge done fortrx's n:o <0 80154573 undo n:o <0 0
6 History listlength 6
7 Total number oflock structs in row lock hash table 0
第4行显示的是当前的transaction id, 这个ID是一个系统变量随时每次新的transaction产生而增加。
第5行显示的正在进行清空(purge)操作的transaction ID。你可以通过查看第4和第5行ID的区别,明白没有被purge的事务落后的情况。关于什么是purge操作,我在下面进行了详细说明。
第6行,记录了undo spaces内unpurged的事务的个数。
(注:有心人也许会计算4,5行ID之差,与第6行的这个数值比较,可能会发现完全不匹配。这点我也困惑了一段时间。其实是这样,事务的ID并不是按顺序purge的,所以有可能ID大于第5行当前purge的ID的事务,已经在前面被purge了。Purge的原则就是记录没有被其它事务继续使用了。)
第7行,英文的原文解释如下,这个我没弄明白。the number of lock structs. Each lock struct usually holds many row locks,so this is not the same as the number of rows locked.
什么是purge操作
要明白什么清空(purge)操作,你得明白什么是事务的多版本控制,即MVCC(multi-version concurrency control)。Innodb为了实现MVCC,需要在表空间内保存老版本的记录信息,这些信息存储于回滚段中(rollback segment),所谓回滚段,在物理存储上是UNDO log的记录。
Purge到底做了些什么?其实它就相当于一个垃圾收集器。取个例子,当用户下一个命令,如 “DELETE FROM t WHERE c = 1;”, InnoDB 不会马上删除对应的记录,它会做如下三件事情:
它标记此记录为删除(通过删除标记位)
存储原始的记录到UNDO log
更新记录列DB_TRX_ID和DB_ROLL_PTR(这些列是Innodb在原记录列上增加的)。DB_TRX_ID记录了最后操作记录的事务ID。DB_ROLL_PTR也叫回滚指针(rollback pointer),指向UNDO log 记录,此UNDO Log记录了原始记录的信息,这些信息可以用来重建原始记录(如发生了rollback的情况)。如果操作是插入,还会有一个
DB_ROW_ID
,这个指明了新记录的行号
.
当事务提交后,那些标记了删除的记录,以及UNDOLog中的记录并不会马上清除,这些记录信息可以被其它事务所重用,或是共享。只有当没有任何事务共享这些记录的时候,这些记录才会被清除(purge)。这就是所谓purge操作。而为了提高数据库的操作效率,purge操作是由另外的线程异步完成。这就是为何前面你所看到的为何存在unpurged的事务的原因。
接下来,是事务的列表,如下有一个例子。
1 ---TRANSACTION0 80157600, ACTIVE 4 sec, process no 3396, OS thread id 1148250464,
thread declared inside InnoDB 442
2 mysqltables in use 1, locked 0
3 MySQLthread id 8079, query id 728899 localhost baron Sending data
4 selectsql_calc_found_rows * from b limit 5
5 Trxread view will not see trx with id>= 0 80157601, sees <0 80157597
第 1 行显示了事务ID。ACTIVE 4 sec表示事务处于ACTIVE状态已经4秒钟了。其它可能的状态还包括“not started,” “active,” “prepared,” and “committedin memory”(once it commits to disk, the state willchange to “not started”)
“threaddeclared inside InnoDB 442”表示,这个thread处于Innodb内核,还有422个tickets可以使用。有一个参数,innodb_concurrency_tickets可以配置一个thread可用的tickets数。
何谓tickets数呢?当Innodb内部线程达到innodb_thread_concurrency上限时,新的thread就需要在thread队列内排队等待进行Innodb内核执行。Thread tickets可以让已经进行Innodb内核的线程,可以执行多次(即多次执行一个时间片周期),这个次数由tickets来决定。直到用完tickets,此线程才会换出内核进入队列。这样做的用处是避免所谓threadthrashing问题,避免线程不停的从内核中换入换出。
一个常见的例子是,如果你有执行时间长的SQL语句在指定tickets内还无法完成,这样就会被换出内核。如此增加的thread的context switch的开销是惊人的。在这种情况下,可考虑增大tickets的值。
第2行,显示了当前事务锁定的数据表
第3行显示了thread id,这个值与是在show full processlist 命令显示的进程ID是一样的。
第4行显示了当前事务执行的SQL语句。
第5行,显示了MVCC,多版本并发控制的信息,表明了哪些其它事务可以看到此记录,哪些不能。
FILE I/O
FILE I/O部分显示了I/O Helper thread的状态,包括一些统计信息
1 --------
2 FILEI/O
3 --------
4 I/Othread 0 state: waiting for i/o request (insert buffer thread)
5 I/Othread 1 state: waiting for i/o request (log thread)
6 I/Othread 2 state: waiting for i/o request (read thread)
7 I/Othread 3 state: waiting for i/o request (write thread)
8 Pendingnormal aio reads: 0, aio writes: 0,
9 ibufaio reads: 0, log i/o's: 0, sync i/o's: 0
10 Pendingflushes (fsync) log: 0; buffer pool: 0
11 17909940OS file reads, 22088963 OS file writes, 1743764 OS fsyncs
12 0.20 reads/s, 16384 avg bytes/read, 5.00 writes/s, 0.80fsyncs/s
4-7行显示了I/O helper thread 的状态.
8-10行显示了各个I/O helper thread的pending operations, pending的log和buffer pool thread的fsync()调用。关于什么是fsync()调用,以及为何有fsync调用,我会专门再拿出一章来说明。请大家等待我的博客后继更新。
11行显示了reads, writes, and fsync()调用次数。
12行显示了每秒的统计信息
第8-9行可以用来检测I/O-bound问题,如果出现很多pending operations,很有可能你的服务器出现了I/O-bound问题。其中缩略词“aio”表示“ 异步I/O(asynchronous I/O).”
INSERT BUFFER AND ADAPTIVE HASHINDEX
1 -------------------------------------
2 INSERTBUFFER AND ADAPTIVE HASH INDEX
3 -------------------------------------
4 Ibuffor space 0: size 1, free list len 887, seg size 889, is not empty
5 Ibuffor space 0: size 1, free list len 887, seg size 889,
6 2431891inserts, 2672643 merged recs, 1059730 merges
7 Hashtable size 8850487, used cells 2381348, node heap has 4091 buffer(s)
8 2208.17 hash searches/s, 175.05 non-hash searches/s
第4行显示了insertbuffer的一些信息,包括free list, segment size
其中space 0,表示可能有多个insert buffer, 如space 0, space 1等。但实际上MySQL并没有多个insert buffer,所以你能看到4,5行是重复的。这算是一个多余的输出。在新版本中,去除了此输出。
第6行显示了Innodb进行了多少次buffer操作。通过比较 inserts和 merges,可以看出insert buffer的效率
第7行显示了hash table的一些信息
第8行显示了每秒进行了多少次hash搜索,以及非hash搜索
LOG
这里记录了tansaction log子系统的信息(如果你不记得了,请看FILE I/O那一节所看到的I/O Helper Thread)
1 ---
2 LOG
3 ---
4 Logsequence number 84 3000620880
5 Logflushed up to 84 3000611265
6 Lastcheckpoint at 84 2939889199
7 0pending log writes, 0 pending chkp writes
8 14073669 log i/o's done, 10.90 log i/o's/second
第4行,显示了当前的LSN。
第5行,显示了已经被flushed(写入磁盘)的logs
第6行,显示了最后一个checkpoint的logs
第7,8行,显示了pending log 的统计信息
BUFFER POOL AND MEMORY
1 ----------------------
2 BUFFERPOOL AND MEMORY
3 ----------------------
4 Totalmemory allocated 4648979546; in additional pool allocated 16773888
5 Bufferpool size 262144
6 Freebuffers 0
7 Databasepages 258053
8 Modifieddb pages 37491
9 Pendingreads 0
10 Pendingwrites: LRU 0, flush list 0, single page 0
11 Pagesread 57973114, created 251137, written 10761167
12 9.79reads/s, 0.31 creates/s, 6.00 writes/s
13 Buffer pool hit rate 999 / 1000
14 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
15 LRU len: 177, unzip_LRU len: 0
第4行显示了分配给Innodb的内存大小,以及additional pool使用的大小(如果没有使用,会显示为0)
14行显示了每秒线性预读跟随机预读的次数。
InnoDB 提供了两种预读的方式,一种是 Linear read ahead,由参数innodb_read_ahead_threshold控制,当你连续读取一个 extent 的 threshold 个 page 的时候,会触发下一个 extent 64个page的预读。另外一种是Random read-ahead,由参数innodb_random_read_ahead控制,当你连续读取设定的数量的page后,会触发读取这个extent的剩余page。
InnoDB 的预读功能是使用后台线程异步完成的。InnoDB启动了innodb_read_io_threads个后台线程,来完成IO request,并且可以使用Native AIO,在你的环境中如果安装了libaio,在MySQL实例启动的时候,查看系统日志:InnoDB: Using Linux native AIO 表明InnoDB 已经使用Native AIO了。在Linearread ahead触发的时候,InnoDB通过io_submit()提交了下一个extent的64个pages的IO request,并由一个read IO thread完成。
15行显示了LRU跟压缩页LRU list的长度。9-10行显示了pending的reads 和writes
11行显示了Innodb读写和创建的页面(pages)
13行显示了Innodb的buffer pool命中率,通常要保证在998/1000以上。如果没有,可考虑增大buffer pool size,以及优化你的查询
ROW OPERATIONS
这一部分显示了rowoperation及其它的一些统计信息
1 --------------
2 ROWOPERATIONS
3 --------------
4 0queries inside InnoDB, 0 queries in queue
5 1read views open inside InnoDB
6 Mainthread process no. 10099, id 88021936, state: waiting for server activity
7 Numberof rows inserted 143, updated 3000041, deleted 0, read 24865563
8 0.00inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
9 ----------------------------
10 ENDOF INNODB MONITOR OUTPUT
11 ============================
第4行显示了有多少线程在Innodb内核(你可回顾transaction一章)
第5行显示了有多少read view被打开了,一个read view是一致性保证的MVCC “snapshot”