With stats enabled, master logs show Unique constraint error while inserting into metric query table

[Aruna Sadashiva]

With stats enabled, we are seeing errors like these logged into master exec log files:

2015-01-23 05:43:47,538, ERROR, SQL, Node Number: 0, CPU: 0, PIN: 10201, Process
 Name: $Z0008BG, SQLCODE: 8102, QID: MXID110000102012122887353584666950000000003
06U3333300_16095_STMT_PUBLICATION, *** ERROR[8102] The operation is prevented by
 a unique constraint.
2015-01-23 05:43:47,538, ERROR, MXOSRVR, Node Number: 0, CPU: 0, PIN:10201, Proc
ess Name:$Z0008BG , , ,A NonStop Process Service error Failed to write statistic
s: insert into Trafodion."_REPOS_".metric_query_table values(0,0,0,10201,10201,0
,0,0,'16.235.158.28',0,'$Z0008BG',CONVERTTIMESTAMP(212288749246229932),'MXID1100
0010201212288735358466695000000000206U3333300_329_SQL_CUR_1','DB__ROOT','NONE',1
,'','MXID11000010201212288735358466695000000000206U3333300','n013','FASTJDBC','S
QL_CUR_1','SQL_SELECT_UNIQUE','',CONVERTTIMESTAMP(212288750018652982),CONVERTTIM
ESTAMP(212288749223334904),CONVERTTIMESTAMP(212288749246209807),22874903,0,0,0,0
,0,0,0,0,0,0,'212288735358466695001020000',5620000,5150000,430000,0,0,40000,2,3,
3,0,1,695080,0,0,0,0,0,0,0.0017074,1,0.00170667,3.0646e-07,0,4.25794e-07,0.00170
74,0,0,'',0,'2',0,0,0,780140615,0,0,0,0,0,0,0,0,0,47,'<N/A>',0,0,0,0,NULL,0,'NON
E','',NULL,0,0,0,0,'<N/A>','select * from trafodion.javabench.ycsb_table_8 where
 PRIM_KEY = ?','
LC RC OP OPERATOR OPT DESCRIPTION CARD
---- ---- ---- -------------------- -------- -------------------- ---------

1 . 2 root o 1.00E+000
. . 1 trafodion_scan YCSB_TABLE_8 1.00E+000
',0,0,0,0,0,0,0,-1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0)----Error detail - *** ERROR[
8102] The operation is prevented by a unique constraint. [2015-01-23 05:43:47] h
as occurred.

[Judy Zhao (hongxia-zhao)]

Currently I was able to reproduce the [bug 1414100]. Daniel helped me to analyze the bug and provide very useful information . Thanks for Daniel's great help!

Following is the reproduce steps:

1. Run mxosrvr with <query> config mode ;

2. Create a table ,for example mgbtest.ord;

3. Run following steps from trafci

>PREPARE testord FROM select * from mgbtest.ord where ORDERID = ?;

>EXECUTE testord USING 1;

>EXECUTE testord USING 2;

When running into the 2nd EXECUTE ,the error will be reported as following:

2015-03-05 06:17:25,050, ERROR, SQL, Node Number: 0, CPU: 0, PIN: 1084, Process Name: $Z0000VZ, SQLCODE: 8102, QID: MXID11000001084212292295084557778000000000306U3333300_853_STMT_PUBLICATION, *** ERROR[8102] The operation is prevented by a unique constraint.
2015-03-05 06:17:25,050, ERROR, MXOSRVR, Node Number: 0, CPU: 0, PIN:1084, Process Name:$Z0000VZ , , ,A NonStop Process Service error Failed to write statistics: insert into Trafodion."_REPOS_".metric_query_table values(0,0,0,1084,1084,0,0,0,'16.235.163.122',0,'$Z0000VZ',CONVERTTIMESTAMP(212292296143715565),'MXID11000001084212292295084557778000000000206U3333300_848_TESTORD','DB__ROOT','NONE',1,'','MXID11000001084212292295084557778000000000206U3333300','g4t3015.houston.hp.com','TrafCI','TESTORD','SQL_SELECT_NON_UNIQUE','',CONVERTTIMESTAMP(212292296143715565),CONVERTTIMESTAMP(212292296129270853),CONVERTTIMESTAMP(212292296129274142),3289,0,0,0,0,0,0,0,0,0,0,'212292295084557778001084000',0,680000,40000,0,10000,0,2,3,3,0,1,530096,0,0,0,0,0,0,0,50,0.00170667,5.45205e-06,0,7.34664e-06,0.00171947,0,0,'',0,'2',0,0,0,101254338,1509,2153,2,0,32,5,15,8,13,1515870810,'<N/A>',0,0,0,0,CONVERTTIMESTAMP(212292296244968713),1,'NONE','NONE',CONVERTTIMESTAMP(212292296244969897),535918,101253850,0,100,'<N/A>','select * from mgbtest.ord where ORDERID = ?','',0,0,0,0,0,1,1,0,0,0,0,32,5,0,0,0,0,0,0,0,0,0,1509,0)----Error detail - *** ERROR[8102] The operation is prevented by a unique constraint. [2015-03-05 06:17:25] has occurred.

4. Possible Root cause :

There are identical EXEC_START_UTC_TS and QUERY_ID ( PRIMARY KEY ) for all the consecutive EXECUTE statements of one PREPARE.

I will continue to work on this and do more investigation .

[Judy Zhao (hongxia-zhao)]

Discussion about how to fix the issue:

1. Is it correct that EXEC_START_UTC_TS is identical for all the consecutive EXECUTE statements ?
Rao – Nope. Every execute should have its own start time... we need to change the current way of prepare time to execute time.

Run following steps from trafci

>PREPARE testord FROM select * from mgbtest.ord where ORDERID = ?;

>EXECUTE testord USING 1; //pQuery_info->m_exec_start_utc_ts =212292649111812177

>EXECUTE testord USING 2; //pQuery_info->m_exec_start_utc_ts =212292649111812177

2. For multiple EXECUTE statements per PREPARE ,shall we insert only one row or multiple rows? What is the design for this?
Rao – If aggregation is enabled then whatever executes completed within the aggregation time are accumulated and written to repository as one record.