MySQL Bugs: #69438: incorrect transaction active time for recoving transaction after crash

Bug #69438	incorrect transaction active time for recoving transaction after crash
Submitted:	11 Jun 2013 6:02	Modified:	11 Dec 2013 13:32
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6.12	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
I killed mysqld, and after restart it rolls back the half completed transaction.

InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 386843 row operations to undo
InnoDB: Trx id counter is 593920

...

InnoDB: Starting in background the rollback of uncommitted transactions
2013-06-11 07:52:15 1b70  InnoDB: Rolling back trx with id 593421, 386843 rows to undo

InnoDB Status shows:

---TRANSACTION 593421, ACTIVE 1370929936 sec recovered trx
ROLLING BACK 1 lock struct(s), heap size 320, 0 row lock(s), undo log entries 385062

Notice, "1370929936" is bogus.
The real length of transaction was more in the ballpark of a minute before I killed it.

How to repeat:
Kill server midway in the insert..select.  after restart, check innodb status and see the long trx time (do it before it rollback entire trx).
---
drop table if exists t1,v;
create table t1(a char(255) charset latin1,index(a))engine=innodb;
set transaction isolation level read committed;
create or replace view v as select 1 union select 2 union 
select 3 union select 4 union select 5 union select 6;
insert into t1(a) select 'aaaa bbbb cccc dddd' from 
v,v t2,v t3,v t4, v t5,v t6,v t7,v t8;
---

5.5.32 is showing correct trx active time.  I tested 5.6.10+ and 5.7.2 and they have incorrect trx active times.

the problem is trx->trx_started is 0000-00-00 00:00:00

Fixed as of MySQL 5.6.16, 5.7.4:

"During crash recovery, an incorrect transaction active time
would result in rolling back an uncommitted transaction."

Thank you for the bug report.

5.6$ bzr log -r 5679
------------------------------------------------------------
revno: 5679
committer: Anil Toshniwal <anil.toshniwal@oracle.com>
branch nick: mysql-5.6
timestamp: Wed 2013-12-11 13:35:55 +0530
message:
  Bug#16936961 INCORRECT TRANSACTION ACTIVE TIME FOR RECOVING TRANSACTION
               AFTER CRASH
  Problem: The start_time member of trx_t structure is uninitialized in
           trx_create(), that is, at the time of transaction object creation.
           The start_time was initialized only at the start of transaction. 
           So after crash, start_time was taking the garbage value and while
           rollback is running in background for uncommited trx.
  
  Fixed: Initialized the start_time member in trx_resurrect_*(), when trx
         is in either ACTIVE or PREPARED STATE. 
  
  Approved by Jimmy (rb#4046).