From 51ca91f55da544e11287bc701ffae746797c9260 Mon Sep 17 00:00:00 2001 From: Dmitry Yemanov Date: Tue, 31 Jan 2023 17:27:45 +0300 Subject: [PATCH] Add COMPILE trace events for procedures/functions/triggers --- src/include/firebird/FirebirdInterface.idl | 40 +- src/include/firebird/IdlFbInterfaces.h | 325 ++++++++++++++- src/include/gen/Firebird.pas | 309 +++++++++++++- src/jrd/Function.epp | 8 +- src/jrd/exe.cpp | 14 +- src/jrd/jrd.cpp | 6 + src/jrd/met.epp | 14 +- src/jrd/trace/TraceJrdHelpers.h | 324 ++++++++++++--- src/jrd/trace/TraceManager.cpp | 76 ++-- src/jrd/trace/TraceManager.h | 9 + src/jrd/trace/TraceObjects.cpp | 53 +-- src/jrd/trace/TraceObjects.h | 279 ++++++++++--- src/utilities/ntrace/TracePluginImpl.cpp | 448 +++++++++++++++------ src/utilities/ntrace/TracePluginImpl.h | 50 ++- src/utilities/ntrace/fbtrace.conf | 9 + src/utilities/ntrace/paramtable.h | 3 + 16 files changed, 1621 insertions(+), 346 deletions(-) diff --git a/src/include/firebird/FirebirdInterface.idl b/src/include/firebird/FirebirdInterface.idl index 6035ac27ca..5425db83df 100644 --- a/src/include/firebird/FirebirdInterface.idl +++ b/src/include/firebird/FirebirdInterface.idl @@ -1360,6 +1360,11 @@ interface TraceProcedure : Versioned const string getProcName(); TraceParams getInputs(); PerformanceInfo* getPerf(); + +version: // 4.0 -> 5.0 + int64 getStmtID(); + const string getPlan(); + const string getExplainedPlan(); } interface TraceFunction : Versioned @@ -1368,6 +1373,11 @@ interface TraceFunction : Versioned TraceParams getInputs(); TraceParams getResult(); PerformanceInfo* getPerf(); + +version: // 4.0 -> 5.0 + int64 getStmtID(); + const string getPlan(); + const string getExplainedPlan(); } interface TraceTrigger : Versioned @@ -1385,6 +1395,11 @@ interface TraceTrigger : Versioned int getAction(); int getWhich(); PerformanceInfo* getPerf(); + +version: // 4.0 -> 5.0 + int64 getStmtID(); + const string getPlan(); + const string getExplainedPlan(); } interface TraceServiceConnection : TraceConnection @@ -1539,13 +1554,25 @@ interface TracePlugin : ReferenceCounted // Stored functions execution [notImplemented(true)] - boolean trace_func_execute (TraceDatabaseConnection connection, TraceTransaction transaction, TraceFunction function, - boolean started, uint func_result); + boolean trace_func_execute(TraceDatabaseConnection connection, TraceTransaction transaction, + TraceFunction function, boolean started, uint func_result); version: // 4.0.1 -> 4.0.2 - boolean trace_dsql_restart(TraceDatabaseConnection connection, TraceTransaction transaction, TraceSQLStatement statement, - uint number); + boolean trace_dsql_restart(TraceDatabaseConnection connection, TraceTransaction transaction, + TraceSQLStatement statement, uint number); +version: // 4.0 -> 5.0 + + // Compilation of stored procedures, functions, triggers + + boolean trace_proc_compile(TraceDatabaseConnection connection, TraceProcedure procedure, + int64 time_millis, uint proc_result); + + boolean trace_func_compile(TraceDatabaseConnection connection, TraceFunction function, + int64 time_millis, uint func_result); + + boolean trace_trigger_compile(TraceDatabaseConnection connection, TraceTrigger trigger, + int64 time_millis, uint trig_result); } // Trace plugin second level factory (this is what is known to PluginManager as "trace plugin") @@ -1572,7 +1599,10 @@ interface TraceFactory : PluginBase const uint TRACE_EVENT_ERROR = 17; const uint TRACE_EVENT_SWEEP = 18; const uint TRACE_EVENT_FUNC_EXECUTE = 19; - const uint TRACE_EVENT_MAX = 20; // keep it last + const uint TRACE_EVENT_PROC_COMPILE = 20; + const uint TRACE_EVENT_FUNC_COMPILE = 21; + const uint TRACE_EVENT_TRIGGER_COMPILE = 22; + const uint TRACE_EVENT_MAX = 23; // keep it last // What notifications does plugin need uint64 trace_needs(); diff --git a/src/include/firebird/IdlFbInterfaces.h b/src/include/firebird/IdlFbInterfaces.h index be925cb45e..11181d39f5 100644 --- a/src/include/firebird/IdlFbInterfaces.h +++ b/src/include/firebird/IdlFbInterfaces.h @@ -5602,7 +5602,7 @@ namespace Firebird } }; -#define FIREBIRD_ITRACE_PROCEDURE_VERSION 2u +#define FIREBIRD_ITRACE_PROCEDURE_VERSION 3u class ITraceProcedure : public IVersioned { @@ -5612,6 +5612,9 @@ namespace Firebird const char* (CLOOP_CARG *getProcName)(ITraceProcedure* self) CLOOP_NOEXCEPT; ITraceParams* (CLOOP_CARG *getInputs)(ITraceProcedure* self) CLOOP_NOEXCEPT; PerformanceInfo* (CLOOP_CARG *getPerf)(ITraceProcedure* self) CLOOP_NOEXCEPT; + ISC_INT64 (CLOOP_CARG *getStmtID)(ITraceProcedure* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getPlan)(ITraceProcedure* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getExplainedPlan)(ITraceProcedure* self) CLOOP_NOEXCEPT; }; protected: @@ -5644,9 +5647,39 @@ namespace Firebird PerformanceInfo* ret = static_cast(this->cloopVTable)->getPerf(this); return ret; } + + ISC_INT64 getStmtID() + { + if (cloopVTable->version < 3) + { + return 0; + } + ISC_INT64 ret = static_cast(this->cloopVTable)->getStmtID(this); + return ret; + } + + const char* getPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getPlan(this); + return ret; + } + + const char* getExplainedPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getExplainedPlan(this); + return ret; + } }; -#define FIREBIRD_ITRACE_FUNCTION_VERSION 2u +#define FIREBIRD_ITRACE_FUNCTION_VERSION 3u class ITraceFunction : public IVersioned { @@ -5657,6 +5690,9 @@ namespace Firebird ITraceParams* (CLOOP_CARG *getInputs)(ITraceFunction* self) CLOOP_NOEXCEPT; ITraceParams* (CLOOP_CARG *getResult)(ITraceFunction* self) CLOOP_NOEXCEPT; PerformanceInfo* (CLOOP_CARG *getPerf)(ITraceFunction* self) CLOOP_NOEXCEPT; + ISC_INT64 (CLOOP_CARG *getStmtID)(ITraceFunction* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getPlan)(ITraceFunction* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getExplainedPlan)(ITraceFunction* self) CLOOP_NOEXCEPT; }; protected: @@ -5695,9 +5731,39 @@ namespace Firebird PerformanceInfo* ret = static_cast(this->cloopVTable)->getPerf(this); return ret; } + + ISC_INT64 getStmtID() + { + if (cloopVTable->version < 3) + { + return 0; + } + ISC_INT64 ret = static_cast(this->cloopVTable)->getStmtID(this); + return ret; + } + + const char* getPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getPlan(this); + return ret; + } + + const char* getExplainedPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getExplainedPlan(this); + return ret; + } }; -#define FIREBIRD_ITRACE_TRIGGER_VERSION 2u +#define FIREBIRD_ITRACE_TRIGGER_VERSION 3u class ITraceTrigger : public IVersioned { @@ -5709,6 +5775,9 @@ namespace Firebird int (CLOOP_CARG *getAction)(ITraceTrigger* self) CLOOP_NOEXCEPT; int (CLOOP_CARG *getWhich)(ITraceTrigger* self) CLOOP_NOEXCEPT; PerformanceInfo* (CLOOP_CARG *getPerf)(ITraceTrigger* self) CLOOP_NOEXCEPT; + ISC_INT64 (CLOOP_CARG *getStmtID)(ITraceTrigger* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getPlan)(ITraceTrigger* self) CLOOP_NOEXCEPT; + const char* (CLOOP_CARG *getExplainedPlan)(ITraceTrigger* self) CLOOP_NOEXCEPT; }; protected: @@ -5757,6 +5826,36 @@ namespace Firebird PerformanceInfo* ret = static_cast(this->cloopVTable)->getPerf(this); return ret; } + + ISC_INT64 getStmtID() + { + if (cloopVTable->version < 3) + { + return 0; + } + ISC_INT64 ret = static_cast(this->cloopVTable)->getStmtID(this); + return ret; + } + + const char* getPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getPlan(this); + return ret; + } + + const char* getExplainedPlan() + { + if (cloopVTable->version < 3) + { + return 0; + } + const char* ret = static_cast(this->cloopVTable)->getExplainedPlan(this); + return ret; + } }; #define FIREBIRD_ITRACE_SERVICE_CONNECTION_VERSION 3u @@ -6029,7 +6128,7 @@ namespace Firebird } }; -#define FIREBIRD_ITRACE_PLUGIN_VERSION 4u +#define FIREBIRD_ITRACE_PLUGIN_VERSION 5u class ITracePlugin : public IReferenceCounted { @@ -6058,6 +6157,9 @@ namespace Firebird FB_BOOLEAN (CLOOP_CARG *trace_event_sweep)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceSweepInfo* sweep, unsigned sweep_state) CLOOP_NOEXCEPT; FB_BOOLEAN (CLOOP_CARG *trace_func_execute)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceFunction* function, FB_BOOLEAN started, unsigned func_result) CLOOP_NOEXCEPT; FB_BOOLEAN (CLOOP_CARG *trace_dsql_restart)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceSQLStatement* statement, unsigned number) CLOOP_NOEXCEPT; + FB_BOOLEAN (CLOOP_CARG *trace_proc_compile)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceProcedure* procedure, ISC_INT64 time_millis, unsigned proc_result) CLOOP_NOEXCEPT; + FB_BOOLEAN (CLOOP_CARG *trace_func_compile)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceFunction* function, ISC_INT64 time_millis, unsigned func_result) CLOOP_NOEXCEPT; + FB_BOOLEAN (CLOOP_CARG *trace_trigger_compile)(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceTrigger* trigger, ISC_INT64 time_millis, unsigned trig_result) CLOOP_NOEXCEPT; }; protected: @@ -6216,6 +6318,36 @@ namespace Firebird FB_BOOLEAN ret = static_cast(this->cloopVTable)->trace_dsql_restart(this, connection, transaction, statement, number); return ret; } + + FB_BOOLEAN trace_proc_compile(ITraceDatabaseConnection* connection, ITraceProcedure* procedure, ISC_INT64 time_millis, unsigned proc_result) + { + if (cloopVTable->version < 5) + { + return 0; + } + FB_BOOLEAN ret = static_cast(this->cloopVTable)->trace_proc_compile(this, connection, procedure, time_millis, proc_result); + return ret; + } + + FB_BOOLEAN trace_func_compile(ITraceDatabaseConnection* connection, ITraceFunction* function, ISC_INT64 time_millis, unsigned func_result) + { + if (cloopVTable->version < 5) + { + return 0; + } + FB_BOOLEAN ret = static_cast(this->cloopVTable)->trace_func_compile(this, connection, function, time_millis, func_result); + return ret; + } + + FB_BOOLEAN trace_trigger_compile(ITraceDatabaseConnection* connection, ITraceTrigger* trigger, ISC_INT64 time_millis, unsigned trig_result) + { + if (cloopVTable->version < 5) + { + return 0; + } + FB_BOOLEAN ret = static_cast(this->cloopVTable)->trace_trigger_compile(this, connection, trigger, time_millis, trig_result); + return ret; + } }; #define FIREBIRD_ITRACE_FACTORY_VERSION 4u @@ -6262,7 +6394,10 @@ namespace Firebird static CLOOP_CONSTEXPR unsigned TRACE_EVENT_ERROR = 17; static CLOOP_CONSTEXPR unsigned TRACE_EVENT_SWEEP = 18; static CLOOP_CONSTEXPR unsigned TRACE_EVENT_FUNC_EXECUTE = 19; - static CLOOP_CONSTEXPR unsigned TRACE_EVENT_MAX = 20; + static CLOOP_CONSTEXPR unsigned TRACE_EVENT_PROC_COMPILE = 20; + static CLOOP_CONSTEXPR unsigned TRACE_EVENT_FUNC_COMPILE = 21; + static CLOOP_CONSTEXPR unsigned TRACE_EVENT_TRIGGER_COMPILE = 22; + static CLOOP_CONSTEXPR unsigned TRACE_EVENT_MAX = 23; ISC_UINT64 trace_needs() { @@ -17636,6 +17771,9 @@ namespace Firebird this->getProcName = &Name::cloopgetProcNameDispatcher; this->getInputs = &Name::cloopgetInputsDispatcher; this->getPerf = &Name::cloopgetPerfDispatcher; + this->getStmtID = &Name::cloopgetStmtIDDispatcher; + this->getPlan = &Name::cloopgetPlanDispatcher; + this->getExplainedPlan = &Name::cloopgetExplainedPlanDispatcher; } } vTable; @@ -17680,6 +17818,45 @@ namespace Firebird return static_cast(0); } } + + static ISC_INT64 CLOOP_CARG cloopgetStmtIDDispatcher(ITraceProcedure* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getStmtID(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetPlanDispatcher(ITraceProcedure* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetExplainedPlanDispatcher(ITraceProcedure* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getExplainedPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } }; template > > @@ -17698,6 +17875,9 @@ namespace Firebird virtual const char* getProcName() = 0; virtual ITraceParams* getInputs() = 0; virtual PerformanceInfo* getPerf() = 0; + virtual ISC_INT64 getStmtID() = 0; + virtual const char* getPlan() = 0; + virtual const char* getExplainedPlan() = 0; }; template @@ -17717,6 +17897,9 @@ namespace Firebird this->getInputs = &Name::cloopgetInputsDispatcher; this->getResult = &Name::cloopgetResultDispatcher; this->getPerf = &Name::cloopgetPerfDispatcher; + this->getStmtID = &Name::cloopgetStmtIDDispatcher; + this->getPlan = &Name::cloopgetPlanDispatcher; + this->getExplainedPlan = &Name::cloopgetExplainedPlanDispatcher; } } vTable; @@ -17774,6 +17957,45 @@ namespace Firebird return static_cast(0); } } + + static ISC_INT64 CLOOP_CARG cloopgetStmtIDDispatcher(ITraceFunction* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getStmtID(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetPlanDispatcher(ITraceFunction* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetExplainedPlanDispatcher(ITraceFunction* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getExplainedPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } }; template > > @@ -17793,6 +18015,9 @@ namespace Firebird virtual ITraceParams* getInputs() = 0; virtual ITraceParams* getResult() = 0; virtual PerformanceInfo* getPerf() = 0; + virtual ISC_INT64 getStmtID() = 0; + virtual const char* getPlan() = 0; + virtual const char* getExplainedPlan() = 0; }; template @@ -17813,6 +18038,9 @@ namespace Firebird this->getAction = &Name::cloopgetActionDispatcher; this->getWhich = &Name::cloopgetWhichDispatcher; this->getPerf = &Name::cloopgetPerfDispatcher; + this->getStmtID = &Name::cloopgetStmtIDDispatcher; + this->getPlan = &Name::cloopgetPlanDispatcher; + this->getExplainedPlan = &Name::cloopgetExplainedPlanDispatcher; } } vTable; @@ -17883,6 +18111,45 @@ namespace Firebird return static_cast(0); } } + + static ISC_INT64 CLOOP_CARG cloopgetStmtIDDispatcher(ITraceTrigger* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getStmtID(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetPlanDispatcher(ITraceTrigger* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static const char* CLOOP_CARG cloopgetExplainedPlanDispatcher(ITraceTrigger* self) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::getExplainedPlan(); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } }; template > > @@ -17903,6 +18170,9 @@ namespace Firebird virtual int getAction() = 0; virtual int getWhich() = 0; virtual PerformanceInfo* getPerf() = 0; + virtual ISC_INT64 getStmtID() = 0; + virtual const char* getPlan() = 0; + virtual const char* getExplainedPlan() = 0; }; template @@ -18587,6 +18857,9 @@ namespace Firebird this->trace_event_sweep = &Name::clooptrace_event_sweepDispatcher; this->trace_func_execute = &Name::clooptrace_func_executeDispatcher; this->trace_dsql_restart = &Name::clooptrace_dsql_restartDispatcher; + this->trace_proc_compile = &Name::clooptrace_proc_compileDispatcher; + this->trace_func_compile = &Name::clooptrace_func_compileDispatcher; + this->trace_trigger_compile = &Name::clooptrace_trigger_compileDispatcher; } } vTable; @@ -18879,6 +19152,45 @@ namespace Firebird } } + static FB_BOOLEAN CLOOP_CARG clooptrace_proc_compileDispatcher(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceProcedure* procedure, ISC_INT64 time_millis, unsigned proc_result) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::trace_proc_compile(connection, procedure, time_millis, proc_result); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static FB_BOOLEAN CLOOP_CARG clooptrace_func_compileDispatcher(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceFunction* function, ISC_INT64 time_millis, unsigned func_result) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::trace_func_compile(connection, function, time_millis, func_result); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + + static FB_BOOLEAN CLOOP_CARG clooptrace_trigger_compileDispatcher(ITracePlugin* self, ITraceDatabaseConnection* connection, ITraceTrigger* trigger, ISC_INT64 time_millis, unsigned trig_result) CLOOP_NOEXCEPT + { + try + { + return static_cast(self)->Name::trace_trigger_compile(connection, trigger, time_millis, trig_result); + } + catch (...) + { + StatusType::catchException(0); + return static_cast(0); + } + } + static void CLOOP_CARG cloopaddRefDispatcher(IReferenceCounted* self) CLOOP_NOEXCEPT { try @@ -18940,6 +19252,9 @@ namespace Firebird virtual FB_BOOLEAN trace_event_sweep(ITraceDatabaseConnection* connection, ITraceSweepInfo* sweep, unsigned sweep_state) = 0; virtual FB_BOOLEAN trace_func_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceFunction* function, FB_BOOLEAN started, unsigned func_result) = 0; virtual FB_BOOLEAN trace_dsql_restart(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceSQLStatement* statement, unsigned number) = 0; + virtual FB_BOOLEAN trace_proc_compile(ITraceDatabaseConnection* connection, ITraceProcedure* procedure, ISC_INT64 time_millis, unsigned proc_result) = 0; + virtual FB_BOOLEAN trace_func_compile(ITraceDatabaseConnection* connection, ITraceFunction* function, ISC_INT64 time_millis, unsigned func_result) = 0; + virtual FB_BOOLEAN trace_trigger_compile(ITraceDatabaseConnection* connection, ITraceTrigger* trigger, ISC_INT64 time_millis, unsigned trig_result) = 0; }; template diff --git a/src/include/gen/Firebird.pas b/src/include/gen/Firebird.pas index 2b85a1feb0..d50b247f2f 100644 --- a/src/include/gen/Firebird.pas +++ b/src/include/gen/Firebird.pas @@ -618,15 +618,24 @@ type ITraceProcedure_getProcNamePtr = function(this: ITraceProcedure): PAnsiChar; cdecl; ITraceProcedure_getInputsPtr = function(this: ITraceProcedure): ITraceParams; cdecl; ITraceProcedure_getPerfPtr = function(this: ITraceProcedure): PerformanceInfoPtr; cdecl; + ITraceProcedure_getStmtIDPtr = function(this: ITraceProcedure): Int64; cdecl; + ITraceProcedure_getPlanPtr = function(this: ITraceProcedure): PAnsiChar; cdecl; + ITraceProcedure_getExplainedPlanPtr = function(this: ITraceProcedure): PAnsiChar; cdecl; ITraceFunction_getFuncNamePtr = function(this: ITraceFunction): PAnsiChar; cdecl; ITraceFunction_getInputsPtr = function(this: ITraceFunction): ITraceParams; cdecl; ITraceFunction_getResultPtr = function(this: ITraceFunction): ITraceParams; cdecl; ITraceFunction_getPerfPtr = function(this: ITraceFunction): PerformanceInfoPtr; cdecl; + ITraceFunction_getStmtIDPtr = function(this: ITraceFunction): Int64; cdecl; + ITraceFunction_getPlanPtr = function(this: ITraceFunction): PAnsiChar; cdecl; + ITraceFunction_getExplainedPlanPtr = function(this: ITraceFunction): PAnsiChar; cdecl; ITraceTrigger_getTriggerNamePtr = function(this: ITraceTrigger): PAnsiChar; cdecl; ITraceTrigger_getRelationNamePtr = function(this: ITraceTrigger): PAnsiChar; cdecl; ITraceTrigger_getActionPtr = function(this: ITraceTrigger): Integer; cdecl; ITraceTrigger_getWhichPtr = function(this: ITraceTrigger): Integer; cdecl; ITraceTrigger_getPerfPtr = function(this: ITraceTrigger): PerformanceInfoPtr; cdecl; + ITraceTrigger_getStmtIDPtr = function(this: ITraceTrigger): Int64; cdecl; + ITraceTrigger_getPlanPtr = function(this: ITraceTrigger): PAnsiChar; cdecl; + ITraceTrigger_getExplainedPlanPtr = function(this: ITraceTrigger): PAnsiChar; cdecl; ITraceServiceConnection_getServiceIDPtr = function(this: ITraceServiceConnection): Pointer; cdecl; ITraceServiceConnection_getServiceMgrPtr = function(this: ITraceServiceConnection): PAnsiChar; cdecl; ITraceServiceConnection_getServiceNamePtr = function(this: ITraceServiceConnection): PAnsiChar; cdecl; @@ -670,6 +679,9 @@ type ITracePlugin_trace_event_sweepPtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; sweep: ITraceSweepInfo; sweep_state: Cardinal): Boolean; cdecl; ITracePlugin_trace_func_executePtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; transaction: ITraceTransaction; function_: ITraceFunction; started: Boolean; func_result: Cardinal): Boolean; cdecl; ITracePlugin_trace_dsql_restartPtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; transaction: ITraceTransaction; statement: ITraceSQLStatement; number: Cardinal): Boolean; cdecl; + ITracePlugin_trace_proc_compilePtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; procedure_: ITraceProcedure; time_millis: Int64; proc_result: Cardinal): Boolean; cdecl; + ITracePlugin_trace_func_compilePtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; function_: ITraceFunction; time_millis: Int64; func_result: Cardinal): Boolean; cdecl; + ITracePlugin_trace_trigger_compilePtr = function(this: ITracePlugin; connection: ITraceDatabaseConnection; trigger: ITraceTrigger; time_millis: Int64; trig_result: Cardinal): Boolean; cdecl; ITraceFactory_trace_needsPtr = function(this: ITraceFactory): QWord; cdecl; ITraceFactory_trace_createPtr = function(this: ITraceFactory; status: IStatus; init_info: ITraceInitInfo): ITracePlugin; cdecl; IUdrFunctionFactory_setupPtr = procedure(this: IUdrFunctionFactory; status: IStatus; context: IExternalContext; metadata: IRoutineMetadata; inBuilder: IMetadataBuilder; outBuilder: IMetadataBuilder); cdecl; @@ -3144,14 +3156,20 @@ type getProcName: ITraceProcedure_getProcNamePtr; getInputs: ITraceProcedure_getInputsPtr; getPerf: ITraceProcedure_getPerfPtr; + getStmtID: ITraceProcedure_getStmtIDPtr; + getPlan: ITraceProcedure_getPlanPtr; + getExplainedPlan: ITraceProcedure_getExplainedPlanPtr; end; ITraceProcedure = class(IVersioned) - const VERSION = 2; + const VERSION = 3; function getProcName(): PAnsiChar; function getInputs(): ITraceParams; function getPerf(): PerformanceInfoPtr; + function getStmtID(): Int64; + function getPlan(): PAnsiChar; + function getExplainedPlan(): PAnsiChar; end; ITraceProcedureImpl = class(ITraceProcedure) @@ -3160,6 +3178,9 @@ type function getProcName(): PAnsiChar; virtual; abstract; function getInputs(): ITraceParams; virtual; abstract; function getPerf(): PerformanceInfoPtr; virtual; abstract; + function getStmtID(): Int64; virtual; abstract; + function getPlan(): PAnsiChar; virtual; abstract; + function getExplainedPlan(): PAnsiChar; virtual; abstract; end; TraceFunctionVTable = class(VersionedVTable) @@ -3167,15 +3188,21 @@ type getInputs: ITraceFunction_getInputsPtr; getResult: ITraceFunction_getResultPtr; getPerf: ITraceFunction_getPerfPtr; + getStmtID: ITraceFunction_getStmtIDPtr; + getPlan: ITraceFunction_getPlanPtr; + getExplainedPlan: ITraceFunction_getExplainedPlanPtr; end; ITraceFunction = class(IVersioned) - const VERSION = 2; + const VERSION = 3; function getFuncName(): PAnsiChar; function getInputs(): ITraceParams; function getResult(): ITraceParams; function getPerf(): PerformanceInfoPtr; + function getStmtID(): Int64; + function getPlan(): PAnsiChar; + function getExplainedPlan(): PAnsiChar; end; ITraceFunctionImpl = class(ITraceFunction) @@ -3185,6 +3212,9 @@ type function getInputs(): ITraceParams; virtual; abstract; function getResult(): ITraceParams; virtual; abstract; function getPerf(): PerformanceInfoPtr; virtual; abstract; + function getStmtID(): Int64; virtual; abstract; + function getPlan(): PAnsiChar; virtual; abstract; + function getExplainedPlan(): PAnsiChar; virtual; abstract; end; TraceTriggerVTable = class(VersionedVTable) @@ -3193,10 +3223,13 @@ type getAction: ITraceTrigger_getActionPtr; getWhich: ITraceTrigger_getWhichPtr; getPerf: ITraceTrigger_getPerfPtr; + getStmtID: ITraceTrigger_getStmtIDPtr; + getPlan: ITraceTrigger_getPlanPtr; + getExplainedPlan: ITraceTrigger_getExplainedPlanPtr; end; ITraceTrigger = class(IVersioned) - const VERSION = 2; + const VERSION = 3; const TYPE_ALL = Cardinal(0); const TYPE_BEFORE = Cardinal(1); const TYPE_AFTER = Cardinal(2); @@ -3206,6 +3239,9 @@ type function getAction(): Integer; function getWhich(): Integer; function getPerf(): PerformanceInfoPtr; + function getStmtID(): Int64; + function getPlan(): PAnsiChar; + function getExplainedPlan(): PAnsiChar; end; ITraceTriggerImpl = class(ITraceTrigger) @@ -3216,6 +3252,9 @@ type function getAction(): Integer; virtual; abstract; function getWhich(): Integer; virtual; abstract; function getPerf(): PerformanceInfoPtr; virtual; abstract; + function getStmtID(): Int64; virtual; abstract; + function getPlan(): PAnsiChar; virtual; abstract; + function getExplainedPlan(): PAnsiChar; virtual; abstract; end; TraceServiceConnectionVTable = class(TraceConnectionVTable) @@ -3380,10 +3419,13 @@ type trace_event_sweep: ITracePlugin_trace_event_sweepPtr; trace_func_execute: ITracePlugin_trace_func_executePtr; trace_dsql_restart: ITracePlugin_trace_dsql_restartPtr; + trace_proc_compile: ITracePlugin_trace_proc_compilePtr; + trace_func_compile: ITracePlugin_trace_func_compilePtr; + trace_trigger_compile: ITracePlugin_trace_trigger_compilePtr; end; ITracePlugin = class(IReferenceCounted) - const VERSION = 4; + const VERSION = 5; const RESULT_SUCCESS = Cardinal(0); const RESULT_FAILED = Cardinal(1); const RESULT_UNAUTHORIZED = Cardinal(2); @@ -3414,6 +3456,9 @@ type function trace_event_sweep(connection: ITraceDatabaseConnection; sweep: ITraceSweepInfo; sweep_state: Cardinal): Boolean; function trace_func_execute(connection: ITraceDatabaseConnection; transaction: ITraceTransaction; function_: ITraceFunction; started: Boolean; func_result: Cardinal): Boolean; function trace_dsql_restart(connection: ITraceDatabaseConnection; transaction: ITraceTransaction; statement: ITraceSQLStatement; number: Cardinal): Boolean; + function trace_proc_compile(connection: ITraceDatabaseConnection; procedure_: ITraceProcedure; time_millis: Int64; proc_result: Cardinal): Boolean; + function trace_func_compile(connection: ITraceDatabaseConnection; function_: ITraceFunction; time_millis: Int64; func_result: Cardinal): Boolean; + function trace_trigger_compile(connection: ITraceDatabaseConnection; trigger: ITraceTrigger; time_millis: Int64; trig_result: Cardinal): Boolean; end; ITracePluginImpl = class(ITracePlugin) @@ -3443,6 +3488,9 @@ type function trace_event_sweep(connection: ITraceDatabaseConnection; sweep: ITraceSweepInfo; sweep_state: Cardinal): Boolean; virtual; abstract; function trace_func_execute(connection: ITraceDatabaseConnection; transaction: ITraceTransaction; function_: ITraceFunction; started: Boolean; func_result: Cardinal): Boolean; virtual; abstract; function trace_dsql_restart(connection: ITraceDatabaseConnection; transaction: ITraceTransaction; statement: ITraceSQLStatement; number: Cardinal): Boolean; virtual; abstract; + function trace_proc_compile(connection: ITraceDatabaseConnection; procedure_: ITraceProcedure; time_millis: Int64; proc_result: Cardinal): Boolean; virtual; abstract; + function trace_func_compile(connection: ITraceDatabaseConnection; function_: ITraceFunction; time_millis: Int64; func_result: Cardinal): Boolean; virtual; abstract; + function trace_trigger_compile(connection: ITraceDatabaseConnection; trigger: ITraceTrigger; time_millis: Int64; trig_result: Cardinal): Boolean; virtual; abstract; end; TraceFactoryVTable = class(PluginBaseVTable) @@ -3472,7 +3520,10 @@ type const TRACE_EVENT_ERROR = Cardinal(17); const TRACE_EVENT_SWEEP = Cardinal(18); const TRACE_EVENT_FUNC_EXECUTE = Cardinal(19); - const TRACE_EVENT_MAX = Cardinal(20); + const TRACE_EVENT_PROC_COMPILE = Cardinal(20); + const TRACE_EVENT_FUNC_COMPILE = Cardinal(21); + const TRACE_EVENT_TRIGGER_COMPILE = Cardinal(22); + const TRACE_EVENT_MAX = Cardinal(23); function trace_needs(): QWord; function trace_create(status: IStatus; init_info: ITraceInitInfo): ITracePlugin; @@ -8497,6 +8548,36 @@ begin Result := TraceProcedureVTable(vTable).getPerf(Self); end; +function ITraceProcedure.getStmtID(): Int64; +begin + if (vTable.version < 3) then begin + Result := 0; + end + else begin + Result := TraceProcedureVTable(vTable).getStmtID(Self); + end; +end; + +function ITraceProcedure.getPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceProcedureVTable(vTable).getPlan(Self); + end; +end; + +function ITraceProcedure.getExplainedPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceProcedureVTable(vTable).getExplainedPlan(Self); + end; +end; + function ITraceFunction.getFuncName(): PAnsiChar; begin Result := TraceFunctionVTable(vTable).getFuncName(Self); @@ -8517,6 +8598,36 @@ begin Result := TraceFunctionVTable(vTable).getPerf(Self); end; +function ITraceFunction.getStmtID(): Int64; +begin + if (vTable.version < 3) then begin + Result := 0; + end + else begin + Result := TraceFunctionVTable(vTable).getStmtID(Self); + end; +end; + +function ITraceFunction.getPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceFunctionVTable(vTable).getPlan(Self); + end; +end; + +function ITraceFunction.getExplainedPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceFunctionVTable(vTable).getExplainedPlan(Self); + end; +end; + function ITraceTrigger.getTriggerName(): PAnsiChar; begin Result := TraceTriggerVTable(vTable).getTriggerName(Self); @@ -8542,6 +8653,36 @@ begin Result := TraceTriggerVTable(vTable).getPerf(Self); end; +function ITraceTrigger.getStmtID(): Int64; +begin + if (vTable.version < 3) then begin + Result := 0; + end + else begin + Result := TraceTriggerVTable(vTable).getStmtID(Self); + end; +end; + +function ITraceTrigger.getPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceTriggerVTable(vTable).getPlan(Self); + end; +end; + +function ITraceTrigger.getExplainedPlan(): PAnsiChar; +begin + if (vTable.version < 3) then begin + Result := nil; + end + else begin + Result := TraceTriggerVTable(vTable).getExplainedPlan(Self); + end; +end; + function ITraceServiceConnection.getServiceID(): Pointer; begin Result := TraceServiceConnectionVTable(vTable).getServiceID(Self); @@ -8769,6 +8910,36 @@ begin end; end; +function ITracePlugin.trace_proc_compile(connection: ITraceDatabaseConnection; procedure_: ITraceProcedure; time_millis: Int64; proc_result: Cardinal): Boolean; +begin + if (vTable.version < 5) then begin + Result := false; + end + else begin + Result := TracePluginVTable(vTable).trace_proc_compile(Self, connection, procedure_, time_millis, proc_result); + end; +end; + +function ITracePlugin.trace_func_compile(connection: ITraceDatabaseConnection; function_: ITraceFunction; time_millis: Int64; func_result: Cardinal): Boolean; +begin + if (vTable.version < 5) then begin + Result := false; + end + else begin + Result := TracePluginVTable(vTable).trace_func_compile(Self, connection, function_, time_millis, func_result); + end; +end; + +function ITracePlugin.trace_trigger_compile(connection: ITraceDatabaseConnection; trigger: ITraceTrigger; time_millis: Int64; trig_result: Cardinal): Boolean; +begin + if (vTable.version < 5) then begin + Result := false; + end + else begin + Result := TracePluginVTable(vTable).trace_trigger_compile(Self, connection, trigger, time_millis, trig_result); + end; +end; + function ITraceFactory.trace_needs(): QWord; begin Result := TraceFactoryVTable(vTable).trace_needs(Self); @@ -14379,6 +14550,33 @@ begin end end; +function ITraceProcedureImpl_getStmtIDDispatcher(this: ITraceProcedure): Int64; cdecl; +begin + try + Result := ITraceProcedureImpl(this).getStmtID(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceProcedureImpl_getPlanDispatcher(this: ITraceProcedure): PAnsiChar; cdecl; +begin + try + Result := ITraceProcedureImpl(this).getPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceProcedureImpl_getExplainedPlanDispatcher(this: ITraceProcedure): PAnsiChar; cdecl; +begin + try + Result := ITraceProcedureImpl(this).getExplainedPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + var ITraceProcedureImpl_vTable: TraceProcedureVTable; @@ -14423,6 +14621,33 @@ begin end end; +function ITraceFunctionImpl_getStmtIDDispatcher(this: ITraceFunction): Int64; cdecl; +begin + try + Result := ITraceFunctionImpl(this).getStmtID(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceFunctionImpl_getPlanDispatcher(this: ITraceFunction): PAnsiChar; cdecl; +begin + try + Result := ITraceFunctionImpl(this).getPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceFunctionImpl_getExplainedPlanDispatcher(this: ITraceFunction): PAnsiChar; cdecl; +begin + try + Result := ITraceFunctionImpl(this).getExplainedPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + var ITraceFunctionImpl_vTable: TraceFunctionVTable; @@ -14476,6 +14701,33 @@ begin end end; +function ITraceTriggerImpl_getStmtIDDispatcher(this: ITraceTrigger): Int64; cdecl; +begin + try + Result := ITraceTriggerImpl(this).getStmtID(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceTriggerImpl_getPlanDispatcher(this: ITraceTrigger): PAnsiChar; cdecl; +begin + try + Result := ITraceTriggerImpl(this).getPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITraceTriggerImpl_getExplainedPlanDispatcher(this: ITraceTrigger): PAnsiChar; cdecl; +begin + try + Result := ITraceTriggerImpl(this).getExplainedPlan(); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + var ITraceTriggerImpl_vTable: TraceTriggerVTable; @@ -15028,6 +15280,33 @@ begin end end; +function ITracePluginImpl_trace_proc_compileDispatcher(this: ITracePlugin; connection: ITraceDatabaseConnection; procedure_: ITraceProcedure; time_millis: Int64; proc_result: Cardinal): Boolean; cdecl; +begin + try + Result := ITracePluginImpl(this).trace_proc_compile(connection, procedure_, time_millis, proc_result); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITracePluginImpl_trace_func_compileDispatcher(this: ITracePlugin; connection: ITraceDatabaseConnection; function_: ITraceFunction; time_millis: Int64; func_result: Cardinal): Boolean; cdecl; +begin + try + Result := ITracePluginImpl(this).trace_func_compile(connection, function_, time_millis, func_result); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + +function ITracePluginImpl_trace_trigger_compileDispatcher(this: ITracePlugin; connection: ITraceDatabaseConnection; trigger: ITraceTrigger; time_millis: Int64; trig_result: Cardinal): Boolean; cdecl; +begin + try + Result := ITracePluginImpl(this).trace_trigger_compile(connection, trigger, time_millis, trig_result); + except + on e: Exception do FbException.catchException(nil, e); + end +end; + var ITracePluginImpl_vTable: TracePluginVTable; @@ -16713,25 +16992,34 @@ initialization ITraceContextVariableImpl_vTable.getVarValue := @ITraceContextVariableImpl_getVarValueDispatcher; ITraceProcedureImpl_vTable := TraceProcedureVTable.create; - ITraceProcedureImpl_vTable.version := 2; + ITraceProcedureImpl_vTable.version := 3; ITraceProcedureImpl_vTable.getProcName := @ITraceProcedureImpl_getProcNameDispatcher; ITraceProcedureImpl_vTable.getInputs := @ITraceProcedureImpl_getInputsDispatcher; ITraceProcedureImpl_vTable.getPerf := @ITraceProcedureImpl_getPerfDispatcher; + ITraceProcedureImpl_vTable.getStmtID := @ITraceProcedureImpl_getStmtIDDispatcher; + ITraceProcedureImpl_vTable.getPlan := @ITraceProcedureImpl_getPlanDispatcher; + ITraceProcedureImpl_vTable.getExplainedPlan := @ITraceProcedureImpl_getExplainedPlanDispatcher; ITraceFunctionImpl_vTable := TraceFunctionVTable.create; - ITraceFunctionImpl_vTable.version := 2; + ITraceFunctionImpl_vTable.version := 3; ITraceFunctionImpl_vTable.getFuncName := @ITraceFunctionImpl_getFuncNameDispatcher; ITraceFunctionImpl_vTable.getInputs := @ITraceFunctionImpl_getInputsDispatcher; ITraceFunctionImpl_vTable.getResult := @ITraceFunctionImpl_getResultDispatcher; ITraceFunctionImpl_vTable.getPerf := @ITraceFunctionImpl_getPerfDispatcher; + ITraceFunctionImpl_vTable.getStmtID := @ITraceFunctionImpl_getStmtIDDispatcher; + ITraceFunctionImpl_vTable.getPlan := @ITraceFunctionImpl_getPlanDispatcher; + ITraceFunctionImpl_vTable.getExplainedPlan := @ITraceFunctionImpl_getExplainedPlanDispatcher; ITraceTriggerImpl_vTable := TraceTriggerVTable.create; - ITraceTriggerImpl_vTable.version := 2; + ITraceTriggerImpl_vTable.version := 3; ITraceTriggerImpl_vTable.getTriggerName := @ITraceTriggerImpl_getTriggerNameDispatcher; ITraceTriggerImpl_vTable.getRelationName := @ITraceTriggerImpl_getRelationNameDispatcher; ITraceTriggerImpl_vTable.getAction := @ITraceTriggerImpl_getActionDispatcher; ITraceTriggerImpl_vTable.getWhich := @ITraceTriggerImpl_getWhichDispatcher; ITraceTriggerImpl_vTable.getPerf := @ITraceTriggerImpl_getPerfDispatcher; + ITraceTriggerImpl_vTable.getStmtID := @ITraceTriggerImpl_getStmtIDDispatcher; + ITraceTriggerImpl_vTable.getPlan := @ITraceTriggerImpl_getPlanDispatcher; + ITraceTriggerImpl_vTable.getExplainedPlan := @ITraceTriggerImpl_getExplainedPlanDispatcher; ITraceServiceConnectionImpl_vTable := TraceServiceConnectionVTable.create; ITraceServiceConnectionImpl_vTable.version := 3; @@ -16781,7 +17069,7 @@ initialization ITraceInitInfoImpl_vTable.getLogWriter := @ITraceInitInfoImpl_getLogWriterDispatcher; ITracePluginImpl_vTable := TracePluginVTable.create; - ITracePluginImpl_vTable.version := 4; + ITracePluginImpl_vTable.version := 5; ITracePluginImpl_vTable.addRef := @ITracePluginImpl_addRefDispatcher; ITracePluginImpl_vTable.release := @ITracePluginImpl_releaseDispatcher; ITracePluginImpl_vTable.trace_get_error := @ITracePluginImpl_trace_get_errorDispatcher; @@ -16806,6 +17094,9 @@ initialization ITracePluginImpl_vTable.trace_event_sweep := @ITracePluginImpl_trace_event_sweepDispatcher; ITracePluginImpl_vTable.trace_func_execute := @ITracePluginImpl_trace_func_executeDispatcher; ITracePluginImpl_vTable.trace_dsql_restart := @ITracePluginImpl_trace_dsql_restartDispatcher; + ITracePluginImpl_vTable.trace_proc_compile := @ITracePluginImpl_trace_proc_compileDispatcher; + ITracePluginImpl_vTable.trace_func_compile := @ITracePluginImpl_trace_func_compileDispatcher; + ITracePluginImpl_vTable.trace_trigger_compile := @ITracePluginImpl_trace_trigger_compileDispatcher; ITraceFactoryImpl_vTable := TraceFactoryVTable.create; ITraceFactoryImpl_vTable.version := 4; diff --git a/src/jrd/Function.epp b/src/jrd/Function.epp index c58b8db1f2..c9c4e5bca9 100644 --- a/src/jrd/Function.epp +++ b/src/jrd/Function.epp @@ -46,6 +46,7 @@ #include "../jrd/vio_proto.h" #include "../common/utils_proto.h" #include "../jrd/DebugInterface.h" +#include "../jrd/trace/TraceJrdHelpers.h" #include "../jrd/Function.h" @@ -454,16 +455,21 @@ Function* Function::loadMetadata(thread_db* tdbb, USHORT id, bool noscan, USHORT } else if (!X.RDB$FUNCTION_BLR.NULL) { + const string name = function->getName().toString(); + try { + TraceFuncCompile trace(tdbb, name); + function->parseBlr(tdbb, csb, &X.RDB$FUNCTION_BLR, X.RDB$DEBUG_INFO.NULL ? NULL : &X.RDB$DEBUG_INFO); + + trace.finish(function->getStatement(), ITracePlugin::RESULT_SUCCESS); } catch (const Exception& ex) { StaticStatusVector temp_status; ex.stuffException(temp_status); - const string name = function->getName().toString(); (Arg::Gds(isc_bad_fun_BLR) << Arg::Str(name) << Arg::StatusVector(temp_status.begin())).raise(); } diff --git a/src/jrd/exe.cpp b/src/jrd/exe.cpp index 0ca4ef8692..8fa79657cb 100644 --- a/src/jrd/exe.cpp +++ b/src/jrd/exe.cpp @@ -563,9 +563,10 @@ void EXE_execute_ddl_triggers(thread_db* tdbb, jrd_tra* transaction, bool preTri for (const auto& trigger : *attachment->att_ddl_triggers) { - const bool preTrigger = ((trigger.type & 0x1) == 0); + const auto type = trigger.type & ~TRIGGER_TYPE_MASK; + const bool preTrigger = ((type & 1) == 0); - if ((trigger.type & (1LL << action)) && (preTriggers == preTrigger)) + if ((type & (1LL << action)) && (preTriggers == preTrigger)) { triggers.add() = trigger; } @@ -1114,10 +1115,11 @@ static void execute_looper(thread_db* tdbb, void EXE_execute_triggers(thread_db* tdbb, - TrigVector** triggers, - record_param* old_rpb, - record_param* new_rpb, - TriggerAction trigger_action, StmtNode::WhichTrigger which_trig) + TrigVector** triggers, + record_param* old_rpb, + record_param* new_rpb, + TriggerAction trigger_action, + StmtNode::WhichTrigger which_trig) { /************************************** * diff --git a/src/jrd/jrd.cpp b/src/jrd/jrd.cpp index d8506fcaeb..6f53b6dbfc 100644 --- a/src/jrd/jrd.cpp +++ b/src/jrd/jrd.cpp @@ -886,8 +886,10 @@ void Trigger::compile(thread_db* tdbb) { // Allocate statement memory pool MemoryPool* new_pool = att->createPool(); + // Trigger request is not compiled yet. Lets do it now USHORT par_flags = (USHORT) (flags & TRG_ignore_perm) ? csb_ignore_perm : 0; + if (type & 1) par_flags |= csb_pre_trigger; else @@ -904,6 +906,8 @@ void Trigger::compile(thread_db* tdbb) if (engine.isEmpty()) { + TraceTrigCompile trace(tdbb, this); + if (debugInfo.hasData()) { DBG_parse_debug_info((ULONG) debugInfo.getCount(), debugInfo.begin(), @@ -912,6 +916,8 @@ void Trigger::compile(thread_db* tdbb) PAR_blr(tdbb, relation, blr.begin(), (ULONG) blr.getCount(), NULL, &csb, &statement, (relation ? true : false), par_flags); + + trace.finish(statement, ITracePlugin::RESULT_SUCCESS); } else { diff --git a/src/jrd/met.epp b/src/jrd/met.epp index a339a4cc12..63509cfd1c 100644 --- a/src/jrd/met.epp +++ b/src/jrd/met.epp @@ -93,6 +93,7 @@ #include "../common/classes/Hash.h" #include "../common/classes/MsgPrint.h" #include "../jrd/Function.h" +#include "../jrd/trace/TraceJrdHelpers.h" #ifdef HAVE_CTYPE_H @@ -2034,17 +2035,19 @@ void MET_load_trigger(thread_db* tdbb, if (TRG.RDB$RELATION_NAME.NULL) { + fb_assert(!relation); + if ((TRG.RDB$TRIGGER_TYPE & TRIGGER_TYPE_MASK) == TRIGGER_TYPE_DB || (TRG.RDB$TRIGGER_TYPE & TRIGGER_TYPE_MASK) == TRIGGER_TYPE_DDL) { - // this is a database trigger + // this is a database or DDL trigger get_trigger(tdbb, relation, &TRG.RDB$TRIGGER_BLR, &debug_blob_id, triggers, TRG.RDB$TRIGGER_NAME, - TRG.RDB$TRIGGER_TYPE & ~TRIGGER_TYPE_MASK, + TRG.RDB$TRIGGER_TYPE, (bool) TRG.RDB$SYSTEM_FLAG, trig_flags, engine, @@ -3667,16 +3670,21 @@ jrd_prc* MET_procedure(thread_db* tdbb, USHORT id, bool noscan, USHORT flags) } else { + const string name = procedure->getName().toString(); + try { + TraceProcCompile trace(tdbb, name); + procedure->parseBlr(tdbb, csb, &P.RDB$PROCEDURE_BLR, P.RDB$DEBUG_INFO.NULL ? NULL : &P.RDB$DEBUG_INFO); + + trace.finish(procedure->getStatement(), ITracePlugin::RESULT_SUCCESS); } catch (const Exception& ex) { StaticStatusVector temp_status; ex.stuffException(temp_status); - const string name = procedure->getName().toString(); (Arg::Gds(isc_bad_proc_BLR) << Arg::Str(name) << Arg::StatusVector(temp_status.begin())).raise(); } diff --git a/src/jrd/trace/TraceJrdHelpers.h b/src/jrd/trace/TraceJrdHelpers.h index 61a5589fe8..4746299299 100644 --- a/src/jrd/trace/TraceJrdHelpers.h +++ b/src/jrd/trace/TraceJrdHelpers.h @@ -29,6 +29,7 @@ #define JRD_TRACE_JRD_HELPERS_H #include "../../jrd/jrd.h" +#include "../../jrd/trace/TraceManager.h" #include "../../jrd/trace/TraceObjects.h" namespace Jrd { @@ -91,6 +92,54 @@ private: }; +class TraceProcCompile +{ +public: + TraceProcCompile(thread_db* tdbb, const Firebird::string& name) : + m_tdbb(tdbb), m_name(name) + { + const auto attachment = m_tdbb->getAttachment(); + + const auto trace_mgr = attachment->att_trace_manager; + m_need_trace = trace_mgr->needs(ITraceFactory::TRACE_EVENT_PROC_COMPILE); + + if (!m_need_trace) + return; + + m_start_clock = fb_utils::query_performance_counter(); + } + + ~TraceProcCompile() + { + finish(nullptr, ITracePlugin::RESULT_FAILED); + } + + void finish(Statement* statement, ntrace_result_t result) + { + if (!m_need_trace) + return; + + m_need_trace = false; + + const auto time = (fb_utils::query_performance_counter() - m_start_clock) * 1000 / + fb_utils::query_performance_frequency(); + + const auto attachment = m_tdbb->getAttachment(); + + TraceConnectionImpl conn(attachment); + TraceProcedureImpl proc(m_name, statement); + + const auto trace_mgr = attachment->att_trace_manager; + trace_mgr->event_proc_compile(&conn, &proc, time, result); + } + +private: + bool m_need_trace; + thread_db* const m_tdbb; + const Firebird::string m_name; + SINT64 m_start_clock; +}; + class TraceProcExecute { public: @@ -98,8 +147,12 @@ public: m_tdbb(tdbb), m_request(request) { - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + const auto trace_mgr = attachment->att_trace_manager; m_need_trace = trace_mgr->needs(ITraceFactory::TRACE_EVENT_PROC_EXECUTE); + if (!m_need_trace) return; @@ -107,9 +160,9 @@ public: m_request->req_proc_caller = caller; { // scope - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); - TraceProcedureImpl proc(m_request, NULL); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); + TraceProcedureImpl proc(m_request, nullptr); trace_mgr->event_proc_execute(&conn, &tran, &proc, true, ITracePlugin::RESULT_SUCCESS); } @@ -136,26 +189,30 @@ public: return; m_need_trace = false; + if (have_cursor) { m_request->req_fetch_elapsed = fb_utils::query_performance_counter() - m_start_clock; return; } - TraceRuntimeStats stats(m_tdbb->getAttachment(), m_request->req_fetch_baseline, &m_request->req_stats, + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + TraceRuntimeStats stats(attachment, m_request->req_fetch_baseline, &m_request->req_stats, fb_utils::query_performance_counter() - m_start_clock, m_request->req_fetch_rowcount); - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); TraceProcedureImpl proc(m_request, stats.getPerf()); - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; - trace_mgr->event_proc_execute(&conn, &tran, &proc, false, result); + const auto trace_mgr = attachment->att_trace_manager; + trace_mgr->event_proc_execute(&conn, &tran, &proc, false, result); - m_request->req_proc_inputs = NULL; - m_request->req_proc_caller = NULL; - m_request->req_fetch_baseline = NULL; + m_request->req_proc_inputs = nullptr; + m_request->req_proc_caller = nullptr; + m_request->req_fetch_baseline = nullptr; } private: @@ -172,7 +229,9 @@ public: m_tdbb(tdbb), m_request(request) { - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto attachment = m_tdbb->getAttachment(); + const auto trace_mgr = attachment->att_trace_manager; + m_need_trace = (request->req_flags & req_proc_fetch) && trace_mgr->needs(ITraceFactory::TRACE_EVENT_PROC_EXECUTE); @@ -193,6 +252,7 @@ public: return; m_need_trace = false; + m_request->req_fetch_elapsed += fb_utils::query_performance_counter() - m_start_clock; if (!eof) { @@ -200,20 +260,23 @@ public: return; } - TraceRuntimeStats stats(m_tdbb->getAttachment(), m_request->req_fetch_baseline, &m_request->req_stats, + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + TraceRuntimeStats stats(attachment, m_request->req_fetch_baseline, &m_request->req_stats, m_request->req_fetch_elapsed, m_request->req_fetch_rowcount); - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); TraceProcedureImpl proc(m_request, stats.getPerf()); - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto trace_mgr = attachment->att_trace_manager; trace_mgr->event_proc_execute(&conn, &tran, &proc, false, result); - m_request->req_proc_inputs = NULL; - m_request->req_proc_caller = NULL; + m_request->req_proc_inputs = nullptr; + m_request->req_proc_caller = nullptr; m_request->req_fetch_elapsed = 0; - m_request->req_fetch_baseline = NULL; + m_request->req_fetch_baseline = nullptr; } private: @@ -224,6 +287,55 @@ private: }; +class TraceFuncCompile +{ +public: + TraceFuncCompile(thread_db* tdbb, const Firebird::string& name) : + m_tdbb(tdbb), + m_name(name) + { + const auto attachment = m_tdbb->getAttachment(); + + const auto trace_mgr = attachment->att_trace_manager; + m_need_trace = trace_mgr->needs(ITraceFactory::TRACE_EVENT_FUNC_COMPILE); + + if (!m_need_trace) + return; + + m_start_clock = fb_utils::query_performance_counter(); + } + + ~TraceFuncCompile() + { + finish(nullptr, ITracePlugin::RESULT_FAILED); + } + + void finish(Statement* statement, ntrace_result_t result) + { + if (!m_need_trace) + return; + + m_need_trace = false; + + const auto time = (fb_utils::query_performance_counter() - m_start_clock) * 1000 / + fb_utils::query_performance_frequency(); + + const auto attachment = m_tdbb->getAttachment(); + + TraceConnectionImpl conn(attachment); + TraceFunctionImpl func(m_name, statement); + + const auto trace_mgr = attachment->att_trace_manager; + trace_mgr->event_func_compile(&conn, &func, time, result); + } + +private: + bool m_need_trace; + thread_db* const m_tdbb; + const Firebird::string m_name; + SINT64 m_start_clock; +}; + class TraceFuncExecute { public: @@ -234,8 +346,12 @@ public: m_inMsg(inMsg), m_inMsgLength(inMsgLength) { - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + const auto trace_mgr = attachment->att_trace_manager; m_need_trace = trace_mgr->needs(ITraceFactory::TRACE_EVENT_FUNC_EXECUTE); + if (!m_need_trace) return; @@ -243,13 +359,11 @@ public: m_request->req_proc_caller = caller; { // scope - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); - TraceDscFromMsg inputs(*getDefaultMemoryPool(), - m_request->getStatement()->function->getInputFormat(), - m_inMsg, m_inMsgLength); - TraceFunctionImpl func(m_request, inputs, NULL, NULL); + TraceDscFromMsg inputs(request->getStatement()->function->getInputFormat(), m_inMsg, m_inMsgLength); + TraceFunctionImpl func(m_request, nullptr, inputs, nullptr); trace_mgr->event_func_execute(&conn, &tran, &func, true, ITracePlugin::RESULT_SUCCESS); } @@ -259,7 +373,7 @@ public: m_request->req_fetch_elapsed = 0; m_request->req_fetch_rowcount = 0; fb_assert(!m_request->req_fetch_baseline); - m_request->req_fetch_baseline = NULL; + m_request->req_fetch_baseline = nullptr; MemoryPool* pool = m_request->req_pool; m_request->req_fetch_baseline = FB_NEW_POOL(*pool) RuntimeStatistics(*pool, m_request->req_stats); @@ -277,25 +391,25 @@ public: m_need_trace = false; - TraceRuntimeStats stats(m_tdbb->getAttachment(), m_request->req_fetch_baseline, &m_request->req_stats, + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + TraceRuntimeStats stats(attachment, m_request->req_fetch_baseline, &m_request->req_stats, fb_utils::query_performance_counter() - m_start_clock, m_request->req_fetch_rowcount); - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); - TraceDscFromMsg inputs(*getDefaultMemoryPool(), - m_request->getStatement()->function->getInputFormat(), - m_inMsg, m_inMsgLength); + TraceDscFromMsg inputs(m_request->getStatement()->function->getInputFormat(), m_inMsg, m_inMsgLength); + TraceFunctionImpl func(m_request, stats.getPerf(), inputs, value); - TraceFunctionImpl func(m_request, inputs, stats.getPerf(), value); - - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto trace_mgr = attachment->att_trace_manager; trace_mgr->event_func_execute(&conn, &tran, &func, false, result); - m_request->req_proc_inputs = NULL; - m_request->req_proc_caller = NULL; - m_request->req_fetch_baseline = NULL; + m_request->req_proc_inputs = nullptr; + m_request->req_proc_caller = nullptr; + m_request->req_fetch_baseline = nullptr; } private: @@ -308,15 +422,112 @@ private: }; +class TraceTrigCompile +{ +public: + TraceTrigCompile(thread_db* tdbb, const Trigger* trigger) : + m_tdbb(tdbb) + { + const auto attachment = m_tdbb->getAttachment(); + + const auto trace_mgr = attachment->att_trace_manager; + m_need_trace = trace_mgr->needs(ITraceFactory::TRACE_EVENT_TRIGGER_COMPILE); + + if (!m_need_trace) + return; + + m_name = trigger->name.c_str(); + m_relationName = trigger->relation ? trigger->relation->rel_name.c_str() : ""; + + const auto type = (trigger->type & ~TRIGGER_TYPE_MASK); + + switch (trigger->type & TRIGGER_TYPE_MASK) + { + case TRIGGER_TYPE_DML: + { + // TYPE_BEFORE == 1, TYPE_AFTER == 2 + m_which = ((type + 1) & 1) + 1; + m_action = (type + 1) >> 1; + + fb_assert(m_action == TRIGGER_INSERT || + m_action == TRIGGER_UPDATE || + m_action == TRIGGER_DELETE); + } + break; + + case TRIGGER_TYPE_DB: + { + m_action = type + DB_TRIGGER_MAX - 1; + + fb_assert(m_action == TRIGGER_CONNECT || + m_action == TRIGGER_DISCONNECT || + m_action == TRIGGER_TRANS_START || + m_action == TRIGGER_TRANS_COMMIT || + m_action == TRIGGER_TRANS_ROLLBACK); + } + break; + + case TRIGGER_TYPE_DDL: + { + // TYPE_BEFORE == 1, TYPE_AFTER == 2 + m_which = (type & 1) + 1; + m_action = TRIGGER_DDL; + } + break; + + default: + fb_assert(false); + } + + m_start_clock = fb_utils::query_performance_counter(); + } + + ~TraceTrigCompile() + { + finish(nullptr, ITracePlugin::RESULT_FAILED); + } + + void finish(Statement* statement, ntrace_result_t result) + { + if (!m_need_trace) + return; + + m_need_trace = false; + + const auto time = (fb_utils::query_performance_counter() - m_start_clock) * 1000 / + fb_utils::query_performance_frequency(); + + const auto attachment = m_tdbb->getAttachment(); + + TraceConnectionImpl conn(attachment); + TraceTriggerImpl trig(m_name, m_relationName, m_which, m_action, statement); + + const auto trace_mgr = attachment->att_trace_manager; + trace_mgr->event_trigger_compile(&conn, &trig, time, result); + } + +private: + bool m_need_trace; + thread_db* const m_tdbb; + Firebird::string m_name; + Firebird::string m_relationName; + int m_which = 0; + int m_action = 0; + SINT64 m_start_clock; +}; + class TraceTrigExecute { public: - TraceTrigExecute(thread_db* tdbb, Request* trigger, int which_trig) : + TraceTrigExecute(thread_db* tdbb, Request* request, int which) : m_tdbb(tdbb), - m_request(trigger), - m_which_trig(which_trig) + m_request(request), + m_which(which) { - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + const auto trace_mgr = attachment->att_trace_manager; + m_need_trace = !(m_request->getStatement()->flags & Statement::FLAG_SYS_TRIGGER) && trace_mgr->needs(ITraceFactory::TRACE_EVENT_TRIGGER_EXECUTE); @@ -324,15 +535,15 @@ public: return; { // scope - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); - TraceTriggerImpl trig(m_request, m_which_trig, NULL); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); + TraceTriggerImpl trig(m_which, m_request, nullptr); trace_mgr->event_trigger_execute(&conn, &tran, &trig, true, ITracePlugin::RESULT_SUCCESS); } fb_assert(!m_request->req_fetch_baseline); - m_request->req_fetch_baseline = NULL; + m_request->req_fetch_baseline = nullptr; MemoryPool* pool = m_request->req_pool; m_request->req_fetch_baseline = FB_NEW_POOL(*pool) RuntimeStatistics(*pool, m_request->req_stats); @@ -346,17 +557,20 @@ public: m_need_trace = false; - TraceRuntimeStats stats(m_tdbb->getAttachment(), m_request->req_fetch_baseline, &m_request->req_stats, + const auto attachment = m_tdbb->getAttachment(); + const auto transaction = m_tdbb->getTransaction(); + + TraceRuntimeStats stats(attachment, m_request->req_fetch_baseline, &m_request->req_stats, fb_utils::query_performance_counter() - m_start_clock, 0); - TraceConnectionImpl conn(m_tdbb->getAttachment()); - TraceTransactionImpl tran(m_tdbb->getTransaction()); - TraceTriggerImpl trig(m_request, m_which_trig, stats.getPerf()); + TraceConnectionImpl conn(attachment); + TraceTransactionImpl tran(transaction); + TraceTriggerImpl trig(m_which, m_request, stats.getPerf()); - TraceManager* trace_mgr = m_tdbb->getAttachment()->att_trace_manager; + const auto trace_mgr = attachment->att_trace_manager; trace_mgr->event_trigger_execute(&conn, &tran, &trig, false, result); - m_request->req_fetch_baseline = NULL; + m_request->req_fetch_baseline = nullptr; } ~TraceTrigExecute() @@ -369,7 +583,7 @@ private: thread_db* const m_tdbb; Request* const m_request; SINT64 m_start_clock; - const int m_which_trig; + const int m_which; }; diff --git a/src/jrd/trace/TraceManager.cpp b/src/jrd/trace/TraceManager.cpp index 1a72ad3c05..8cf453af16 100644 --- a/src/jrd/trace/TraceManager.cpp +++ b/src/jrd/trace/TraceManager.cpp @@ -408,8 +408,7 @@ bool TraceManager::need_dsql_execute(Attachment* att) } void TraceManager::event_dsql_prepare(Attachment* att, jrd_tra* transaction, - ITraceSQLStatement* statement, - ntrace_counter_t time_millis, ntrace_result_t req_result) + ITraceSQLStatement* statement, ntrace_counter_t time_millis, ntrace_result_t req_result) { TraceConnectionImpl conn(att); TraceTransactionImpl tran(transaction); @@ -464,7 +463,7 @@ void TraceManager::event_dsql_restart(Attachment* att, jrd_tra* transaction, void TraceManager::event_attach(ITraceDatabaseConnection* connection, - bool create_db, ntrace_result_t att_result) + bool create_db, ntrace_result_t att_result) { EXECUTE_HOOKS(trace_attach, (connection, create_db, att_result)); @@ -480,51 +479,72 @@ void TraceManager::event_detach(ITraceDatabaseConnection* connection, bool drop_ } void TraceManager::event_transaction_start(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, unsigned tpb_length, const ntrace_byte_t* tpb, - ntrace_result_t tra_result) + ITraceTransaction* transaction, unsigned tpb_length, const ntrace_byte_t* tpb, + ntrace_result_t tra_result) { EXECUTE_HOOKS(trace_transaction_start, (connection, transaction, tpb_length, tpb, tra_result)); } void TraceManager::event_transaction_end(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, bool commit, bool retain_context, - ntrace_result_t tra_result) + ITraceTransaction* transaction, bool commit, bool retain_context, + ntrace_result_t tra_result) { EXECUTE_HOOKS(trace_transaction_end, (connection, transaction, commit, retain_context, tra_result)); } void TraceManager::event_set_context(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, ITraceContextVariable* variable) + ITraceTransaction* transaction, ITraceContextVariable* variable) { EXECUTE_HOOKS(trace_set_context, (connection, transaction, variable)); } - void TraceManager::event_proc_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceProcedure* procedure, bool started, ntrace_result_t proc_result) +void TraceManager::event_proc_compile(ITraceDatabaseConnection* connection, + ITraceProcedure* procedure, ntrace_counter_t time_millis, ntrace_result_t proc_result) +{ + EXECUTE_HOOKS(trace_proc_compile, + (connection, procedure, time_millis, proc_result)); +} + +void TraceManager::event_proc_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, + ITraceProcedure* procedure, bool started, ntrace_result_t proc_result) { EXECUTE_HOOKS(trace_proc_execute, (connection, transaction, procedure, started, proc_result)); } +void TraceManager::event_func_compile(ITraceDatabaseConnection* connection, + ITraceFunction* function, ntrace_counter_t time_millis, ntrace_result_t func_result) +{ + EXECUTE_HOOKS(trace_func_compile, + (connection, function, time_millis, func_result)); +} + void TraceManager::event_func_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceFunction* function, bool started, ntrace_result_t func_result) + ITraceFunction* function, bool started, ntrace_result_t func_result) { EXECUTE_HOOKS(trace_func_execute, (connection, transaction, function, started, func_result)); } +void TraceManager::event_trigger_compile(ITraceDatabaseConnection* connection, + ITraceTrigger* trigger, ntrace_counter_t time_millis, ntrace_result_t trig_result) +{ + EXECUTE_HOOKS(trace_trigger_compile, + (connection, trigger, time_millis, trig_result)); +} + void TraceManager::event_trigger_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceTrigger* trigger, bool started, ntrace_result_t trig_result) + ITraceTrigger* trigger, bool started, ntrace_result_t trig_result) { EXECUTE_HOOKS(trace_trigger_execute, (connection, transaction, trigger, started, trig_result)); } void TraceManager::event_dsql_prepare(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceSQLStatement* statement, ntrace_counter_t time_millis, ntrace_result_t req_result) + ITraceSQLStatement* statement, ntrace_counter_t time_millis, ntrace_result_t req_result) { EXECUTE_HOOKS(trace_dsql_prepare, (connection, transaction, statement, @@ -532,29 +552,29 @@ void TraceManager::event_dsql_prepare(ITraceDatabaseConnection* connection, ITra } void TraceManager::event_dsql_free(ITraceDatabaseConnection* connection, - ITraceSQLStatement* statement, unsigned short option) + ITraceSQLStatement* statement, unsigned short option) { EXECUTE_HOOKS(trace_dsql_free, (connection, statement, option)); } void TraceManager::event_dsql_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceSQLStatement* statement, bool started, ntrace_result_t req_result) + ITraceSQLStatement* statement, bool started, ntrace_result_t req_result) { EXECUTE_HOOKS(trace_dsql_execute, (connection, transaction, statement, started, req_result)); } void TraceManager::event_dsql_restart(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, - ITraceSQLStatement* statement, unsigned number) + ITraceSQLStatement* statement, unsigned number) { EXECUTE_HOOKS(trace_dsql_restart, (connection, transaction, statement, number)); } void TraceManager::event_blr_compile(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, ITraceBLRStatement* statement, - ntrace_counter_t time_millis, ntrace_result_t req_result) + ITraceTransaction* transaction, ITraceBLRStatement* statement, + ntrace_counter_t time_millis, ntrace_result_t req_result) { EXECUTE_HOOKS(trace_blr_compile, (connection, transaction, statement, @@ -562,16 +582,16 @@ void TraceManager::event_blr_compile(ITraceDatabaseConnection* connection, } void TraceManager::event_blr_execute(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, ITraceBLRStatement* statement, - ntrace_result_t req_result) + ITraceTransaction* transaction, ITraceBLRStatement* statement, + ntrace_result_t req_result) { EXECUTE_HOOKS(trace_blr_execute, (connection, transaction, statement, req_result)); } void TraceManager::event_dyn_execute(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, ITraceDYNRequest* request, - ntrace_counter_t time_millis, ntrace_result_t req_result) + ITraceTransaction* transaction, ITraceDYNRequest* request, + ntrace_counter_t time_millis, ntrace_result_t req_result) { EXECUTE_HOOKS(trace_dyn_execute, (connection, transaction, request, time_millis, @@ -585,17 +605,17 @@ void TraceManager::event_service_attach(ITraceServiceConnection* service, ntrace } void TraceManager::event_service_start(ITraceServiceConnection* service, - unsigned switches_length, const char* switches, - ntrace_result_t start_result) + unsigned switches_length, const char* switches, + ntrace_result_t start_result) { EXECUTE_HOOKS(trace_service_start, (service, switches_length, switches, start_result)); } void TraceManager::event_service_query(ITraceServiceConnection* service, - unsigned send_item_length, const ntrace_byte_t* send_items, - unsigned recv_item_length, const ntrace_byte_t* recv_items, - ntrace_result_t query_result) + unsigned send_item_length, const ntrace_byte_t* send_items, + unsigned recv_item_length, const ntrace_byte_t* recv_items, + ntrace_result_t query_result) { EXECUTE_HOOKS(trace_service_query, (service, send_item_length, send_items, @@ -616,7 +636,7 @@ void TraceManager::event_error(ITraceConnection* connection, ITraceStatusVector* void TraceManager::event_sweep(ITraceDatabaseConnection* connection, ITraceSweepInfo* sweep, - ntrace_process_state_t sweep_state) + ntrace_process_state_t sweep_state) { EXECUTE_HOOKS(trace_event_sweep, (connection, sweep, sweep_state)); diff --git a/src/jrd/trace/TraceManager.h b/src/jrd/trace/TraceManager.h index ebd732c0c6..047663d50e 100644 --- a/src/jrd/trace/TraceManager.h +++ b/src/jrd/trace/TraceManager.h @@ -85,12 +85,21 @@ public: void event_set_context(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceContextVariable* variable); + void event_proc_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceProcedure* procedure, ntrace_counter_t time_millis, ntrace_result_t proc_result); + void event_proc_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceProcedure* procedure, bool started, ntrace_result_t proc_result); + void event_func_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceFunction* function, ntrace_counter_t time_millis, ntrace_result_t func_result); + void event_func_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceFunction* function, bool started, ntrace_result_t func_result); + void event_trigger_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTrigger* trigger, ntrace_counter_t time_millis, ntrace_result_t trig_result); + void event_trigger_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceTrigger* trigger, bool started, ntrace_result_t trig_result); diff --git a/src/jrd/trace/TraceObjects.cpp b/src/jrd/trace/TraceObjects.cpp index 93863a9acb..69526224e9 100644 --- a/src/jrd/trace/TraceObjects.cpp +++ b/src/jrd/trace/TraceObjects.cpp @@ -58,6 +58,18 @@ using namespace Firebird; namespace Jrd { +const char* StatementHolder::ensurePlan(bool explained) +{ + if (m_statement && (m_plan.isEmpty() || m_planExplained != explained)) + { + m_planExplained = explained; + m_plan = Optimizer::getPlan(JRD_get_thread_data(), m_statement, explained); + } + + return m_plan.c_str(); +} + + /// TraceConnectionImpl unsigned TraceConnectionImpl::getKind() @@ -194,28 +206,6 @@ const char* TraceSQLStatementImpl::getTextUTF8() return m_textUTF8.c_str(); } -const char* TraceSQLStatementImpl::getPlan() -{ - fillPlan(false); - return m_plan.c_str(); -} - -const char* TraceSQLStatementImpl::getExplainedPlan() -{ - fillPlan(true); - return m_plan.c_str(); -} - -void TraceSQLStatementImpl::fillPlan(bool explained) -{ - if (m_plan.isEmpty() || m_planExplained != explained) - { - m_planExplained = explained; - if (m_stmt->getStatement()) - m_plan = Optimizer::getPlan(JRD_get_thread_data(), m_stmt->getStatement(), m_planExplained); - } -} - PerformanceInfo* TraceSQLStatementImpl::getPerf() { return m_perf; @@ -400,7 +390,7 @@ const char* TraceParamsImpl::getTextUTF8(CheckStatusWrapper* status, FB_SIZE_T i void TraceDscFromValues::fillParams() { - if (m_descs.getCount() || !m_params) + if (m_descs.getCount() || !m_request || !m_params) return; thread_db* tdbb = JRD_get_thread_data(); @@ -485,23 +475,6 @@ void TraceDscFromMsg::fillParams() } -/// TraceTriggerImpl - -const char* TraceTriggerImpl::getTriggerName() -{ - return m_trig->getStatement()->triggerName.c_str(); -} - -const char* TraceTriggerImpl::getRelationName() -{ - if (m_trig->req_rpb.getCount() == 0) - return NULL; - - const jrd_rel* rel = m_trig->req_rpb[0].rpb_relation; - return rel ? rel->rel_name.c_str() : NULL; -} - - /// TraceLogWriterImpl class TraceLogWriterImpl final : diff --git a/src/jrd/trace/TraceObjects.h b/src/jrd/trace/TraceObjects.h index ed661a8a76..5eb9165b6d 100644 --- a/src/jrd/trace/TraceObjects.h +++ b/src/jrd/trace/TraceObjects.h @@ -53,6 +53,49 @@ class Database; class Attachment; class jrd_tra; + +class StatementHolder +{ +public: + explicit StatementHolder(const Statement* statement) + : m_statement(statement) + {} + + explicit StatementHolder(const Request* request) + : m_statement(request ? request->getStatement() : nullptr) + {} + + SINT64 getId() const + { + return m_statement ? m_statement->getStatementId() : 0; + } + + Firebird::string getName() const + { + if (m_statement) + { + if (m_statement->procedure) + return m_statement->procedure->getName().toString(); + + if (m_statement->function) + return m_statement->function->getName().toString(); + + if (m_statement->triggerName.hasData()) + return m_statement->triggerName.c_str(); + } + + return ""; + } + + const char* ensurePlan(bool explained); + +private: + const Statement* const m_statement; + Firebird::string m_plan; + bool m_planExplained = false; +}; + + class TraceConnectionImpl : public Firebird::AutoIface > { @@ -174,14 +217,15 @@ public: class TraceSQLStatementImpl : - public Firebird::AutoIface > + public Firebird::AutoIface >, + public StatementHolder { public: TraceSQLStatementImpl(DsqlRequest* stmt, Firebird::PerformanceInfo* perf) : + StatementHolder(stmt ? stmt->getStatement() : nullptr), m_stmt(stmt), m_perf(perf), - m_planExplained(false), - m_inputs(*getDefaultMemoryPool(), m_stmt) + m_inputs(stmt) {} // TraceSQLStatement implementation @@ -189,22 +233,27 @@ public: Firebird::PerformanceInfo* getPerf(); Firebird::ITraceParams* getInputs(); const char* getText(); - const char* getPlan(); const char* getTextUTF8(); - const char* getExplainedPlan(); + + const char* getPlan() + { + return ensurePlan(false); + } + + const char* getExplainedPlan() + { + return ensurePlan(true); + } private: class DSQLParamsImpl : public Firebird::AutoIface > { public: - DSQLParamsImpl(Firebird::MemoryPool& pool, DsqlRequest* const stmt) : - m_stmt(stmt), - m_params(NULL), - m_descs(pool) + explicit DSQLParamsImpl(DsqlRequest* const stmt) : + m_stmt(stmt) { - const dsql_msg* msg = m_stmt->getDsqlStatement()->getSendMsg(); - if (msg) + if (const auto msg = m_stmt->getDsqlStatement()->getSendMsg()) m_params = &msg->msg_parameters; } @@ -216,17 +265,15 @@ private: void fillParams(); DsqlRequest* const m_stmt; - const Firebird::Array* m_params; + const Firebird::Array* m_params = nullptr; Firebird::HalfStaticArray m_descs; Firebird::string temp_utf8_text; }; - void fillPlan(bool explained); - DsqlRequest* const m_stmt; Firebird::PerformanceInfo* const m_perf; Firebird::string m_plan; - bool m_planExplained; + bool m_planExplained = false; DSQLParamsImpl m_inputs; Firebird::string m_textUTF8; }; @@ -302,8 +349,7 @@ private: class TraceDescriptors { public: - explicit TraceDescriptors(Firebird::MemoryPool& pool) : - m_descs(pool), + TraceDescriptors() : m_traceParams(this) { } @@ -342,8 +388,7 @@ private: class TraceDscFromValues : public TraceDescriptors { public: - TraceDscFromValues(Firebird::MemoryPool& pool, Request* request, const ValueListNode* params) : - TraceDescriptors(pool), + TraceDscFromValues(Request* request, const ValueListNode* params) : m_request(request), m_params(params) {} @@ -352,17 +397,15 @@ protected: void fillParams(); private: - Request* m_request; - const ValueListNode* m_params; + Request* const m_request; + const ValueListNode* const m_params; }; class TraceDscFromMsg : public TraceDescriptors { public: - TraceDscFromMsg(Firebird::MemoryPool& pool, const Format* format, - const UCHAR* inMsg, ULONG inMsgLength) : - TraceDescriptors(pool), + TraceDscFromMsg(const Format* format, const UCHAR* inMsg, ULONG inMsgLength) : m_format(format), m_inMsg(inMsg), m_inMsgLength(inMsgLength) @@ -372,17 +415,16 @@ protected: void fillParams(); private: - const Format* m_format; - const UCHAR* m_inMsg; - ULONG m_inMsgLength; + const Format* const m_format; + const UCHAR* const m_inMsg; + const ULONG m_inMsgLength; }; class TraceDscFromDsc : public TraceDescriptors { public: - TraceDscFromDsc(Firebird::MemoryPool& pool, const dsc* desc) : - TraceDescriptors(pool) + TraceDscFromDsc(const dsc* desc) { if (desc) m_descs.add(*desc); @@ -399,15 +441,24 @@ protected: class TraceProcedureImpl : - public Firebird::AutoIface > + public Firebird::AutoIface >, + public StatementHolder { public: + TraceProcedureImpl(const Firebird::string& name, const Statement* statement) : + StatementHolder(statement), + m_name(name), + m_request(nullptr), + m_perf(nullptr), + m_inputs(nullptr, nullptr) + {} + TraceProcedureImpl(Request* request, Firebird::PerformanceInfo* perf) : + StatementHolder(request), + m_name(getName()), m_request(request), m_perf(perf), - m_inputs(*getDefaultMemoryPool(), request->req_proc_caller, request->req_proc_inputs), - m_name(m_request->getStatement()->procedure->getName().toString()) - + m_inputs(request->req_proc_caller, request->req_proc_inputs) {} // TraceProcedure implementation @@ -416,27 +467,61 @@ public: return m_name.c_str(); } - Firebird::ITraceParams* getInputs() { return m_inputs; } - Firebird::PerformanceInfo* getPerf() { return m_perf; }; + Firebird::ITraceParams* getInputs() + { + return m_inputs; + } + + Firebird::PerformanceInfo* getPerf() + { + return m_perf; + }; + + ISC_INT64 getStmtID() + { + return getId(); + } + + const char* getPlan() + { + return ensurePlan(false); + } + + const char* getExplainedPlan() + { + return ensurePlan(true); + } private: + const Firebird::string m_name; Request* const m_request; Firebird::PerformanceInfo* const m_perf; TraceDscFromValues m_inputs; - Firebird::string m_name; }; class TraceFunctionImpl : - public Firebird::AutoIface > + public Firebird::AutoIface >, + public StatementHolder { public: - TraceFunctionImpl(Request* request, Firebird::ITraceParams* inputs, Firebird::PerformanceInfo* perf, const dsc* value) : + TraceFunctionImpl(const Firebird::string& name, const Statement* statement) : + StatementHolder(statement), + m_name(name), + m_request(nullptr), + m_perf(nullptr), + m_inputs(nullptr), + m_value(nullptr) + {} + + TraceFunctionImpl(Request* request, Firebird::PerformanceInfo* perf, + Firebird::ITraceParams* inputs, const dsc* value) : + StatementHolder(request), + m_name(getName()), m_request(request), m_perf(perf), m_inputs(inputs), - m_value(*getDefaultMemoryPool(), value), - m_name(m_request->getStatement()->function->getName().toString()) + m_value(value) {} // TraceFunction implementation @@ -445,39 +530,119 @@ public: return m_name.c_str(); } - Firebird::ITraceParams* getInputs() { return m_inputs; } - Firebird::ITraceParams* getResult() { return m_value; } - Firebird::PerformanceInfo* getPerf() { return m_perf; }; + Firebird::ITraceParams* getInputs() + { + return m_inputs; + } + + Firebird::ITraceParams* getResult() + { + return m_value; + } + + Firebird::PerformanceInfo* getPerf() + { + return m_perf; + }; + + ISC_INT64 getStmtID() + { + return getId(); + } + + const char* getPlan() + { + return ensurePlan(false); + } + + const char* getExplainedPlan() + { + return ensurePlan(true); + } private: + Firebird::string m_name; Request* const m_request; Firebird::PerformanceInfo* const m_perf; - Firebird::ITraceParams* m_inputs; + Firebird::ITraceParams* const m_inputs; TraceDscFromDsc m_value; - Firebird::string m_name; }; class TraceTriggerImpl : - public Firebird::AutoIface > + public Firebird::AutoIface >, + public StatementHolder { public: - TraceTriggerImpl(const Request* trig, SSHORT which, Firebird::PerformanceInfo* perf) : - m_trig(trig), - m_which(which), - m_perf(perf) + TraceTriggerImpl(const Firebird::string& name, const Firebird::string& relationName, + int which, int action, const Statement* statement) : + StatementHolder(statement), + m_name(name), + m_relationName(relationName), + m_which(which), + m_action(action), + m_request(nullptr), + m_perf(nullptr) + {} + + TraceTriggerImpl(int which, const Request* request, Firebird::PerformanceInfo* perf) : + StatementHolder(request), + m_name(getName()), + m_relationName((request->req_rpb.hasData() && request->req_rpb[0].rpb_relation) ? + request->req_rpb[0].rpb_relation->rel_name : ""), + m_which(which), + m_action(request->req_trigger_action), + m_request(request), + m_perf(perf) {} // TraceTrigger implementation - const char* getTriggerName(); - const char* getRelationName(); - int getAction() { return m_trig->req_trigger_action; } - int getWhich() { return m_which; } - Firebird::PerformanceInfo* getPerf() { return m_perf; } + const char* getTriggerName() + { + return m_name.nullStr(); + } + + const char* getRelationName() + { + return m_relationName.nullStr(); + } + + int getWhich() + { + return m_which; + } + + int getAction() + { + return m_action; + } + + Firebird::PerformanceInfo* getPerf() + { + return m_perf; + } + + ISC_INT64 getStmtID() + { + return getId(); + } + + const char* getPlan() + { + return ensurePlan(false); + } + + const char* getExplainedPlan() + { + return ensurePlan(true); + } private: - const Request* const m_trig; - const SSHORT m_which; + const Firebird::string m_name; + const Firebird::string m_relationName; + const int m_which; + const int m_action; + const Request* const m_request; Firebird::PerformanceInfo* const m_perf; }; diff --git a/src/utilities/ntrace/TracePluginImpl.cpp b/src/utilities/ntrace/TracePluginImpl.cpp index 7cf2fb5936..e6448e7f99 100644 --- a/src/utilities/ntrace/TracePluginImpl.cpp +++ b/src/utilities/ntrace/TracePluginImpl.cpp @@ -98,6 +98,7 @@ TracePluginImpl::TracePluginImpl(IPluginBase* plugin, transactions(getDefaultMemoryPool()), statements(getDefaultMemoryPool()), services(getDefaultMemoryPool()), + routines(*getDefaultMemoryPool()), include_codes(*getDefaultMemoryPool()), exclude_codes(*getDefaultMemoryPool()) { @@ -215,6 +216,45 @@ TracePluginImpl::~TracePluginImpl() } } +bool TracePluginImpl::checkRoutine(StmtNumber stmt_id) +{ + { // scope + ReadLockGuard lock(routinesLock, FB_FUNCTION); + + if (routines.exist(stmt_id)) + return true; + } + + WriteLockGuard lock(routinesLock, FB_FUNCTION); + + if (!routines.exist(stmt_id)) + routines.add(stmt_id); + + return false; +} + +template +string TracePluginImpl::getPlan(C* routine) +{ + const char* access_path = config.print_plan ? + (config.explain_plan ? routine->getExplainedPlan() : routine->getPlan()) + : NULL; + + if (access_path && *access_path) + { + const size_t access_path_length = strlen(access_path); + + string temp; + temp.printf(NEWLINE + "^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^" + "%.*s" NEWLINE, access_path_length, access_path); + + return temp; + } + + return NEWLINE; +} + void TracePluginImpl::logRecord(const char* action) { // We use atomic file appends for logging. Do not try to break logging @@ -329,11 +369,16 @@ void TracePluginImpl::logRecordTrans(const char* action, ITraceDatabaseConnectio logRecordConn(action, connection); } -void TracePluginImpl::logRecordProcFunc(const char* action, ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, const char* obj_type, const char* obj_name) +void TracePluginImpl::logRecordProc(const char* action, ITraceDatabaseConnection* connection, + ITraceTransaction* transaction, ITraceProcedure* procedure) { + const StmtNumber stmt_id = procedure->getStmtID(); + string temp; - temp.printf(NEWLINE "%s %s:" NEWLINE, obj_type, obj_name); + temp.printf(NEWLINE "%s %s:", "Procedure", procedure->getProcName()); + + temp += (stmt_id && !checkRoutine(stmt_id)) ? getPlan(procedure) : NEWLINE; + record.insert(0, temp); if (!transaction) { @@ -344,6 +389,110 @@ void TracePluginImpl::logRecordProcFunc(const char* action, ITraceDatabaseConnec } } +void TracePluginImpl::logRecordFunc(const char* action, ITraceDatabaseConnection* connection, + ITraceTransaction* transaction, ITraceFunction* function) +{ + const StmtNumber stmt_id = function->getStmtID(); + + string temp; + temp.printf(NEWLINE "%s %s:", "Function", function->getFuncName()); + + temp += (stmt_id && !checkRoutine(stmt_id)) ? getPlan(function) : NEWLINE; + + record.insert(0, temp); + + if (!transaction) { + logRecordConn(action, connection); + } + else { + logRecordTrans(action, connection, transaction); + } +} + +void TracePluginImpl::logRecordTrig(const char* action, ITraceDatabaseConnection* connection, + ITraceTransaction* transaction, ITraceTrigger* trigger) +{ + const StmtNumber stmt_id = trigger->getStmtID(); + + string name = "Trigger"; + + if (trigger->getTriggerName()) + { + string trgname; + trgname.printf(" %s", trigger->getTriggerName()); + name += trgname; + } + + if ((trigger->getWhich() != ITraceTrigger::TYPE_ALL) && trigger->getRelationName()) + { + string relation; + relation.printf(" FOR %s", trigger->getRelationName()); + name += relation; + } + + string extras; + switch (trigger->getWhich()) + { + case ITraceTrigger::TYPE_ALL: + extras = "ON "; //// TODO: Why ALL means ON (DATABASE) triggers? + break; + case ITraceTrigger::TYPE_BEFORE: + extras = "BEFORE "; + break; + case ITraceTrigger::TYPE_AFTER: + extras = "AFTER "; + break; + default: + extras = " "; + break; + } + + switch (trigger->getAction()) + { + case TRIGGER_INSERT: + extras += "INSERT"; + break; + case TRIGGER_UPDATE: + extras += "UPDATE"; + break; + case TRIGGER_DELETE: + extras += "DELETE"; + break; + case TRIGGER_CONNECT: + extras += "CONNECT"; + break; + case TRIGGER_DISCONNECT: + extras += "DISCONNECT"; + break; + case TRIGGER_TRANS_START: + extras += "TRANSACTION_START"; + break; + case TRIGGER_TRANS_COMMIT: + extras += "TRANSACTION_COMMIT"; + break; + case TRIGGER_TRANS_ROLLBACK: + extras + "TRANSACTION_ROLLBACK"; + break; + case TRIGGER_DDL: + extras += "DDL"; + break; + default: + extras += "Unknown trigger action"; + break; + } + + record.printf(NEWLINE "%s (%s):", name.c_str(), extras.c_str()); + + record += (stmt_id && !checkRoutine(stmt_id)) ? getPlan(trigger) : NEWLINE; + + if (!transaction) { + logRecordConn(action, connection); + } + else { + logRecordTrans(action, connection, transaction); + } +} + void TracePluginImpl::logRecordStmt(const char* action, ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceStatement* statement, bool isSQL) { @@ -1402,6 +1551,29 @@ void TracePluginImpl::log_event_set_context(ITraceDatabaseConnection* connection } } +void TracePluginImpl::log_event_proc_compile(ITraceDatabaseConnection* connection, + ITraceProcedure* procedure, ntrace_counter_t time_millis, ntrace_result_t proc_result) +{ + if (config.log_procedure_compile) + { + const char* event_type; + switch (proc_result) + { + case ITracePlugin::RESULT_SUCCESS: + event_type = "COMPILE_PROCEDURE"; + break; + case ITracePlugin::RESULT_FAILED: + event_type = "FAILED COMPILE_PROCEDURE"; + break; + default: + event_type = "Unknown event in COMPILE_PROCEDURE"; + break; + } + record.printf("%7d ms" NEWLINE, time_millis); + logRecordProc(event_type, connection, nullptr, procedure); + } +} + void TracePluginImpl::log_event_proc_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceProcedure* procedure, bool started, ntrace_result_t proc_result) @@ -1420,6 +1592,7 @@ void TracePluginImpl::log_event_proc_execute(ITraceDatabaseConnection* connectio ITraceParams* params = procedure->getInputs(); if (params && params->getCount()) { + record.append(NEWLINE); appendParams(params); record.append(NEWLINE); } @@ -1456,7 +1629,30 @@ void TracePluginImpl::log_event_proc_execute(ITraceDatabaseConnection* connectio break; } - logRecordProcFunc(event_type, connection, transaction, "Procedure", procedure->getProcName()); + logRecordProc(event_type, connection, transaction, procedure); +} + +void TracePluginImpl::log_event_func_compile(ITraceDatabaseConnection* connection, + ITraceFunction* function, ntrace_counter_t time_millis, ntrace_result_t func_result) +{ + if (config.log_function_compile) + { + const char* event_type; + switch (func_result) + { + case ITracePlugin::RESULT_SUCCESS: + event_type = "COMPILE_FUNCTION"; + break; + case ITracePlugin::RESULT_FAILED: + event_type = "FAILED COMPILE_FUNCTION"; + break; + default: + event_type = "Unknown event in COMPILE_FUNCTION"; + break; + } + record.printf("%7d ms" NEWLINE, time_millis); + logRecordFunc(event_type, connection, nullptr, function); + } } void TracePluginImpl::log_event_func_execute(ITraceDatabaseConnection* connection, @@ -1477,6 +1673,7 @@ void TracePluginImpl::log_event_func_execute(ITraceDatabaseConnection* connectio ITraceParams* params = function->getInputs(); if (params && params->getCount()) { + record.append(NEWLINE); appendParams(params); record.append(NEWLINE); } @@ -1523,7 +1720,73 @@ void TracePluginImpl::log_event_func_execute(ITraceDatabaseConnection* connectio break; } - logRecordProcFunc(event_type, connection, transaction, "Function", function->getFuncName()); + logRecordFunc(event_type, connection, transaction, function); +} + +void TracePluginImpl::log_event_trigger_compile(ITraceDatabaseConnection* connection, + ITraceTrigger* trigger, ntrace_counter_t time_millis, ntrace_result_t trig_result) +{ + if (config.log_trigger_compile) + { + const char* event_type; + switch (trig_result) + { + case ITracePlugin::RESULT_SUCCESS: + event_type = "COMPILE_TRIGGER"; + break; + case ITracePlugin::RESULT_FAILED: + event_type = "FAILED COMPILE_TRIGGER"; + break; + default: + event_type = "Unknown event in COMPILE_TRIGGER"; + break; + } + record.printf("%7d ms" NEWLINE, time_millis); + logRecordTrig(event_type, connection, nullptr, trigger); + } +} + +void TracePluginImpl::log_event_trigger_execute(ITraceDatabaseConnection* connection, + ITraceTransaction* transaction, ITraceTrigger* trigger, bool started, ntrace_result_t trig_result) +{ + if (!config.log_trigger_start && started) + return; + + if (!config.log_trigger_finish && !started) + return; + + // Do not log operation if it is below time threshold + const PerformanceInfo* info = started ? NULL : trigger->getPerf(); + if (config.time_threshold && info && info->pin_time < config.time_threshold) + return; + + if (info) + { + appendGlobalCounts(info); + appendTableCounts(info); + } + + const char* event_type; + switch (trig_result) + { + case ITracePlugin::RESULT_SUCCESS: + event_type = started ? "EXECUTE_TRIGGER_START" : + "EXECUTE_TRIGGER_FINISH"; + break; + case ITracePlugin::RESULT_FAILED: + event_type = started ? "FAILED EXECUTE_TRIGGER_START" : + "FAILED EXECUTE_TRIGGER_FINISH"; + break; + case ITracePlugin::RESULT_UNAUTHORIZED: + event_type = started ? "UNAUTHORIZED EXECUTE_TRIGGER_START" : + "UNAUTHORIZED EXECUTE_TRIGGER_FINISH"; + break; + default: + event_type = "Unknown event at executing trigger"; + break; + } + + logRecordTrig(event_type, connection, transaction, trigger); } void TracePluginImpl::register_sql_statement(ITraceSQLStatement* statement) @@ -1572,23 +1835,7 @@ void TracePluginImpl::register_sql_statement(ITraceSQLStatement* statement) } *stmt_data.description += temp; - const char* access_path = config.print_plan ? - (config.explain_plan ? statement->getExplainedPlan() : statement->getPlan()) - : NULL; - - if (access_path && *access_path) - { - const size_t access_path_length = strlen(access_path); - temp.printf(NEWLINE - "^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^" - "%.*s" NEWLINE, access_path_length, access_path); - - *stmt_data.description += temp; - } - else - { - *stmt_data.description += NEWLINE; - } + *stmt_data.description += getPlan(statement); } else { @@ -2127,114 +2374,6 @@ void TracePluginImpl::log_event_service_detach(ITraceServiceConnection* service, } } -void TracePluginImpl::log_event_trigger_execute(ITraceDatabaseConnection* connection, - ITraceTransaction* transaction, ITraceTrigger* trigger, bool started, ntrace_result_t trig_result) -{ - if (!config.log_trigger_start && started) - return; - - if (!config.log_trigger_finish && !started) - return; - - // Do not log operation if it is below time threshold - const PerformanceInfo* info = started ? NULL : trigger->getPerf(); - if (config.time_threshold && info && info->pin_time < config.time_threshold) - return; - - string trgname(trigger->getTriggerName()); - - if (trgname.empty()) - trgname = ""; - - if ((trigger->getWhich() != ITraceTrigger::TYPE_ALL) && trigger->getRelationName()) - { - string relation; - relation.printf(" FOR %s", trigger->getRelationName()); - trgname.append(relation); - } - - string action; - switch (trigger->getWhich()) - { - case ITraceTrigger::TYPE_ALL: - action = "ON "; //// TODO: Why ALL means ON (DATABASE) triggers? - break; - case ITraceTrigger::TYPE_BEFORE: - action = "BEFORE "; - break; - case ITraceTrigger::TYPE_AFTER: - action = "AFTER "; - break; - default: - action = " "; - break; - } - - switch (trigger->getAction()) - { - case TRIGGER_INSERT: - action.append("INSERT"); - break; - case TRIGGER_UPDATE: - action.append("UPDATE"); - break; - case TRIGGER_DELETE: - action.append("DELETE"); - break; - case TRIGGER_CONNECT: - action.append("CONNECT"); - break; - case TRIGGER_DISCONNECT: - action.append("DISCONNECT"); - break; - case TRIGGER_TRANS_START: - action.append("TRANSACTION_START"); - break; - case TRIGGER_TRANS_COMMIT: - action.append("TRANSACTION_COMMIT"); - break; - case TRIGGER_TRANS_ROLLBACK: - action.append("TRANSACTION_ROLLBACK"); - break; - case TRIGGER_DDL: - action.append("DDL"); - break; - default: - action.append("Unknown trigger action"); - break; - } - - record.printf("\t%s (%s) " NEWLINE, trgname.c_str(), action.c_str()); - - if (info) - { - appendGlobalCounts(info); - appendTableCounts(info); - } - - const char* event_type; - switch (trig_result) - { - case ITracePlugin::RESULT_SUCCESS: - event_type = started ? "EXECUTE_TRIGGER_START" : - "EXECUTE_TRIGGER_FINISH"; - break; - case ITracePlugin::RESULT_FAILED: - event_type = started ? "FAILED EXECUTE_TRIGGER_START" : - "FAILED EXECUTE_TRIGGER_FINISH"; - break; - case ITracePlugin::RESULT_UNAUTHORIZED: - event_type = started ? "UNAUTHORIZED EXECUTE_TRIGGER_START" : - "UNAUTHORIZED EXECUTE_TRIGGER_FINISH"; - break; - default: - event_type = "Unknown event at executing trigger"; - break; - } - - logRecordTrans(event_type, connection, transaction); -} - void TracePluginImpl::log_event_error(ITraceConnection* connection, ITraceStatusVector* status, const char* function) { @@ -2411,6 +2550,22 @@ FB_BOOLEAN TracePluginImpl::trace_set_context(ITraceDatabaseConnection* connecti } } +// Stored procedure compiling +FB_BOOLEAN TracePluginImpl::trace_proc_compile(ITraceDatabaseConnection* connection, + ITraceProcedure* procedure, ISC_INT64 time_millis, ntrace_result_t proc_result) +{ + try + { + log_event_proc_compile(connection, procedure, time_millis, proc_result); + return true; + } + catch (const Firebird::Exception& ex) + { + marshal_exception(ex); + return false; + } +} + // Stored procedure executing FB_BOOLEAN TracePluginImpl::trace_proc_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceProcedure* procedure, @@ -2428,6 +2583,22 @@ FB_BOOLEAN TracePluginImpl::trace_proc_execute(ITraceDatabaseConnection* connect } } +// Stored function compiling +FB_BOOLEAN TracePluginImpl::trace_func_compile(ITraceDatabaseConnection* connection, + ITraceFunction* function, ISC_INT64 time_millis, ntrace_result_t func_result) +{ + try + { + log_event_func_compile(connection, function, time_millis, func_result); + return true; + } + catch (const Firebird::Exception& ex) + { + marshal_exception(ex); + return false; + } +} + // Stored function executing FB_BOOLEAN TracePluginImpl::trace_func_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceFunction* function, @@ -2445,6 +2616,23 @@ FB_BOOLEAN TracePluginImpl::trace_func_execute(ITraceDatabaseConnection* connect } } +// Stored trigger compiling +FB_BOOLEAN TracePluginImpl::trace_trigger_compile(ITraceDatabaseConnection* connection, + ITraceTrigger* trigger, ISC_INT64 time_millis, ntrace_result_t trig_result) +{ + try + { + log_event_trigger_compile(connection, trigger, time_millis, trig_result); + return true; + } + catch (const Firebird::Exception& ex) + { + marshal_exception(ex); + return false; + } +} + +// Stored trigger executing FB_BOOLEAN TracePluginImpl::trace_trigger_execute(ITraceDatabaseConnection* connection, ITraceTransaction* transaction, ITraceTrigger* trigger, FB_BOOLEAN started, ntrace_result_t trig_result) diff --git a/src/utilities/ntrace/TracePluginImpl.h b/src/utilities/ntrace/TracePluginImpl.h index a5e125f379..11c3af0e08 100644 --- a/src/utilities/ntrace/TracePluginImpl.h +++ b/src/utilities/ntrace/TracePluginImpl.h @@ -130,6 +130,14 @@ public: typedef Firebird::BePlusTree ServicesTree; + template + struct RoutineHelper + { + C* const routine; + }; + + typedef Firebird::SortedArray RoutinesList; + TracePluginImpl(Firebird::IPluginBase* factory, const TracePluginConfig& configuration, Firebird::ITraceInitInfo* initInfo); private: @@ -161,6 +169,9 @@ private: Firebird::RWLock servicesLock; ServicesTree services; + Firebird::RWLock routinesLock; + RoutinesList routines; + // Lock for log rotation Firebird::RWLock renameLock; @@ -187,15 +198,26 @@ private: void register_blr_statement(Firebird::ITraceBLRStatement* statement); void register_service(Firebird::ITraceServiceConnection* service); + void register_procedure(Firebird::ITraceProcedure* procedure); + void register_function(Firebird::ITraceFunction* function); + void register_trigger(Firebird::ITraceTrigger* trigger); + bool checkServiceFilter(Firebird::ITraceServiceConnection* service, bool started); + bool checkRoutine(StmtNumber stmt_id); + template Firebird::string getPlan(C* routine); + // Write message to text log file void logRecord(const char* action); void logRecordConn(const char* action, Firebird::ITraceDatabaseConnection* connection); void logRecordTrans(const char* action, Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction); - void logRecordProcFunc(const char* action, Firebird::ITraceDatabaseConnection* connection, - Firebird::ITraceTransaction* transaction, const char* obj_type, const char* obj_name); + void logRecordProc(const char* action, Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTransaction* transaction, Firebird::ITraceProcedure* procedure); + void logRecordFunc(const char* action, Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTransaction* transaction, Firebird::ITraceFunction* function); + void logRecordTrig(const char* action, Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTransaction* transaction, Firebird::ITraceTrigger* trigger); void logRecordStmt(const char* action, Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceStatement* statement, bool isSQL); @@ -223,14 +245,23 @@ private: Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceContextVariable* variable); + void log_event_proc_compile( + Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceProcedure* procedure, ntrace_counter_t time_millis, unsigned proc_result); void log_event_proc_execute( Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceProcedure* procedure, bool started, unsigned proc_result); + void log_event_func_compile( + Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceFunction* function, ntrace_counter_t time_millis, unsigned func_result); void log_event_func_execute( Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceFunction* function, bool started, unsigned func_result); + void log_event_trigger_compile( + Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTrigger* trigger, ntrace_counter_t time_millis, unsigned trig_result); void log_event_trigger_execute( Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceTrigger* trigger, bool started, unsigned trig_result); @@ -283,14 +314,19 @@ public: FB_BOOLEAN trace_transaction_end(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, FB_BOOLEAN commit, FB_BOOLEAN retain_context, unsigned tra_result); - // Stored procedures, functions and triggers execution - FB_BOOLEAN trace_proc_execute (Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, + // Stored procedures, functions and triggers compilation and execution + FB_BOOLEAN trace_proc_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceProcedure* procedure, ISC_INT64 time_millis, unsigned proc_result); + FB_BOOLEAN trace_proc_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceProcedure* procedure, FB_BOOLEAN started, unsigned proc_result); - FB_BOOLEAN trace_func_execute (Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, + FB_BOOLEAN trace_func_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceFunction* function, ISC_INT64 time_millis, unsigned func_result); + FB_BOOLEAN trace_func_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, Firebird::ITraceFunction* function, FB_BOOLEAN started, unsigned func_result); + FB_BOOLEAN trace_trigger_compile(Firebird::ITraceDatabaseConnection* connection, + Firebird::ITraceTrigger* trigger, ISC_INT64 time_millis, unsigned trig_result); FB_BOOLEAN trace_trigger_execute(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, - Firebird::ITraceTrigger* trigger, - FB_BOOLEAN started, unsigned trig_result); + Firebird::ITraceTrigger* trigger, FB_BOOLEAN started, unsigned trig_result); // Assignment to context variables FB_BOOLEAN trace_set_context(Firebird::ITraceDatabaseConnection* connection, Firebird::ITraceTransaction* transaction, diff --git a/src/utilities/ntrace/fbtrace.conf b/src/utilities/ntrace/fbtrace.conf index 67b59db482..00a5ea66d7 100644 --- a/src/utilities/ntrace/fbtrace.conf +++ b/src/utilities/ntrace/fbtrace.conf @@ -76,18 +76,27 @@ database #log_statement_finish = false + # Put record when stored procedure is being compiled + #log_procedure_compile = false + # Put record when stored procedure is start execution #log_procedure_start = false # Put record when stored procedure is finish execution #log_procedure_finish = false + # Put record when stored function is being compiled + #log_function_compile = false + # Put record when stored function is start execution #log_function_start = false # Put record when stored function is finish execution #log_function_finish = false + # Put record when trigger is being compiled + #log_trigger_compile = false + # Put trigger execute records #log_trigger_start = false diff --git a/src/utilities/ntrace/paramtable.h b/src/utilities/ntrace/paramtable.h index 5c8a67e975..29e4d84fe7 100644 --- a/src/utilities/ntrace/paramtable.h +++ b/src/utilities/ntrace/paramtable.h @@ -51,10 +51,13 @@ BOOL_PARAMETER(log_statement_prepare, false) BOOL_PARAMETER(log_statement_free, false) BOOL_PARAMETER(log_statement_start, false) BOOL_PARAMETER(log_statement_finish, false) +BOOL_PARAMETER(log_procedure_compile, false) BOOL_PARAMETER(log_procedure_start, false) BOOL_PARAMETER(log_procedure_finish, false) +BOOL_PARAMETER(log_function_compile, false) BOOL_PARAMETER(log_function_start, false) BOOL_PARAMETER(log_function_finish, false) +BOOL_PARAMETER(log_trigger_compile, false) BOOL_PARAMETER(log_trigger_start, false) BOOL_PARAMETER(log_trigger_finish, false) BOOL_PARAMETER(print_plan, false)