Skip to content

Commit 82b98c0

Browse files
asfernandesasfernandes
committed
Add TOTAL_TIME column to PLG$PROF_REQUESTS. Add view PLG$PROF_STATEMENT_STATS_VIEW.
1 parent 7411434 commit 82b98c0

File tree

9 files changed

+132
-31
lines changed

9 files changed

+132
-31
lines changed

‎doc/sql.extensions/README.profiler.md‎

Lines changed: 43 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -266,6 +266,7 @@ Below is the list of tables that stores profile data.
266266
- `CALLER_REQUEST_ID` type `BIGINT` - Caller request ID
267267
- `START_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment this request was first gathered profile data
268268
- `FINISH_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment this request was finished
269+
- `TOTAL_TIME` type `BIGINT` - Accumulated execution time (in nanoseconds) of the request
269270
- Primary key: `PROFILE_ID, REQUEST_ID`
270271

271272
## Table `PLG$PROF_PSQL_STATS`
@@ -275,10 +276,10 @@ Below is the list of tables that stores profile data.
275276
- `LINE_NUM` type `INTEGER` - Line number of the statement
276277
- `COLUMN_NUM` type `INTEGER` - Column number of the statement
277278
- `STATEMENT_ID` type `BIGINT` - Statement ID
278-
- `COUNTER` type `BIGINT` - Number of executed times of the statement
279-
- `MIN_TIME` type `BIGINT` - Minimal time (in nanoseconds) of a statement execution
280-
- `MAX_TIME` type `BIGINT` - Maximum time (in nanoseconds) of a statement execution
281-
- `TOTAL_TIME` type `BIGINT` - Accumulated execution time (in nanoseconds) of the statement
279+
- `COUNTER` type `BIGINT` - Number of executed times of the line/column
280+
- `MIN_TIME` type `BIGINT` - Minimal time (in nanoseconds) of a line/column execution
281+
- `MAX_TIME` type `BIGINT` - Maximum time (in nanoseconds) of a line/column execution
282+
- `TOTAL_TIME` type `BIGINT` - Accumulated execution time (in nanoseconds) of the line/column
282283
- Primary key: `PROFILE_ID, REQUEST_ID, LINE_NUM, COLUMN_NUM`
283284

284285
## Table `PLG$PROF_RECORD_SOURCE_STATS`
@@ -306,6 +307,44 @@ They should be the preferred way to analyze the collected data. They can also be
306307

307308
After hot spots are found, one can drill down in the data at the request level through the tables.
308309

