8
0
mirror of https://github.com/FirebirdSQL/firebird.git synced 2025-02-02 10:00:38 +01:00

Estimate and amortize in the profiler the time spent getting performance counters.

Also make some ProfilerManager code inline.
This commit is contained in:
Adriano dos Santos Fernandes 2023-06-24 21:47:34 -03:00 committed by Adriano dos Santos Fernandes
parent 3c0fb038e6
commit cfffebf92e
5 changed files with 227 additions and 176 deletions

View File

@ -560,70 +560,6 @@ void ProfilerManager::onRequestFinish(Request* request, Stats& stats)
}
}
void ProfilerManager::beforePsqlLineColumn(Request* request, ULONG line, ULONG column)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_BEFORE_EVENTS))
currentSession->pluginSession->beforePsqlLineColumn(profileRequestId, line, column);
}
void ProfilerManager::afterPsqlLineColumn(Request* request, ULONG line, ULONG column, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
currentSession->pluginSession->afterPsqlLineColumn(profileRequestId, line, column, &stats);
}
void ProfilerManager::beforeRecordSourceOpen(Request* request, const RecordSource* rsb)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_BEFORE_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->beforeRecordSourceOpen(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr);
}
}
void ProfilerManager::afterRecordSourceOpen(Request* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceOpen(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}
void ProfilerManager::beforeRecordSourceGetRecord(Request* request, const RecordSource* rsb)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_BEFORE_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->beforeRecordSourceGetRecord(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr);
}
}
void ProfilerManager::afterRecordSourceGetRecord(Request* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, IProfilerSession::FLAG_AFTER_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceGetRecord(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}
void ProfilerManager::cancelSession()
{
if (currentSession)
@ -773,37 +709,6 @@ ProfilerManager::Statement* ProfilerManager::getStatement(Request* request)
return mainProfileStatement;
}
SINT64 ProfilerManager::getRequest(Request* request, unsigned flags)
{
if (!isActive() || (flags && !(currentSession->flags & flags)))
return 0;
const auto mainRequestId = request->getRequestId();
if (!currentSession->requests.exist(mainRequestId))
{
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
do
{
getStatement(request); // define the statement and ignore the result
const StmtNumber callerRequestId = request->req_caller ? request->req_caller->getRequestId() : 0;
LogLocalStatus status("Profiler onRequestStart");
currentSession->pluginSession->onRequestStart(&status,
(SINT64) request->getRequestId(), (SINT64) request->getStatement()->getStatementId(),
(SINT64) callerRequestId, timestamp);
currentSession->requests.add(request->getRequestId());
request = request->req_caller;
} while (request && !currentSession->requests.exist(request->getRequestId()));
}
return mainRequestId;
}
//--------------------------------------

View File

@ -25,11 +25,14 @@
#include "firebird.h"
#include "firebird/Message.h"
#include "../common/PerformanceStopWatch.h"
#include "../common/classes/auto.h"
#include "../common/classes/fb_string.h"
#include "../common/classes/Nullable.h"
#include "../common/classes/RefCounted.h"
#include "../common/classes/TimerImpl.h"
#include "../jrd/recsrc/RecordSource.h"
#include "../jrd/req.h"
#include "../jrd/SystemPackages.h"
namespace Jrd {
@ -43,7 +46,7 @@ class thread_db;
class ProfilerListener;
class ProfilerManager final
class ProfilerManager final : public Firebird::PerformanceStopWatch
{
friend class ProfilerListener;
friend class ProfilerPackage;
@ -66,6 +69,70 @@ public:
FB_UINT64 elapsedTicks;
};
class RecordSourceStopWatcher final
{
public:
enum class Event
{
OPEN,
GET_RECORD
};
public:
RecordSourceStopWatcher(thread_db* tdbb, const RecordSource* aRecordSource, Event aEvent)
: recordSource(aRecordSource),
event(aEvent)
{
const auto attachment = tdbb->getAttachment();
request = tdbb->getRequest();
profilerManager = attachment->isProfilerActive() && !request->hasInternalStatement() ?
attachment->getProfilerManager(tdbb) :
nullptr;
if (profilerManager)
{
lastTicks = profilerManager->queryTicks();
profilerManager->prepareRecSource(tdbb, request, recordSource);
if (profilerManager->currentSession->flags & Firebird::IProfilerSession::FLAG_BEFORE_EVENTS)
{
if (event == Event::OPEN)
profilerManager->beforeRecordSourceOpen(request, recordSource);
else
profilerManager->beforeRecordSourceGetRecord(request, recordSource);
}
lastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
}
}
~RecordSourceStopWatcher()
{
if (profilerManager)
{
const SINT64 currentTicks = profilerManager->queryTicks();
const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
currentTicks, lastTicks, lastAccumulatedOverhead);
Stats stats(elapsedTicks);
if (event == Event::OPEN)
profilerManager->afterRecordSourceOpen(request, recordSource, stats);
else
profilerManager->afterRecordSourceGetRecord(request, recordSource, stats);
}
}
private:
const RecordSource* recordSource;
Request* request;
ProfilerManager* profilerManager;
SINT64 lastTicks;
SINT64 lastAccumulatedOverhead;
Event event;
};
private:
class Statement final
{
@ -126,12 +193,70 @@ public:
void prepareCursor(thread_db* tdbb, Request* request, const Select* select);
void prepareRecSource(thread_db* tdbb, Request* request, const RecordSource* rsb);
void onRequestFinish(Request* request, Stats& stats);
void beforePsqlLineColumn(Request* request, ULONG line, ULONG column);
void afterPsqlLineColumn(Request* request, ULONG line, ULONG column, Stats& stats);
void beforeRecordSourceOpen(Request* request, const RecordSource* rsb);
void afterRecordSourceOpen(Request* request, const RecordSource* rsb, Stats& stats);
void beforeRecordSourceGetRecord(Request* request, const RecordSource* rsb);
void afterRecordSourceGetRecord(Request* request, const RecordSource* rsb, Stats& stats);
void beforePsqlLineColumn(Request* request, ULONG line, ULONG column)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_BEFORE_EVENTS))
currentSession->pluginSession->beforePsqlLineColumn(profileRequestId, line, column);
}
void afterPsqlLineColumn(Request* request, ULONG line, ULONG column, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_AFTER_EVENTS))
currentSession->pluginSession->afterPsqlLineColumn(profileRequestId, line, column, &stats);
}
void beforeRecordSourceOpen(Request* request, const RecordSource* rsb)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_BEFORE_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->beforeRecordSourceOpen(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr);
}
}
void afterRecordSourceOpen(Request* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_AFTER_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceOpen(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}
void beforeRecordSourceGetRecord(Request* request, const RecordSource* rsb)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_BEFORE_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->beforeRecordSourceGetRecord(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr);
}
}
void afterRecordSourceGetRecord(Request* request, const RecordSource* rsb, Stats& stats)
{
if (const auto profileRequestId = getRequest(request, Firebird::IProfilerSession::FLAG_AFTER_EVENTS))
{
const auto profileStatement = getStatement(request);
const auto sequencePtr = profileStatement->recSourceSequence.get(rsb->getRecSourceProfileId());
fb_assert(sequencePtr);
currentSession->pluginSession->afterRecordSourceGetRecord(
profileRequestId, rsb->getCursorProfileId(), *sequencePtr, &stats);
}
}
bool isActive() const
{
@ -161,7 +286,39 @@ private:
void updateFlushTimer(bool canStopTimer = true);
Statement* getStatement(Request* request);
SINT64 getRequest(Request* request, unsigned flags);
SINT64 getRequest(Request* request, unsigned flags)
{
using namespace Firebird;
if (!isActive() || (flags && !(currentSession->flags & flags)))
return 0;
const auto mainRequestId = request->getRequestId();
if (!currentSession->requests.exist(mainRequestId))
{
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
do
{
getStatement(request); // define the statement and ignore the result
const StmtNumber callerRequestId = request->req_caller ? request->req_caller->getRequestId() : 0;
LogLocalStatus status("Profiler onRequestStart");
currentSession->pluginSession->onRequestStart(&status,
(SINT64) request->getRequestId(), (SINT64) request->getStatement()->getStatementId(),
(SINT64) callerRequestId, timestamp);
currentSession->requests.add(request->getRequestId());
request = request->req_caller;
} while (request && !currentSession->requests.exist(request->getRequestId()));
}
return mainRequestId;
}
private:
Firebird::AutoPtr<ProfilerListener> listener;

View File

@ -905,7 +905,7 @@ void EXE_start(thread_db* tdbb, Request* request, jrd_tra* transaction)
for (auto& rpb : request->req_rpb)
rpb.rpb_runtime_flags = 0;
request->req_profiler_perf_counter = 0;
request->req_profiler_ticks = 0;
// Store request start time for timestamp work
request->validateTimeStamp();
@ -997,9 +997,9 @@ void EXE_unwind(thread_db* tdbb, Request* request)
const auto attachment = request->req_attachment;
if (attachment->isProfilerActive() && !request->hasInternalStatement())
if (request->req_profiler_ticks && attachment->isProfilerActive() && !request->hasInternalStatement())
{
ProfilerManager::Stats stats(request->req_profiler_perf_counter);
ProfilerManager::Stats stats(request->req_profiler_ticks);
attachment->getProfilerManager(tdbb)->onRequestFinish(request, stats);
}
}
@ -1387,23 +1387,39 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
// Execute stuff until we drop
SINT64 initialPerfCounter = fb_utils::query_performance_counter();
SINT64 lastPerfCounter = initialPerfCounter;
ProfilerManager* profilerManager;
SINT64 profilerInitialTicks, profilerInitialAccumulatedOverhead, profilerLastTicks, profilerLastAccumulatedOverhead;
if (attachment->isProfilerActive() && !request->hasInternalStatement())
{
profilerManager = attachment->getProfilerManager(tdbb);
profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
profilerManager->getAccumulatedOverhead();
}
else
{
profilerManager = nullptr;
profilerInitialTicks = 0;
profilerLastTicks = 0;
profilerInitialAccumulatedOverhead = 0;
profilerLastAccumulatedOverhead = 0;
}
const StmtNode* profileNode = nullptr;
const auto profilerCallAfterPsqlLineColumn = [&] {
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
const SINT64 currentProfilerTicks = profilerManager->queryTicks();
if (profileNode)
{
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
attachment->getProfilerManager(tdbb)->afterPsqlLineColumn(request,
profileNode->line, profileNode->column,
stats);
const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
currentProfilerTicks, profilerLastTicks, profilerLastAccumulatedOverhead);
ProfilerManager::Stats stats(elapsedTicks);
profilerManager->afterPsqlLineColumn(request, profileNode->line, profileNode->column, stats);
}
return currentPerfCounter;
return currentProfilerTicks;
};
while (node && !(request->req_flags & req_stall))
@ -1422,17 +1438,24 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
if (attachment->isProfilerActive() && !request->hasInternalStatement())
{
if (!profilerInitialTicks)
{
profilerManager = attachment->getProfilerManager(tdbb);
profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
profilerManager->getAccumulatedOverhead();
}
if (node->hasLineColumn &&
node->isProfileAware() &&
(!profileNode ||
!(node->line == profileNode->line && node->column == profileNode->column)))
{
lastPerfCounter = profilerCallAfterPsqlLineColumn();
profilerLastTicks = profilerCallAfterPsqlLineColumn();
profilerLastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
profileNode = node;
attachment->getProfilerManager(tdbb)->beforePsqlLineColumn(request,
profileNode->line, profileNode->column);
profilerManager->beforePsqlLineColumn(request, profileNode->line, profileNode->column);
}
}
}
@ -1441,8 +1464,13 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
if (exeState.exit)
{
if (attachment->isProfilerActive() && !request->hasInternalStatement())
request->req_profiler_perf_counter += profilerCallAfterPsqlLineColumn() - initialPerfCounter;
if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
{
const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
profilerCallAfterPsqlLineColumn(), profilerInitialTicks, profilerInitialAccumulatedOverhead);
request->req_profiler_ticks += elapsedTicks;
}
return node;
}
@ -1484,8 +1512,13 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
}
} // while()
if (attachment->isProfilerActive() && !request->hasInternalStatement())
request->req_profiler_perf_counter += profilerCallAfterPsqlLineColumn() - initialPerfCounter;
if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
{
const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
profilerCallAfterPsqlLineColumn(), profilerInitialTicks, profilerInitialAccumulatedOverhead);
request->req_profiler_ticks += elapsedTicks;
}
request->adjustCallerStats();
@ -1512,10 +1545,10 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
request->invalidateTimeStamp();
release_blobs(tdbb, request);
if (attachment->isProfilerActive() && !request->hasInternalStatement())
if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
{
ProfilerManager::Stats stats(request->req_profiler_perf_counter);
attachment->getProfilerManager(tdbb)->onRequestFinish(request, stats);
ProfilerManager::Stats stats(request->req_profiler_ticks);
profilerManager->onRequestFinish(request, stats);
}
}

