Trafodion

Statement Label could not be allocated

Bug #1422894 reported by Gary Hall on 2015-02-17

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Trafodion	Fix Committed	High	Arvind Narain	Trafodion r1.0.1

Bug Description

This has happened multiple times since Friday on performance test system Zircon4 - reporting the last two since now running 1.0.1rc2 at present.

2015-02-17 18:36:22 ERROR -
>----------------------------------------------------------
> Unexpected SQLEXCEPTION, Error Code = -1
> Stream Number : 989 , Transaction Number : 1
> SingletonSelect , scale = 20 , key_value = user5589248998698799825
> Statement Label could not be allocated. [2015-02-17 18:36:22]
>----------------------------------------------------------

org.trafodion.jdbc.t4.HPT4Exception: Statement Label could not be allocated. [2015-02-17 18:36:22]
        at org.trafodion.jdbc.t4.HPT4Messages.throwSQLException(HPT4Messages.java:206)
        at org.trafodion.jdbc.t4.InterfaceStatement.prepare(InterfaceStatement.java:1108)
        at org.trafodion.jdbc.t4.TrafT4PreparedStatement.prepare(TrafT4PreparedStatement.java:2234)
        at org.trafodion.jdbc.t4.TrafT4Connection.prepareStatement(TrafT4Connection.java:772)
        at DatabaseConnector.prepare_statement(DatabaseConnector.java:180)
        at YCSBWorkload2.runSingletonSelect(YCSBWorkload2.java:268)
        at WorkloadDriver.run(WorkloadDriver.java:427)

======================================================================================
An mxosrvr core has occurred both times as well. Stack trace for the two cores are:

