firebird/firebird-mirror
firebird/firebird-mirror
8
0
Fork 1
mirror of https://github.com/FirebirdSQL/firebird.git synced 2025-01-22 18:03:03 +01:00
Code Issues

Design for future extensions with different timings types.

Browse Source 
Add ProfilerStats interface and pass it to plugin instead of runTime parameter.

Rename *_TIME columns to *_ELAPSED_TIME.
This commit is contained in:
Adriano dos Santos Fernandes 2022-06-22 22:25:47 -03:00
parent fb9f5c6dcc
commit 2f2f5fec30
9 changed files with 369 additions and 213 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

60
doc/sql.extensions/README.profiler.md
View File

@ -266,7 +266,7 @@ Below is the list of tables that stores profile data.
- `CALLER_REQUEST_ID` type `BIGINT` - Caller request ID
- `START_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment this request was first gathered profile data
- `FINISH_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment this request was finished
- `TOTAL_TIME` type `BIGINT` - Accumulated execution time (in nanoseconds) of the request
- `TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the request
- Primary key: `PROFILE_ID, REQUEST_ID`
## Table `PLG$PROF_PSQL_STATS`
@ -277,9 +277,9 @@ Below is the list of tables that stores profile data.
- `COLUMN_NUM` type `INTEGER` - Column number of the statement
- `STATEMENT_ID` type `BIGINT` - Statement ID
- `COUNTER` type `BIGINT` - Number of executed times of the line/column
- `MIN_TIME` type `BIGINT` - Minimal time (in nanoseconds) of a line/column execution
- `MAX_TIME` type `BIGINT` - Maximum time (in nanoseconds) of a line/column execution
- `TOTAL_TIME` type `BIGINT` - Accumulated execution time (in nanoseconds) of the line/column
- `MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a line/column execution
- `MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a line/column execution
- `TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the line/column executions
- Primary key: `PROFILE_ID, REQUEST_ID, LINE_NUM, COLUMN_NUM`
## Table `PLG$PROF_RECORD_SOURCE_STATS`
@ -290,13 +290,13 @@ Below is the list of tables that stores profile data.
- `RECORD_SOURCE_ID` type `BIGINT` - Record source ID
- `STATEMENT_ID` type `BIGINT` - Statement ID
- `OPEN_COUNTER` type `BIGINT` - Number of open times of the record source
- `OPEN_MIN_TIME` type `BIGINT` - Minimal time (in nanoseconds) of a record source open
- `OPEN_MAX_TIME` type `BIGINT` - Maximum time (in nanoseconds) of a record source open
- `OPEN_TOTAL_TIME` type `BIGINT` - Accumulated open time (in nanoseconds) of the record source
- `OPEN_MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a record source open
- `OPEN_MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a record source open
- `OPEN_TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the record source openings
- `FETCH_COUNTER` type `BIGINT` - Number of fetch times of the record source
- `FETCH_MIN_TIME` type `BIGINT` - Minimal time (in nanoseconds) of a record source fetch
- `FETCH_MAX_TIME` type `BIGINT` - Maximum time (in nanoseconds) of a record source fetch
- `FETCH_TOTAL_TIME` type `BIGINT` - Accumulated fetch time (in nanoseconds) of the record source
- `FETCH_MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a record source fetch
- `FETCH_MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a record source fetch
- `FETCH_TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the record source fetches
- Primary key: `PROFILE_ID, REQUEST_ID, CURSOR_ID, RECORD_SOURCE_ID`
# Auxiliary views
@ -323,10 +323,10 @@ select req.profile_id,
statement_id = coalesce(sta.parent_statement_id, req.statement_id)
) sql_text,
count(*) counter,
min(req.total_time) min_time,
max(req.total_time) max_time,
cast(sum(req.total_time) as bigint) total_time,
cast(sum(req.total_time) / count(*) as bigint) avg_time
min(req.total_elapsed_time) min_elapsed_time,
max(req.total_elapsed_time) max_elapsed_time,
cast(sum(req.total_elapsed_time) as bigint) total_elapsed_time,
cast(sum(req.total_elapsed_time) / count(*) as bigint) avg_elapsed_time
from plg$prof_requests req
join plg$prof_statements sta
on sta.profile_id = req.profile_id and
@ -342,7 +342,7 @@ select req.profile_id,
sta.parent_statement_id,
sta_parent.statement_type,
sta_parent.routine_name
order by sum(req.total_time) desc
order by sum(req.total_elapsed_time) desc
```
## View `PLG$PROF_PSQL_STATS_VIEW`
@ -363,10 +363,10 @@ select pstat.profile_id,
pstat.line_num,
pstat.column_num,
cast(sum(pstat.counter) as bigint) counter,
min(pstat.min_time) min_time,
max(pstat.max_time) max_time,
cast(sum(pstat.total_time) as bigint) total_time,
cast(sum(pstat.total_time) / nullif(sum(pstat.counter), 0) as bigint) avg_time
min(pstat.min_elapsed_time) min_elapsed_time,
max(pstat.max_elapsed_time) max_elapsed_time,
cast(sum(pstat.total_elapsed_time) as bigint) total_elapsed_time,
cast(sum(pstat.total_elapsed_time) / nullif(sum(pstat.counter), 0) as bigint) avg_elapsed_time
from plg$prof_psql_stats pstat
join plg$prof_statements sta
on sta.profile_id = pstat.profile_id and
@ -384,7 +384,7 @@ select pstat.profile_id,
sta_parent.routine_name,
pstat.line_num,
pstat.column_num
order by sum(pstat.total_time) desc
order by sum(pstat.total_elapsed_time) desc
```
## View `PLG$PROF_RECORD_SOURCE_STATS_VIEW`
@ -407,16 +407,16 @@ select rstat.profile_id,
recsrc.parent_record_source_id,
recsrc.access_path,
cast(sum(rstat.open_counter) as bigint) open_counter,
min(rstat.open_min_time) open_min_time,
max(rstat.open_max_time) open_max_time,
cast(sum(rstat.open_total_time) as bigint) open_total_time,
cast(sum(rstat.open_total_time) / nullif(sum(rstat.open_counter), 0) as bigint) open_avg_time,
min(rstat.open_min_elapsed_time) open_min_elapsed_time,
max(rstat.open_max_elapsed_time) open_max_elapsed_time,
cast(sum(rstat.open_total_elapsed_time) as bigint) open_total_elapsed_time,
cast(sum(rstat.open_total_elapsed_time) / nullif(sum(rstat.open_counter), 0) as bigint) open_avg_elapsed_time,
cast(sum(rstat.fetch_counter) as bigint) fetch_counter,
min(rstat.fetch_min_time) fetch_min_time,
max(rstat.fetch_max_time) fetch_max_time,
cast(sum(rstat.fetch_total_time) as bigint) fetch_total_time,
cast(sum(rstat.fetch_total_time) / nullif(sum(rstat.fetch_counter), 0) as bigint) fetch_avg_time,
cast(coalesce(sum(rstat.open_total_time), 0) + coalesce(sum(rstat.fetch_total_time), 0) as bigint) open_fetch_total_time
min(rstat.fetch_min_elapsed_time) fetch_min_elapsed_time,
max(rstat.fetch_max_elapsed_time) fetch_max_elapsed_time,
cast(sum(rstat.fetch_total_elapsed_time) as bigint) fetch_total_elapsed_time,
cast(sum(rstat.fetch_total_elapsed_time) / nullif(sum(rstat.fetch_counter), 0) as bigint) fetch_avg_elapsed_time,
cast(coalesce(sum(rstat.open_total_elapsed_time), 0) + coalesce(sum(rstat.fetch_total_elapsed_time), 0) as bigint) open_fetch_total_elapsed_time
from plg$prof_record_source_stats rstat
join plg$prof_record_sources recsrc
on recsrc.profile_id = rstat.profile_id and
@ -441,5 +441,5 @@ select rstat.profile_id,
rstat.record_source_id,
recsrc.parent_record_source_id,
recsrc.access_path
order by coalesce(sum(rstat.open_total_time), 0) + coalesce(sum(rstat.fetch_total_time), 0) desc
order by coalesce(sum(rstat.open_total_elapsed_time), 0) + coalesce(sum(rstat.fetch_total_elapsed_time), 0) desc
```

15
src/include/firebird/FirebirdInterface.idl
View File

@ -1721,8 +1721,6 @@ interface ProfilerSession : Disposable
void finish(Status status, ISC_TIMESTAMP_TZ timestamp);
//// FIXME: Add memory stats
void defineStatement(Status status, int64 statementId, int64 parentStatementId,
const string type, const string packageName, const string routineName, const string sqlText);
@ -1734,14 +1732,19 @@ interface ProfilerSession : Disposable
void onRequestStart(Status status, int64 requestId, int64 statementId, int64 callerRequestId,
ISC_TIMESTAMP_TZ timestamp);
void onRequestFinish(Status status, int64 requestId, ISC_TIMESTAMP_TZ timestamp, uint64 runTime);
void onRequestFinish(Status status, int64 requestId, ISC_TIMESTAMP_TZ timestamp, ProfilerStats stats);
void beforePsqlLineColumn(int64 requestId, uint line, uint column);
void afterPsqlLineColumn(int64 requestId, uint line, uint column, uint64 runTime);
void afterPsqlLineColumn(int64 requestId, uint line, uint column, ProfilerStats stats);
void beforeRecordSourceOpen(int64 requestId, uint cursorId, uint recSourceId);
void afterRecordSourceOpen(int64 requestId, uint cursorId, uint recSourceId, uint64 runTime);
void afterRecordSourceOpen(int64 requestId, uint cursorId, uint recSourceId, ProfilerStats stats);
void beforeRecordSourceGetRecord(int64 requestId, uint cursorId, uint recSourceId);
void afterRecordSourceGetRecord(int64 requestId, uint cursorId, uint recSourceId, uint64 runTime);
void afterRecordSourceGetRecord(int64 requestId, uint cursorId, uint recSourceId, ProfilerStats stats);
}
interface ProfilerStats : Versioned
{
uint64 getElapsedTime();
}

127
src/include/firebird/IdlFbInterfaces.h
View File

@ -123,6 +123,7 @@ namespace Firebird
class IReplicatedSession;
class IProfilerPlugin;
class IProfilerSession;
class IProfilerStats;
// Interfaces declarations
@ -6701,13 +6702,13 @@ namespace Firebird
void (CLOOP_CARG *defineStatement)(IProfilerSession* self, IStatus* status, ISC_INT64 statementId, ISC_INT64 parentStatementId, const char* type, const char* packageName, const char* routineName, const char* sqlText) throw();
void (CLOOP_CARG *defineRecordSource)(IProfilerSession* self, ISC_INT64 statementId, unsigned cursorId, unsigned recSourceId, const char* accessPath, unsigned parentRecSourceId) throw();
void (CLOOP_CARG *onRequestStart)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_INT64 statementId, ISC_INT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp) throw();
void (CLOOP_CARG *onRequestFinish)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) throw();
void (CLOOP_CARG *onRequestFinish)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats) throw();
void (CLOOP_CARG *beforePsqlLineColumn)(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column) throw();
void (CLOOP_CARG *afterPsqlLineColumn)(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime) throw();
void (CLOOP_CARG *afterPsqlLineColumn)(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column, IProfilerStats* stats) throw();
void (CLOOP_CARG *beforeRecordSourceOpen)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) throw();
void (CLOOP_CARG *afterRecordSourceOpen)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) throw();
void (CLOOP_CARG *afterRecordSourceOpen)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) throw();
void (CLOOP_CARG *beforeRecordSourceGetRecord)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) throw();
void (CLOOP_CARG *afterRecordSourceGetRecord)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) throw();
void (CLOOP_CARG *afterRecordSourceGetRecord)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) throw();
};
protected:
@ -6771,10 +6772,10 @@ namespace Firebird
StatusType::checkException(status);
}
template <typename StatusType> void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime)
template <typename StatusType> void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats)
{
StatusType::clearException(status);
static_cast<VTable*>(this->cloopVTable)->onRequestFinish(this, status, requestId, timestamp, runTime);
static_cast<VTable*>(this->cloopVTable)->onRequestFinish(this, status, requestId, timestamp, stats);
StatusType::checkException(status);
}
@ -6783,9 +6784,9 @@ namespace Firebird
static_cast<VTable*>(this->cloopVTable)->beforePsqlLineColumn(this, requestId, line, column);
}
void afterPsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime)
void afterPsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column, IProfilerStats* stats)
{
static_cast<VTable*>(this->cloopVTable)->afterPsqlLineColumn(this, requestId, line, column, runTime);
static_cast<VTable*>(this->cloopVTable)->afterPsqlLineColumn(this, requestId, line, column, stats);
}
void beforeRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId)
@ -6793,9 +6794,9 @@ namespace Firebird
static_cast<VTable*>(this->cloopVTable)->beforeRecordSourceOpen(this, requestId, cursorId, recSourceId);
}
void afterRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime)
void afterRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats)
{
static_cast<VTable*>(this->cloopVTable)->afterRecordSourceOpen(this, requestId, cursorId, recSourceId, runTime);
static_cast<VTable*>(this->cloopVTable)->afterRecordSourceOpen(this, requestId, cursorId, recSourceId, stats);
}
void beforeRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId)
@ -6803,9 +6804,37 @@ namespace Firebird
static_cast<VTable*>(this->cloopVTable)->beforeRecordSourceGetRecord(this, requestId, cursorId, recSourceId);
}
void afterRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime)
void afterRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats)
{
static_cast<VTable*>(this->cloopVTable)->afterRecordSourceGetRecord(this, requestId, cursorId, recSourceId, runTime);
static_cast<VTable*>(this->cloopVTable)->afterRecordSourceGetRecord(this, requestId, cursorId, recSourceId, stats);
}
};
class IProfilerStats : public IVersioned
{
public:
struct VTable : public IVersioned::VTable
{
ISC_UINT64 (CLOOP_CARG *getElapsedTime)(IProfilerStats* self) throw();
};
protected:
IProfilerStats(DoNotInherit)
: IVersioned(DoNotInherit())
{
}
~IProfilerStats()
{
}
public:
static const unsigned VERSION = 2;
ISC_UINT64 getElapsedTime()
{
ISC_UINT64 ret = static_cast<VTable*>(this->cloopVTable)->getElapsedTime(this);
return ret;
}
};
@ -20204,13 +20233,13 @@ namespace Firebird
}
}
static void CLOOP_CARG clooponRequestFinishDispatcher(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) throw()
static void CLOOP_CARG clooponRequestFinishDispatcher(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats) throw()
{
StatusType status2(status);
try
{
static_cast<Name*>(self)->Name::onRequestFinish(&status2, requestId, timestamp, runTime);
static_cast<Name*>(self)->Name::onRequestFinish(&status2, requestId, timestamp, stats);
}
catch (...)
{
@ -20230,11 +20259,11 @@ namespace Firebird
}
}
static void CLOOP_CARG cloopafterPsqlLineColumnDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime) throw()
static void CLOOP_CARG cloopafterPsqlLineColumnDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column, IProfilerStats* stats) throw()
{
try
{
static_cast<Name*>(self)->Name::afterPsqlLineColumn(requestId, line, column, runTime);
static_cast<Name*>(self)->Name::afterPsqlLineColumn(requestId, line, column, stats);
}
catch (...)
{
@ -20254,11 +20283,11 @@ namespace Firebird
}
}
static void CLOOP_CARG cloopafterRecordSourceOpenDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) throw()
static void CLOOP_CARG cloopafterRecordSourceOpenDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) throw()
{
try
{
static_cast<Name*>(self)->Name::afterRecordSourceOpen(requestId, cursorId, recSourceId, runTime);
static_cast<Name*>(self)->Name::afterRecordSourceOpen(requestId, cursorId, recSourceId, stats);
}
catch (...)
{
@ -20278,11 +20307,11 @@ namespace Firebird
}
}
static void CLOOP_CARG cloopafterRecordSourceGetRecordDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) throw()
static void CLOOP_CARG cloopafterRecordSourceGetRecordDispatcher(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) throw()
{
try
{
static_cast<Name*>(self)->Name::afterRecordSourceGetRecord(requestId, cursorId, recSourceId, runTime);
static_cast<Name*>(self)->Name::afterRecordSourceGetRecord(requestId, cursorId, recSourceId, stats);
}
catch (...)
{
@ -20323,13 +20352,63 @@ namespace Firebird
virtual void defineStatement(StatusType* status, ISC_INT64 statementId, ISC_INT64 parentStatementId, const char* type, const char* packageName, const char* routineName, const char* sqlText) = 0;
virtual void defineRecordSource(ISC_INT64 statementId, unsigned cursorId, unsigned recSourceId, const char* accessPath, unsigned parentRecSourceId) = 0;
virtual void onRequestStart(StatusType* status, ISC_INT64 requestId, ISC_INT64 statementId, ISC_INT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp) = 0;
virtual void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) = 0;
virtual void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats) = 0;
virtual void beforePsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column) = 0;
virtual void afterPsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime) = 0;
virtual void afterPsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column, IProfilerStats* stats) = 0;
virtual void beforeRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) = 0;
virtual void afterRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) = 0;
virtual void afterRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) = 0;
virtual void beforeRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) = 0;
virtual void afterRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 runTime) = 0;
virtual void afterRecordSourceGetRecord(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) = 0;
};
template <typename Name, typename StatusType, typename Base>
class IProfilerStatsBaseImpl : public Base
{
public:
typedef IProfilerStats Declaration;
IProfilerStatsBaseImpl(DoNotInherit = DoNotInherit())
{
static struct VTableImpl : Base::VTable
{
VTableImpl()
{
this->version = Base::VERSION;
this->getElapsedTime = &Name::cloopgetElapsedTimeDispatcher;
}
} vTable;
this->cloopVTable = &vTable;
}
static ISC_UINT64 CLOOP_CARG cloopgetElapsedTimeDispatcher(IProfilerStats* self) throw()
{
try
{
return static_cast<Name*>(self)->Name::getElapsedTime();
}
catch (...)
{
StatusType::catchException(0);
return static_cast<ISC_UINT64>(0);
}
}
};
template <typename Name, typename StatusType, typename Base = IVersionedImpl<Name, StatusType, Inherit<IProfilerStats> > >
class IProfilerStatsImpl : public IProfilerStatsBaseImpl<Name, StatusType, Base>
{
protected:
IProfilerStatsImpl(DoNotInherit = DoNotInherit())
{
}
public:
virtual ~IProfilerStatsImpl()
{
}
virtual ISC_UINT64 getElapsedTime() = 0;
};
};

101
src/include/gen/Firebird.pas
View File

@ -113,6 +113,7 @@ type
IReplicatedSession = class;
IProfilerPlugin = class;
IProfilerSession = class;
IProfilerStats = class;
FbException = class(Exception)
public
@ -724,13 +725,14 @@ type
IProfilerSession_defineStatementPtr = procedure(this: IProfilerSession; status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); cdecl;
IProfilerSession_defineRecordSourcePtr = procedure(this: IProfilerSession; statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal); cdecl;
IProfilerSession_onRequestStartPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ); cdecl;
IProfilerSession_onRequestFinishPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); cdecl;
IProfilerSession_onRequestFinishPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; stats: IProfilerStats); cdecl;
IProfilerSession_beforePsqlLineColumnPtr = procedure(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal); cdecl;
IProfilerSession_afterPsqlLineColumnPtr = procedure(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord); cdecl;
IProfilerSession_afterPsqlLineColumnPtr = procedure(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal; stats: IProfilerStats); cdecl;
IProfilerSession_beforeRecordSourceOpenPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); cdecl;
IProfilerSession_afterRecordSourceOpenPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); cdecl;
IProfilerSession_afterRecordSourceOpenPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); cdecl;
IProfilerSession_beforeRecordSourceGetRecordPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); cdecl;
IProfilerSession_afterRecordSourceGetRecordPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); cdecl;
IProfilerSession_afterRecordSourceGetRecordPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); cdecl;
IProfilerStats_getElapsedTimePtr = function(this: IProfilerStats): QWord; cdecl;
VersionedVTable = class
version: NativeInt;
@ -3821,13 +3823,13 @@ type
procedure defineStatement(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar);
procedure defineRecordSource(statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal);
procedure onRequestStart(status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ);
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord);
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; stats: IProfilerStats);
procedure beforePsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal);
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord);
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; stats: IProfilerStats);
procedure beforeRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
procedure afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord);
procedure afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats);
procedure beforeRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
procedure afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord);
procedure afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats);
end;
IProfilerSessionImpl = class(IProfilerSession)
@ -3841,13 +3843,29 @@ type
procedure defineStatement(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); virtual; abstract;
procedure defineRecordSource(statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal); virtual; abstract;
procedure onRequestStart(status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ); virtual; abstract;
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); virtual; abstract;
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; stats: IProfilerStats); virtual; abstract;
procedure beforePsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal); virtual; abstract;
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord); virtual; abstract;
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; stats: IProfilerStats); virtual; abstract;
procedure beforeRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); virtual; abstract;
procedure afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); virtual; abstract;
procedure afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); virtual; abstract;
procedure beforeRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); virtual; abstract;
procedure afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); virtual; abstract;
procedure afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); virtual; abstract;
end;
ProfilerStatsVTable = class(VersionedVTable)
getElapsedTime: IProfilerStats_getElapsedTimePtr;
end;
IProfilerStats = class(IVersioned)
const VERSION = 2;
function getElapsedTime(): QWord;
end;
IProfilerStatsImpl = class(IProfilerStats)
constructor create;
function getElapsedTime(): QWord; virtual; abstract;
end;
function fb_get_master_interface : IMaster; cdecl; external 'fbclient';
@ -9002,9 +9020,9 @@ begin
FbException.checkException(status);
end;
procedure IProfilerSession.onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord);
procedure IProfilerSession.onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; stats: IProfilerStats);
begin
ProfilerSessionVTable(vTable).onRequestFinish(Self, status, requestId, timestamp, runTime);
ProfilerSessionVTable(vTable).onRequestFinish(Self, status, requestId, timestamp, stats);
FbException.checkException(status);
end;
@ -9013,9 +9031,9 @@ begin
ProfilerSessionVTable(vTable).beforePsqlLineColumn(Self, requestId, line, column);
end;
procedure IProfilerSession.afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord);
procedure IProfilerSession.afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; stats: IProfilerStats);
begin
ProfilerSessionVTable(vTable).afterPsqlLineColumn(Self, requestId, line, column, runTime);
ProfilerSessionVTable(vTable).afterPsqlLineColumn(Self, requestId, line, column, stats);
end;
procedure IProfilerSession.beforeRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
@ -9023,9 +9041,9 @@ begin
ProfilerSessionVTable(vTable).beforeRecordSourceOpen(Self, requestId, cursorId, recSourceId);
end;
procedure IProfilerSession.afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord);
procedure IProfilerSession.afterRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats);
begin
ProfilerSessionVTable(vTable).afterRecordSourceOpen(Self, requestId, cursorId, recSourceId, runTime);
ProfilerSessionVTable(vTable).afterRecordSourceOpen(Self, requestId, cursorId, recSourceId, stats);
end;
procedure IProfilerSession.beforeRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
@ -9033,9 +9051,14 @@ begin
ProfilerSessionVTable(vTable).beforeRecordSourceGetRecord(Self, requestId, cursorId, recSourceId);
end;
procedure IProfilerSession.afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord);
procedure IProfilerSession.afterRecordSourceGetRecord(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats);
begin
ProfilerSessionVTable(vTable).afterRecordSourceGetRecord(Self, requestId, cursorId, recSourceId, runTime);
ProfilerSessionVTable(vTable).afterRecordSourceGetRecord(Self, requestId, cursorId, recSourceId, stats);
end;
function IProfilerStats.getElapsedTime(): QWord;
begin
Result := ProfilerStatsVTable(vTable).getElapsedTime(Self);
end;
var
@ -15683,10 +15706,10 @@ begin
end
end;
procedure IProfilerSessionImpl_onRequestFinishDispatcher(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); cdecl;
procedure IProfilerSessionImpl_onRequestFinishDispatcher(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; stats: IProfilerStats); cdecl;
begin
try
IProfilerSessionImpl(this).onRequestFinish(status, requestId, timestamp, runTime);
IProfilerSessionImpl(this).onRequestFinish(status, requestId, timestamp, stats);
except
on e: Exception do FbException.catchException(status, e);
end
@ -15701,10 +15724,10 @@ begin
end
end;
procedure IProfilerSessionImpl_afterPsqlLineColumnDispatcher(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord); cdecl;
procedure IProfilerSessionImpl_afterPsqlLineColumnDispatcher(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal; stats: IProfilerStats); cdecl;
begin
try
IProfilerSessionImpl(this).afterPsqlLineColumn(requestId, line, column, runTime);
IProfilerSessionImpl(this).afterPsqlLineColumn(requestId, line, column, stats);
except
on e: Exception do FbException.catchException(nil, e);
end
@ -15719,10 +15742,10 @@ begin
end
end;
procedure IProfilerSessionImpl_afterRecordSourceOpenDispatcher(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); cdecl;
procedure IProfilerSessionImpl_afterRecordSourceOpenDispatcher(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); cdecl;
begin
try
IProfilerSessionImpl(this).afterRecordSourceOpen(requestId, cursorId, recSourceId, runTime);
IProfilerSessionImpl(this).afterRecordSourceOpen(requestId, cursorId, recSourceId, stats);
except
on e: Exception do FbException.catchException(nil, e);
end
@ -15737,10 +15760,10 @@ begin
end
end;
procedure IProfilerSessionImpl_afterRecordSourceGetRecordDispatcher(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; runTime: QWord); cdecl;
procedure IProfilerSessionImpl_afterRecordSourceGetRecordDispatcher(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); cdecl;
begin
try
IProfilerSessionImpl(this).afterRecordSourceGetRecord(requestId, cursorId, recSourceId, runTime);
IProfilerSessionImpl(this).afterRecordSourceGetRecord(requestId, cursorId, recSourceId, stats);
except
on e: Exception do FbException.catchException(nil, e);
end
@ -15754,6 +15777,23 @@ begin
vTable := IProfilerSessionImpl_vTable;
end;
function IProfilerStatsImpl_getElapsedTimeDispatcher(this: IProfilerStats): QWord; cdecl;
begin
try
Result := IProfilerStatsImpl(this).getElapsedTime();
except
on e: Exception do FbException.catchException(nil, e);
end
end;
var
IProfilerStatsImpl_vTable: ProfilerStatsVTable;
constructor IProfilerStatsImpl.create;
begin
vTable := IProfilerStatsImpl_vTable;
end;
constructor FbException.create(status: IStatus);
begin
inherited Create('FbException');
@ -16770,6 +16810,10 @@ initialization
IProfilerSessionImpl_vTable.beforeRecordSourceGetRecord := @IProfilerSessionImpl_beforeRecordSourceGetRecordDispatcher;
IProfilerSessionImpl_vTable.afterRecordSourceGetRecord := @IProfilerSessionImpl_afterRecordSourceGetRecordDispatcher;
IProfilerStatsImpl_vTable := ProfilerStatsVTable.create;
IProfilerStatsImpl_vTable.version := 2;
IProfilerStatsImpl_vTable.getElapsedTime := @IProfilerStatsImpl_getElapsedTimeDispatcher;
finalization
IVersionedImpl_vTable.destroy;
IReferenceCountedImpl_vTable.destroy;
@ -16868,5 +16912,6 @@ finalization
IReplicatedSessionImpl_vTable.destroy;
IProfilerPluginImpl_vTable.destroy;
IProfilerSessionImpl_vTable.destroy;
IProfilerStatsImpl_vTable.destroy;
end.

16
src/jrd/ProfilerManager.cpp
View File

@ -510,14 +510,14 @@ void ProfilerManager::prepareRecSource(thread_db* tdbb, jrd_req* request, const
}
}
void ProfilerManager::onRequestFinish(jrd_req* request, FB_UINT64 runTime)
void ProfilerManager::onRequestFinish(jrd_req* request, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, 0))
{
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
LogLocalStatus status("Profiler onRequestFinish");
currentSession->pluginSession->onRequestFinish(&status, profileRequestId, timestamp, runTime);
currentSession->pluginSession->onRequestFinish(&status, profileRequestId, timestamp, &stats);
currentSession->requests.findAndRemove(profileRequestId);
}
@ -529,10 +529,10 @@ void ProfilerManager::beforePsqlLineColumn(jrd_req* request, ULONG line, ULONG c
currentSession->pluginSession->beforePsqlLineColumn(profileRequestId, line, column);
}
void ProfilerManager::afterPsqlLineColumn(jrd_req* request, ULONG line, ULONG column, FB_UINT64 runTime)
void ProfilerManager::afterPsqlLineColumn(jrd_req* request, ULONG line, ULONG column, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
currentSession->pluginSession->afterPsqlLineColumn(profileRequestId, line, column, runTime);
currentSession->pluginSession->afterPsqlLineColumn(profileRequestId, line, column, &stats);
}
void ProfilerManager::beforeRecordSourceOpen(jrd_req* request, const RecordSource* rsb)
@ -548,7 +548,7 @@ void ProfilerManager::beforeRecordSourceOpen(jrd_req* request, const RecordSourc
}
}
void ProfilerManager::afterRecordSourceOpen(jrd_req* request, const RecordSource* rsb, FB_UINT64 runTime)
void ProfilerManager::afterRecordSourceOpen(jrd_req* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
{
@ -557,7 +557,7 @@ void ProfilerManager::afterRecordSourceOpen(jrd_req* request, const RecordSource
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceOpen(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, runTime);
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}
@ -574,7 +574,7 @@ void ProfilerManager::beforeRecordSourceGetRecord(jrd_req* request, const Record
}
}
void ProfilerManager::afterRecordSourceGetRecord(jrd_req* request, const RecordSource* rsb, FB_UINT64 runTime)
void ProfilerManager::afterRecordSourceGetRecord(jrd_req* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
{
@ -583,7 +583,7 @@ void ProfilerManager::afterRecordSourceGetRecord(jrd_req* request, const RecordS
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceGetRecord(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, runTime);
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}

26
src/jrd/ProfilerManager.h
View File

@ -47,6 +47,24 @@ class ProfilerManager final
friend class ProfilerListener;
friend class ProfilerPackage;
public:
class Stats final : public Firebird::IProfilerStatsImpl<Stats, Firebird::ThrowStatusExceptionWrapper>
{
public:
explicit Stats(FB_UINT64 aElapsedTime)
: elapsedTime(aElapsedTime)
{}
public:
FB_UINT64 getElapsedTime() override
{
return elapsedTime;
}
private:
FB_UINT64 elapsedTime = 0;
};
private:
class Statement final
{
@ -103,13 +121,13 @@ public:
const Firebird::PathName& pluginName, const Firebird::string& description, const Firebird::string& options);
void prepareRecSource(thread_db* tdbb, jrd_req* request, const RecordSource* rsb);
void onRequestFinish(jrd_req* request, FB_UINT64 runTime);
void onRequestFinish(jrd_req* request, Stats& stats);
void beforePsqlLineColumn(jrd_req* request, ULONG line, ULONG column);
void afterPsqlLineColumn(jrd_req* request, ULONG line, ULONG column, FB_UINT64 runTime);
void afterPsqlLineColumn(jrd_req* request, ULONG line, ULONG column, Stats& stats);
void beforeRecordSourceOpen(jrd_req* request, const RecordSource* rsb);
void afterRecordSourceOpen(jrd_req* request, const RecordSource* rsb, FB_UINT64 runTime);
void afterRecordSourceOpen(jrd_req* request, const RecordSource* rsb, Stats& stats);
void beforeRecordSourceGetRecord(jrd_req* request, const RecordSource* rsb);
void afterRecordSourceGetRecord(jrd_req* request, const RecordSource* rsb, FB_UINT64 runTime);
void afterRecordSourceGetRecord(jrd_req* request, const RecordSource* rsb, Stats& stats);
bool isActive() const
{

14
src/jrd/exe.cpp
View File

@ -1005,7 +1005,10 @@ void EXE_unwind(thread_db* tdbb, jrd_req* request)
const auto attachment = request->req_attachment;
if (attachment->isProfilerActive() && !request->hasInternalStatement())
attachment->getProfilerManager(tdbb)->onRequestFinish(request, request->req_profiler_time);
{
ProfilerManager::Stats stats(request->req_profiler_time);
attachment->getProfilerManager(tdbb)->onRequestFinish(request, stats);
}
}
request->req_sorts.unlinkAll();
@ -1370,9 +1373,11 @@ const StmtNode* EXE_looper(thread_db* tdbb, jrd_req* request, const StmtNode* no
if (profileNode)
{
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
attachment->getProfilerManager(tdbb)->afterPsqlLineColumn(request,
profileNode->line, profileNode->column,
currentPerfCounter - lastPerfCounter);
stats);
}
return currentPerfCounter;
@ -1485,7 +1490,10 @@ const StmtNode* EXE_looper(thread_db* tdbb, jrd_req* request, const StmtNode* no
release_blobs(tdbb, request);
if (attachment->isProfilerActive() && !request->hasInternalStatement())
attachment->getProfilerManager(tdbb)->onRequestFinish(request, request->req_profiler_time);
{
ProfilerManager::Stats stats(request->req_profiler_time);
attachment->getProfilerManager(tdbb)->onRequestFinish(request, stats);
}
}
request->req_next = node;

6
src/jrd/recsrc/RecordSource.cpp
View File

@ -77,7 +77,8 @@ void RecordSource::open(thread_db* tdbb) const
if (profilerManager)
{
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
profilerManager->afterRecordSourceOpen(request, this, currentPerfCounter - lastPerfCounter);
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
profilerManager->afterRecordSourceOpen(request, this, stats);
}
}
@ -105,7 +106,8 @@ bool RecordSource::getRecord(thread_db* tdbb) const
if (profilerManager)
{
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
profilerManager->afterRecordSourceGetRecord(request, this, currentPerfCounter - lastPerfCounter);
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
profilerManager->afterRecordSourceGetRecord(request, this, stats);
}
return ret;

217
src/plugins/profiler/Profiler.cpp
View File

@ -68,22 +68,22 @@ void quote(string& name)
struct Stats
{
void hit(FB_UINT64 runTime)
void hit(FB_UINT64 elapsedTime)
{
if (counter == 0 || runTime < minTime)
minTime = runTime;
if (counter == 0 || elapsedTime < minElapsedTime)
minElapsedTime = elapsedTime;
if (counter == 0 || runTime > maxTime)
maxTime = runTime;
if (counter == 0 || elapsedTime > maxElapsedTime)
maxElapsedTime = elapsedTime;
totalTime += runTime;
totalElapsedTime += elapsedTime;
++counter;
}
FB_UINT64 counter = 0;
FB_UINT64 minTime = 0;
FB_UINT64 maxTime = 0;
FB_UINT64 totalTime = 0;
FB_UINT64 minElapsedTime = 0;
FB_UINT64 maxElapsedTime = 0;
FB_UINT64 totalElapsedTime = 0;
};
struct RecordSource
@ -166,26 +166,27 @@ public:
SINT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp) override;
void onRequestFinish(ThrowStatusExceptionWrapper* status, SINT64 requestId,
ISC_TIMESTAMP_TZ timestamp, FB_UINT64 runTime) override;
ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats) override;
void beforePsqlLineColumn(SINT64 requestId, unsigned line, unsigned column) override
{
}
void afterPsqlLineColumn(SINT64 requestId, unsigned line, unsigned column, FB_UINT64 runTime) override;
void afterPsqlLineColumn(SINT64 requestId, unsigned line, unsigned column, IProfilerStats* stats) override;
void beforeRecordSourceOpen(SINT64 requestId, unsigned cursorId, unsigned recSourceId) override
{
}
void afterRecordSourceOpen(SINT64 requestId, unsigned cursorId, unsigned recSourceId, FB_UINT64 runTime) override;
void afterRecordSourceOpen(SINT64 requestId, unsigned cursorId, unsigned recSourceId,
IProfilerStats* stats) override;
void beforeRecordSourceGetRecord(SINT64 requestId, unsigned cursorId, unsigned recSourceId) override
{
}
void afterRecordSourceGetRecord(SINT64 requestId, unsigned cursorId, unsigned recSourceId,
FB_UINT64 runTime) override;
IProfilerStats* stats) override;
public:
RefPtr<ProfilerPlugin> plugin;
@ -393,7 +394,7 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
constexpr auto requestSql = R"""(
update or insert into plg$prof_requests
(profile_id, request_id, statement_id, caller_request_id, start_timestamp, finish_timestamp, total_time)
(profile_id, request_id, statement_id, caller_request_id, start_timestamp, finish_timestamp, total_elapsed_time)
values (?, ?, ?, ?, ?, ?, ?)
matching (profile_id, request_id)
)""";
@ -405,7 +406,7 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
(FB_BIGINT, callerRequestId)
(FB_TIMESTAMP_TZ, startTimestamp)
(FB_TIMESTAMP_TZ, finishTimestamp)
(FB_BIGINT, totalTime)
(FB_BIGINT, totalElapsedTime)
) requestMessage(status, MasterInterfacePtr());
requestMessage.clear();
@ -417,13 +418,13 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
record_source_id type of column plg$prof_record_source_stats.record_source_id = ?,
statement_id type of column plg$prof_record_source_stats.statement_id = ?,
open_counter type of column plg$prof_record_source_stats.open_counter = ?,
open_min_time type of column plg$prof_record_source_stats.open_min_time = ?,
open_max_time type of column plg$prof_record_source_stats.open_max_time = ?,
open_total_time type of column plg$prof_record_source_stats.open_total_time = ?,
open_min_elapsed_time type of column plg$prof_record_source_stats.open_min_elapsed_time = ?,
open_max_elapsed_time type of column plg$prof_record_source_stats.open_max_elapsed_time = ?,
open_total_elapsed_time type of column plg$prof_record_source_stats.open_total_elapsed_time = ?,
fetch_counter type of column plg$prof_record_source_stats.fetch_counter = ?,
fetch_min_time type of column plg$prof_record_source_stats.fetch_min_time = ?,
fetch_max_time type of column plg$prof_record_source_stats.fetch_max_time = ?,
fetch_total_time type of column plg$prof_record_source_stats.fetch_total_time = ?
fetch_min_elapsed_time type of column plg$prof_record_source_stats.fetch_min_elapsed_time = ?,
fetch_max_elapsed_time type of column plg$prof_record_source_stats.fetch_max_elapsed_time = ?,
fetch_total_elapsed_time type of column plg$prof_record_source_stats.fetch_total_elapsed_time = ?
)
as
begin
@ -435,21 +436,21 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
record_source_id = :record_source_id
when not matched then
insert (profile_id, request_id, cursor_id, record_source_id, statement_id,
open_counter, open_min_time, open_max_time, open_total_time,
fetch_counter, fetch_min_time, fetch_max_time, fetch_total_time)
open_counter, open_min_elapsed_time, open_max_elapsed_time, open_total_elapsed_time,
fetch_counter, fetch_min_elapsed_time, fetch_max_elapsed_time, fetch_total_elapsed_time)
values (:profile_id, :request_id, :cursor_id, :record_source_id, :statement_id,
:open_counter, :open_min_time, :open_max_time, :open_total_time,
:fetch_counter, :fetch_min_time, :fetch_max_time, :fetch_total_time)
:open_counter, :open_min_elapsed_time, :open_max_elapsed_time, :open_total_elapsed_time,
:fetch_counter, :fetch_min_elapsed_time, :fetch_max_elapsed_time, :fetch_total_elapsed_time)
when matched then
update set
open_counter = open_counter + :open_counter,
open_min_time = minvalue(open_min_time, :open_min_time),
open_max_time = maxvalue(open_max_time, :open_max_time),
open_total_time = open_total_time + :open_total_time,
open_min_elapsed_time = minvalue(open_min_elapsed_time, :open_min_elapsed_time),
open_max_elapsed_time = maxvalue(open_max_elapsed_time, :open_max_elapsed_time),
open_total_elapsed_time = open_total_elapsed_time + :open_total_elapsed_time,
fetch_counter = fetch_counter + :fetch_counter,
fetch_min_time = minvalue(fetch_min_time, :fetch_min_time),
fetch_max_time = maxvalue(fetch_max_time, :fetch_max_time),
fetch_total_time = fetch_total_time + :fetch_total_time;
fetch_min_elapsed_time = minvalue(fetch_min_elapsed_time, :fetch_min_elapsed_time),
fetch_max_elapsed_time = maxvalue(fetch_max_elapsed_time, :fetch_max_elapsed_time),
fetch_total_elapsed_time = fetch_total_elapsed_time + :fetch_total_elapsed_time;
end
)""";
@ -460,13 +461,13 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
(FB_INTEGER, recordSourceId)
(FB_BIGINT, statementId)
(FB_BIGINT, openCounter)
(FB_BIGINT, openMinTime)
(FB_BIGINT, openMaxTime)
(FB_BIGINT, openTotalTime)
(FB_BIGINT, openMinElapsedTime)
(FB_BIGINT, openMaxElapsedTime)
(FB_BIGINT, openTotalElapsedTime)
(FB_BIGINT, fetchCounter)
(FB_BIGINT, fetchMinTime)
(FB_BIGINT, fetchMaxTime)
(FB_BIGINT, fetchTotalTime)
(FB_BIGINT, fetchMinElapsedTime)
(FB_BIGINT, fetchMaxElapsedTime)
(FB_BIGINT, fetchTotalElapsedTime)
) recSrcStatsMessage(status, MasterInterfacePtr());
recSrcStatsMessage.clear();
@ -478,9 +479,9 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
column_num type of column plg$prof_psql_stats.column_num = ?,
statement_id type of column plg$prof_psql_stats.statement_id = ?,
counter type of column plg$prof_psql_stats.counter = ?,
min_time type of column plg$prof_psql_stats.min_time = ?,
max_time type of column plg$prof_psql_stats.max_time = ?,
total_time type of column plg$prof_psql_stats.total_time = ?
min_elapsed_time type of column plg$prof_psql_stats.min_elapsed_time = ?,
max_elapsed_time type of column plg$prof_psql_stats.max_elapsed_time = ?,
total_elapsed_time type of column plg$prof_psql_stats.total_elapsed_time = ?
)
as
begin
@ -492,15 +493,15 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
column_num = :column_num
when not matched then
insert (profile_id, request_id, line_num, column_num,
statement_id, counter, min_time, max_time, total_time)
statement_id, counter, min_elapsed_time, max_elapsed_time, total_elapsed_time)
values (:profile_id, :request_id, :line_num, :column_num,
:statement_id, :counter, :min_time, :max_time, :total_time)
:statement_id, :counter, :min_elapsed_time, :max_elapsed_time, :total_elapsed_time)
when matched then
update set
counter = counter + :counter,
min_time = minvalue(min_time, :min_time),
max_time = maxvalue(max_time, :max_time),
total_time = total_time + :total_time;
min_elapsed_time = minvalue(min_elapsed_time, :min_elapsed_time),
max_elapsed_time = maxvalue(max_elapsed_time, :max_elapsed_time),
total_elapsed_time = total_elapsed_time + :total_elapsed_time;
end
)""";
@ -511,9 +512,9 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
(FB_INTEGER, columnNum)
(FB_BIGINT, statementId)
(FB_BIGINT, counter)
(FB_BIGINT, minTime)
(FB_BIGINT, maxTime)
(FB_BIGINT, totalTime)
(FB_BIGINT, minElapsedTime)
(FB_BIGINT, maxElapsedTime)
(FB_BIGINT, totalElapsedTime)
) psqlStatsMessage(status, MasterInterfacePtr());
psqlStatsMessage.clear();
@ -735,8 +736,8 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
requestMessage->finishTimestampNull = profileRequest.finishTimestamp.isUnknown();
requestMessage->finishTimestamp = profileRequest.finishTimestamp.value;
requestMessage->totalTimeNull = profileRequest.totalTime.isUnknown();
requestMessage->totalTime = profileRequest.totalTime.value;
requestMessage->totalElapsedTimeNull = profileRequest.totalTime.isUnknown();
requestMessage->totalElapsedTime = profileRequest.totalTime.value;
addBatch(requestBatch, requestBatchSize, requestMessage);
@ -769,26 +770,26 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
recSrcStatsMessage->openCounterNull = FB_FALSE;
recSrcStatsMessage->openCounter = stats.openStats.counter;
recSrcStatsMessage->openMinTimeNull = FB_FALSE;
recSrcStatsMessage->openMinTime = stats.openStats.minTime;
recSrcStatsMessage->openMinElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->openMinElapsedTime = stats.openStats.minElapsedTime;
recSrcStatsMessage->openMaxTimeNull = FB_FALSE;
recSrcStatsMessage->openMaxTime = stats.openStats.maxTime;
recSrcStatsMessage->openMaxElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->openMaxElapsedTime = stats.openStats.maxElapsedTime;
recSrcStatsMessage->openTotalTimeNull = FB_FALSE;
recSrcStatsMessage->openTotalTime = stats.openStats.totalTime;
recSrcStatsMessage->openTotalElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->openTotalElapsedTime = stats.openStats.totalElapsedTime;
recSrcStatsMessage->fetchCounterNull = FB_FALSE;
recSrcStatsMessage->fetchCounter = stats.fetchStats.counter;
recSrcStatsMessage->fetchMinTimeNull = FB_FALSE;
recSrcStatsMessage->fetchMinTime = stats.fetchStats.minTime;
recSrcStatsMessage->fetchMinElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->fetchMinElapsedTime = stats.fetchStats.minElapsedTime;
recSrcStatsMessage->fetchMaxTimeNull = FB_FALSE;
recSrcStatsMessage->fetchMaxTime = stats.fetchStats.maxTime;
recSrcStatsMessage->fetchMaxElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->fetchMaxElapsedTime = stats.fetchStats.maxElapsedTime;
recSrcStatsMessage->fetchTotalTimeNull = FB_FALSE;
recSrcStatsMessage->fetchTotalTime = stats.fetchStats.totalTime;
recSrcStatsMessage->fetchTotalElapsedTimeNull = FB_FALSE;
recSrcStatsMessage->fetchTotalElapsedTime = stats.fetchStats.totalElapsedTime;
addBatch(recSrcStatsBatch, recSrcStatsBatchSize, recSrcStatsMessage);
}
@ -817,14 +818,14 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
psqlStatsMessage->counterNull = FB_FALSE;
psqlStatsMessage->counter = statsIt.second.counter;
psqlStatsMessage->minTimeNull = FB_FALSE;
psqlStatsMessage->minTime = statsIt.second.minTime;
psqlStatsMessage->minElapsedTimeNull = FB_FALSE;
psqlStatsMessage->minElapsedTime = statsIt.second.minElapsedTime;
psqlStatsMessage->maxTimeNull = FB_FALSE;
psqlStatsMessage->maxTime = statsIt.second.maxTime;
psqlStatsMessage->maxElapsedTimeNull = FB_FALSE;
psqlStatsMessage->maxElapsedTime = statsIt.second.maxElapsedTime;
psqlStatsMessage->totalTimeNull = FB_FALSE;
psqlStatsMessage->totalTime = statsIt.second.totalTime;
psqlStatsMessage->totalElapsedTimeNull = FB_FALSE;
psqlStatsMessage->totalElapsedTime = statsIt.second.totalElapsedTime;
addBatch(psqlStatsBatch, psqlStatsBatchSize, psqlStatsMessage);
}
@ -944,7 +945,7 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
caller_request_id bigint,
start_timestamp timestamp with time zone not null,
finish_timestamp timestamp with time zone,
total_time bigint,
total_elapsed_time bigint,
constraint plg$prof_requests_pk
primary key (profile_id, request_id)
using index plg$prof_requests_profile_request,
@ -972,9 +973,9 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
column_num integer not null,
statement_id bigint not null,
counter bigint not null,
min_time bigint not null,
max_time bigint not null,
total_time bigint not null,
min_elapsed_time bigint not null,
max_elapsed_time bigint not null,
total_elapsed_time bigint not null,
constraint plg$prof_psql_stats_pk
primary key (profile_id, request_id, line_num, column_num)
using index plg$prof_psql_stats_profile_request_line_column,
@ -1002,13 +1003,13 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
record_source_id bigint not null,
statement_id bigint not null,
open_counter bigint not null,
open_min_time bigint not null,
open_max_time bigint not null,
open_total_time bigint not null,
open_min_elapsed_time bigint not null,
open_max_elapsed_time bigint not null,
open_total_elapsed_time bigint not null,
fetch_counter bigint not null,
fetch_min_time bigint not null,
fetch_max_time bigint not null,
fetch_total_time bigint not null,
fetch_min_elapsed_time bigint not null,
fetch_max_elapsed_time bigint not null,
fetch_total_elapsed_time bigint not null,
constraint plg$prof_record_source_stats_pk
primary key (profile_id, request_id, cursor_id, record_source_id)
using index plg$prof_record_source_stats_profile_request_cursor_recsource,
@ -1045,10 +1046,10 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
statement_id = coalesce(sta.parent_statement_id, req.statement_id)
) sql_text,
count(*) counter,
min(req.total_time) min_time,
max(req.total_time) max_time,
cast(sum(req.total_time) as bigint) total_time,
cast(sum(req.total_time) / count(*) as bigint) avg_time
min(req.total_elapsed_time) min_elapsed_time,
max(req.total_elapsed_time) max_elapsed_time,
cast(sum(req.total_elapsed_time) as bigint) total_elapsed_time,
cast(sum(req.total_elapsed_time) / count(*) as bigint) avg_elapsed_time
from plg$prof_requests req
join plg$prof_statements sta
on sta.profile_id = req.profile_id and
@ -1064,7 +1065,7 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
sta.parent_statement_id,
sta_parent.statement_type,
sta_parent.routine_name
order by sum(req.total_time) desc
order by sum(req.total_elapsed_time) desc
)""",
"grant select on table plg$prof_statement_stats_view to plg$profiler",
@ -1088,10 +1089,10 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
pstat.line_num,
pstat.column_num,
cast(sum(pstat.counter) as bigint) counter,
min(pstat.min_time) min_time,
max(pstat.max_time) max_time,
cast(sum(pstat.total_time) as bigint) total_time,
cast(sum(pstat.total_time) / nullif(sum(pstat.counter), 0) as bigint) avg_time
min(pstat.min_elapsed_time) min_elapsed_time,
max(pstat.max_elapsed_time) max_elapsed_time,
cast(sum(pstat.total_elapsed_time) as bigint) total_elapsed_time,
cast(sum(pstat.total_elapsed_time) / nullif(sum(pstat.counter), 0) as bigint) avg_elapsed_time
from plg$prof_psql_stats pstat
join plg$prof_statements sta
on sta.profile_id = pstat.profile_id and
@ -1109,7 +1110,7 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
sta_parent.routine_name,
pstat.line_num,
pstat.column_num
order by sum(pstat.total_time) desc
order by sum(pstat.total_elapsed_time) desc
)""",
"grant select on table plg$prof_psql_stats_view to plg$profiler",
@ -1135,16 +1136,16 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
recsrc.parent_record_source_id,
recsrc.access_path,
cast(sum(rstat.open_counter) as bigint) open_counter,
min(rstat.open_min_time) open_min_time,
max(rstat.open_max_time) open_max_time,
cast(sum(rstat.open_total_time) as bigint) open_total_time,
cast(sum(rstat.open_total_time) / nullif(sum(rstat.open_counter), 0) as bigint) open_avg_time,
min(rstat.open_min_elapsed_time) open_min_elapsed_time,
max(rstat.open_max_elapsed_time) open_max_elapsed_time,
cast(sum(rstat.open_total_elapsed_time) as bigint) open_total_elapsed_time,
cast(sum(rstat.open_total_elapsed_time) / nullif(sum(rstat.open_counter), 0) as bigint) open_avg_elapsed_time,
cast(sum(rstat.fetch_counter) as bigint) fetch_counter,
min(rstat.fetch_min_time) fetch_min_time,
max(rstat.fetch_max_time) fetch_max_time,
cast(sum(rstat.fetch_total_time) as bigint) fetch_total_time,
cast(sum(rstat.fetch_total_time) / nullif(sum(rstat.fetch_counter), 0) as bigint) fetch_avg_time,
cast(coalesce(sum(rstat.open_total_time), 0) + coalesce(sum(rstat.fetch_total_time), 0) as bigint) open_fetch_total_time
min(rstat.fetch_min_elapsed_time) fetch_min_elapsed_time,
max(rstat.fetch_max_elapsed_time) fetch_max_elapsed_time,
cast(sum(rstat.fetch_total_elapsed_time) as bigint) fetch_total_elapsed_time,
cast(sum(rstat.fetch_total_elapsed_time) / nullif(sum(rstat.fetch_counter), 0) as bigint) fetch_avg_elapsed_time,
cast(coalesce(sum(rstat.open_total_elapsed_time), 0) + coalesce(sum(rstat.fetch_total_elapsed_time), 0) as bigint) open_fetch_total_time
from plg$prof_record_source_stats rstat
join plg$prof_record_sources recsrc
on recsrc.profile_id = rstat.profile_id and
@ -1169,7 +1170,7 @@ void ProfilerPlugin::createMetadata(ThrowStatusExceptionWrapper* status, RefPtr<
rstat.record_source_id,
recsrc.parent_record_source_id,
recsrc.access_path
order by coalesce(sum(rstat.open_total_time), 0) + coalesce(sum(rstat.fetch_total_time), 0) desc
order by coalesce(sum(rstat.open_total_elapsed_time), 0) + coalesce(sum(rstat.fetch_total_elapsed_time), 0) desc
)""",
"grant select on table plg$prof_record_source_stats_view to plg$profiler"
@ -1332,40 +1333,40 @@ void Session::onRequestStart(ThrowStatusExceptionWrapper* status, SINT64 request
}
void Session::onRequestFinish(ThrowStatusExceptionWrapper* status, SINT64 requestId,
ISC_TIMESTAMP_TZ timestamp, FB_UINT64 runTime)
ISC_TIMESTAMP_TZ timestamp, IProfilerStats* stats)
{
if (auto request = requests.get(requestId))
{
request->dirty = true;
request->finishTimestamp = timestamp;
request->totalTime = runTime;
request->totalTime = stats->getElapsedTime();
}
}
void Session::afterPsqlLineColumn(SINT64 requestId, unsigned line, unsigned column, FB_UINT64 runTime)
void Session::afterPsqlLineColumn(SINT64 requestId, unsigned line, unsigned column, IProfilerStats* stats)
{
if (auto request = requests.get(requestId))
{
const auto profileStats = request->psqlStats.getOrPut({line, column});
profileStats->hit(runTime);
profileStats->hit(stats->getElapsedTime());
}
}
void Session::afterRecordSourceOpen(SINT64 requestId, unsigned cursorId, unsigned recSourceId, FB_UINT64 runTime)
void Session::afterRecordSourceOpen(SINT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats)
{
if (auto request = requests.get(requestId))
{
auto stats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
stats->openStats.hit(runTime);
auto profileStats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
profileStats->openStats.hit(stats->getElapsedTime());
}
}
void Session::afterRecordSourceGetRecord(SINT64 requestId, unsigned cursorId, unsigned recSourceId, FB_UINT64 runTime)
void Session::afterRecordSourceGetRecord(SINT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats)
{
if (auto request = requests.get(requestId))
{
auto stats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
stats->fetchStats.hit(runTime);
auto profileStats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
profileStats->fetchStats.hit(stats->getElapsedTime());
}
}