310+
## View `PLG$PROF_STATEMENT_STATS_VIEW`
311+
```
312+
select req.profile_id,
313+
req.statement_id,
314+
sta.statement_type,
315+
sta.package_name,
316+
sta.routine_name,
317+
sta.parent_statement_id,
318+
sta_parent.statement_type parent_statement_type,
319+
sta_parent.routine_name parent_routine_name,
320+
(select sql_text
321+
from plg$prof_statements
322+
where profile_id = req.profile_id and
323+
statement_id = coalesce(sta.parent_statement_id, req.statement_id)
324+
) sql_text,
325+
count(*) counter,
326+
min(req.total_time) min_time,
327+
max(req.total_time) max_time,
328+
sum(req.total_time) total_time,
329+
sum(req.total_time) / count(*) avg_time
330+
from plg$prof_requests req
331+
join plg$prof_statements sta
332+
on sta.profile_id = req.profile_id and
333+
sta.statement_id = req.statement_id
334+
left join plg$prof_statements sta_parent
335+
on sta_parent.profile_id = sta.profile_id and
336+
sta_parent.statement_id = sta.parent_statement_id
337+
group by req.profile_id,
338+
req.statement_id,
339+
sta.statement_type,
340+
sta.package_name,
341+
sta.routine_name,
342+
sta.parent_statement_id,
343+
sta_parent.statement_type,
344+
sta_parent.routine_name
345+
order by sum(req.total_time) desc
346+
```
347+
309348
## View `PLG$PROF_PSQL_STATS_VIEW`
310349
```
311350
select pstat.profile_id,

‎src/include/firebird/FirebirdInterface.idl‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1734,7 +1734,7 @@ interface ProfilerSession : Disposable
17341734
void onRequestStart(Status status, int64 requestId, int64 statementId, int64 callerRequestId,
17351735
ISC_TIMESTAMP_TZ timestamp);
17361736

1737-
void onRequestFinish(Status status, int64 requestId, ISC_TIMESTAMP_TZ timestamp);
1737+
void onRequestFinish(Status status, int64 requestId, ISC_TIMESTAMP_TZ timestamp, uint64 runTime);
17381738

17391739
void beforePsqlLineColumn(int64 requestId, uint line, uint column);
17401740
void afterPsqlLineColumn(int64 requestId, uint line, uint column, uint64 runTime);

‎src/include/firebird/IdlFbInterfaces.h‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -6701,7 +6701,7 @@ namespace Firebird
67016701
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();
67026702
void (CLOOP_CARG *defineRecordSource)(IProfilerSession* self, ISC_INT64 statementId, unsigned cursorId, unsigned recSourceId, const char* accessPath, unsigned parentRecSourceId) throw();
67036703
void (CLOOP_CARG *onRequestStart)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_INT64 statementId, ISC_INT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp) throw();
6704-
void (CLOOP_CARG *onRequestFinish)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp) throw();
6704+
void (CLOOP_CARG *onRequestFinish)(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) throw();
67056705
void (CLOOP_CARG *beforePsqlLineColumn)(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column) throw();
67066706
void (CLOOP_CARG *afterPsqlLineColumn)(IProfilerSession* self, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime) throw();
67076707
void (CLOOP_CARG *beforeRecordSourceOpen)(IProfilerSession* self, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) throw();
@@ -6771,10 +6771,10 @@ namespace Firebird
67716771
StatusType::checkException(status);
67726772
}
67736773

6774-
template <typename StatusType> void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp)
6774+
template <typename StatusType> void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime)
67756775
{
67766776
StatusType::clearException(status);
6777-
static_cast<VTable*>(this->cloopVTable)->onRequestFinish(this, status, requestId, timestamp);
6777+
static_cast<VTable*>(this->cloopVTable)->onRequestFinish(this, status, requestId, timestamp, runTime);
67786778
StatusType::checkException(status);
67796779
}
67806780

@@ -20204,13 +20204,13 @@ namespace Firebird
2020420204
}
2020520205
}
2020620206

20207-
static void CLOOP_CARG clooponRequestFinishDispatcher(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp) throw()
20207+
static void CLOOP_CARG clooponRequestFinishDispatcher(IProfilerSession* self, IStatus* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) throw()
2020820208
{
2020920209
StatusType status2(status);
2021020210

2021120211
try
2021220212
{
20213-
static_cast<Name*>(self)->Name::onRequestFinish(&status2, requestId, timestamp);
20213+
static_cast<Name*>(self)->Name::onRequestFinish(&status2, requestId, timestamp, runTime);
2021420214
}
2021520215
catch (...)
2021620216
{
@@ -20323,7 +20323,7 @@ namespace Firebird
2032320323
virtual void defineStatement(StatusType* status, ISC_INT64 statementId, ISC_INT64 parentStatementId, const char* type, const char* packageName, const char* routineName, const char* sqlText) = 0;
2032420324
virtual void defineRecordSource(ISC_INT64 statementId, unsigned cursorId, unsigned recSourceId, const char* accessPath, unsigned parentRecSourceId) = 0;
2032520325
virtual void onRequestStart(StatusType* status, ISC_INT64 requestId, ISC_INT64 statementId, ISC_INT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp) = 0;
20326-
virtual void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp) = 0;
20326+
virtual void onRequestFinish(StatusType* status, ISC_INT64 requestId, ISC_TIMESTAMP_TZ timestamp, ISC_UINT64 runTime) = 0;
2032720327
virtual void beforePsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column) = 0;
2032820328
virtual void afterPsqlLineColumn(ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 runTime) = 0;
2032920329
virtual void beforeRecordSourceOpen(ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) = 0;

‎src/include/gen/Firebird.pas‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -724,7 +724,7 @@ ISC_TIMESTAMP_TZ_EX = record
724724
IProfilerSession_defineStatementPtr = procedure(this: IProfilerSession; status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); cdecl;
725725
IProfilerSession_defineRecordSourcePtr = procedure(this: IProfilerSession; statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal); cdecl;
726726
IProfilerSession_onRequestStartPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ); cdecl;
727-
IProfilerSession_onRequestFinishPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ); cdecl;
727+
IProfilerSession_onRequestFinishPtr = procedure(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); cdecl;
728728
IProfilerSession_beforePsqlLineColumnPtr = procedure(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal); cdecl;
729729
IProfilerSession_afterPsqlLineColumnPtr = procedure(this: IProfilerSession; requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord); cdecl;
730730
IProfilerSession_beforeRecordSourceOpenPtr = procedure(this: IProfilerSession; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); cdecl;
@@ -3821,7 +3821,7 @@ IProfilerSession = class(IDisposable)
38213821
procedure defineStatement(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar);
38223822
procedure defineRecordSource(statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal);
38233823
procedure onRequestStart(status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ);
3824-
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ);
3824+
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord);
38253825
procedure beforePsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal);
38263826
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord);
38273827
procedure beforeRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
@@ -3841,7 +3841,7 @@ IProfilerSessionImpl = class(IProfilerSession)
38413841
procedure defineStatement(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); virtual; abstract;
38423842
procedure defineRecordSource(statementId: Int64; cursorId: Cardinal; recSourceId: Cardinal; accessPath: PAnsiChar; parentRecSourceId: Cardinal); virtual; abstract;
38433843
procedure onRequestStart(status: IStatus; requestId: Int64; statementId: Int64; callerRequestId: Int64; timestamp: ISC_TIMESTAMP_TZ); virtual; abstract;
3844-
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ); virtual; abstract;
3844+
procedure onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); virtual; abstract;
38453845
procedure beforePsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal); virtual; abstract;
38463846
procedure afterPsqlLineColumn(requestId: Int64; line: Cardinal; column: Cardinal; runTime: QWord); virtual; abstract;
38473847
procedure beforeRecordSourceOpen(requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); virtual; abstract;
@@ -9002,9 +9002,9 @@ procedure IProfilerSession.onRequestStart(status: IStatus; requestId: Int64; sta
90029002
FbException.checkException(status);
90039003
end;
90049004

9005-
procedure IProfilerSession.onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ);
9005+
procedure IProfilerSession.onRequestFinish(status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord);
90069006
begin
9007-
ProfilerSessionVTable(vTable).onRequestFinish(Self, status, requestId, timestamp);
9007+
ProfilerSessionVTable(vTable).onRequestFinish(Self, status, requestId, timestamp, runTime);
90089008
FbException.checkException(status);
90099009
end;
90109010

@@ -15683,10 +15683,10 @@ procedure IProfilerSessionImpl_onRequestStartDispatcher(this: IProfilerSession;
1568315683
end
1568415684
end;
1568515685

15686-
procedure IProfilerSessionImpl_onRequestFinishDispatcher(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ); cdecl;
15686+
procedure IProfilerSessionImpl_onRequestFinishDispatcher(this: IProfilerSession; status: IStatus; requestId: Int64; timestamp: ISC_TIMESTAMP_TZ; runTime: QWord); cdecl;
1568715687
begin
1568815688
try
15689-
IProfilerSessionImpl(this).onRequestFinish(status, requestId, timestamp);
15689+
IProfilerSessionImpl(this).onRequestFinish(status, requestId, timestamp, runTime);
1569015690
except
1569115691
on e: Exception do FbException.catchException(status, e);
1569215692
end

‎src/jrd/ProfilerManager.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -510,14 +510,14 @@ void ProfilerManager::prepareRecSource(thread_db* tdbb, jrd_req* request, const
510510
}
511511
}
512512

513-
void ProfilerManager::onRequestFinish(jrd_req* request)
513+
void ProfilerManager::onRequestFinish(jrd_req* request, FB_UINT64 runTime)
514514
{
515515
if (const auto profileRequestId = getRequest(request, 0))
516516
{
517517
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
518518

519519
LogLocalStatus status("Profiler onRequestFinish");
520-
currentSession->pluginSession->onRequestFinish(&status, profileRequestId, timestamp);
520+
currentSession->pluginSession->onRequestFinish(&status, profileRequestId, timestamp, runTime);
521521

522522
currentSession->requests.findAndRemove(profileRequestId);
523523
}

‎src/jrd/ProfilerManager.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -103,7 +103,7 @@ class ProfilerManager final
103103
const Firebird::PathName& pluginName, const Firebird::string& description, const Firebird::string& options);
104104

105105
void prepareRecSource(thread_db* tdbb, jrd_req* request, const RecordSource* rsb);
106-
void onRequestFinish(jrd_req* request);
106+
void onRequestFinish(jrd_req* request, FB_UINT64 runTime);
107107
void beforePsqlLineColumn(jrd_req* request, ULONG line, ULONG column);
108108
void afterPsqlLineColumn(jrd_req* request, ULONG line, ULONG column, FB_UINT64 runTime);
109109
void beforeRecordSourceOpen(jrd_req* request, const RecordSource* rsb);

‎src/jrd/exe.cpp‎

Lines changed: 17 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -910,6 +910,8 @@ void EXE_start(thread_db* tdbb, jrd_req* request, jrd_tra* transaction)
910910

911911
request->req_records_affected.clear();
912912

913+
request->req_profiler_time = 0;
914+
913915
// Store request start time for timestamp work
914916
TimeZoneUtil::validateGmtTimeStamp(request->req_gmt_timestamp);
915917

@@ -1003,7 +1005,7 @@ void EXE_unwind(thread_db* tdbb, jrd_req* request)
10031005
const auto attachment = request->req_attachment;
10041006

10051007
if (attachment->isProfilerActive() && !request->hasInternalStatement())
1006-
attachment->getProfilerManager(tdbb)->onRequestFinish(request);
1008+
attachment->getProfilerManager(tdbb)->onRequestFinish(request, request->req_profiler_time);
10071009
}
10081010

10091011
request->req_sorts.unlinkAll();
@@ -1359,7 +1361,8 @@ const StmtNode* EXE_looper(thread_db* tdbb, jrd_req* request, const StmtNode* no
13591361

13601362
// Execute stuff until we drop
13611363

1362-
SINT64 lastPerfCounter = fb_utils::query_performance_counter();
1364+
SINT64 initialPerfCounter = fb_utils::query_performance_counter();
1365+
SINT64 lastPerfCounter = initialPerfCounter;
13631366
const StmtNode* profileNode = nullptr;
13641367

13651368
while (node && !(request->req_flags & req_stall))
@@ -1444,13 +1447,18 @@ const StmtNode* EXE_looper(thread_db* tdbb, jrd_req* request, const StmtNode* no
14441447
}
14451448
} // while()
14461449

1447-
if (attachment->isProfilerActive() && !request->hasInternalStatement() && profileNode)
1450+
if (attachment->isProfilerActive() && !request->hasInternalStatement())
14481451
{
14491452
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
14501453

1451-
attachment->getProfilerManager(tdbb)->afterPsqlLineColumn(request,
1452-
profileNode->line, profileNode->column,
1453-
currentPerfCounter - lastPerfCounter);
1454+
if (profileNode)
1455+
{
1456+
attachment->getProfilerManager(tdbb)->afterPsqlLineColumn(request,
1457+
profileNode->line, profileNode->column,
1458+
currentPerfCounter - lastPerfCounter);
1459+
}
1460+
1461+
request->req_profiler_time += currentPerfCounter - initialPerfCounter;
14541462
}
14551463

14561464
request->adjustCallerStats();
@@ -1477,6 +1485,9 @@ const StmtNode* EXE_looper(thread_db* tdbb, jrd_req* request, const StmtNode* no
14771485
request->req_flags &= ~(req_active | req_reserved);
14781486
request->req_gmt_timestamp.invalidate();
14791487
release_blobs(tdbb, request);
1488+
1489+
if (attachment->isProfilerActive() && !request->hasInternalStatement())
1490+
attachment->getProfilerManager(tdbb)->onRequestFinish(request, request->req_profiler_time);
14801491
}
14811492

14821493
request->req_next = node;

‎src/jrd/req.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -269,6 +269,7 @@ class jrd_req : public pool_alloc<type_req>
269269
RuntimeStatistics req_stats;
270270
RuntimeStatistics req_base_stats;
271271
AffectedRows req_records_affected; // records affected by the last statement
272+
FB_UINT64 req_profiler_time; // profiler time
272273

273274
const StmtNode* req_next; // next node for execution
274275
EDS::Statement* req_ext_stmt; // head of list of active dynamic statements

0 commit comments

Comments
 (0)