echo /local/cores/1005/core.1424198189.n020.5019.mxosrvr
echo
…
[Thread debugging using libthread_db enabled]
Core was generated by `mxosrvr -ZKHOST n014.cm.cluster:2181,n015.cm.cluster:2181,n016.cm.cluster:2181'.
Program terminated with signal 6, Aborted.
#0 0x00007ffff4a328a5 in raise () from /lib64/libc.so.6
#0 0x00007ffff4a328a5 in raise () from /lib64/libc.so.6
#1 0x00007ffff4a3400d in abort () from /lib64/libc.so.6
#2 0x00007ffff5d51a55 in os::abort(bool) () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#3 0x00007ffff5ed1f87 in VMError::report_and_die() () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#4 0x00007ffff5d5696f in JVM_handle_linux_signal () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#5 <signal handler called>
#6 0x00007ffff43119e9 in SQLCLI_PerformTasks(CliGlobals *, ULng32, SQLSTMT_ID *, SQLDESC_ID *, SQLDESC_ID *, Lng32, Lng32, typedef
__va_list_tag __va_list_tag *, SQLCLI_PTR_PAIRS *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, tasks=606, statement_id=0x19ee4d8, inpu
t_descriptor=0x0, output_descriptor=0x0, num_input_ptr_pairs=0, num_output_ptr_pairs=0, ap=0x7fffd22385d0, input_ptr_pairs=0x0, outp
ut_ptr_pairs=0x0) at ../cli/Cli.cpp:2943
#7 0x00007ffff431bbfb in SQLCLI_ExecDirect2(CliGlobals *, SQLSTMT_ID *, SQLDESC_ID *, Int32, SQLDESC_ID *, Lng32, typedef __va_list
_tag __va_list_tag *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, statement_id=0x19ee4d8, sql_source=<value optimized out>, prepFlags=
0, input_descriptor=0x0, num_ptr_pairs=0, ap=0x7fffd22385d0, ptr_pairs=0x0) at ../cli/Cli.cpp:3718
#8 0x00007ffff4377bba in SQL_EXEC_ExecDirect2 (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, prep_flags=0, input_descriptor=0x
0, num_ptr_pairs=0) at ../cli/CliExtern.cpp:2326
#9 0x00007ffff6a74e17 in SRVR::WSQL_EXEC_ExecDirect (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, input_descriptor=0x0, num_p
tr_pairs=0) at SQLWrapper.cpp:360
#10 0x00007ffff6a6a8c0 in SRVR::EXECDIRECT (pSrvrStmt=0x19edec0) at sqlinterface.cpp:4479
#11 0x00007ffff6a2e245 in SRVR::ControlProc (pParam=0x19edec0) at csrvrstmt.cpp:757
#12 0x00007ffff6a2f008 in SRVR_STMT_HDL::ExecDirect (this=0x19edec0, inCursorName=0x0, inSqlString=0x1a54498 "insert into Trafodion.
\"_REPOS_\".metric_query_aggr_table values(0,0,0,5019,5019,9,0,0,'15.250.48.108',0,'$Z09043E','MXID110090050192122909579434510640000
00000206U3333300',CONVERTTIMESTAMP(2122909581694"..., inStmtType=<value optimized out>, inSqlStmtType=<value optimized out>, inSqlAs
yncEnable=<value optimized out>, inQueryTimeout=0) at csrvrstmt.cpp:439
#13 0x00000000004ccb1b in SessionWatchDog (arg=<value optimized out>) at SrvrConnect.cpp:818
#14 0x00007ffff45b2851 in start_thread () from /lib64/libpthread.so.0
#15 0x00007ffff4ae890d in clone () from /lib64/libc.so.6

=====
echo
echo /local/cores/1005/core.1424198231.n014.61369.mxosrvr
echo
…
[Thread debugging using libthread_db enabled]
Core was generated by `mxosrvr -ZKHOST n014.cm.cluster:2181,n015.cm.cluster:2181,n016.cm.cluster:2181'.
Program terminated with signal 6, Aborted.
#0 0x00007ffff4a328a5 in raise () from /lib64/libc.so.6
#0 0x00007ffff4a328a5 in raise () from /lib64/libc.so.6
#1 0x00007ffff4a3400d in abort () from /lib64/libc.so.6
#2 0x00007ffff5d51a55 in os::abort(bool) () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#3 0x00007ffff5ed1f87 in VMError::report_and_die() () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#4 0x00007ffff5d5696f in JVM_handle_linux_signal () from /usr/java/jdk1.7.0_67/jre/lib/amd64/server/libjvm.so
#5 <signal handler called>
#6 SRVR_STMT_HDL::cleanupAll (this=0x0) at csrvrstmt.cpp:625
#7 0x00007ffff6a2ef90 in SRVR_STMT_HDL::ExecDirect (this=0x0, inCursorName=0x0, inSqlString=0x1844e68 "update Trafodion.\"_REPOS_\"
.metric_query_aggr_table set AGGREGATION_END_UTC_TS = CONVERTTIMESTAMP(212290958231118193),TOTAL_EST_ROWS_ACCESSED = 0,TOTAL_EST_ROW
S_USED = 0,TOTAL_ROWS_RETRIEVED = 0,TOTAL_"..., inStmtType=<value optimized out>, inSqlStmtType=<value optimized out>, inSqlAsyncEna
ble=<value optimized out>, inQueryTimeout=0) at csrvrstmt.cpp:414
#8 0x00000000004ccb1b in SessionWatchDog (arg=<value optimized out>) at SrvrConnect.cpp:818
#9 0x00007ffff45b2851 in start_thread () from /lib64/libpthread.so.0
#10 0x00007ffff4ae890d in clone () from /lib64/libc.so.6

Sandhya Sundaresan (sandhya-sundaresan) on 2015-02-17

Changed in trafodion:
importance:	Undecided → High
assignee:	nobody → Mike Hanlon (mike-hanlon)

Revision history for this message

Mike Hanlon (mike-hanlon) wrote on 2015-02-18:

Download full text (8.7 KiB)

Notes on pid 5019
/local/cores/1005/core.1424198189.n020.5019.mxosrvr

#5 <signal handler called>
#6 0x00007ffff43119e9 in SQLCLI_PerformTasks(CliGlobals *, ULng32, SQLSTMT_ID *, SQLDESC_ID *, SQLDESC_ID *, Lng32, Lng32, typedef __va_list_tag __va_list_tag *, SQLCLI_PTR_PAIRS *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, tasks=606, statement_id=0x19ee4d8,
    input_descriptor=0x0, output_descriptor=0x0, num_input_ptr_pairs=0, num_output_ptr_pairs=0, ap=0x7fffd22385d0, input_ptr_pairs=0x0,
    output_ptr_pairs=0x0) at ../cli/Cli.cpp:2943
#7 0x00007ffff431bbfb in SQLCLI_ExecDirect2(CliGlobals *, SQLSTMT_ID *, SQLDESC_ID *, Int32, SQLDESC_ID *, Lng32, typedef __va_list_tag __va_list_tag *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, statement_id=0x19ee4d8, sql_source=<value optimized out>, prepFlags=0,
    input_descriptor=0x0, num_ptr_pairs=0, ap=0x7fffd22385d0, ptr_pairs=0x0) at ../cli/Cli.cpp:3718
