详解show innodb status(转)

(翻译了mysqlperformance blog的文章,网址为http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/,英文不好,大家见笑)

在show innodb status中,现实的值是每秒中的。确保数据是20-30秒之间的一个抽样,若
将计算时间运行为0或1秒左右的数据抽样,所得的信息是没有意义的。

1、开始信息为数据抽样的时间间隔
CODE:
1.=====================================
2.060717  3:07:56 INNODB MONITOR OUTPUT
3.=====================================
4.Per second averages calculated from the last 44 seconds

2、下面是信号量的信息

CODE:
1.———-
2.SEMAPHORES
3.———-
4.OS WAIT ARRAY INFO: reservation count 13569, signal count 11421
5.–Thread 1152170336 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds the semaphore:
6.Mutex at 0×2a957858b8 created file buf0buf.c line 517, lock var 0
7.waiters flag 0
8.wait is ending
9.–Thread 1147709792 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds the semaphore:
10.Mutex at 0×2a957858b8 created file buf0buf.c line 517, lock var 0
11.waiters flag 0
12.wait is ending
13.Mutex spin waits 5672442, rounds 3899888, OS waits 4719
14.RW-shared spins 5920, OS waits 2918; RW-excl spins 3463, OS waits 3163

在这一块,有两部分内容。一部分是列出当前的等待。它只有在高度并发的环境下,导致innodb不得不频繁进入
os的等待时才会显示。如果通过旋转锁的方式解决这个问题,这一部分将不会出现。
通过此块信息,可以得知当前访问的热点。(但需要对mysql源码有一定了解)
“lock var”的当前值代表的互斥体的状态(locked=1/free=0)
“waiters flag”是当前等待的数量。另外”wait is ending”在此处表示互斥对象已经释放,但os还没有分配线程,
所以继续执行
第二部分的信息是对事件的计数,”reservation count”和”signal count”显示了当前的innodb使用了多少同步数组,
slot被分配给innodb、线程被信号通知使用同步数组的频度。这些计数可以被用于显示innodb需要进入os等待的频度
,通过os waits获得又读写锁、互斥体引起的系统等待。
spin waits和spin rounds是另一个重要的信息。比起os wait,旋转锁的等待开销相对小。但它占用cpu
可也通过调节innodb_sync_spin_loops来适当改变。

下面的信息是关于死锁的
CODE:
1.————————
2.LATEST DETECTED DEADLOCK
3.————————
4.060717  4:16:48
5.*** (1) TRANSACTION:
6.TRANSACTION 0 42313619, ACTIVE 49 sec, process no 10099, OS thread id 3771312 starting index read
7.mysql tables in use 1, locked 1
8.LOCK WAIT 3 lock struct(s), heap size 320
9.MySQL thread id 30898, query id 100626 localhost root Updating
10.update iz set pad=’a’ where i=2
11.*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
12.RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313619 lock_mode X locks rec but not gap waiting
13.Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
14. 0: len 4; hex 80000002; asc     ;; 1: len 6; hex 00000285a78f; asc       ;; 2: len 7; hex 00000040150110; asc    @   ;; 3: len 10; hex 61202020202020202020; asc a         ;;
15.
16.*** (2) TRANSACTION:
17.TRANSACTION 0 42313620, ACTIVE 24 sec, process no 10099, OS thread id 4078512 starting index read, thread declared inside InnoDB 500
18.mysql tables in use 1, locked 1
19.3 lock struct(s), heap size 320
20.MySQL thread id 30899, query id 100627 localhost root Updating
21.update iz set pad=’a’ where i=1
22.*** (2) HOLDS THE LOCK(S):
23.RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313620 lock_mode X locks rec but not gap
24.Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
25. 0: len 4; hex 80000002; asc     ;; 1: len 6; hex 00000285a78f; asc       ;; 2: len 7; hex 00000040150110; asc    @   ;; 3: len 10; hex 61202020202020202020; asc a         ;;
26.
27.*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
28.RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313620 lock_mode X locks rec but not gap waiting
29.Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
30. 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 00000285a78e; asc       ;; 2: len 7; hex 000000003411d9; asc     4  ;; 3: len 10; hex 61202020202020202020; asc a         ;;
31.
32.*** WE ROLL BACK TRANSACTION (2)

对于上次死锁,显示了什么造成了死锁,在死锁时的状态,它们持有了哪些锁,在等待那些innodb决定将哪个事务回滚。它只是简单的描述,要了解细节,会需要查看binlog

同死锁类似,我们可以获得最近一次外键限制失败的简单信息

