| Bug #66586 | SHOW INNODB STATUS and I_S show wrong transaction start time and duration | ||
|---|---|---|---|
| Submitted: | 28 Aug 2012 21:51 | Modified: | 10 Jan 2013 12:20 |
| Reporter: | Elena Stepanova | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.6.6, 5.6.7 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | regression | ||
[28 Aug 2012 21:51]
Elena Stepanova
[29 Aug 2012 6:12]
Valeriy Kravchuk
Thank you for the bug report. Verified with current mysql-5.6 on Linux: [openxs@chief mysql-test]$ ./mtr bug66586 Logging: ./mtr bug66586 120829 9:08:09 [Note] Plugin 'FEDERATED' is disabled. 120829 9:08:09 [Note] Binlog end 120829 9:08:09 [Note] Shutting down plugin 'CSV' 120829 9:08:09 [Note] Shutting down plugin 'MyISAM' MySQL Version 5.6.7 Checking supported features... - skipping ndbcluster - SSL connections supported - binaries are debug compiled Collecting tests... Removing old var directory... Creating var directory '/home/openxs/dbs/5.6/mysql-test/var'... Installing system database... Using server port 43724 ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 main.bug66586 [ fail ] Test ended at 2012-08-29 09:08:25 CURRENT_TEST: main.bug66586 --- /home/openxs/dbs/5.6/mysql-test/r/bug66586.result 2012-08-29 09:07:59.105937758 +0300 +++ /home/openxs/dbs/5.6/mysql-test/r/bug66586.reject 2012-08-29 09:08:24.914214365 +0300 @@ -0,0 +1,140 @@ +SHOW VARIABLES LIKE '%version%'; +Variable_name Value +innodb_version 1.2.7 +protocol_version 10 +slave_type_conversions +version 5.6.7-debug-log +version_comment Source distribution +version_compile_machine x86_64 +version_compile_os Linux +SELECT NOW(); +NOW() +2012-08-29 09:08:20 +CREATE TABLE t1 (i INT) ENGINE=InnoDB; +BEGIN; +INSERT INTO t1 VALUES (1); +SELECT 'First' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX; +attempt trx_id trx_started trx_query +First 1292 2012-08-29 09:08:20 SELECT 'First' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX +COMMIT; +BEGIN; +INSERT INTO t1 VALUES (2); +SELECT 'Second' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX; +attempt trx_id trx_started trx_query +Second 1293 2012-08-29 09:08:20 SELECT 'Second' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX +COMMIT; +BEGIN; +INSERT INTO t1 VALUES (3); +SHOW ENGINE INNODB STATUS; +Type Name Status +InnoDB +===================================== +120829 9:08:24 INNODB MONITOR OUTPUT +===================================== +Per second averages calculated from the last 5 seconds +----------------- +BACKGROUND THREAD +----------------- +srv_master_thread loops: 3 srv_active, 0 srv_shutdown, 1 srv_idle +srv_master_thread log flush and writes: 4 +---------- +SEMAPHORES +---------- +---------- +MUTEX INFO +---------- +Locked mutex: addr 0x17418e0 thread 140610163025664 file /home/openxs/bzr/mysql-5.6-work/storage/innobase/handler/ha_innodb.cc line 12181 +Locked mutex: addr 0x1741860 thread 140610163025664 file /home/openxs/bzr/mysql-5.6-work/storage/innobase/srv/srv0srv.cc line 1081 +Total number of mutexes 694 +------------- +RW-LATCH INFO +------------- +Total number of rw-locks 1135 +OS WAIT ARRAY INFO: reservation count 10 +OS WAIT ARRAY INFO: signal count 10 +Mutex spin waits 81, rounds 360, OS waits 8 +RW-shared spins 1, rounds 30, OS waits 1 +RW-excl spins 1, rounds 34, OS waits 1 +Spin rounds per wait: 4.44 mutex, 30.00 RW-shared, 34.00 RW-excl +------------ +TRANSACTIONS +------------ +Trx id counter 1307 +Purge done for trx's n:o < 1305 undo n:o < 0 state: running +History list length 4 +Total number of lock structs in row lock hash table 0 +LIST OF TRANSACTIONS FOR EACH SESSION: +---TRANSACTION 1306, ACTIVE 4 sec +1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1 +MySQL thread id 2, OS thread handle 0x7fe25ad1a700, query id 32 localhost root init +SHOW ENGINE INNODB STATUS +-------- +FILE I/O +-------- +I/O thread 0 state: waiting for completed aio requests (insert buffer thread) +I/O thread 1 state: waiting for completed aio requests (log thread) +I/O thread 2 state: waiting for completed aio requests (read thread) +I/O thread 3 state: waiting for completed aio requests (read thread) +I/O thread 4 state: waiting for completed aio requests (write thread) +I/O thread 5 state: waiting for completed aio requests (write thread) +Pending normal aio reads: 0 [0, 0] , aio writes: 0 [0, 0] , + ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 +Pending flushes (fsync) log: 0; buffer pool: 0 +186 OS file reads, 37 OS file writes, 21 OS fsyncs +30.99 reads/s, 27328 avg bytes/read, 6.17 writes/s, 3.50 fsyncs/s +------------------------------------- +INSERT BUFFER AND ADAPTIVE HASH INDEX +------------------------------------- +Ibuf: size 1, free list len 0, seg size 2, 0 merges +merged operations: + insert 0, delete mark 0, delete 0 +discarded operations: + insert 0, delete mark 0, delete 0 +Hash table size 17393, used cells 0, node heap has 0 buffer(s) +0.00 hash searches/s, 17.40 non-hash searches/s +--- +LOG +--- +Log sequence number 1641999 +Log flushed up to 1641164 +Pages flushed up to 1633350 +Last checkpoint at 1629432 +0 pending log writes, 0 pending chkp writes +18 log i/o's done, 3.00 log i/o's/second +---------------------- +BUFFER POOL AND MEMORY +---------------------- +Total memory allocated 8749056; in additional pool allocated 0 +Dictionary memory allocated 70357 +Buffer pool size 512 +Free buffers 330 +Database pages 182 +Old database pages 0 +Modified db pages 22 +Pending reads 0 +Pending writes: LRU 0, flush list 0 single page 0 +Pages made young 0, not young 0 +0.00 youngs/s, 0.00 non-youngs/s +Pages read 170, created 12, written 20 +28.33 reads/s, 2.00 creates/s, 3.33 writes/s +Buffer pool hit rate 822 / 1000, young-making rate 0 / 1000 not 0 / 1000 +Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s +LRU len: 182, unzip_LRU len: 0 +I/O sum[0]:cur[0], unzip sum[0]:cur[0] +-------------- +ROW OPERATIONS +-------------- +0 queries inside InnoDB, 0 queries in queue +0 read views open inside InnoDB +Main thread process no. 2262, id 140610133485312, state: sleeping +Number of rows inserted 3, updated 0, deleted 0, read 0 +0.60 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s +---------------------------- +END OF INNODB MONITOR OUTPUT +============================ + +SELECT 'Third' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX; +attempt trx_id trx_started trx_query +Third 1306 2012-08-29 09:08:20 SELECT 'Third' as attempt, trx_id, trx_started, trx_query FROM INFORMATION_SCHEMA.INNODB_TRX +COMMIT; +DROP TABLE t1; mysqltest: Result length mismatch
[10 Jan 2013 12:20]
Erlend Dahl
Fixed in 5.6.7.