View File

@ -56,62 +56,18 @@ RecordSource::RecordSource(CompilerScratch* csb)
void RecordSource::open(thread_db* tdbb) const
{
const auto attachment = tdbb->getAttachment();
const auto request = tdbb->getRequest();
const auto profilerManager = attachment->isProfilerActive() && !request->hasInternalStatement() ?
attachment->getProfilerManager(tdbb) :
nullptr;
const SINT64 lastPerfCounter = profilerManager ?
fb_utils::query_performance_counter() :
0;
if (profilerManager)
{
profilerManager->prepareRecSource(tdbb, request, this);
profilerManager->beforeRecordSourceOpen(request, this);
}
ProfilerManager::RecordSourceStopWatcher profilerRecordSourceStopWatcher(tdbb, this,
ProfilerManager::RecordSourceStopWatcher::Event::OPEN);
internalOpen(tdbb);
if (profilerManager)
{
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
profilerManager->afterRecordSourceOpen(request, this, stats);
}
}
bool RecordSource::getRecord(thread_db* tdbb) const
{
const auto attachment = tdbb->getAttachment();
const auto request = tdbb->getRequest();
ProfilerManager::RecordSourceStopWatcher profilerRecordSourceStopWatcher(tdbb, this,
ProfilerManager::RecordSourceStopWatcher::Event::GET_RECORD);
const auto profilerManager = attachment->isProfilerActive() && !request->hasInternalStatement() ?
attachment->getProfilerManager(tdbb) :
nullptr;
const SINT64 lastPerfCounter = profilerManager ?
fb_utils::query_performance_counter() :
0;
if (profilerManager)
{
profilerManager->prepareRecSource(tdbb, request, this);
profilerManager->beforeRecordSourceGetRecord(request, this);
}
const auto ret = internalGetRecord(tdbb);
if (profilerManager)
{
const SINT64 currentPerfCounter = fb_utils::query_performance_counter();
ProfilerManager::Stats stats(currentPerfCounter - lastPerfCounter);
profilerManager->afterRecordSourceGetRecord(request, this, stats);
}
return ret;
return internalGetRecord(tdbb);
}
string RecordSource::printName(thread_db* tdbb, const string& name, bool quote)

View File

@ -410,7 +410,7 @@ public:
RuntimeStatistics req_stats;
RuntimeStatistics req_base_stats;
AffectedRows req_records_affected; // records affected by the last statement
FB_UINT64 req_profiler_perf_counter; // profiler performance counter
FB_UINT64 req_profiler_ticks; // profiler ticks
const StmtNode* req_next; // next node for execution
EDS::Statement* req_ext_stmt; // head of list of active dynamic statements