CODE:
1.————————
2.LATEST FOREIGN KEY ERROR
3.————————
4.060717  4:29:00 Transaction:
5.TRANSACTION 0 336342767, ACTIVE 0 sec, process no 3946, OS thread id 1151088992 inserting, thread declared inside InnoDB 500
6.mysql tables in use 1, locked 1
7.3 lock struct(s), heap size 368, undo log entries 1
8.MySQL thread id 9697561, query id 188161264 localhost root update
9.insert into child values(2,2)
10.Foreign key constraint fails for table `test/child`:
11.,
12.  CONSTRAINT `child_ibfk_1` FOREIGN KEY (`parent_id`) REFERENCES `parent` (`id`) ON DELETE CASCADE
13.Trying to add in child table, in index `par_ind` tuple:
14.DATA TUPLE: 2 fields;
15. 0: len 4; hex 80000002; asc     ;; 1: len 6; hex 000000000401; asc       ;;
16.
17.But in parent table `test/parent`, in index `PRIMARY`,
18.the closest match we can find is record:
19.PHYSICAL RECORD: n_fields 3; 1-byte offs TRUE; info bits 0
20. 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 0000140c2d8f; asc     – ;; 2: len 7; hex 80009c40050084; asc    @   ;;

innodb将打印引起错误的语句、相应的外键定义以及在父表中最近的记录。

下面是关于当前活动的事务的状态
CODE:
1.————
2.TRANSACTIONS
3.————
4.Trx id counter 0 80157601
5.Purge done for trx’s n:o <0 80154573 undo n:o <0 0
6.History list length 6
7.Total number of lock structs in row lock hash table 0
8.LIST OF TRANSACTIONS FOR EACH SESSION:
9.—TRANSACTION 0 0, not started, process no 3396, OS thread id 1152440672
10.MySQL thread id 8080, query id 728900 localhost root
11.show innodb status
12.—TRANSACTION 0 80157600, ACTIVE 4 sec, process no 3396, OS thread id 1148250464, thread declared inside InnoDB 442
13.mysql tables in use 1, locked 0
14.MySQL thread id 8079, query id 728899 localhost root Sending data
15.select sql_calc_found_rows  * from b limit 5
16.Trx read view will not see trx with id>= 0 80157601, sees <0 80157597
17.—TRANSACTION 0 80157599, ACTIVE 5 sec, process no 3396, OS thread id 1150142816 fetching rows, thread declared inside InnoDB 166
18.mysql tables in use 1, locked 0
19.MySQL thread id 8078, query id 728898 localhost root Sending data
20.select sql_calc_found_rows  * from b limit 5
21.Trx read view will not see trx with id>= 0 80157600, sees <0 80157596
22.—TRANSACTION 0 80157598, ACTIVE 7 sec, process no 3396, OS thread id 1147980128 fetching rows, thread declared inside InnoDB 114
23.mysql tables in use 1, locked 0
24.MySQL thread id 8077, query id 728897 localhost root Sending data
25.select sql_calc_found_rows  * from b limit 5
26.Trx read view will not see trx with id>= 0 80157599, sees <0 80157595
27.—TRANSACTION 0 80157597, ACTIVE 7 sec, process no 3396, OS thread id 1152305504 fetching rows, thread declared inside InnoDB 400
28.mysql tables in use 1, locked 0
29.MySQL thread id 8076, query id 728896 localhost root Sending data
30.select sql_calc_found_rows  * from b limit 5
31.Trx read view will not see trx with id>= 0 80157598, sees <0 80157594

如果只有少量的连接,将会列出所有的事务列表,Purge done for trx’s n:o表示已经清除的事务号,innodb只能清除潜在不使用的事务号,
旧的未提交的事务将会阻塞清除进程,占用资源。通过当前的事务号和清理的事务号的差可以获得相应当前的事务数。
histor list length 6 是在未做空间中未清理的事务。它随着更新和提交事务的增多而增多,随着清理工作而减少。
Total number of lock structs in row lock hash table 是所有事务锁结构分配的数量。注意这不是被锁的行的数量,每个锁会锁住多行。
如果一个连接中,没有运行的事务则显示not started,否则显示active。注:如果是多语句事务,即使处在sleep阶段,也可以是active。
innodb还会显示os的线程id和进程id,这对于使用gdb调试程序时很有用。同时还显示了事务的状态,如fetching或updating。
“Thread declared inside InnoDB 400″表示线程在innodb的内核中运行,还有400个tickets使用。通过使用innodb_thread_concurrency
调节并发在innodb内核中的线程数。如果线程未运行在innodb内核中,其状态显示为waitting in innodb queue或sleeping before joining innodb queue
innodb会让线程在进入等待前先sleep一段时间(当没有足够的slot可用的时候)。这可能使active的线程数小于innodb_thread_concurrency的值。
对此,可以调节innodb_thread_sleep_delay变量来调节sleep的时间长短。它以毫秒计算。
mysql tables in use 1, locked 0显示了该事务使用的表的数量和使用的锁,除非使用alter table或lock table等语句,一般情况innodb不加锁

