SHOW ENGINE INNODB STATUS displayed ROLLING BACK for a transaction that later continued on

[Peiran Song]

From a customer's SHOW ENGINE INNODB STATUS samples, we found one transaction first in ROLLING BACK and then continued on. I never encountered this before and don't know how to reproduce it. But the customer sees ROLLING BACK in the transaction section for this query from time to time.

Server version: PS 5.5.28

17:07:10
---TRANSACTION 182AC2408, ACTIVE 8 sec inserting
mysql tables in use 1, locked 1
ROLLING BACK 461 lock struct(s), heap size 63928, 1435 row lock(s), undo log entries 1217
MySQL thread id 225564, OS thread handle 0x7f45dd7e2700, query id 1383215000 myserver 10.1.13.82 tungsten update
INSERT INTO mydb.mytable (c1, c2, c3, c4, c5, c6...) VALUES (1339,1136,8124716,0,'m',1,1,0,0,1,0,0,'15-01-11 05:00:00','15-01-11 05:38:51','15-01-11 05:38:51',NOW(),NOW()),(1742,1629,27909032,0,'m',1,1,0,0,1,0,0,'15-01-11 05:00:00','15-01-11 05:38:38','15-01-11 05:38:38',NOW(),NOW()),(1743,1644,4968364,0,'m',1,1,0,0,1,0,0,'15-01-11 05:00:00','15-01-11 0

17:07:10
---TRANSACTION 182AC2408, ACTIVE 8 sec starting index read
mysql tables in use 1, locked 1
489 lock struct(s), heap size 80312, 1463 row lock(s), undo log entries 1231
MySQL thread id 225564, OS thread handle 0x7f45dd7e2700, query id 1383215000 myserver 10.1.13.82 tungsten update
INSERT INTO mydb.mytable (c1, c2, c3, c4, c5, c6...) VALUES

[Valerii Kravchuk (valerii-kravchuk)]

So, what is the bug here? Undocumented "ROLLING BACK" message? Or the fact that transaction continued?

I see the following in the code:

trx_get_que_state_str(
/*==================*/
        const trx_t* trx) /*!< in: transaction */
{
        /* be sure to adjust TRX_QUE_STATE_STR_MAX_LEN if you change this */
        switch (trx->lock.que_state) {
        case TRX_QUE_RUNNING:
                return("RUNNING");
        case TRX_QUE_LOCK_WAIT:
                return("LOCK WAIT");
        case TRX_QUE_ROLLING_BACK:
                return("ROLLING BACK");
        case TRX_QUE_COMMITTING:
                return("COMMITTING");
        default:
                return("UNKNOWN");
        }
}

And then:

Percona-Server/storage/innobase/trx/trx0trx.cc:2040: case TRX_QUE_ROLLING_BACK:

Here we have:

        /* trx->lock.que_state of an ACTIVE transaction may change
        while we are not holding trx->mutex. We perform a dirty read
        for performance reasons. */

        switch (trx->lock.que_state) {
        case TRX_QUE_RUNNING:
                newline = FALSE; break;
        case TRX_QUE_LOCK_WAIT:
                fputs("LOCK WAIT ", f); break;
        case TRX_QUE_ROLLING_BACK:
                fputs("ROLLING BACK ", f); break;
        case TRX_QUE_COMMITTING:
                fputs("COMMITTING ", f); break;
        default:
                fprintf(f, "que state %lu ", (ulong) trx->lock.que_state);
        }

Percona-Server/storage/innobase/trx/trx0roll.cc:1300: trx->lock.que_state = TRX_QUE_ROLLING_BACK;

Here we have:

/*********************************************************************//**
Starts a rollback operation, creates the UNDO graph that will do the
actual undo operation.
@return query graph thread that will perform the UNDO operations. */
static
que_thr_t*
trx_rollback_start(
/*===============*/
        trx_t* trx, /*!< in: transaction */
        ib_id_t roll_limit) /*!< in: rollback to undo no (for
                                        partial undo), 0 if we are rolling back
                                        the entire transaction */
{

...

        /* Build a 'query' graph which will perform the undo operations */

        roll_graph = trx_roll_graph_build(trx);

        trx->graph = roll_graph;

        trx->lock.que_state = TRX_QUE_ROLLING_BACK;

        return(que_fork_start_command(roll_graph));
 }

So, my idea is that maybe transaction had to do some "mini rollback" to get data for the table at the moment statement execution began, to check some constraint maybe?

Just a speculation for now.

[Peiran Song (peiran-song)]

The common knowledge is that rollback applies to a statement or transaction as far as I know.

If there is a third type of rollback and this statement indeed was running such a rollback, then 1) that should be documented, 2) it should probably use a separate trx queue state, and when printed out, it should provide some info like "ROLLING BACK bla".

If there isn't a third type of rollback, then 1) how did this statement get into a transient rollback state? 2) how did it get out of it, any potential lose of changes?

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3249