#8 0x00007ffff4377bba in SQL_EXEC_ExecDirect2 (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, prep_flags=0, input_descriptor=0x0,
    num_ptr_pairs=0) at ../cli/CliExtern.cpp:2326
#9 0x00007ffff6a74e17 in SRVR::WSQL_EXEC_ExecDirect (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, input_descriptor=0x0,
    num_ptr_pairs=0) at SQLWrapper.cpp:360
#10 0x00007ffff6a6a8c0 in SRVR::EXECDIRECT (pSrvrStmt=0x19edec0) at sqlinterface.cpp:4479
#11 0x00007ffff6a2e245 in SRVR::ControlProc (pParam=0x19edec0) at csrvrstmt.cpp:757
#12 0x00007ffff6a2f008 in SRVR_STMT_HDL::ExecDirect (this=0x19edec0, inCursorName=0x0,
    inSqlString=0x1a54498 "insert into Trafodion.\"_REPOS_\".metric_query_aggr_table values(0,0,0,5019,5019,9,0,0,'15.250.48.108',0,'$Z09043E','MXID11009005019212290957943451064000000000206U3333300',CONVERTTIMESTAMP(2122909581694"..., inStmtType=<value optimized out>,
    inSqlStmtType=<value optimized out>, inSqlAsyncEnable=<value optimized out>, inQueryTimeout=0) at csrvrstmt.cpp:439
#13 0x00000000004ccb1b in SessionWatchDog (arg=<value optimized out>) at SrvrConnect.cpp:818
#14 0x00007ffff45b2851 in start_thread () from /lib64/libpthread.so.0
#15 0x00007ffff4ae890d in clone () from /lib64/libc.so.6

In Frame 6 --
(gdb) p *statement_id
$3 = {
  version = -293728816,
  name_mode = 32767,
  module = 0x2932287261686320,
  identifier = 0x0,
  handle = 0x0,
  charset = 0x0,
  identifier_len = 0,
  tag = 1819047278
}

(gdb) p statement_id->module
$6 = (const SQLMODULE_ID *) 0x2932287261686320
(gdb) p statement_id->module->module_name
Cannot access memory at address 0x2932287261686328
(gdb) p stmtInfo
$7 = (StatementInfo *) 0x0

The statement_id param is definitely corrupt.But this the first use of statement_id in SQLCLI_PerformTasks -- see tasks and stmt_info.

Notes on pid 5019
/local/cores/1005/core.1424198189.n020.5019.mxosrvr

#5  <signal handler called>
#6  0x00007ffff43119e9 in SQLCLI_PerformTasks(CliGlobals *, ULng32, SQLSTMT_ID *, SQLDESC_ID *, SQLDESC_ID *, Lng32, Lng32, typedef __va_list_tag __va_list_tag *, SQLCLI_PTR_PAIRS *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, tasks=606, statement_id=0x19ee4d8,
    input_descriptor=0x0, output_descriptor=0x0, num_input_ptr_pairs=0, num_output_ptr_pairs=0, ap=0x7fffd22385d0, input_ptr_pairs=0x0,
    output_ptr_pairs=0x0) at ../cli/Cli.cpp:2943
#7  0x00007ffff431bbfb in SQLCLI_ExecDirect2(CliGlobals *, SQLSTMT_ID *, SQLDESC_ID *, Int32, SQLDESC_ID *, Lng32, typedef __va_list_tag __va_list_tag *, SQLCLI_PTR_PAIRS *) (cliGlobals=0xeea9c0, statement_id=0x19ee4d8, sql_source=<value optimized out>, prepFlags=0,
    input_descriptor=0x0, num_ptr_pairs=0, ap=0x7fffd22385d0, ptr_pairs=0x0) at ../cli/Cli.cpp:3718
#8  0x00007ffff4377bba in SQL_EXEC_ExecDirect2 (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, prep_flags=0, input_descriptor=0x0,
    num_ptr_pairs=0) at ../cli/CliExtern.cpp:2326
#9  0x00007ffff6a74e17 in SRVR::WSQL_EXEC_ExecDirect (statement_id=0x19ee4d8, sql_source=0x7fffd22387c0, input_descriptor=0x0,
    num_ptr_pairs=0) at SQLWrapper.cpp:360