下面是文件输入输出的信息:
CODE:
1.——–
2.FILE I/O
3.——–
4.I/O thread 0 state: waiting for i/o request (insert buffer thread)
5.I/O thread 1 state: waiting for i/o request (log thread)
6.I/O thread 2 state: waiting for i/o request (read thread)
7.I/O thread 3 state: waiting for i/o request (write thread)
8.Pending normal aio reads: 0, aio writes: 0,
9. ibuf aio reads: 0, log i/o’s: 0, sync i/o’s: 0
10.Pending flushes (fsync) log: 0; buffer pool: 0
11.17909940 OS file reads, 22088963 OS file writes, 1743764 OS fsyncs
12.0.20 reads/s, 16384 avg bytes/read, 5.00 writes/s, 0.80 fsyncs/s

显示了辅助线程insert buffer thread, log thread, read thread和write thread的当前状态。在每个辅助线程上挂起的操作数也显示出来。
同时也显示了挂起的fsync操作。”16384 avg bytes/read”显示了读请求的平均大小。

CODE:
1.————————————-
2.INSERT BUFFER AND ADAPTIVE HASH INDEX
3.————————————-
4.Ibuf for space 0: size 1, free list len 887, seg size 889, is not empty
5.Ibuf for space 0: size 1, free list len 887, seg size 889,
6.2431891 inserts, 2672643 merged recs, 1059730 merges
7.Hash table size 8850487, used cells 2381348, node heap has 4091 buffer(s)
8.2208.17 hash searches/s, 175.05 non-hash searches/s

此处显示了插入缓存和调节hash表的使用状况。number of merges与number of pretty的比率显示了插入缓存的效率
通过non-hash searches比hash searches的值可知hash表的效率。
但无法调节insert buffer 和adjust hash table。

CODE:
1.—
2.LOG
3.—
4.Log sequence number 84 3000620880
5.Log flushed up to   84 3000611265
6.Last checkpoint at  84 2939889199
7.0 pending log writes, 0 pending chkp writes
8.14073669 log i/o’s done, 10.90 log i/o’s/second

log sequence number 显示了innodb向log中写入的bytes。也可得知当前log被flushed到哪一点,通过此可以检验innodb_log_buffer_size的理想状况,
若有30%的数据没有被flush入log中,应该适当增大innodb_log_buffer_size。

 CODE:
1.———————-
2.BUFFER POOL AND MEMORY
3.———————-
4.Total memory allocated 4648979546; in additional pool allocated 16773888
5.Buffer pool size   262144
6.Free buffers       0
7.Database pages     258053
8.Modified db pages  37491
9.Pending reads 0
10.Pending writes: LRU 0, flush list 0, single page 0
11.Pages read 57973114, created 251137, written 10761167
12.9.79 reads/s, 0.31 creates/s, 6.00 writes/s
13.Buffer pool hit rate 999 / 1000

此节信息表明了buffer pool的效率和内存的使用。可获得innodb分配的所有内存,额外的分配的池,buffer pool中的页面数量,free页面的数量,
和脏数据页。由此可以作为依据调节buffer pool的大小,即使free页为0,database pases也将不等于buffer pool的所有大小,因为buffer pool也存入了
锁信息,调节的hash索引,和其他系统结构。
pending reads 和writes 表明了在buffer pool级别悬挂的请求。innodb将多个请求合并到一个文件级别,这里是不同的。此外,还可看到其他的io提交信息,
LRU——用最近最少使用算法换出的脏数据页; flush list:需要通过checkpointing进程刷新的旧页面;single page:独立的页面写操作。
也可看到正在被读写创建的数据页。最后还可看到buffer pool的命中率。

CODE:
1.————–
2.ROW OPERATIONS
3.————–
4.0 queries inside InnoDB, 0 queries in queue
5.1 read views open inside InnoDB
6.Main thread process no. 10099, id 88021936, state: waiting for server activity
7.Number of rows inserted 143, updated 3000041, deleted 0, read 24865563
8.0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

最后一节信息:以行为基础,显示行操作的数量,及一些系统信息。此处信息相对简单易读,不作介绍。