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 | OS WAIT的信息,reservation count表示Innodb产生了多少次OS WAIT, signal count表示,进行OS WAIT的线程,接收到多少次信号(singal)被唤醒。如果你看到signal的数值很大,通常是几十万,上百万。就表明,可能是很多I/O的等待,或是Innodb争用(contention)问题。关于争用问题,可能与OS的进程调度有关,你可尝试减少innodb_thread_concurrency参数。 |
5 --Thread1152170336 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds | 首先你要明白Innodb如何处理互斥量(Mutexes),以及什么是两步获得锁(two-step approach)。首先进程,试图获得一个锁,如果此锁被它人占用。它就会执行所谓的spin wait,即所谓循环的查询”锁被释放了吗?”。如果在循环过程中,一直未得到锁释放的信息,则其转入OS WAIT,即所谓线程进入挂起(suspended)状态。直到锁被释放后,通过信号(singal)唤醒线程。 |
the semaphore: | Mutex spin waits 是线程无法获取锁,而进入的spin wait |
6 Mutexat 0x2a957858b8 created file buf0buf.c line 517, lock var 0 | rounds 是spin wait进行轮询检查Mutextes的次数 |
7 waitersflag 0 | OS waits 是线程放弃spin-wait进入挂起状态 |
8 waitis ending | Spin wait的消耗远小于OS waits。Spinwait利用cpu的空闲时间,检查锁的状态,OS Wait会有所谓content switch,从CPU内核中换出当前执行线程以供其它线程使用。你可以通过innodb_sync_spin_loops参数来平衡spin wait和os wait。 |
9 --Thread1147709792 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds | |
the semaphore: | 5-12 显示的是具体争用(contention)等待的事件,这个要求你对于MySQL的代码比较熟悉。buf0buf.c实际上表示服务器有 buffer pool争用的情况。 |
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 | 13-14显示了更详细的锁(Mutexes)的信息,如RW-shared表示共享锁,RW-excl表示排它锁 |
LATEST DETECTED DEADLOCK | |
1 ------------------------ | |
2 LATESTDETECTED DEADLOCK | |
3 ------------------------ | |
4 07091311:14:21 | 第4行显示了死锁发生的时间。第5-10行,显示了第一个死锁的第一个事务 |
5 ***(1) TRANSACTION: | 第5-10行,显示了第一个死锁的第一个事务 |
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 | 11-15行显示了死锁发生时事务1等待的锁。14行,可以忽略,显示的信息只有在调试Innodb时有用。重要的是12行,它说明了事务想获得test.tiny_dl 表的GEN_CLUST_INDEX* 索引对应的X 排它锁(有必要说明一下,Innodb的锁是与索引相关的,具体可以看我的博客关于Innodb锁的介绍)。 |
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: | 16-21行显示了事务2的状态 |
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): | 22-26显示了事务2获得的锁 |
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: | 27-31显示了事务2等待的锁。 |
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) | 32行,显示了它选择哪一个事务回滚,以避免无限期的死锁等待。关于这点,Innodb有一个内在的死锁检测机制,当死锁等待超过一定时间后,就会回滚其中一个事务。innodb_lock_wait_timeout可配置死锁的等待超时时间。 |
TRANSACTIONS | |
这一部分包含Innodb 事务(transactions)的统计信息,还有当前活动的事务列表。 | |
接下来,先介绍开始的统计部分 | |
1 ------------ | |
2 TRANSACTIONS | |
3 ------------ | |
4 Trx id counter 080157601 | 第4行显示的是当前的transaction id, 这个ID是一个系统变量随时每次新的transaction产生而增加。 |
5 Purge done fortrx's n:o <0 80154573 undo n:o <0 0 | 第5行显示的正在进行清空(purge)操作的transaction ID。你可以通过查看第4和第5行ID的区别,明白没有被purge的事务落后的情况。关于什么是purge操作,我在下面进行了详细说明。 |
6 History listlength 6 | 第6行,记录了undo spaces内unpurged的事务的个数。 |
7 Total number oflock structs in row lock hash table 0 | |
什么是purge操作 | |
要明白什么清空(purge)操作,你得明白什么是事务的多版本控制,即MVCC(multi-version concurrency control)。Innodb为了实现MVCC,需要在表空间内保存老版本的记录信息,这些信息存储于回滚段中(rollback segment),所谓回滚段,在物理存储上是UNDO log的记录。 | |
Purge到底做了些什么?其实它就相当于一个垃圾收集器。取个例子,当用户下一个命令,如 “DELETE FROM t WHERE c = 1;”, InnoDB 不会马上删除对应的记录,它会做如下三件事情: | |
1. 它标记此记录为删除(通过删除标记位) | |
2. 存储原始的记录到UNDO log | |
3. 更新记录列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, | 第 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”) |
thread declared inside InnoDB 442 | “threaddeclared inside InnoDB 442”表示,这个thread处于Innodb内核,还有422个tickets可以使用。有一个参数,innodb_concurrency_tickets可以配置一个thread可用的tickets数。 |
2 mysqltables in use 1, locked 0 | 第2行,显示了当前事务锁定的数据表 |
3 MySQLthread id 8079, query id 728899 localhost baron Sending data | 第3行显示了thread id,这个值与是在show full processlist 命令显示的进程ID是一样的。 |
4 selectsql_calc_found_rows * from b limit 5 | 第4行显示了当前事务执行的SQL语句。 |
5 Trxread view will not see trx with id>= 0 80157601, sees <0 80157597 | 第5行,显示了MVCC,多版本并发控制的信息,表明了哪些其它事务可以看到此记录,哪些不能。 |
何谓tickets数呢?当Innodb内部线程达到innodb_thread_concurrency上限时,新的thread就需要在thread队列内排队等待进行Innodb内核执行。Thread tickets可以让已经进行Innodb内核的线程,可以执行多次(即多次执行一个时间片周期),这个次数由tickets来决定。直到用完tickets,此线程才会换出内核进入队列。这样做的用处是避免所谓threadthrashing问题,避免线程不停的从内核中换入换出。一个常见的例子是,如果你有执行时间长的SQL语句在指定tickets内还无法完成,这样就会被换出内核。如此增加的thread的context switch的开销是惊人的。在这种情况下,可考虑增大tickets的值。 | |
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) | 4-7行显示了I/O helper 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, | /O helper thread的pending operations, pending的log和buffer pool thread的fsync()调用。 |
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 | 11行显示了reads, writes, and fsync()调用次数。 |
12 0.20 reads/s, 16384 avg bytes/read, 5.00 writes/s, 0.80fsyncs/s | 12行显示了每秒的统计信息 |
INSERT BUFFER AND ADAPTIVE HASHINDEX | |
1 ------------------------------------- | |
2 INSERTBUFFER AND ADAPTIVE HASH INDEX | |
3 ------------------------------------- | |
4 Ibuffor :size 1, free list len 887, seg size 889, is not empty | 第4行显示了insertbuffer的一些信息,包括free list, segment size |
6 2431891inserts, 2672643 merged recs, 1059730 merges | 第6行显示了Innodb进行了多少次buffer操作。通过比较 inserts和 merges,可以看出insert buffer的效率 |
7 Hashtable size 8850487, used cells 2381348, node heap has 4091 buffer(s) | hash table的一些信息 |
8 2208.17 hash searches/s, 175.05 non-hash searches/s | 第8行显示了每秒进行了多少次hash搜索,以及非hash搜索 |
LOG | |
这里记录了tansaction log子系统的信息 | |
1 --- | |
2 LOG | |
3 --- | |
4 Logsequence number 84 3000620880 | 第4行,显示了当前的log sequencenumber。Log sequence number表示有多少字节写入到了log文件内 |
5 Logflushed up to 84 3000611265 | 第5行,显示了已经被flushed(写入磁盘)的logs |
6 Lastcheckpoint at 84 2939889199 | 第6行,显示了最后一个checkpoint的logs |
7 0pending log writes, 0 pending chkp writes | 第7,8行,显示了pending log 的统计信息 |
8 14073669 log i/o's done, 10.90 log i/o's/second | |
BUFFER POOL AND MEMORY | |
1 ---------------------- | |
2 BUFFERPOOL AND MEMORY | |
3 ---------------------- | 第4行显示了分配给Innodb的内存大小,以及additional pool使用的大小(如果没有使用,会显示为0) |
4 Totalmemory allocated 4648979546; in additional pool allocated 16773888 | 第5-8行显示了buffer pool的信息。分别显示了Buffer pool大小,空闲的buffers, database pages, 脏页(dirty pages) 。你会看到buffer pool size比database pages要大,这是因为buffer pool还会存放lock index, hash index等一些其它的系统信息。 |
5 Bufferpool size 262144 | |
6 Freebuffers 0 | |
7 Databasepages 258053 | |
8 Modifieddb pages 37491 | |
9 Pendingreads 0 | 9-10行显示了pending的reads 和writes |
10 Pendingwrites: LRU 0, flush list 0, single page 0 | |
11 Pages read 57973114, created 251137, written 10761167 | 11行显示了Innodb读写和创建的页面(pages) |
12 9.79reads/s, 0.31 creates/s, 6.00 writes/s | |
13 Buffer pool hit rate 999 / 1000 | 13行显示了Innodb的buffer pool命中率,通常要保证在998/1000以上。如果没有,可考虑增大buffer pool size,以及优化你的查询 |
ROW OPERATIONS | |
这一部分显示了rowoperation及其它的一些统计信息 | |
1 -------------- | |
2 ROWOPERATIONS | |
3 -------------- | |
4 0queries inside InnoDB, 0 queries in queue | 第4行显示了有多少线程在Innodb内核 |
5 1read views open inside InnoDB | 第5行显示了有多少read view被打开了,一个read view是一致性保证的MVCC “snapshot” |
6 Mainthread process no. 10099, id 88021936, state: waiting for server activity | 第6行显示了内核的main thread的状态信息,其余可能的状态还会有: |
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 ============================ | |
archiving log (if log archive is on) | |
doing background droptables | |
doing insert buffer merge | |
flushing buffer pool pages | |
flushing log | |
making checkpoint | |
purging | |
reserving kernel mutex | |
sleeping | |
suspending | |
waiting for buffer poolflush to end | |
waiting forser veractivity | |
7-8行显示了行操作(rowoperation)的一些统计信息。 |