#10 0x00007ffff6a6a8c0 in SRVR::EXECDIRECT (pSrvrStmt=0x19edec0) at sqlinterface.cpp:4479
#11 0x00007ffff6a2e245 in SRVR::ControlProc (pParam=0x19edec0) at csrvrstmt.cpp:757
#12 0x00007ffff6a2f008 in SRVR_STMT_HDL::ExecDirect (this=0x19edec0, inCursorName=0x0,
    inSqlString=0x1a54498 "insert into Trafodion.\"_REPOS_\".metric_query_aggr_table values(0,0,0,5019,5019,9,0,0,'15.250.48.108',0,'$Z09043E','MXID11009005019212290957943451064000000000206U3333300',CONVERTTIMESTAMP(2122909581694"..., inStmtType=<value optimized out>,
    inSqlStmtType=<value optimized out>, inSqlAsyncEnable=<value optimized out>, inQueryTimeout=0) at csrvrstmt.cpp:439
#13 0x00000000004ccb1b in SessionWatchDog (arg=<value optimized out>) at SrvrConnect.cpp:818
#14 0x00007ffff45b2851 in start_thread () from /lib64/libpthread.so.0
#15 0x00007ffff4ae890d in clone () from /lib64/libc.so.6

In Frame 6 -- 
(gdb) p *statement_id
$3 = {
  version = -293728816,
  name_mode = 32767,
  module = 0x2932287261686320,
  identifier = 0x0,
  handle = 0x0,
  charset = 0x0,
  identifier_len = 0,
  tag = 1819047278
}

The statement_id param is definitely corrupt.But this the first use of statement_id in SQLCLI_PerformTasks -- see tasks and stmt_info.

