Details
-
Bug
-
Status: Open
-
Critical
-
Resolution: Unresolved
-
None
-
None
Description
We are seeing this error message streaming during the order entry benchmark.
2015-01-17 11:25:49,116, ERROR, SQL, Node Number: 0, CPU: 0, PIN: 63243, Process Name: $Z001GLY, SQLCODE: 8605, QID: MXID110000632432122882535634324540
00000000206U3333300_24_STMT_COMMIT_1, *** ERROR[8605] Committing a transaction which has not started.
2015-01-17 11:25:50,667, ERROR, SQL, Node Number: 0, CPU: 0, PIN: 63243, Process Name: $Z001GLY, SQLCODE: 8605, QID: MXID110000632432122882535634324540
00000000206U3333300_24_STMT_COMMIT_1, *** ERROR[8605] Committing a transaction which has not started.
2015-01-17 11:26:17,823, ERROR, SQL, Node Number: 0, CPU: 0, PIN: 63243, Process Name: $Z001GLY, SQLCODE: 8605, QID: MXID110000632432122882535634324540
00000000206U3333300_24_STMT_COMMIT_1, *** ERROR[8605] Committing a transaction which has not started.
The counts are prolific. The master above shows every couple of seconds.
master_exec_0_13398.log:10241
master_exec_0_13942.log:12065
master_exec_0_17055.log:10110
master_exec_0_19990.log:11068
master_exec_0_20733.log:11818
master_exec_0_21408.log:10560
master_exec_0_22203.log:10633
master_exec_0_22274.log:1223
master_exec_0_24271.log:10096
master_exec_0_24852.log:1477
master_exec_0_24895.log:10791
master_exec_0_24990.log:12213
master_exec_0_26398.log:11618
master_exec_0_26536.log:1298
The only place where the error occurs is when commitTransaction is called and there isn’t an xnInProgress.
executor/ex_transaction.cpp: EXE_COMMIT_TRANSACTION_ERROR, &errorCond_);
exp/ExpErrorEnums.h: EXE_COMMIT_TRANSACTION_ERROR = 8605,
short ExTransaction::commitTransaction(NABoolean waited)
{
dp2Xns_ = FALSE;
if (! xnInProgress())
{
// Set the transaDiagsArea.
// This is the first error. So reset the diags area.
if (transDiagsArea_)
ExRaiseSqlError(heap_, &transDiagsArea_,
EXE_COMMIT_TRANSACTION_ERROR, &errorCond_);
return -1;
}
It must have something to do with inherited transactions. inheritTransaction is the only place where we set XnInProgress_ to false. The order entry does not use ESPs so there is no reason to have an inherited transaction.
Guy has shown the problem with a simple test case.
First scenario:
- I’m going to do a prepare/exec without using transactions.
/home/squser2> trafci.sh
Welcome to Trafodion Command Interface
Copyright(C) 2013-2014 Hewlett-Packard Development Company, L.P.
User Name: squser2
Host Name/IP Address: n001:21000
Password:
Connected to Trafodion
SQL>set schema mxoltp;
— SQL operation complete.
SQL>prepare cmd from select [first 10]* from tbl500;
-
-
- WARNING[6008] Statistics for column (CNT) from table TRAFODION.MXOLTP.TBL500 were not available. As a result, the access path chosen might not be the best possible. [2015-01-20 19:26:52]
- SQL command prepared.
-
SQL>execute cmd;
CNT COL1 COL2 COL3 COL4 COL5 COL6 COL7 COL10
---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- --------------------------------------------------------------------------------------------------------------------------------
3 1 2 0 4 5 6 7 AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
…
176 1 2 1 4 5 6 7 AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
— 10 row(s) selected.
SQL>exit
/home/squser2>
Here’s the master_exec_ log.
/opt/hp/squser2/git150118/logs> tail -f master_exec_6_63946.log
2015-01-20 19:26:52,591, INFO, SQL, Node Number: 0, CPU: 6, PIN: 63946, Process Name: $Z061H71, SQLCODE: 6008, QID: MXID11006063946212288460034592277000000000406U3333300_1177_CMD, *** WARNING[6008] Statistics for column (CNT) from table TRAFODION.MXOLTP.TBL500 were not available. As a result, the access path chosen might not be the best possible.
^C
/opt/hp/squser2/git150118/logs>
Second Scenario :
- I’m going to do a prepare and do the exec within a transactions.
/home/squser2> trafci.sh
Welcome to Trafodion Command Interface
Copyright(C) 2013-2014 Hewlett-Packard Development Company, L.P.
User Name: squser2
Host Name/IP Address: n001:21000
Password:
Connected to Trafodion
SQL>set schema mxoltp;
— SQL operation complete.
SQL>prepare cmd from select [first 10]* from tbl500;
-
-
- WARNING[6008] Statistics for column (CNT) from table TRAFODION.MXOLTP.TBL500 were not available. As a result, the access path chosen might not be the best possible. [2015-01-20 19:35:04]
- SQL command prepared.
-
SQL>begin work;
— SQL operation complete.
SQL>execute cmd;
CNT COL1 COL2 COL3 COL4 COL5 COL6 COL7 COL10
---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- --------------------------------------------------------------------------------------------------------------------------------
3 1 2 0 4 5 6 7 AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
…
176 1 2 1 4 5 6 7 AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAL
— 10 row(s) selected.
SQL>commit work;
— SQL operation complete.
SQL>exit
/home/squser2>
Here’s the master_exec_ log.
2015-01-20 19:35:04,011, INFO, SQL, Node Number: 0, CPU: 4, PIN: 2006, Process Name: $Z0401MB, SQLCODE: 6008, QID: MXID11004002006212288460034800667000000000406U3333300_1177_CMD, *** WARNING[6008] Statistics for column (CNT) from table TRAFODION.MXOLTP.TBL500 were not available. As a result, the access path chosen might not be the best possible.
2015-01-20 19:36:25,843, INFO, SQL.ESP, Node Number: 0, CPU: 4, PIN: 21984, Process Name: $Z040HY4,,, An ESP process is launched.
2015-01-20 19:36:38,979, ERROR, SQL, Node Number: 0, CPU: 4, PIN: 2006, Process Name: $Z0401MB, SQLCODE: 8609, QID: MXID11004002006212288460034800667000000000406U3333300_1160_STMT_ROLLBACK_1, *** ERROR[8609] Waited rollback performed without starting a transaction.
Notice in my second scenario here, an ESP is started. Why?????
And the 8609 msg shows up.