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:
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.6.12 OS:Any
Assigned to: CPU Architecture:Any
Tags: regression

[11 Jun 2013 6:02] Shane Bester
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;
[11 Jun 2013 6:07] MySQL Verification Team
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.
[11 Jun 2013 7:10] MySQL Verification Team
the problem is trx->trx_started is 0000-00-00 00:00:00
[11 Dec 2013 13:32] Daniel Price
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.
[3 Feb 2014 11:20] Laurynas Biveinis
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
               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).