2893 Lng32 SQLCLI_PerformTasks(
2894      /*IN*/ CliGlobals * cliGlobals,
2895      /*IN*/ ULng32 tasks,
2896      /*IN*/ SQLSTMT_ID * statement_id,
2897      /*IN  OPTIONAL*/ SQLDESC_ID * input_descriptor,
2898      /*IN  OPTIONAL*/ SQLDESC_ID * output_descriptor,
2899      /*IN*/ Lng32 num_input_ptr_pairs,
2900      /*IN*/ Lng32 num_output_ptr_pairs,
2901      /*IN*/ va_list ap,
2902      /*IN*/ SQLCLI_PTR_PAIRS input_ptr_pairs[],
2903      /*IN*/ SQLCLI_PTR_PAIRS output_ptr_pairs[])
2904 {
2905   Lng32 retcode = SUCCESS;
2906
2907   if (!statement_id)
2908     return -CLI_STMT_NOT_EXSISTS;
2909
2910   ContextCli   & currContext = *(cliGlobals->currContext());
2911   ComDiagsArea & diags       = currContext.diags();
2912
2913   StatementInfo * stmtInfo = NULL;
2914   StmtStats *stmtStats = NULL;
2915   if ((tasks & CLI_PT_OPT_STMT_INFO) &&
2916       (statement_id->name_mode != desc_handle))
2917     {
2918       stmtInfo = (StatementInfo *)(statement_id->handle);
2919       if (stmtInfo == NULL)
2920         {
2921           // when do we deallocate this heap? Or do we?
2922           CollHeap * heap = cliGlobals->currContext()->exCollHeap();
2923           stmtInfo = new(heap) StatementInfo();
2924           statement_id->handle = stmtInfo;
2925         }
2926     }
2927
2928   // create initial context, if first call, and add module, if any.
2929   if (tasks & CLI_PT_PROLOGUE)
2930     {
2931       retcode = CliPrologue(cliGlobals,
2932                             ((stmtInfo && stmtInfo->moduleAdded()) ?
2933                              NULL : statement_id->module));
2934       if (isERROR(retcode))
2935         return retcode;
2936
2937       if (stmtInfo)
2938         stmtInfo->setModuleAdded(TRUE);
2939     }
2940   else
2941     {
2942       // module must have been added
2943       if ((statement_id->module) &&
2944           (statement_id->module->module_name) &&
2945           (!currContext.moduleAdded(statement_id->module)))
2946         {
2947           diags << DgSqlCode(-CLI_MODULE_NOT_ADDED);
2948           return SQLCLI_ReturnCode(&currContext,
2949                                    -CLI_MODULE_NOT_ADDED);
2950         }
2951     }

In frame 7, SQLCLI_ExecDirect2, there are several uses of statement_id. Line 3654 passes statement_id->module and that would have caused a fault in CliPrologue.  Also, line 3663 would have gotten NULL from ContextCli::getStatement.  which would have raised an error. If this thread has corrupted the SQLSTMT_ID struct that statement_id points to, it must have happened in some method that SQLCLI_ExecDirect2 calls, even tho no pointer is passted to the called method. But all of the compiler code is called from this frame.

3640 Lng32 SQLCLI_ExecDirect2(/*IN*/           CliGlobals * cliGlobals,
3641                /*IN*/           SQLSTMT_ID * statement_id,
3642                /*IN*/           SQLDESC_ID * sql_source,
3643                /*IN*/           Int32 prepFlags,
3644                /*IN  OPTIONAL*/ SQLDESC_ID * input_descriptor,
3645                /*IN*/                 Lng32   num_ptr_pairs,
3646                /*IN*/              va_list   ap,
3647                /*IN*/     SQLCLI_PTR_PAIRS   ptr_pairs[]
3648                )
3649 {
3650   Lng32 retcode;
3651
3652
3653   // create initial context, if first call, and add module, if any.
3654   retcode = CliPrologue(cliGlobals,statement_id->module);
3655   if (isERROR(retcode))
3656     return retcode;
3657
3658   ContextCli   & currContext = *(cliGlobals->currContext());
3659   ComDiagsArea & diags       = currContext.diags();
3660
3661   /* prepare the statement */
3662
3663   Statement * stmt = currContext.getStatement(statement_id);
3664   //LCOV_EXCL_START
3665   /* stmt must exist */
3666   if (!stmt)
3667     {
3668       diags << DgSqlCode(-CLI_STMT_NOT_EXSISTS);
3669       return SQLCLI_ReturnCode(&currContext,-CLI_STMT_NOT_EXSISTS);
3670     }
3671   //LCOV_EXCL_STOP
3672   stmt->getGlobals()->clearCancelState();
3673
3674   StrTarget strTarget;
3675   retcode = stmt->initStrTarget(sql_source, currContext, diags, strTarget);
3676   if (isERROR(retcode))
3677     return SQLCLI_ReturnCode(&currContext,retcode);
3678   // CLI callers are not allowed to request PREPARE or EXEC DIRECT
3679   // operations on stored procedure result sets.
3680   //LCOV_EXCL_START
3681   if (stmt->getParentCall())
3682   {
3683     diags << DgSqlCode(-EXE_UDR_RS_PREPARE_NOT_ALLOWED);
3684     return SQLCLI_ReturnCode(&currContext, -EXE_UDR_RS_PREPARE_NOT_ALLOWED);
3685   }
3686   //LCOV_EXCL_STOP
3687
3688   // For ExecDirect, MXOSRVR calls SQL_EXEC_SetStmtAttr(NULL) to set the unique id
3689   // before calling SQL_EXEC_EXECDirect. So, we need to use them
3690   if (stmt->getUniqueStmtId() == NULL)
3691     stmt->setUniqueStmtId(NULL);
3692   // Set the StmtStats in the shared segment
3693   stmt->setStmtStats(FALSE);
3694   SQLCLI_Prepare_Setup_Pre(currContext, stmt, 1);
3695   UInt32 tmpFlags;
3696   SessionDefaults *sd = currContext.getSessionDefaults();
3697   if (sd != NULL && sd->getCallEmbeddedArkcmp())
3698       tmpFlags = prepFlags | PREPARE_USE_EMBEDDED_ARKCMP;
3699   else
3700       tmpFlags = prepFlags;
3701   if (sql_source)
3702
3703   retcode =
3704    stmt->prepare(strTarget.getStr(), diags, NULL, 0L,
3705                   strTarget.getIntCharSet(),TRUE,tmpFlags);
3706
3707   SQLCLI_Prepare_Setup_Post(currContext, stmt, 1);
3708
3709   if (isERROR(retcode))
3710     return SQLCLI_ReturnCode(&currContext,retcode);
3711
3712   stmt->issuePlanVersioningWarnings (diags);
3713
3714   ULng32 tasks = CLI_PT_GET_INPUT_DESC | CLI_PT_EXEC | CLI_PT_FETCH |
3715                         CLI_PT_CLOSE |CLI_PT_SPECIAL_END_PROCESS | CLI_PT_EPILOGUE;
3716   return SQLCLI_PerformTasks(cliGlobals, tasks, statement_id,
3717                              input_descriptor, NULL,
3718                              num_ptr_pairs, 0, ap, ptr_pairs, 0);
3719 }

Revision history for this message

Mike Hanlon (mike-hanlon) wrote on 2015-02-18:

Download full text (5.9 KiB)

Quoting some email from Arvind:

From: Narain, Arvind
Sent: Tuesday, February 17, 2015 8:24 PM
To: Varshneya, Renu; Hanlon, Mike; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath; Le Rouzo, Christophe
Subject: RE: ZIRCON4: I've never seen this error message before

Hi Renu,

Yes it is related to enabling stats. Went thru the cores with Selva – current thinking is that this is happening because of updating of the statement list maintained by mxosrvr by two different threads - we need to make that code thread safe. We didn’t face these cores on Lava though we did run with the modified code since Feb.

These cores did happen earlier too on Zircon (Feb 13 run).

Regards
Arvind

From: Varshneya, Renu
Sent: Tuesday, February 17, 2015 4:22 PM
To: Narain, Arvind; Hanlon, Mike; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath
Subject: RE: ZIRCON4: I've never seen this error message before

Thanks Arvind. Even though different issues, are they related to stats?
Mike mentioned in his earlier email that the queries did not fail. Could they have been AQRed?

From: Narain, Arvind
Sent: Tuesday, February 17, 2015 4:17 PM
To: Hanlon, Mike; Varshneya, Renu; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath
Subject: RE: ZIRCON4: I've never seen this error message before

25567 should be a separate bug – seems like the context got messed up. In the repository context I also see CREATE TABLE LIBRARIES.

Regarding 61369, the change that went into mxosrvr was to delete an existing statement and create a new one for each of the inserts/updates done to the repository table. Granted we should be checking if pSrvrStmt is NULL before doing ExecDirect on the same (to avoid the core), but I’m seeing a pattern of 8802 and 8804 errors for the repository context:

                        pSrvrStmt = getSrvrStmt("STMT_PUBLICATION", FALSE);
                        if (pSrvrStmt != NULL)
                        {
                                pSrvrStmt->cleanupAll();
                                pSrvrStmt->Close(SQL_DROP);
                                pSrvrStmt = NULL;
                        }

pSrvrStmt = getSrvrStmt("STMT_PUBLICATION", TRUE);

ss.str("");
ss.clear();

This change was tested in Feb with OE and YCSB runs.

The messages that I currently see in the logs are:

n020: /opt/hp/squser4/tr101rc2/logs/master_exec_9_5019.log:2015-02-17 18:36:23,050, ERROR, MXOSRVR, Node Number: 9, CPU: 9, PIN:5019, Process Name:$Z09043E , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8804, sql error = *** ERROR[8804] The provided input statement does not exist in the current context. [2015-02-17 18:36:23].

Quoting some email from Arvind:

From: Narain, Arvind 
Sent: Tuesday, February 17, 2015 8:24 PM
To: Varshneya, Renu; Hanlon, Mike; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath; Le Rouzo, Christophe
Subject: RE: ZIRCON4: I've never seen this error message before

Hi Renu,

Yes it is related to enabling stats. Went thru the cores with Selva – current thinking is that this is happening because of updating of the statement list maintained by mxosrvr by two different threads - we need to make that code thread safe.  We didn’t face these cores on Lava though we did run with the modified code since Feb.

These cores did happen earlier too on Zircon (Feb 13 run).

Regards
Arvind

From: Varshneya, Renu 
Sent: Tuesday, February 17, 2015 4:22 PM
To: Narain, Arvind; Hanlon, Mike; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath
Subject: RE: ZIRCON4: I've never seen this error message before

Thanks Arvind. Even though different issues, are they related to stats?
Mike mentioned in his earlier email that the queries did not fail. Could they have been AQRed?

From: Narain, Arvind 
Sent: Tuesday, February 17, 2015 4:17 PM
To: Hanlon, Mike; Varshneya, Renu; Hegde, Anuradha; Govindarajan, Selvaganes; Du, Justin
Cc: Sundaresan, Sandhya; Capirala, Tharaknath
Subject: RE: ZIRCON4: I've never seen this error message before

25567 should be a separate bug – seems like the context got messed up. In the repository context I also see CREATE TABLE LIBRARIES.

pSrvrStmt = getSrvrStmt("STMT_PUBLICATION", TRUE);

ss.str("");
                        ss.clear();

This change was tested in Feb with OE and YCSB runs.

The messages that I currently see in the logs are:

n014: /opt/hp/squser4/tr101rc2/logs/master_exec_3_61369.log:2015-02-17 18:36:22,796, ERROR, MXOSRVR, Node Number: 3, CPU: 3, PIN:61369, Process Name:$Z031F3E , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8804, sql error = *** ERROR[8804] The provided input statement does not exist in the current context. [2015-02-17 18:36:22].
n014: /opt/hp/squser4/tr101rc2/logs/master_exec_3_61369.log:2015-02-17 18:37:11,118, ERROR, SQL, Node Number: 0, CPU: 3, PIN: 61369, Process Name: $Z031F3E, SQLCODE: 8802,, *** ERROR[8802] Statement allocation failed because the statement already exists in the current context.
n014: /opt/hp/squser4/tr101rc2/logs/master_exec_3_61369.log:2015-02-17 18:37:11,118, ERROR, MXOSRVR, Node Number: 3, CPU: 3, PIN:61369, Process Name:$Z031F3E , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8802, sql error = *** ERROR[8802] Statement allocation failed because the statement already exists in the current context. [2015-02-17 18:37:11].

n015: /opt/hp/squser4/tr101rc2/logs/master_exec_4_27661.log:2015-02-17 19:51:27,248, ERROR, MXOSRVR, Node Number: 4, CPU: 4, PIN:27661, Process Name:$Z040MKB , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8804, sql error = *** ERROR[8804] The provided input statement does not exist in the current context. [2015-02-17 19:51:27].
n015: /opt/hp/squser4/tr101rc2/logs/master_exec_4_56189.log:2015-02-17 23:12:17,436, ERROR, SQL, Node Number: 0, CPU: 4, PIN: 56189, Process Name: $Z041AVE, SQLCODE: 8802,, *** ERROR[8802] Statement allocation failed because the statement already exists in the current context.
n015: /opt/hp/squser4/tr101rc2/logs/master_exec_4_56189.log:2015-02-17 23:12:17,436, ERROR, MXOSRVR, Node Number: 4, CPU: 4, PIN:56189, Process Name:$Z041AVE , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8802, sql error = *** ERROR[8802] Statement allocation failed because the statement already exists in the current context. [2015-02-17 23:12:17].

n012: /opt/hp/squser4/tr101rc2/logs/master_exec_1_13057.log:2015-02-17 19:51:27,237, ERROR, MXOSRVR, Node Number: 1, CPU: 1, PIN:13057, Process Name:$Z010AN2 , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8804, sql error = *** ERROR[8804] The provided input statement does not exist in the current context. [2015-02-17 19:51:27].
n012: /opt/hp/squser4/tr101rc2/logs/master_exec_1_13057.log:2015-02-17 19:52:14,489, ERROR, SQL, Node Number: 0, CPU: 1, PIN: 13057, Process Name: $Z010AN2, SQLCODE: 8802,, *** ERROR[8802] Statement allocation failed because the statement already exists in the current context.
n012: /opt/hp/squser4/tr101rc2/logs/master_exec_1_13057.log:2015-02-17 19:52:14,489, ERROR, MXOSRVR, Node Number: 1, CPU: 1, PIN:13057, Process Name:$Z010AN2 , , ,A SQL/MX query failed. SQLCODE: SQL statement allocate failed, sqlcode = -8802, sql error = *** ERROR[8802] Statement allocation failed because the statement already exists in the current context. [2015-02-17 19:52:14].

Still checking – looking at the other cores too.

Mike Hanlon (mike-hanlon) on 2015-03-24

Changed in trafodion:
assignee:	Mike Hanlon (mike-hanlon) → Arvind Narain (arvind-narain)

Anuradha (anuradha-hegde) on 2015-04-02

Changed in trafodion:
milestone:	none → r1.2
assignee:	Arvind Narain (arvind-narain) → Daniel Lu (ping-lu)
milestone:	r1.2 → r1.1
assignee:	Daniel Lu (ping-lu) → nobody
assignee:	nobody → Arvind Narain (arvind-narain)
status:	New → Fix Committed
milestone:	r1.1 → r1.0.1

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.