diff --git a/builds/win32/msvc15/engine_static.vcxproj b/builds/win32/msvc15/engine_static.vcxproj
index e561ec88c72..0dad8e3b53d 100644
--- a/builds/win32/msvc15/engine_static.vcxproj
+++ b/builds/win32/msvc15/engine_static.vcxproj
@@ -126,6 +126,7 @@
+
@@ -344,6 +345,7 @@
+
diff --git a/builds/win32/msvc15/engine_static.vcxproj.filters b/builds/win32/msvc15/engine_static.vcxproj.filters
index f4ebd410f1d..121d60544b0 100644
--- a/builds/win32/msvc15/engine_static.vcxproj.filters
+++ b/builds/win32/msvc15/engine_static.vcxproj.filters
@@ -345,6 +345,9 @@
JRD files
+
+ JRD files
+
JRD files
@@ -980,6 +983,9 @@
Header files
+
+ Header files
+
Header files
diff --git a/doc/sql.extensions/README.profiler.md b/doc/sql.extensions/README.profiler.md
index 8f7dad7b7a3..9f759ff6242 100644
--- a/doc/sql.extensions/README.profiler.md
+++ b/doc/sql.extensions/README.profiler.md
@@ -4,7 +4,7 @@ The profiler allows users to measure performance cost of SQL and PSQL code. It's
This documentation treats the engine and plugin parts as a single thing, in the way the default profiler (`Default_Profiler`) is going to be used.
-The `RDB$PROFILER` package can profile execution of PSQL code, collecting statistics of how many times each line was executed along with its minimum, maximum and accumulated execution times (with nanoseconds precision), as well as open and fetch statistics of implicit and explicit SQL cursors.
+The `RDB$PROFILER` package can profile execution of PSQL code, collecting statistics of how many times each line was executed along with its accumulated execution times (with nanoseconds precision), as well as open and fetch statistics of implicit and explicit SQL cursors. When requested, it also collects minimum and maximum execution times (see "Timing modes").
To collect profile data, a user must first start a profile session with `RDB$PROFILER.START_SESSION`. This function returns a profile session ID which is later stored in the profiler snapshot tables to be queried and analyzed by the user. A profiler session may be local (same attachment) or remote (another attachment).
@@ -22,12 +22,53 @@ A new session may be started when a session is already active. In that case, it
To analyze the collected data, the user must flush the data to the snapshot tables, which can be done by finishing or pausing a session (with `FLUSH` parameter set to `TRUE`), or calling `RDB$PROFILER.FLUSH`. Data is flushed using an autonomous transaction (a transaction started and finished for the specific purpose of profiler data update).
+## Timing modes (FB 6.0)
+
+The profiler collects timings in one of two modes, chosen per session with the `SAMPLING_INTERVAL` parameter of `RDB$PROFILER.START_SESSION`. In both modes, the counters (`COUNTER`, `OPEN_COUNTER` and `FETCH_COUNTER`) are exact, as every event (PSQL statement execution, record source open and fetch) is counted. The modes differ in how elapsed times are obtained.
+
+The mode used by each session is stored in `PLG$PROF_SESSIONS.SAMPLING_INTERVAL`.
+
+### Sampled timings (default)
+
+With `SAMPLING_INTERVAL` greater than `0` (the default is `100`), elapsed times are sampled. Events are not timed individually: a background thread wakes up about every `SAMPLING_INTERVAL` microseconds (the interval is randomly varied by up to 25%, so code that repeats at a similar period is not systematically missed or over-counted), records which request, PSQL line/column and record sources each profiled attachment is executing at that moment, and charges the wall time elapsed since its previous sample to each of them.
+
+As there is no clock read and no plugin call for each event, the overhead is low: in typical PSQL loops and queries, a profiled run takes about 10% more than an unprofiled one.
+
+Consequences:
+- Elapsed times are statistical. The accumulated time of a line, record source or request is accurate when it adds up to many sampling intervals, no matter whether it comes from a few long executions or from many executions shorter than the interval. The relative error is about `1 / sqrt(number of samples)`: about 10% for an item with 10 ms in total at the default interval, and about 3% for 100 ms. Items with only about a millisecond in total are approximate, and may get no time at all.
+- Times are inclusive, like in measured mode: the time of a line or record source includes the routines it calls and the record sources it reads from.
+- Times include the small overhead of the profiler while the statements run, but not the time spent by the profiler flushing its data.
+- `MIN_ELAPSED_TIME`, `MAX_ELAPSED_TIME`, `OPEN_MIN_ELAPSED_TIME`, `OPEN_MAX_ELAPSED_TIME`, `FETCH_MIN_ELAPSED_TIME` and `FETCH_MAX_ELAPSED_TIME` are `NULL`, as individual executions are not timed. The average time of an execution can still be calculated from the accumulated time and the counter, like the `AVG_ELAPSED_TIME` columns of the auxiliary views do.
+
+A smaller interval gives more samples, so more precise times for short items. From `1000` down to the default `100`, the overhead is practically the same; at `50`, it may be slightly higher. Valid values are from `50` to `1000000` microseconds.
+
+### Measured timings
+
+With `SAMPLING_INTERVAL` set to `0`, the elapsed time of every event is measured by reading the clock before and after it, as in previous versions.
+
+```sql
+select rdb$profiler.start_session('Measured', sampling_interval => 0) from rdb$database;
+```
+
+Consequences:
+- Minimum and maximum times of individual executions are reported.
+- The overhead is much higher: a profiled run may take about two or three times the unprofiled time, as each event reads the clock and calls the profiler plugin.
+- The time spent by the profiler itself is measured and subtracted from the reported times, so they approximate the times without profiler. The correction is approximate: deeply nested record sources with very frequent fetches may be under-reported by 10% to 15%.
+
+### Choosing a mode
+
+Use the default sampled timings to find where time is spent, which is what accumulated times are for. Use measured timings when the minimum and maximum times of individual executions are needed, preferably in a session limited to the code being analyzed, as its overhead is higher.
+
+Profiler plugins that do not implement the `IProfilerSession` methods for aggregated statistics (`addPsqlLineColumnStats`, `addRecordSourceOpenStats` and `addRecordSourceGetRecordStats`) always receive measured timings, whatever `SAMPLING_INTERVAL` is.
+
+Plugins that implement them receive no per-event calls when timings are sampled: `beforePsqlLineColumn`, `afterPsqlLineColumn`, `beforeRecordSourceOpen`, `afterRecordSourceOpen`, `beforeRecordSourceGetRecord` and `afterRecordSourceGetRecord` are not called, whatever flags `IProfilerSession::getFlags` returns, and the statistics are delivered with the `add*Stats` methods instead. The interval is passed to `IProfilerSession::setSamplingInterval` when the session starts. A plugin that needs the per-event calls should be used with `SAMPLING_INTERVAL` set to `0`.
+
## Important
When the profiler is active, there is an overhead that makes everything slower.
This overhead varies depending on OS, kernel version and CPU hardware and it's difficult to predict.
-But sometimes this overhead may be very high, say, greater than 100%.
+But sometimes this overhead may be very high, say, greater than 100%, mainly when timings are measured (`SAMPLING_INTERVAL` set to `0`).
If this happens in Linux, you may see what clock source it's using with this command:
@@ -160,12 +201,15 @@ When `DETAILED_REQUESTS` is used, `PLG$PROF_REQUESTS` will store detailed reques
When `DETAILED_REQUESTS` is not used (the default), `PLG$PROF_REQUESTS` stores an aggregated record per statement, using `REQUEST_ID = 0`.
+`SAMPLING_INTERVAL` chooses how elapsed times are collected (see "Timing modes"). A value from `50` to `1000000` samples the timings with that interval in microseconds; `0` measures every event, also reporting minimum and maximum times. `NULL` means the default `100`. Other values raise an error.
+
Input parameters:
- `DESCRIPTION` type `VARCHAR(255) CHARACTER SET UTF8` default `NULL`
- `FLUSH_INTERVAL` type `INTEGER` default `NULL`
- `ATTACHMENT_ID` type `BIGINT` default `NULL` (meaning `CURRENT_CONNECTION`)
- `PLUGIN_NAME` type `VARCHAR(255) CHARACTER SET UTF8` default `NULL`
- `PLUGIN_OPTIONS` type `VARCHAR(255) CHARACTER SET UTF8` default `NULL`
+ - `SAMPLING_INTERVAL` type `INTEGER` default `100`
Return type: `BIGINT NOT NULL`.
@@ -265,6 +309,8 @@ Below is the list of snapshot views that expose profile data.
- `DESCRIPTION` type `VARCHAR(255) CHARACTER SET UTF8` - Description passed in `RDB$PROFILER.START_SESSION`
- `START_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment the profile session was started
- `FINISH_TIMESTAMP` type `TIMESTAMP WITH TIME ZONE` - Moment the profile session was finished (NULL when not finished)
+ - `SAMPLING_INTERVAL` type `INTEGER` - Interval (in microseconds) of sampled timings, `0` when timings were measured
+ for every event, NULL for sessions recorded by previous versions
- Primary key: `PROFILE_ID`
## Table `PLG$PROF_STATEMENTS`
@@ -325,8 +371,8 @@ Below is the list of snapshot views that expose profile data.
- `LINE_NUM` type `INTEGER` - Line number of the statement
- `COLUMN_NUM` type `INTEGER` - Column number of the statement
- `COUNTER` type `BIGINT` - Number of executed times 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
+ - `MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a line/column execution, `NULL` when timings are sampled
+ - `MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a line/column execution, `NULL` when timings are sampled
- `TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the line/column executions
- Primary key: `PROFILE_ID, STATEMENT_ID, REQUEST_ID, LINE_NUM, COLUMN_NUM`
@@ -339,12 +385,12 @@ Below is the list of snapshot views that expose profile data.
- `CURSOR_ID` type `INTEGER` - Cursor ID
- `RECORD_SOURCE_ID` type `INTEGER` - Record source ID
- `OPEN_COUNTER` type `BIGINT` - Number of open times 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_MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a record source open, `NULL` when timings are sampled
+ - `OPEN_MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a record source open, `NULL` when timings are sampled
- `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_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_MIN_ELAPSED_TIME` type `BIGINT` - Minimal elapsed time (in nanoseconds) of a record source fetch, `NULL` when timings are sampled
+ - `FETCH_MAX_ELAPSED_TIME` type `BIGINT` - Maximum elapsed time (in nanoseconds) of a record source fetch, `NULL` when timings are sampled
- `FETCH_TOTAL_ELAPSED_TIME` type `BIGINT` - Accumulated elapsed time (in nanoseconds) of the record source fetches
- Primary key: `PROFILE_ID, STATEMENT_ID, REQUEST_ID, CURSOR_ID, RECORD_SOURCE_ID`
diff --git a/src/common/PerformanceStopWatch.h b/src/common/PerformanceStopWatch.h
index 791d075a35f..d06befe2b58 100644
--- a/src/common/PerformanceStopWatch.h
+++ b/src/common/PerformanceStopWatch.h
@@ -29,34 +29,62 @@
namespace Firebird
{
-// This class is a wrapper to fb_utils::query_performance_counter() with a way to let
-// the caller amortize timings expended in that function calls.
+// This class is a wrapper to fb_utils::query_performance_counter() that lets the caller exclude
+// the time spent by the caller's own bookkeeping from the measured intervals.
+//
+// The bookkeeping done for an event is bracketed by queryTicks() and endOverhead(). The bracketed
+// time is accumulated and subtracted from every interval that encloses it, so a parent (a request,
+// a record source) doesn't get charged with the cost of measuring its children.
+// Each clock read samples the time somewhere in the middle of its own execution, so the part of
+// the reads that falls outside the brackets is accounted with the cost of one read (queryCost).
+// That cost depends on the CPU frequency, which changes while running (a core that was idle runs
+// the first reads slower), so it's measured again every CALIBRATION_INTERVAL_MS, inside a bracket.
+// Overheads are kept in 1/OVERHEAD_SCALE ticks, as a read may cost less than a tick (on Windows).
+//
// This class is not thread-safe.
class PerformanceStopWatch
{
public:
- PerformanceStopWatch() = default;
+ PerformanceStopWatch()
+ : calibrationIntervalTicks(fb_utils::query_performance_frequency() * CALIBRATION_INTERVAL_MS / 1000),
+ queryCost(measureQueryCost()),
+ nextCalibrationTicks(fb_utils::query_performance_counter() + calibrationIntervalTicks)
+ {
+ }
+
PerformanceStopWatch(const PerformanceStopWatch&) = delete;
PerformanceStopWatch& operator=(const PerformanceStopWatch&) = delete;
public:
- SINT64 queryTicks()
+ SINT64 queryTicks() const
{
- const auto initialTicks = fb_utils::query_performance_counter();
+ return fb_utils::query_performance_counter();
+ }
- if ((initialTicks - lastMeasuredTicks) * 1000 / fb_utils::query_performance_frequency() >
- OVERHEAD_CALC_FREQUENCY_MS)
- {
- const auto currentTicks = lastMeasuredTicks = fb_utils::query_performance_counter();
- lastOverhead = currentTicks - initialTicks;
- accumulatedOverhead += lastOverhead + lastOverhead;
- return currentTicks;
- }
- else
+ // Starts a measured interval without preceding bookkeeping. The cost of this read is still
+ // overhead for the enclosing intervals.
+ SINT64 beginInterval()
+ {
+ accumulatedOverhead += queryCost;
+ return fb_utils::query_performance_counter();
+ }
+
+ // Ends bookkeeping started at overheadStartTicks (a value returned by queryTicks).
+ // Returns the ticks that start the next measured interval.
+ SINT64 endOverhead(SINT64 overheadStartTicks)
+ {
+ SINT64 currentTicks = fb_utils::query_performance_counter();
+
+ if (currentTicks >= nextCalibrationTicks)
{
- accumulatedOverhead += lastOverhead;
- return initialTicks;
+ queryCost = measureQueryCost();
+ currentTicks = fb_utils::query_performance_counter();
+ nextCalibrationTicks = currentTicks + calibrationIntervalTicks;
}
+
+ accumulatedOverhead += (currentTicks - overheadStartTicks) * OVERHEAD_SCALE + queryCost;
+
+ return currentTicks;
}
SINT64 getAccumulatedOverhead() const
@@ -64,27 +92,50 @@ class PerformanceStopWatch
return accumulatedOverhead;
}
+ // Returns the ticks between previousTicks and currentTicks, excluding the bookkeeping done in
+ // between and the parts of the two clock reads inside the interval.
SINT64 getElapsedTicksAndAdjustOverhead(SINT64 currentTicks, SINT64 previousTicks,
- SINT64 previousAccumulatedOverhead)
+ SINT64 previousAccumulatedOverhead) const
{
- const SINT64 overhead = MAX(accumulatedOverhead - previousAccumulatedOverhead, 0);
- const SINT64 elapsedTicks = currentTicks - previousTicks - overhead;
+ const SINT64 overheadTicks = (accumulatedOverhead - previousAccumulatedOverhead + queryCost) / OVERHEAD_SCALE;
+ return MAX(currentTicks - previousTicks - overheadTicks, 0);
+ }
- if (elapsedTicks >= 0)
- return elapsedTicks;
+private:
+ // The average cost of a read in batches of consecutive reads. The difference between just two
+ // consecutive reads underestimates it, as the CPU overlaps their execution. The minimum of the
+ // batches is used, so preemptions and cold caches don't inflate it.
+ static SINT64 measureQueryCost()
+ {
+ constexpr unsigned BATCHES = 8;
+ constexpr unsigned READS_PER_BATCH = 256;
- accumulatedOverhead += elapsedTicks;
+ SINT64 minTicks = 0;
- return 0;
- }
+ for (unsigned batch = 0; batch < BATCHES; ++batch)
+ {
+ const SINT64 startTicks = fb_utils::query_performance_counter();
-public:
- static constexpr SINT64 OVERHEAD_CALC_FREQUENCY_MS = 30 * 1000;
+ for (unsigned i = 0; i < READS_PER_BATCH; ++i)
+ fb_utils::query_performance_counter();
+
+ const SINT64 ticks = fb_utils::query_performance_counter() - startTicks;
+
+ if (batch == 0 || ticks < minTicks)
+ minTicks = ticks;
+ }
+
+ return MAX(minTicks * OVERHEAD_SCALE / (READS_PER_BATCH + 1), 0);
+ }
private:
- SINT64 lastMeasuredTicks = 0;
- SINT64 lastOverhead = 0;
- SINT64 accumulatedOverhead = 0;
+ static constexpr SINT64 OVERHEAD_SCALE = 256;
+ static constexpr SINT64 CALIBRATION_INTERVAL_MS = 100;
+
+ const SINT64 calibrationIntervalTicks;
+ SINT64 queryCost; // in 1/OVERHEAD_SCALE ticks
+ SINT64 nextCalibrationTicks;
+ SINT64 accumulatedOverhead = 0; // in 1/OVERHEAD_SCALE ticks
};
} // namespace Firebird
diff --git a/src/common/TimeZoneUtil.cpp b/src/common/TimeZoneUtil.cpp
index ef092ce5500..6ef630a3f71 100644
--- a/src/common/TimeZoneUtil.cpp
+++ b/src/common/TimeZoneUtil.cpp
@@ -991,8 +991,6 @@ ISC_TIMESTAMP_TZ TimeZoneUtil::getCurrentSystemTimeStamp()
ISC_TIMESTAMP_TZ TimeZoneUtil::getCurrentGmtTimeStamp()
{
- NoThrowTimeStamp now;
-
// ASF: This comment is copied from NoThrowTimeStamp::getCurrentTimeStamp.
// NS: We round generated timestamps to whole millisecond.
// Not many applications can deal with fractional milliseconds properly and
@@ -1000,14 +998,31 @@ ISC_TIMESTAMP_TZ TimeZoneUtil::getCurrentGmtTimeStamp()
// is going to to be somewhere in range between 1 ms (like on UNIX/Risc)
// and 53 ms (such as Win9X)
- int milliseconds;
+ // The system time is a linear count from an epoch, without leap seconds, so it's converted directly
+ // instead of being decoded to a calendar date and encoded back. This is called for every request when
+ // profiling, so it must be cheap.
+
+ constexpr SINT64 MILLISECONDS_PER_DAY = NoThrowTimeStamp::SECONDS_PER_DAY * 1000;
+
+ SINT64 days;
+ SINT64 millisecondsOfDay;
#ifdef WIN_NT
- SYSTEMTIME stUtc;
- GetSystemTime(&stUtc);
- milliseconds = stUtc.wMilliseconds;
+ constexpr ISC_DATE FILETIME_DATE = NoThrowTimeStamp::UNIX_DATE - 134774; // 01.01.1601
+
+ FILETIME ftUtc;
+ GetSystemTimeAsFileTime(&ftUtc); // in 100ns units since 01.01.1601
+
+ ULARGE_INTEGER ftValue;
+ ftValue.LowPart = ftUtc.dwLowDateTime;
+ ftValue.HighPart = ftUtc.dwHighDateTime;
+
+ const SINT64 milliseconds = SINT64(ftValue.QuadPart / 10000);
+ days = FILETIME_DATE + milliseconds / MILLISECONDS_PER_DAY;
+ millisecondsOfDay = milliseconds % MILLISECONDS_PER_DAY;
#else
- time_t seconds; // UTC time
+ SINT64 seconds; // UTC time since 01.01.1970
+ int milliseconds;
#ifdef HAVE_GETTIMEOFDAY
struct timeval tp;
@@ -1020,42 +1035,14 @@ ISC_TIMESTAMP_TZ TimeZoneUtil::getCurrentGmtTimeStamp()
seconds = time_buffer.time;
milliseconds = time_buffer.millitm;
#endif
-#endif // WIN_NT
- const int fractions = milliseconds * ISC_TIME_SECONDS_PRECISION / 1000;
-
-#ifdef WIN_NT
- // Manually convert SYSTEMTIME to "struct tm" used below
-
- struct tm times, *ptimes = ×
-
- times.tm_sec = stUtc.wSecond; // seconds after the minute - [0,59]
- times.tm_min = stUtc.wMinute; // minutes after the hour - [0,59]
- times.tm_hour = stUtc.wHour; // hours since midnight - [0,23]
- times.tm_mday = stUtc.wDay; // day of the month - [1,31]
- times.tm_mon = stUtc.wMonth - 1; // months since January - [0,11]
- times.tm_year = stUtc.wYear - 1900; // years since 1900
- times.tm_wday = stUtc.wDayOfWeek; // days since Sunday - [0,6]
-
- // --- no used for encoding below
- times.tm_yday = 0; // days since January 1 - [0,365]
- times.tm_isdst = -1; // daylight savings time flag
-#else
-#ifdef HAVE_GMTIME_R
- struct tm times, *ptimes = ×
- if (!gmtime_r(&seconds, ×))
- system_call_failed::raise("gmtime_r");
-#else
- struct tm *ptimes = gmtime(&seconds);
- if (!ptimes)
- system_call_failed::raise("gmtime");
-#endif
+ days = NoThrowTimeStamp::UNIX_DATE + seconds / NoThrowTimeStamp::SECONDS_PER_DAY;
+ millisecondsOfDay = (seconds % NoThrowTimeStamp::SECONDS_PER_DAY) * 1000 + milliseconds;
#endif // WIN_NT
- now.encode(ptimes, fractions);
-
ISC_TIMESTAMP_TZ tsTz;
- tsTz.utc_timestamp = now.value();
+ tsTz.utc_timestamp.timestamp_date = ISC_DATE(days);
+ tsTz.utc_timestamp.timestamp_time = ISC_TIME(millisecondsOfDay * (ISC_TIME_SECONDS_PRECISION / 1000));
tsTz.time_zone = GMT_ZONE;
return tsTz;
diff --git a/src/common/utils.cpp b/src/common/utils.cpp
index 00740a86caf..9eb712284ba 100644
--- a/src/common/utils.cpp
+++ b/src/common/utils.cpp
@@ -775,35 +775,25 @@ FetchPassResult fetchPassword(const Firebird::PathName& name, const char*& passw
#ifdef WIN_NT
static SINT64 saved_frequency = 0;
-#elif defined(HAVE_CLOCK_GETTIME)
-constexpr SINT64 BILLION = 1'000'000'000;
#endif
// Returns current value of performance counter
-SINT64 query_performance_counter()
+#if defined(WIN_NT) || !defined(HAVE_CLOCK_GETTIME)
+SINT64 query_performance_counter() noexcept
{
#if defined(WIN_NT)
-
// Use Windows performance counters
LARGE_INTEGER counter;
if (QueryPerformanceCounter(&counter) == 0)
return 0;
return counter.QuadPart;
-#elif defined(HAVE_CLOCK_GETTIME)
-
- // Use high-resolution clock
- struct timespec tp;
- if (clock_gettime(CLOCK_MONOTONIC_RAW, &tp) != 0)
- return 0;
-
- return static_cast(tp.tv_sec) * BILLION + tp.tv_nsec;
#else
-
// This is not safe because of possible wrapping and very imprecise
return clock();
#endif
}
+#endif
// Returns frequency of performance counter in Hz
diff --git a/src/common/utils_proto.h b/src/common/utils_proto.h
index a35f1f01be4..46e9ddc2490 100644
--- a/src/common/utils_proto.h
+++ b/src/common/utils_proto.h
@@ -32,6 +32,9 @@
#include
#include
#include
+#if !defined(WIN_NT) && defined(HAVE_CLOCK_GETTIME)
+#include
+#endif
#include "../common/classes/fb_string.h"
#include "../common/classes/array.h"
@@ -208,8 +211,21 @@ namespace fb_utils
};
FetchPassResult fetchPassword(const Firebird::PathName& name, const char*& password);
+ inline constexpr SINT64 BILLION = 1'000'000'000;
+
// Returns current value of performance counter
- SINT64 query_performance_counter();
+#if !defined(WIN_NT) && defined(HAVE_CLOCK_GETTIME)
+ inline SINT64 query_performance_counter() noexcept
+ {
+ struct timespec tp;
+ if (clock_gettime(CLOCK_MONOTONIC_RAW, &tp) != 0)
+ return 0;
+
+ return static_cast(tp.tv_sec) * BILLION + tp.tv_nsec;
+ }
+#else
+ SINT64 query_performance_counter() noexcept;
+#endif
// Returns frequency of performance counter in Hz
SINT64 query_performance_frequency();
diff --git a/src/dsql/Nodes.h b/src/dsql/Nodes.h
index bba06c46ee0..debd87dc42d 100644
--- a/src/dsql/Nodes.h
+++ b/src/dsql/Nodes.h
@@ -1634,11 +1634,14 @@ class StmtNode : public DmlNode
};
public:
+ static constexpr UCHAR FLAG_LINE_COLUMN = 0x01; // line/column are set
+ static constexpr UCHAR FLAG_NOT_PROFILED = 0x02; // not profiled (wrapper and declaration nodes)
+ static constexpr UCHAR FLAG_PROFILE_ON_RETURN = 0x04; // also profiled on req_return/req_sync (loops that fetch there)
+
+ static constexpr ULONG MAX_PROFILE_SLOT = (1 << 24) - 1;
+
explicit StmtNode(Type aType, MemoryPool& pool)
- : DmlNode(pool),
- parentStmt(NULL),
- impureOffset(0),
- hasLineColumn(false)
+ : DmlNode(pool)
{
}
@@ -1683,24 +1686,13 @@ class StmtNode : public DmlNode
return NULL;
}
- enum class ProfileMode : UCHAR
- {
- NONE, // not profiled (wrapper and declaration nodes)
- EVALUATE, // profiled when evaluated
- EVALUATE_RETURN // also profiled on req_return/req_sync (loops that fetch there)
- };
-
- virtual ProfileMode getProfileMode() const
- {
- return ProfileMode::EVALUATE;
- }
-
virtual const StmtNode* execute(thread_db* tdbb, Request* request, ExeState* exeState) const = 0;
public:
NestConst parentStmt;
- ULONG impureOffset; // Inpure offset from request block.
- bool hasLineColumn;
+ ULONG impureOffset = 0; // Inpure offset from request block.
+ ULONG flags : 8 = 0;
+ ULONG profileSlot : 24 = 0; // Dense index of line/column in the statement, used by the sampling profiler
};
diff --git a/src/dsql/StmtNodes.cpp b/src/dsql/StmtNodes.cpp
index e09b463f64a..c60b87fe843 100644
--- a/src/dsql/StmtNodes.cpp
+++ b/src/dsql/StmtNodes.cpp
@@ -1083,7 +1083,7 @@ void BulkInsertNode::assignValues(thread_db* tdbb, Request* request, jrd_rel* re
auto assign = nodeAs(stmt);
//EXE_assignment(tdbb, assign);
- if (assign->hasLineColumn)
+ if (assign->flags & FLAG_LINE_COLUMN)
{
request->req_src_line = assign->line;
request->req_src_column = assign->column;
@@ -1277,7 +1277,7 @@ const StmtNode* CompoundStmtNode::execute(thread_db* tdbb, Request* request, Exe
{
const StmtNode* stmt = i->getObject();
- if (stmt->hasLineColumn)
+ if (stmt->flags & FLAG_LINE_COLUMN)
{
request->req_src_line = stmt->line;
request->req_src_column = stmt->column;
@@ -6718,7 +6718,7 @@ void ExitNode::genBlr(DsqlCompilerScratch* dsqlScratch)
{
dsqlScratch->appendUChar(blr_begin);
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
dsqlScratch->appendUChar(blr_leave);
@@ -6856,7 +6856,7 @@ void ForNode::genBlr(DsqlCompilerScratch* dsqlScratch)
dsqlScratch->appendUChar(dsqlLabelNumber);
// Put src info for blr_for.
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
}
@@ -6992,7 +6992,7 @@ const StmtNode* ForNode::execute(thread_db* tdbb, Request* request, ExeState* /*
case Request::req_sync:
{
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
{
request->req_src_line = line;
request->req_src_column = column;
@@ -7224,7 +7224,7 @@ void ForRangeNode::genBlr(DsqlCompilerScratch* dsqlScratch)
fb_assert(dsqlLabelNumber < MAX_UCHAR);
dsqlScratch->appendUChar((UCHAR) dsqlLabelNumber);
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
dsqlScratch->appendUChar(blr_for_range);
@@ -7565,7 +7565,7 @@ LineColumnNode* LineColumnNode::dsqlPass(DsqlCompilerScratch* dsqlScratch)
statement->line = line;
statement->column = column;
- statement->hasLineColumn = true;
+ statement->flags |= FLAG_LINE_COLUMN;
return this;
}
@@ -7799,7 +7799,7 @@ void LoopNode::genBlr(DsqlCompilerScratch* dsqlScratch)
dsqlScratch->appendUChar(blr_loop);
dsqlScratch->appendUChar(blr_begin);
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
dsqlScratch->appendUChar(blr_if);
@@ -8366,7 +8366,7 @@ void MergeNode::genBlr(DsqlCompilerScratch* dsqlScratch)
}
// Put src info for blr_for.
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
// Generate FOR loop
@@ -11274,7 +11274,7 @@ void ReturnNode::genBlr(DsqlCompilerScratch* dsqlScratch)
{
dsqlScratch->appendUChar(blr_begin);
- if (hasLineColumn)
+ if (flags & FLAG_LINE_COLUMN)
dsqlScratch->putDebugSrcInfo(line, column);
dsqlScratch->appendUChar(blr_assignment);
diff --git a/src/dsql/StmtNodes.h b/src/dsql/StmtNodes.h
index ae3681acb0c..6de87f44791 100644
--- a/src/dsql/StmtNodes.h
+++ b/src/dsql/StmtNodes.h
@@ -228,16 +228,12 @@ class CompoundStmtNode : public TypedNode
dsqlForceSingular(false),
withLock(false)
{
+ flags |= FLAG_PROFILE_ON_RETURN;
}
public:
@@ -975,11 +960,6 @@ class ForNode final : public TypedNode
StmtNode* pass1(thread_db* tdbb, CompilerScratch* csb) override;
StmtNode* pass2(thread_db* tdbb, CompilerScratch* csb) override;
- ProfileMode getProfileMode() const override
- {
- return ProfileMode::EVALUATE_RETURN;
- }
-
const StmtNode* execute(thread_db* tdbb, Request* request, ExeState* exeState) const override;
bool isWriteLockMode(Request* request) const;
diff --git a/src/include/firebird/FirebirdInterface.idl b/src/include/firebird/FirebirdInterface.idl
index 97a2149574f..1bb45c02dac 100644
--- a/src/include/firebird/FirebirdInterface.idl
+++ b/src/include/firebird/FirebirdInterface.idl
@@ -1891,6 +1891,8 @@ interface ProfilerPlugin : PluginBase
interface ProfilerSession : Disposable
{
+ // Flags of the per-event before* and after* calls, which are made only when timings are measured.
+ // When they are sampled (see setSamplingInterval), these flags are ignored.
const uint FLAG_BEFORE_EVENTS = 0x1;
const uint FLAG_AFTER_EVENTS = 0x2;
@@ -1933,6 +1935,20 @@ version: // 5.0 => 6.0 Alpha1
void defineStatement2(Status status, int64 statementId, int64 parentStatementId,
const string type, const string schemaName, const string packageName, const string routineName,
const string sqlText);
+
+ // Aggregated statistics, used when timings are sampled instead of measured for every event.
+ // counter is exact and may be zero when only elapsed time is reported. Min/max are unknown.
+ void addPsqlLineColumnStats(int64 statementId, int64 requestId, uint line, uint column,
+ uint64 counter, uint64 elapsedTicks);
+ void addRecordSourceOpenStats(int64 statementId, int64 requestId, uint cursorId, uint recSourceId,
+ uint64 counter, uint64 elapsedTicks);
+ void addRecordSourceGetRecordStats(int64 statementId, int64 requestId, uint cursorId, uint recSourceId,
+ uint64 counter, uint64 elapsedTicks);
+
+ // Called after the session starts. 0 means every event is measured and reported with the after* methods.
+ // Otherwise timings are sampled with this interval (in microseconds) and reported with the add*Stats methods,
+ // and no before* or after* method is called, whatever getFlags returns.
+ void setSamplingInterval(uint microseconds);
}
interface ProfilerStats : Versioned
diff --git a/src/include/firebird/IdlFbInterfaces.h b/src/include/firebird/IdlFbInterfaces.h
index ea7b89c20d0..355c63939f6 100644
--- a/src/include/firebird/IdlFbInterfaces.h
+++ b/src/include/firebird/IdlFbInterfaces.h
@@ -7649,6 +7649,10 @@ namespace Firebird
void (CLOOP_CARG *beforeRecordSourceGetRecord)(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) CLOOP_NOEXCEPT;
void (CLOOP_CARG *afterRecordSourceGetRecord)(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) CLOOP_NOEXCEPT;
void (CLOOP_CARG *defineStatement2)(IProfilerSession* self, IStatus* status, ISC_INT64 statementId, ISC_INT64 parentStatementId, const char* type, const char* schemaName, const char* packageName, const char* routineName, const char* sqlText) CLOOP_NOEXCEPT;
+ void (CLOOP_CARG *addPsqlLineColumnStats)(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT;
+ void (CLOOP_CARG *addRecordSourceOpenStats)(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT;
+ void (CLOOP_CARG *addRecordSourceGetRecordStats)(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT;
+ void (CLOOP_CARG *setSamplingInterval)(IProfilerSession* self, unsigned microseconds) CLOOP_NOEXCEPT;
};
protected:
@@ -7765,6 +7769,42 @@ namespace Firebird
static_cast(this->cloopVTable)->defineStatement2(this, status, statementId, parentStatementId, type, schemaName, packageName, routineName, sqlText);
StatusType::checkException(status);
}
+
+ void addPsqlLineColumnStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 counter, ISC_UINT64 elapsedTicks)
+ {
+ if (cloopVTable->version < 4)
+ {
+ return;
+ }
+ static_cast(this->cloopVTable)->addPsqlLineColumnStats(this, statementId, requestId, line, column, counter, elapsedTicks);
+ }
+
+ void addRecordSourceOpenStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks)
+ {
+ if (cloopVTable->version < 4)
+ {
+ return;
+ }
+ static_cast(this->cloopVTable)->addRecordSourceOpenStats(this, statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ }
+
+ void addRecordSourceGetRecordStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks)
+ {
+ if (cloopVTable->version < 4)
+ {
+ return;
+ }
+ static_cast(this->cloopVTable)->addRecordSourceGetRecordStats(this, statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ }
+
+ void setSamplingInterval(unsigned microseconds)
+ {
+ if (cloopVTable->version < 4)
+ {
+ return;
+ }
+ static_cast(this->cloopVTable)->setSamplingInterval(this, microseconds);
+ }
};
#define FIREBIRD_IPROFILER_STATS_VERSION 2u
@@ -22204,6 +22244,10 @@ namespace Firebird
this->beforeRecordSourceGetRecord = &Name::cloopbeforeRecordSourceGetRecordDispatcher;
this->afterRecordSourceGetRecord = &Name::cloopafterRecordSourceGetRecordDispatcher;
this->defineStatement2 = &Name::cloopdefineStatement2Dispatcher;
+ this->addPsqlLineColumnStats = &Name::cloopaddPsqlLineColumnStatsDispatcher;
+ this->addRecordSourceOpenStats = &Name::cloopaddRecordSourceOpenStatsDispatcher;
+ this->addRecordSourceGetRecordStats = &Name::cloopaddRecordSourceGetRecordStatsDispatcher;
+ this->setSamplingInterval = &Name::cloopsetSamplingIntervalDispatcher;
}
} vTable;
@@ -22416,6 +22460,54 @@ namespace Firebird
}
}
+ static void CLOOP_CARG cloopaddPsqlLineColumnStatsDispatcher(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT
+ {
+ try
+ {
+ static_cast(self)->Name::addPsqlLineColumnStats(statementId, requestId, line, column, counter, elapsedTicks);
+ }
+ catch (...)
+ {
+ StatusType::catchException(0);
+ }
+ }
+
+ static void CLOOP_CARG cloopaddRecordSourceOpenStatsDispatcher(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT
+ {
+ try
+ {
+ static_cast(self)->Name::addRecordSourceOpenStats(statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ }
+ catch (...)
+ {
+ StatusType::catchException(0);
+ }
+ }
+
+ static void CLOOP_CARG cloopaddRecordSourceGetRecordStatsDispatcher(IProfilerSession* self, ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) CLOOP_NOEXCEPT
+ {
+ try
+ {
+ static_cast(self)->Name::addRecordSourceGetRecordStats(statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ }
+ catch (...)
+ {
+ StatusType::catchException(0);
+ }
+ }
+
+ static void CLOOP_CARG cloopsetSamplingIntervalDispatcher(IProfilerSession* self, unsigned microseconds) CLOOP_NOEXCEPT
+ {
+ try
+ {
+ static_cast(self)->Name::setSamplingInterval(microseconds);
+ }
+ catch (...)
+ {
+ StatusType::catchException(0);
+ }
+ }
+
static void CLOOP_CARG cloopdisposeDispatcher(IDisposable* self) CLOOP_NOEXCEPT
{
try
@@ -22458,6 +22550,10 @@ namespace Firebird
virtual void beforeRecordSourceGetRecord(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId) = 0;
virtual void afterRecordSourceGetRecord(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, IProfilerStats* stats) = 0;
virtual void defineStatement2(StatusType* status, ISC_INT64 statementId, ISC_INT64 parentStatementId, const char* type, const char* schemaName, const char* packageName, const char* routineName, const char* sqlText) = 0;
+ virtual void addPsqlLineColumnStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned line, unsigned column, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) = 0;
+ virtual void addRecordSourceOpenStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) = 0;
+ virtual void addRecordSourceGetRecordStats(ISC_INT64 statementId, ISC_INT64 requestId, unsigned cursorId, unsigned recSourceId, ISC_UINT64 counter, ISC_UINT64 elapsedTicks) = 0;
+ virtual void setSamplingInterval(unsigned microseconds) = 0;
};
template
diff --git a/src/include/gen/Firebird.pas b/src/include/gen/Firebird.pas
index 10b376125fd..9b51a3ecded 100644
--- a/src/include/gen/Firebird.pas
+++ b/src/include/gen/Firebird.pas
@@ -792,6 +792,10 @@ ISC_TIMESTAMP_TZ_EX = record
IProfilerSession_beforeRecordSourceGetRecordPtr = procedure(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); cdecl;
IProfilerSession_afterRecordSourceGetRecordPtr = procedure(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); cdecl;
IProfilerSession_defineStatement2Ptr = procedure(this: IProfilerSession; status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; schemaName: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); cdecl;
+ IProfilerSession_addPsqlLineColumnStatsPtr = procedure(this: IProfilerSession; statementId: Int64; requestId: Int64; line: Cardinal; column: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+ IProfilerSession_addRecordSourceOpenStatsPtr = procedure(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+ IProfilerSession_addRecordSourceGetRecordStatsPtr = procedure(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+ IProfilerSession_setSamplingIntervalPtr = procedure(this: IProfilerSession; microseconds: Cardinal); cdecl;
IProfilerStats_getElapsedTicksPtr = function(this: IProfilerStats): QWord; cdecl;
IPerformanceCounters_getObjectCountPtr = function(this: IPerformanceCounters): Cardinal; cdecl;
IPerformanceCounters_getMaxCounterIndexPtr = function(this: IPerformanceCounters): Cardinal; cdecl;
@@ -4094,6 +4098,10 @@ ProfilerSessionVTable = class(DisposableVTable)
beforeRecordSourceGetRecord: IProfilerSession_beforeRecordSourceGetRecordPtr;
afterRecordSourceGetRecord: IProfilerSession_afterRecordSourceGetRecordPtr;
defineStatement2: IProfilerSession_defineStatement2Ptr;
+ addPsqlLineColumnStats: IProfilerSession_addPsqlLineColumnStatsPtr;
+ addRecordSourceOpenStats: IProfilerSession_addRecordSourceOpenStatsPtr;
+ addRecordSourceGetRecordStats: IProfilerSession_addRecordSourceGetRecordStatsPtr;
+ setSamplingInterval: IProfilerSession_setSamplingIntervalPtr;
end;
IProfilerSession = class(IDisposable)
@@ -4117,6 +4125,10 @@ IProfilerSession = class(IDisposable)
procedure beforeRecordSourceGetRecord(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal);
procedure afterRecordSourceGetRecord(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats);
procedure defineStatement2(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; schemaName: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar);
+ procedure addPsqlLineColumnStats(statementId: Int64; requestId: Int64; line: Cardinal; column: Cardinal; counter: QWord; elapsedTicks: QWord);
+ procedure addRecordSourceOpenStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord);
+ procedure addRecordSourceGetRecordStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord);
+ procedure setSamplingInterval(microseconds: Cardinal);
end;
IProfilerSessionImpl = class(IProfilerSession)
@@ -4139,6 +4151,10 @@ IProfilerSessionImpl = class(IProfilerSession)
procedure beforeRecordSourceGetRecord(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal); virtual; abstract;
procedure afterRecordSourceGetRecord(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; stats: IProfilerStats); virtual; abstract;
procedure defineStatement2(status: IStatus; statementId: Int64; parentStatementId: Int64; type_: PAnsiChar; schemaName: PAnsiChar; packageName: PAnsiChar; routineName: PAnsiChar; sqlText: PAnsiChar); virtual; abstract;
+ procedure addPsqlLineColumnStats(statementId: Int64; requestId: Int64; line: Cardinal; column: Cardinal; counter: QWord; elapsedTicks: QWord); virtual; abstract;
+ procedure addRecordSourceOpenStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); virtual; abstract;
+ procedure addRecordSourceGetRecordStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); virtual; abstract;
+ procedure setSamplingInterval(microseconds: Cardinal); virtual; abstract;
end;
ProfilerStatsVTable = class(VersionedVTable)
@@ -10446,6 +10462,42 @@ procedure IProfilerSession.defineStatement2(status: IStatus; statementId: Int64;
FbException.checkException(status);
end;
+procedure IProfilerSession.addPsqlLineColumnStats(statementId: Int64; requestId: Int64; line: Cardinal; column: Cardinal; counter: QWord; elapsedTicks: QWord);
+begin
+ if (vTable.version < 4) then begin
+ end
+ else begin
+ ProfilerSessionVTable(vTable).addPsqlLineColumnStats(Self, statementId, requestId, line, column, counter, elapsedTicks);
+ end;
+end;
+
+procedure IProfilerSession.addRecordSourceOpenStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord);
+begin
+ if (vTable.version < 4) then begin
+ end
+ else begin
+ ProfilerSessionVTable(vTable).addRecordSourceOpenStats(Self, statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ end;
+end;
+
+procedure IProfilerSession.addRecordSourceGetRecordStats(statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord);
+begin
+ if (vTable.version < 4) then begin
+ end
+ else begin
+ ProfilerSessionVTable(vTable).addRecordSourceGetRecordStats(Self, statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ end;
+end;
+
+procedure IProfilerSession.setSamplingInterval(microseconds: Cardinal);
+begin
+ if (vTable.version < 4) then begin
+ end
+ else begin
+ ProfilerSessionVTable(vTable).setSamplingInterval(Self, microseconds);
+ end;
+end;
+
function IProfilerStats.getElapsedTicks(): QWord;
begin
Result := ProfilerStatsVTable(vTable).getElapsedTicks(Self);
@@ -18183,6 +18235,42 @@ procedure IProfilerSessionImpl_defineStatement2Dispatcher(this: IProfilerSession
end
end;
+procedure IProfilerSessionImpl_addPsqlLineColumnStatsDispatcher(this: IProfilerSession; statementId: Int64; requestId: Int64; line: Cardinal; column: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+begin
+ try
+ IProfilerSessionImpl(this).addPsqlLineColumnStats(statementId, requestId, line, column, counter, elapsedTicks);
+ except
+ on e: Exception do FbException.catchException(nil, e);
+ end
+end;
+
+procedure IProfilerSessionImpl_addRecordSourceOpenStatsDispatcher(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+begin
+ try
+ IProfilerSessionImpl(this).addRecordSourceOpenStats(statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ except
+ on e: Exception do FbException.catchException(nil, e);
+ end
+end;
+
+procedure IProfilerSessionImpl_addRecordSourceGetRecordStatsDispatcher(this: IProfilerSession; statementId: Int64; requestId: Int64; cursorId: Cardinal; recSourceId: Cardinal; counter: QWord; elapsedTicks: QWord); cdecl;
+begin
+ try
+ IProfilerSessionImpl(this).addRecordSourceGetRecordStats(statementId, requestId, cursorId, recSourceId, counter, elapsedTicks);
+ except
+ on e: Exception do FbException.catchException(nil, e);
+ end
+end;
+
+procedure IProfilerSessionImpl_setSamplingIntervalDispatcher(this: IProfilerSession; microseconds: Cardinal); cdecl;
+begin
+ try
+ IProfilerSessionImpl(this).setSamplingInterval(microseconds);
+ except
+ on e: Exception do FbException.catchException(nil, e);
+ end
+end;
+
var
IProfilerSessionImpl_vTable: ProfilerSessionVTable;
@@ -19387,6 +19475,10 @@ initialization
IProfilerSessionImpl_vTable.beforeRecordSourceGetRecord := @IProfilerSessionImpl_beforeRecordSourceGetRecordDispatcher;
IProfilerSessionImpl_vTable.afterRecordSourceGetRecord := @IProfilerSessionImpl_afterRecordSourceGetRecordDispatcher;
IProfilerSessionImpl_vTable.defineStatement2 := @IProfilerSessionImpl_defineStatement2Dispatcher;
+ IProfilerSessionImpl_vTable.addPsqlLineColumnStats := @IProfilerSessionImpl_addPsqlLineColumnStatsDispatcher;
+ IProfilerSessionImpl_vTable.addRecordSourceOpenStats := @IProfilerSessionImpl_addRecordSourceOpenStatsDispatcher;
+ IProfilerSessionImpl_vTable.addRecordSourceGetRecordStats := @IProfilerSessionImpl_addRecordSourceGetRecordStatsDispatcher;
+ IProfilerSessionImpl_vTable.setSamplingInterval := @IProfilerSessionImpl_setSamplingIntervalDispatcher;
IProfilerStatsImpl_vTable := ProfilerStatsVTable.create;
IProfilerStatsImpl_vTable.version := 2;
diff --git a/src/jrd/Attachment.cpp b/src/jrd/Attachment.cpp
index 596995673fe..693134f2bc0 100644
--- a/src/jrd/Attachment.cpp
+++ b/src/jrd/Attachment.cpp
@@ -859,20 +859,6 @@ ProfilerManager* Attachment::getProfilerManager(thread_db* tdbb)
return profilerManager;
}
-ProfilerManager* Attachment::getActiveProfilerManagerForNonInternalStatement(thread_db* tdbb)
-{
- const auto* request = tdbb->getRequest();
-
- return isProfilerActive() && !request->hasInternalStatement() ?
- getProfilerManager(tdbb) :
- nullptr;
-}
-
-bool Attachment::isProfilerActive()
-{
- return att_profiler_manager && att_profiler_manager->isActive();
-}
-
void Attachment::releaseProfilerManager(thread_db* tdbb)
{
if (!att_profiler_manager)
diff --git a/src/jrd/Attachment.h b/src/jrd/Attachment.h
index 7e9d41c40ed..381275edffb 100644
--- a/src/jrd/Attachment.h
+++ b/src/jrd/Attachment.h
@@ -402,6 +402,8 @@ typedef Firebird::RaiiUnlockGuard AttSyncUnlockGuard
//
class Attachment : public pool_alloc
{
+ friend class ProfilerManager;
+
public:
class SyncGuard
{
@@ -781,8 +783,12 @@ class Attachment : public pool_alloc
}
ProfilerManager* getProfilerManager(thread_db* tdbb);
- ProfilerManager* getActiveProfilerManagerForNonInternalStatement(thread_db* tdbb);
- bool isProfilerActive();
+
+ bool isProfilerActive() const noexcept
+ {
+ return att_profiler_active;
+ }
+
void releaseProfilerManager(thread_db* tdbb);
void purgeTransactions(thread_db* tdbb, const bool force_flag);
@@ -811,6 +817,7 @@ class Attachment : public pool_alloc
InitialOptions att_initial_options; // Initial session options
DebugOptions att_debug_options;
Firebird::AutoPtr att_profiler_manager; // ProfilerManager
+ bool att_profiler_active = false; // att_profiler_manager has an active (not paused) session
JProvider* att_provider; // Provider which created this attachment
diff --git a/src/jrd/ProfilerManager.cpp b/src/jrd/ProfilerManager.cpp
index 9a01cc03fd9..4a03c18f47d 100644
--- a/src/jrd/ProfilerManager.cpp
+++ b/src/jrd/ProfilerManager.cpp
@@ -81,7 +81,7 @@ namespace
{
static_assert(std::is_same::value);
- static constexpr USHORT VERSION = 3;
+ static constexpr USHORT VERSION = 4;
const auto database = tdbb->getDatabase();
@@ -118,6 +118,20 @@ namespace
LCK_release(tdbb, &tempLock);
}
+ // Generations identify the ProfilerRequestProfile pointers stored in requests. They are unique in the
+ // process, so a pointer left in a request by a previous session or manager is never taken as valid.
+ ULONG newProfileGeneration()
+ {
+ // Process-wide: a manager can be recreated while requests still hold profile pointers of the old one.
+ static std::atomic lastGeneration = 0;
+ ULONG generation;
+
+ while ((generation = ++lastGeneration) == 0)
+ ;
+
+ return generation;
+ }
+
const auto& checkResponseIsNotException(const std::optional& responseMessageOpt)
{
if (responseMessageOpt.has_value())
@@ -369,11 +383,14 @@ void ProfilerPackage::startSessionFunction(ThrowStatusExceptionWrapper* /*status
std::nullopt : std::optional{in->flushInterval});
const PathName pluginName(in->pluginName.str, in->pluginNameNull ? 0 : in->pluginName.length);
const string pluginOptions(in->pluginOptions.str, in->pluginOptionsNull ? 0 : in->pluginOptions.length);
+ const std::optional samplingInterval(in->samplingIntervalNull ?
+ std::nullopt : std::optional{in->samplingInterval});
const auto profilerManager = attachment->getProfilerManager(tdbb);
out->sessionIdNull = FB_FALSE;
- out->sessionId = profilerManager->startSession(tdbb, flushInterval, pluginName, description, pluginOptions);
+ out->sessionId = profilerManager->startSession(tdbb, flushInterval, pluginName, description, pluginOptions,
+ samplingInterval);
}
@@ -381,13 +398,17 @@ void ProfilerPackage::startSessionFunction(ThrowStatusExceptionWrapper* /*status
ProfilerManager::ProfilerManager(thread_db* tdbb)
- : activePlugins(*tdbb->getAttachment()->att_pool)
+ : attachment(tdbb->getAttachment()),
+ activePlugins(*attachment->att_pool),
+ requestCallStatus(*attachment->att_pool),
+ requestProfiles(*attachment->att_pool),
+ freeRequestProfiles(*attachment->att_pool),
+ requestSampledTicks(*attachment->att_pool),
+ profileGeneration(newProfileGeneration())
{
- const auto attachment = tdbb->getAttachment();
-
flushTimer = FB_NEW TimerImpl();
- flushTimer->setOnTimer([this, attachment](auto) {
+ flushTimer->setOnTimer([this](auto) {
FbLocalStatus statusVector;
EngineContextHolder innerTdbb(&statusVector, attachment->getInterface(), FB_FUNCTION);
@@ -398,7 +419,12 @@ ProfilerManager::ProfilerManager(thread_db* tdbb)
ProfilerManager::~ProfilerManager()
{
+ attachment->att_profiler_active = false;
flushTimer->stop();
+ stopSampling();
+
+ for (const auto profile : freeRequestProfiles)
+ delete profile;
}
ProfilerManager* ProfilerManager::create(thread_db* tdbb)
@@ -432,20 +458,32 @@ int ProfilerManager::blockingAst(void* astObject)
}
SINT64 ProfilerManager::startSession(thread_db* tdbb, std::optional flushInterval,
- const PathName& pluginName, const string& description, const string& options)
+ const PathName& pluginName, const string& description, const string& options,
+ std::optional samplingInterval)
{
if (flushInterval.has_value())
checkFlushInterval(flushInterval.value());
- AutoSetRestore pauseProfiler(&paused, true);
+ if (samplingInterval.has_value())
+ checkSamplingInterval(samplingInterval.value());
+
+ const bool oldPaused = paused;
+ setPaused(true);
+ Cleanup restorePaused([&] { setPaused(oldPaused); });
+
+ resetCache();
- const auto attachment = tdbb->getAttachment();
ThrowLocalStatus status;
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(attachment->att_current_timezone);
if (currentSession)
{
+ if (sampled)
+ deliverProfiles(nullptr);
+
+ stopSampling();
+
currentSession->pluginSession->finish(&status, timestamp);
currentSession = nullptr;
}
@@ -491,7 +529,18 @@ SINT64 ProfilerManager::startSession(thread_db* tdbb, std::optional flush
currentSession->plugin = std::move(plugin);
currentSession->flags = currentSession->pluginSession->getFlags();
- paused = false;
+ // Plugins that don't know the aggregated stats methods get every event measured.
+ if (currentSession->pluginSession->cloopVTable->version >= IProfilerSession::VERSION)
+ {
+ const ULONG interval = (ULONG) samplingInterval.value_or(DEFAULT_SAMPLING_INTERVAL);
+
+ currentSession->pluginSession->setSamplingInterval(interval);
+
+ if (interval)
+ startSampling(interval);
+ }
+
+ setPaused(false);
if (flushInterval.has_value())
setFlushInterval(flushInterval.value());
@@ -506,6 +555,13 @@ void ProfilerManager::prepareCursor(thread_db* tdbb, Request* request, const Sel
if (!profileStatement)
return;
+ // Fast path for every fetch after the first: a defined record source implies a defined cursor.
+ if (profileStatement->getRecSourceSequence(select->getRecSourceId()))
+ return;
+
+ const SINT64 overheadStartTicks = queryTicks();
+ Cleanup endOverheadCleanup([&] { endOverhead(overheadStartTicks); });
+
const auto cursorId = select->getCursorId();
if (!profileStatement->definedCursors.exist(cursorId))
@@ -526,7 +582,7 @@ void ProfilerManager::prepareRecSource(thread_db* tdbb, Request* request, const
if (!profileStatement)
return;
- if (profileStatement->recSourceSequence.exist(recordSource->getRecSourceId()))
+ if (profileStatement->getRecSourceSequence(recordSource->getRecSourceId()))
return;
fb_assert(profileStatement->definedCursors.exist(recordSource->getCursorId()));
@@ -557,46 +613,319 @@ void ProfilerManager::prepareRecSource(thread_db* tdbb, Request* request, const
currentSession->pluginSession->defineRecordSource(profileStatement->id, cursorId,
*sequencePtr, planEntry->level, accessPath.c_str(), parentSequence);
- profileStatement->recSourceSequence.put(recSourceId, *sequencePtr);
+ profileStatement->setRecSourceSequence(recSourceId, *sequencePtr);
}
}
void ProfilerManager::onRequestFinish(Request* request, Stats& stats)
{
+ // The overhead is subtracted only from measured timings, so it's not accounted when sampling.
+ const bool accountOverhead = !sampled;
+ const SINT64 overheadStartTicks = accountOverhead ? queryTicks() : 0;
+
+ Cleanup endOverheadCleanup([&] {
+ if (accountOverhead)
+ endOverhead(overheadStartTicks);
+ });
+
if (const auto profileRequestId = getRequest(request, 0))
{
const auto* profileStatement = getStatement(request);
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
- LogLocalStatus status("Profiler onRequestFinish");
- currentSession->pluginSession->onRequestFinish(&status, profileStatement->id, profileRequestId,
- timestamp, &stats);
+ RequestCallStatus status(this, "Profiler onRequestFinish");
+
+ if (const auto profile = sampled ? getRequestProfile(request) : nullptr)
+ {
+ deliverProfiles(profile);
+
+ FB_UINT64 sampledTicks = 0;
+
+ if (const auto ticksPtr = requestSampledTicks.get(profileRequestId))
+ {
+ sampledTicks = *ticksPtr;
+ requestSampledTicks.remove(profileRequestId);
+ }
+
+ Stats sampledStats(sampledTicks);
+ currentSession->pluginSession->onRequestFinish(&status, profileStatement->id, profileRequestId,
+ timestamp, &sampledStats);
+
+ request->req_profiler_profile = nullptr;
+ request->req_profiler_sampled = false;
+ releaseRequestProfile(profile);
+ }
+ else
+ {
+ currentSession->pluginSession->onRequestFinish(&status, profileStatement->id, profileRequestId,
+ timestamp, &stats);
+ }
currentSession->requests.findAndRemove(profileRequestId);
+ resetCache();
+ }
+}
+
+// Releases the profile of a request that finished without onRequestFinish, as when its session was paused,
+// before the request gets a new id. Its pending counters are delivered with the previous id.
+void ProfilerManager::releaseStaleRequestProfile(Request* request)
+{
+ const auto profile = request->req_profiler_profile;
+
+ request->req_profiler_profile = nullptr;
+ request->req_profiler_sampled = false;
+
+ if (request->req_profiler_generation != profileGeneration)
+ return;
+
+ if (sampled && currentSession)
+ {
+ deliverProfiles(profile);
+ requestSampledTicks.remove(profile->requestId);
+ }
+
+ releaseRequestProfile(profile);
+}
+
+ProfilerRequestProfile* ProfilerManager::createRequestProfile(Request* request)
+{
+ if (!sampled)
+ return nullptr;
+
+ const auto profileRequestId = getRequest(request, 0);
+
+ if (!profileRequestId)
+ return nullptr;
+
+ const auto profileStatement = getStatement(request);
+
+ if (!profileStatement)
+ return nullptr;
+
+ // A request with a profile of the current generation doesn't get here, and profiles of finished requests
+ // and of other generations are not active, so the request has no active profile to look up.
+ const auto profile = freeRequestProfiles.hasData() ?
+ freeRequestProfiles.pop() :
+ FB_NEW_POOL(*attachment->att_pool) ProfilerRequestProfile(*attachment->att_pool);
+
+ profile->reset(profileStatement->id, profileRequestId);
+ profile->activeIndex = requestProfiles.add(profile);
+
+ request->req_profiler_profile = profile;
+ request->req_profiler_generation = profileGeneration;
+
+ return profile;
+}
+
+void ProfilerManager::releaseRequestProfile(ProfilerRequestProfile* profile)
+{
+ fb_assert(requestProfiles[profile->activeIndex] == profile);
+
+ const auto last = requestProfiles.pop();
+
+ if (last != profile)
+ {
+ requestProfiles[profile->activeIndex] = last;
+ last->activeIndex = profile->activeIndex;
+ }
+
+ freeRequestProfiles.add(profile);
+}
+
+// Delivers the counters of one or all request profiles to the plugin, together with the times sampled
+// since the last call. Sampled request totals are accumulated in requestSampledTicks until the request finishes.
+void ProfilerManager::deliverProfiles(ProfilerRequestProfile* onlyProfile)
+{
+ using Key = ProfilerSampleState::Key;
+ using KeyKind = ProfilerSampleState::KeyKind;
+
+ ProfilerSampleState::SampleMap samples(*getDefaultMemoryPool());
+
+ // A finished request has its frames already popped, and requests usually finish much more often than
+ // samples are taken, so the samples are taken only when the sampler may have added something.
+ if (!onlyProfile || sampleState->mayHaveSamples())
+ sampleState->takeSamples(samples);
+
+ const auto takeTicks = [&](const Key& key) -> FB_UINT64
+ {
+ if (const auto ticksPtr = samples.get(key))
+ {
+ const FB_UINT64 ticks = *ticksPtr;
+ samples.remove(key);
+ return ticks;
+ }
+
+ return 0;
+ };
+
+ const auto deliverCounters = [&](ProfilerRequestProfile& profile)
+ {
+ const auto statementId = profile.statementId;
+ const auto requestId = profile.requestId;
+
+ for (auto& lineCounter : profile.lines)
+ {
+ if (!lineCounter.counter)
+ continue;
+
+ const auto ticks = takeTicks({statementId, requestId, lineCounter.line, lineCounter.column, KeyKind::LINE});
+
+ currentSession->pluginSession->addPsqlLineColumnStats(statementId, requestId,
+ lineCounter.line, lineCounter.column, lineCounter.counter, ticks);
+
+ lineCounter.counter = 0;
+ }
+
+ for (ULONG recSourceId = 0; recSourceId < profile.recSources.getCount(); ++recSourceId)
+ {
+ auto& recSourceCounter = profile.recSources[recSourceId];
+
+ if (recSourceCounter.openCounter)
+ {
+ const auto ticks = takeTicks(
+ {statementId, requestId, recSourceId, recSourceCounter.cursorId, KeyKind::OPEN});
+
+ deliverRecSourceStats(statementId, requestId, recSourceCounter.cursorId, recSourceId,
+ true, recSourceCounter.openCounter, ticks);
+
+ recSourceCounter.openCounter = 0;
+ }
+
+ if (recSourceCounter.fetchCounter)
+ {
+ const auto ticks = takeTicks(
+ {statementId, requestId, recSourceId, recSourceCounter.cursorId, KeyKind::FETCH});
+
+ deliverRecSourceStats(statementId, requestId, recSourceCounter.cursorId, recSourceId,
+ false, recSourceCounter.fetchCounter, ticks);
+
+ recSourceCounter.fetchCounter = 0;
+ }
+ }
+ };
+
+ if (onlyProfile)
+ deliverCounters(*onlyProfile);
+ else
+ {
+ for (const auto profile : requestProfiles)
+ deliverCounters(*profile);
+ }
+
+ // Times of keys without new hits.
+ for (const auto& [key, ticks] : samples)
+ {
+ switch (key.kind)
+ {
+ case KeyKind::REQUEST:
+ *requestSampledTicks.getOrPut(key.requestId) += ticks;
+ break;
+
+ case KeyKind::LINE:
+ currentSession->pluginSession->addPsqlLineColumnStats(key.statementId, key.requestId,
+ key.a, key.b, 0, ticks);
+ break;
+
+ case KeyKind::OPEN:
+ case KeyKind::FETCH:
+ deliverRecSourceStats(key.statementId, key.requestId, key.b, key.a,
+ key.kind == KeyKind::OPEN, 0, ticks);
+ break;
+ }
}
}
+void ProfilerManager::deliverRecSourceStats(SINT64 statementId, SINT64 requestId, ULONG cursorId, ULONG recSourceId,
+ bool open, FB_UINT64 counter, FB_UINT64 elapsedTicks)
+{
+ const auto profileStatement = currentSession->statements.get(StmtNumber(statementId));
+
+ if (!profileStatement)
+ return;
+
+ // Record sources not yet defined to the plugin are not reported, like in the measured mode.
+ if (const auto sequence = profileStatement->getRecSourceSequence(recSourceId))
+ {
+ if (open)
+ {
+ currentSession->pluginSession->addRecordSourceOpenStats(statementId, requestId,
+ cursorId, sequence, counter, elapsedTicks);
+ }
+ else
+ {
+ currentSession->pluginSession->addRecordSourceGetRecordStats(statementId, requestId,
+ cursorId, sequence, counter, elapsedTicks);
+ }
+ }
+}
+
+void ProfilerManager::startSampling(ULONG interval)
+{
+ if (!sampleState)
+ sampleState = FB_NEW ProfilerSampleState();
+
+ sampleState->setInterval(interval);
+ sampled = true;
+ ProfilerSampler::add(sampleState);
+ updateActive();
+}
+
+void ProfilerManager::stopSampling()
+{
+ if (sampled)
+ {
+ ProfilerSampler::remove(sampleState);
+ sampled = false;
+ }
+
+ if (sampleState)
+ {
+ sampleState->setActive(false);
+ sampleState->clearSamples();
+ }
+
+ // Their counters may be pending, but they are discarded with the generation and reset when reused.
+ for (const auto profile : requestProfiles)
+ freeRequestProfiles.add(profile);
+
+ requestProfiles.clear();
+ requestSampledTicks.clear();
+ profileGeneration = newProfileGeneration();
+}
+
void ProfilerManager::cancelSession()
{
+ resetCache();
+
if (currentSession)
{
+ stopSampling();
+
LogLocalStatus status("Profiler cancelSession");
currentSession->pluginSession->cancel(&status);
currentSession = nullptr;
+ updateActive();
}
}
void ProfilerManager::finishSession(thread_db* tdbb, bool flushData)
{
+ resetCache();
+
if (currentSession)
{
- const auto* attachment = tdbb->getAttachment();
- const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(attachment->att_current_timezone);
+ if (sampled)
+ deliverProfiles(nullptr);
+
+ stopSampling();
+
+ const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(tdbb->getAttachment()->att_current_timezone);
LogLocalStatus status("Profiler finish");
currentSession->pluginSession->finish(&status, timestamp);
currentSession = nullptr;
+ updateActive();
}
if (flushData)
@@ -606,7 +935,7 @@ void ProfilerManager::finishSession(thread_db* tdbb, bool flushData)
void ProfilerManager::pauseSession(bool flushData)
{
if (currentSession)
- paused = true;
+ setPaused(true);
if (flushData)
flush();
@@ -616,7 +945,7 @@ void ProfilerManager::resumeSession()
{
if (currentSession)
{
- paused = false;
+ setPaused(false);
updateFlushTimer();
}
}
@@ -632,14 +961,23 @@ void ProfilerManager::setFlushInterval(SLONG interval)
void ProfilerManager::discard()
{
+ resetCache();
+ stopSampling();
+
currentSession = nullptr;
+ updateActive();
activePlugins.clear();
}
void ProfilerManager::flush(bool updateTimer)
{
+ if (sampled && currentSession)
+ deliverProfiles(nullptr);
+
{ // scope
- AutoSetRestore pauseProfiler(&paused, true);
+ const bool oldPaused = paused;
+ setPaused(true);
+ Cleanup restorePaused([&] { setPaused(oldPaused); });
auto pluginAccessor = activePlugins.accessor();
@@ -661,6 +999,14 @@ void ProfilerManager::flush(bool updateTimer)
updateFlushTimer();
}
+void ProfilerManager::updateActive()
+{
+ attachment->att_profiler_active = isActive();
+
+ if (sampleState)
+ sampleState->setActive(sampled && isActive());
+}
+
void ProfilerManager::updateFlushTimer(bool canStopTimer)
{
if (currentSession && !paused && currentFlushInterval)
@@ -669,15 +1015,20 @@ void ProfilerManager::updateFlushTimer(bool canStopTimer)
flushTimer->stop();
}
-ProfilerManager::Statement* ProfilerManager::getStatement(Request* request)
+ProfilerManager::Statement* ProfilerManager::lookupStatement(Request* request)
{
- if (!isActive())
- return nullptr;
-
- auto mainProfileStatement = currentSession->statements.get(request->getStatement()->getStatementId());
+ const StmtNumber mainStatementId = request->getStatement()->getStatementId();
+ auto mainProfileStatement = currentSession->statements.get(mainStatementId);
if (mainProfileStatement)
+ {
+ lastStatement = mainProfileStatement;
+ lastStatementId = mainStatementId;
+
return mainProfileStatement;
+ }
+
+ lastStatement = nullptr; // the map is about to change
for (const auto* statement = request->getStatement();
statement && !currentSession->statements.exist(statement->getStatementId());
@@ -869,10 +1220,12 @@ IpcResponseMessage ProfilerListener::processCommand(thread_db* tdbb, const IpcRe
message.pluginNameNull ? 0 : message.pluginName.length);
const string pluginOptions(message.pluginOptions.str,
message.pluginOptionsNull ? 0 : message.pluginOptions.length);
+ const std::optional samplingInterval(message.samplingIntervalNull ?
+ std::nullopt : std::optional{message.samplingInterval});
return ProfilerPackage::StartSessionOutput::Type{
.sessionId = profilerManager->startSession(tdbb, flushInterval,
- pluginName, description, pluginOptions),
+ pluginName, description, pluginOptions, samplingInterval),
.sessionIdNull = FB_FALSE,
};
},
@@ -998,6 +1351,7 @@ ProfilerPackage::ProfilerPackage(MemoryPool& pool)
{"ATTACHMENT_ID", fld_att_id, true, "null", {blr_null}},
{"PLUGIN_NAME", fld_file_name2, true, "null", {blr_null}},
{"PLUGIN_OPTIONS", fld_short_description, true, "null", {blr_null}},
+ {"SAMPLING_INTERVAL", fld_integer, true, "100", {blr_literal, blr_long, 0, 0x64, 0, 0, 0}},
},
{fld_prof_ses_id, false}
)
diff --git a/src/jrd/ProfilerManager.h b/src/jrd/ProfilerManager.h
index 173ea283a2d..9ef1e517ca7 100644
--- a/src/jrd/ProfilerManager.h
+++ b/src/jrd/ProfilerManager.h
@@ -33,6 +33,7 @@
#include "../common/classes/TimerImpl.h"
#include "../jrd/recsrc/RecordSource.h"
#include "../jrd/req.h"
+#include "../jrd/ProfilerSampler.h"
#include "../jrd/SystemPackages.h"
#include "../jrd/Statement.h"
@@ -47,6 +48,81 @@ class thread_db;
class ProfilerListener;
+// Exact hit counters of a request, used when timings are sampled.
+// They are delivered to the plugin in batches instead of per event.
+class ProfilerRequestProfile final
+{
+public:
+ struct LineCounter
+ {
+ ULONG line = 0;
+ ULONG column = 0;
+ FB_UINT64 counter = 0;
+ };
+
+ struct RecSourceCounter
+ {
+ ULONG cursorId = 0;
+ FB_UINT64 openCounter = 0;
+ FB_UINT64 fetchCounter = 0;
+ };
+
+public:
+ explicit ProfilerRequestProfile(MemoryPool& pool)
+ : lines(pool),
+ recSources(pool)
+ {
+ }
+
+ ProfilerRequestProfile(const ProfilerRequestProfile&) = delete;
+ ProfilerRequestProfile& operator=(const ProfilerRequestProfile&) = delete;
+
+public:
+ // Prepares a new or recycled profile for a request, keeping the memory of the arrays.
+ void reset(SINT64 aStatementId, SINT64 aRequestId)
+ {
+ statementId = aStatementId;
+ requestId = aRequestId;
+ lines.clear();
+ recSources.clear();
+ }
+
+ void hitLine(ULONG slot, ULONG line, ULONG column)
+ {
+ if (slot >= lines.getCount())
+ lines.grow(slot + 1);
+
+ auto& lineCounter = lines[slot];
+
+ // The position of a slot never changes, so it's stored by its first hit. A new entry is zeroed.
+ if (!lineCounter.counter)
+ {
+ lineCounter.line = line;
+ lineCounter.column = column;
+ }
+
+ ++lineCounter.counter;
+ }
+
+ RecSourceCounter& getRecSource(ULONG recSourceId, ULONG cursorId)
+ {
+ if (recSourceId >= recSources.getCount())
+ recSources.grow(recSourceId + 1);
+
+ auto& recSourceCounter = recSources[recSourceId];
+ recSourceCounter.cursorId = cursorId;
+ return recSourceCounter;
+ }
+
+public:
+ SINT64 statementId = 0;
+ SINT64 requestId = 0;
+ Firebird::Array lines; // indexed by StmtNode::profileSlot
+ Firebird::Array recSources; // indexed by record source id
+ FB_SIZE_T activeIndex = 0; // position in ProfilerManager::requestProfiles
+};
+
+
class ProfilerManager final : public Firebird::PerformanceStopWatch
{
friend class ProfilerListener;
@@ -70,6 +146,57 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
FB_UINT64 elapsedTicks;
};
+ // Publishes the frame of an executing request for the sampler, popping it when destroyed.
+ class RequestFrame final
+ {
+ public:
+ RequestFrame() = default;
+
+ ~RequestFrame()
+ {
+ pop();
+ }
+
+ RequestFrame(const RequestFrame&) = delete;
+ RequestFrame& operator=(const RequestFrame&) = delete;
+
+ public:
+ // Does nothing when timings are not sampled.
+ void push(ProfilerManager* profilerManager, Request* request)
+ {
+ fb_assert(!state);
+ state = profilerManager->pushRequestFrame(request, depth);
+ }
+
+ void pop() noexcept
+ {
+ if (state)
+ {
+ state->popTo(depth);
+ state = nullptr;
+ }
+ }
+
+ bool isPushed() const noexcept
+ {
+ return state != nullptr;
+ }
+
+ ProfilerSampleState* getState() const noexcept
+ {
+ return state;
+ }
+
+ unsigned getIndex() const noexcept
+ {
+ return depth;
+ }
+
+ private:
+ ProfilerSampleState* state = nullptr;
+ unsigned depth = 0;
+ };
+
class RecordSourceStopWatcher final
{
public:
@@ -81,8 +208,7 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
public:
RecordSourceStopWatcher(thread_db* tdbb, const RecordSource* recordSource, Event aEvent)
- : RecordSourceStopWatcher(tdbb, tdbb->getAttachment()->getActiveProfilerManagerForNonInternalStatement(tdbb),
- recordSource, aEvent)
+ : RecordSourceStopWatcher(tdbb, getActiveForNonInternalStatement(tdbb), recordSource, aEvent)
{
}
@@ -93,17 +219,35 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
recordSource(recordSource),
event(aEvent)
{
- if (profilerManager)
+ if (profilerManager && profilerManager->sampled)
{
- lastTicks = profilerManager->queryTicks();
+ sampledProfilerManager = profilerManager;
+ sampleState = profilerManager->sampleState;
+
+ frameDepth = sampleState->push(profilerManager->makeFrame(request,
+ recordSource->getRecSourceId(), recordSource->getCursorId(),
+ (event == Event::OPEN ?
+ ProfilerSampleState::FrameKind::OPEN :
+ ProfilerSampleState::FrameKind::FETCH)));
+
+ profilerManager = nullptr;
+ }
+ if (profilerManager)
+ {
if (profilerManager->currentSession->flags & Firebird::IProfilerSession::FLAG_BEFORE_EVENTS)
{
+ const SINT64 overheadStartTicks = profilerManager->queryTicks();
+
if (event == Event::OPEN)
profilerManager->beforeRecordSourceOpen(request, recordSource);
else
profilerManager->beforeRecordSourceGetRecord(request, recordSource);
+
+ lastTicks = profilerManager->endOverhead(overheadStartTicks);
}
+ else
+ lastTicks = profilerManager->beginInterval();
lastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
}
@@ -111,7 +255,24 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
~RecordSourceStopWatcher()
{
- if (profilerManager)
+ if (sampleState)
+ {
+ sampleState->popTo(frameDepth);
+
+ // Counted after the event, like the measured events, so a session paused or finished
+ // during the event doesn't count it.
+ if (const auto profile = sampledProfilerManager->isActive() ?
+ sampledProfilerManager->getRequestProfile(request) : nullptr)
+ {
+ auto& counter = profile->getRecSource(recordSource->getRecSourceId(), recordSource->getCursorId());
+
+ if (event == Event::OPEN)
+ ++counter.openCounter;
+ else
+ ++counter.fetchCounter;
+ }
+ }
+ else if (profilerManager && !profilerManager->sampled) // a session started during the event may sample
{
const SINT64 currentTicks = profilerManager->queryTicks();
const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
@@ -122,6 +283,8 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
profilerManager->afterRecordSourceOpen(request, recordSource, stats);
else
profilerManager->afterRecordSourceGetRecord(request, recordSource, stats);
+
+ profilerManager->endOverhead(currentTicks);
}
}
@@ -129,8 +292,11 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
Request* request;
ProfilerManager* profilerManager;
const AccessPath* recordSource;
+ ProfilerManager* sampledProfilerManager = nullptr;
+ ProfilerSampleState* sampleState = nullptr;
SINT64 lastTicks = 0;
SINT64 lastAccumulatedOverhead = 0;
+ unsigned frameDepth = 0;
Event event;
};
@@ -145,13 +311,26 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
{
}
+ ULONG getRecSourceSequence(ULONG recSourceId) const
+ {
+ return recSourceId < recSourceSequence.getCount() ? recSourceSequence[recSourceId] : 0;
+ }
+
+ void setRecSourceSequence(ULONG recSourceId, ULONG sequence)
+ {
+ if (recSourceId >= recSourceSequence.getCount())
+ recSourceSequence.grow(recSourceId + 1);
+
+ recSourceSequence[recSourceId] = sequence;
+ }
+
Statement(const Statement&) = delete;
void operator=(const Statement&) = delete;
SINT64 id = 0;
Firebird::NonPooledMap cursorNextSequence;
Firebird::SortedArray definedCursors;
- Firebird::NonPooledMap recSourceSequence;
+ Firebird::Array recSourceSequence; // indexed by record source id, 0 = not defined
};
class Session final
@@ -173,6 +352,24 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
unsigned flags = 0;
};
+ // Status of the plugin calls done for every request, which share ProfilerManager::requestCallStatus,
+ // as constructing a LocalStatus for each of them is not cheap. Errors are logged, like LogLocalStatus.
+ class RequestCallStatus final : public Firebird::LogWrapper
+ {
+ public:
+ RequestCallStatus(ProfilerManager* manager, const char* text)
+ : LogWrapper(&manager->requestCallStatus, text)
+ {
+ }
+
+ ~RequestCallStatus()
+ {
+ // Don't leave errors or warnings in the shared status.
+ if (isDirty())
+ status->init();
+ }
+ };
+
private:
ProfilerManager(thread_db* tdbb);
@@ -182,6 +379,15 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
public:
static ProfilerManager* create(thread_db* tdbb);
+ static ProfilerManager* getActiveForNonInternalStatement(thread_db* tdbb)
+ {
+ const auto attachment = tdbb->getAttachment();
+
+ return attachment->isProfilerActive() && !tdbb->getRequest()->hasInternalStatement() ?
+ attachment->att_profiler_manager.get() :
+ nullptr;
+ }
+
static int blockingAst(void* astObject);
ProfilerManager(const ProfilerManager&) = delete;
@@ -189,10 +395,61 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
public:
SINT64 startSession(thread_db* tdbb, std::optional flushInterval,
- const Firebird::PathName& pluginName, const Firebird::string& description, const Firebird::string& options);
+ const Firebird::PathName& pluginName, const Firebird::string& description, const Firebird::string& options,
+ std::optional samplingInterval);
void prepareCursor(thread_db* tdbb, Request* request, const Select* select);
void onRequestFinish(Request* request, Stats& stats);
+ void releaseStaleRequestProfile(Request* request);
+
+ // Timings are sampled by ProfilerSampler instead of measured for every event.
+ bool isSampled() const
+ {
+ return sampled;
+ }
+
+ ProfilerRequestProfile* getRequestProfile(Request* request)
+ {
+ if (request->req_profiler_profile && request->req_profiler_generation == profileGeneration)
+ return request->req_profiler_profile;
+
+ return createRequestProfile(request);
+ }
+
+ // Publishes that the request is executing. Returns the state where the frame was pushed, or nullptr.
+ // Used by RequestFrame, which restores the state with popTo(depth).
+ // The request is not defined to the plugin here, but only with its first statement or record source,
+ // as it's done when every event is measured.
+ ProfilerSampleState* pushRequestFrame(Request* request, unsigned& depth)
+ {
+ if (!sampled)
+ return nullptr;
+
+ request->req_profiler_sampled = true;
+ depth = sampleState->push(makeFrame(request, 0, 0, ProfilerSampleState::FrameKind::REQUEST));
+
+ return sampleState;
+ }
+
+ ProfilerSampleState::Frame makeFrame(Request* request, ULONG a, ULONG b, ProfilerSampleState::FrameKind kind)
+ {
+ if (request->req_profiler_profile && request->req_profiler_generation == profileGeneration)
+ {
+ const auto profile = request->req_profiler_profile;
+ return {profile->statementId, profile->requestId, a, b, kind};
+ }
+
+ return {(SINT64) request->getStatement()->getStatementId(), (SINT64) request->getRequestId(), a, b, kind};
+ }
+
+ void hitPsqlLine(Request* request, ProfilerSampleState* state, unsigned frameIndex,
+ ULONG slot, ULONG line, ULONG column)
+ {
+ if (const auto profile = getRequestProfile(request))
+ profile->hitLine(slot, line, column);
+
+ state->setLine(frameIndex, line, column);
+ }
void beforePsqlLineColumn(Request* request, ULONG line, ULONG column)
{
@@ -219,10 +476,10 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
{
const auto* profileStatement = getStatement(request);
- if (const auto sequencePtr = profileStatement->recSourceSequence.get(recordSource->getRecSourceId()))
+ if (const auto sequence = profileStatement->getRecSourceSequence(recordSource->getRecSourceId()))
{
currentSession->pluginSession->beforeRecordSourceOpen(
- profileStatement->id, profileRequestId, recordSource->getCursorId(), *sequencePtr);
+ profileStatement->id, profileRequestId, recordSource->getCursorId(), sequence);
}
}
}
@@ -233,10 +490,10 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
{
const auto* profileStatement = getStatement(request);
- if (const auto sequencePtr = profileStatement->recSourceSequence.get(recordSource->getRecSourceId()))
+ if (const auto sequence = profileStatement->getRecSourceSequence(recordSource->getRecSourceId()))
{
currentSession->pluginSession->afterRecordSourceOpen(
- profileStatement->id, profileRequestId, recordSource->getCursorId(), *sequencePtr, &stats);
+ profileStatement->id, profileRequestId, recordSource->getCursorId(), sequence, &stats);
}
}
}
@@ -247,10 +504,10 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
{
const auto* profileStatement = getStatement(request);
- if (const auto sequencePtr = profileStatement->recSourceSequence.get(recordSource->getRecSourceId()))
+ if (const auto sequence = profileStatement->getRecSourceSequence(recordSource->getRecSourceId()))
{
currentSession->pluginSession->beforeRecordSourceGetRecord(
- profileStatement->id, profileRequestId, recordSource->getCursorId(), *sequencePtr);
+ profileStatement->id, profileRequestId, recordSource->getCursorId(), sequence);
}
}
}
@@ -261,10 +518,10 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
{
const auto* profileStatement = getStatement(request);
- if (const auto sequencePtr = profileStatement->recSourceSequence.get(recordSource->getRecSourceId()))
+ if (const auto sequence = profileStatement->getRecSourceSequence(recordSource->getRecSourceId()))
{
currentSession->pluginSession->afterRecordSourceGetRecord(
- profileStatement->id, profileRequestId, recordSource->getCursorId(), *sequencePtr, &stats);
+ profileStatement->id, profileRequestId, recordSource->getCursorId(), sequence, &stats);
}
}
}
@@ -279,6 +536,22 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
return listener.hasData();
}
+ static constexpr SLONG DEFAULT_SAMPLING_INTERVAL = 100; // microseconds
+ static constexpr SLONG MIN_SAMPLING_INTERVAL = 50; // microseconds
+ static constexpr SLONG MAX_SAMPLING_INTERVAL = 1'000'000; // microseconds
+
+ // 0 means every event is measured.
+ static void checkSamplingInterval(SLONG interval)
+ {
+ if (interval != 0 && (interval < MIN_SAMPLING_INTERVAL || interval > MAX_SAMPLING_INTERVAL))
+ {
+ Firebird::status_exception::raise(
+ Firebird::Arg::Gds(isc_not_valid_for_var) <<
+ "\"SAMPLING_INTERVAL\"" <<
+ Firebird::Arg::Num(interval));
+ }
+ }
+
static void checkFlushInterval(SLONG interval)
{
if (interval < 0)
@@ -293,6 +566,30 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
private:
void prepareRecSource(thread_db* tdbb, Request* request, const AccessPath* recordSource);
+ ProfilerRequestProfile* createRequestProfile(Request* request);
+ void releaseRequestProfile(ProfilerRequestProfile* profile);
+ void deliverProfiles(ProfilerRequestProfile* onlyProfile);
+ void deliverRecSourceStats(SINT64 statementId, SINT64 requestId, ULONG cursorId, ULONG recSourceId,
+ bool open, FB_UINT64 counter, FB_UINT64 elapsedTicks);
+ void startSampling(ULONG interval);
+ void stopSampling();
+
+ void resetCache()
+ {
+ lastRequest = nullptr;
+ lastRequestId = 0;
+ lastStatement = nullptr;
+ lastStatementId = 0;
+ }
+
+ void setPaused(bool value)
+ {
+ paused = value;
+ updateActive();
+ }
+
+ void updateActive();
+
void cancelSession();
void finishSession(thread_db* tdbb, bool flushData);
void pauseSession(bool flushData);
@@ -303,7 +600,18 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
void updateFlushTimer(bool canStopTimer = true);
- Statement* getStatement(Request* request);
+ Statement* getStatement(Request* request)
+ {
+ if (!isActive())
+ return nullptr;
+
+ if (lastStatement && request->getStatement()->getStatementId() == lastStatementId)
+ return lastStatement;
+
+ return lookupStatement(request);
+ }
+
+ Statement* lookupStatement(Request* request);
SINT64 getRequest(Request* request, unsigned flags)
{
@@ -312,8 +620,12 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
if (!isActive() || (flags && !(currentSession->flags & flags)))
return 0;
+ const auto mainRequest = request;
const auto mainRequestId = request->getRequestId();
+ if (request == lastRequest && mainRequestId == lastRequestId)
+ return mainRequestId;
+
if (!currentSession->requests.exist(mainRequestId))
{
const auto timestamp = TimeZoneUtil::getCurrentTimeStamp(request->req_attachment->att_current_timezone);
@@ -326,7 +638,7 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
request->req_caller->getStatement()->getStatementId() : 0;
const StmtNumber callerRequestId = request->req_caller ? request->req_caller->getRequestId() : 0;
- LogLocalStatus status("Profiler onRequestStart");
+ RequestCallStatus status(this, "Profiler onRequestStart");
currentSession->pluginSession->onRequestStart(&status,
(SINT64) request->getStatement()->getStatementId(), (SINT64) request->getRequestId(),
(SINT64) callerStatementId, (SINT64) callerRequestId, timestamp);
@@ -337,16 +649,42 @@ class ProfilerManager final : public Firebird::PerformanceStopWatch
} while (request && !currentSession->requests.exist(request->getRequestId()));
}
+ lastRequest = mainRequest;
+ lastRequestId = mainRequestId;
+
return mainRequestId;
}
private:
+ Attachment* const attachment;
Firebird::AutoPtr listener;
Firebird::LeftPooledMap> activePlugins;
Firebird::AutoPtr currentSession;
+ Firebird::LocalStatus requestCallStatus; // see RequestCallStatus
Firebird::RefPtr flushTimer;
unsigned currentFlushInterval = 0;
bool paused = false;
+ bool sampled = false;
+
+ // Sampling state. sampleState lives as long as the manager, so frames pushed in one session
+ // are popped correctly even when the session changes in the middle of a request.
+ Firebird::RefPtr sampleState;
+ // Profiles of unfinished requests and finished ones kept for reuse, so requests don't allocate them.
+ // Both own their profiles.
+ Firebird::Array requestProfiles;
+ Firebird::Array freeRequestProfiles;
+ Firebird::NonPooledMap requestSampledTicks; // sampled totals of unfinished requests
+ ULONG profileGeneration; // changed when requestProfiles is cleared, unique in the process
+
+ // Last request known to the current session, to avoid repeated lookups on every event.
+ Request* lastRequest = nullptr;
+ StmtNumber lastRequestId = 0;
+
+ // Last statement looked up in the current session. It's keyed by the statement id instead of by
+ // lastRequest, as sampled timings don't call getRequest for every event, so lastRequest may be
+ // another request, like the caller of a procedure that fetches from a cursor.
+ Statement* lastStatement = nullptr;
+ StmtNumber lastStatementId = 0;
};
@@ -434,6 +772,7 @@ class ProfilerPackage final : public SystemPackage
(FB_BIGINT, attachmentId)
(FB_INTL_VARCHAR(255 * METADATA_BYTES_PER_CHAR, CS_METADATA), pluginName)
(FB_INTL_VARCHAR(255 * METADATA_BYTES_PER_CHAR, CS_METADATA), pluginOptions)
+ (FB_INTEGER, samplingInterval)
);
FB_MESSAGE(StartSessionOutput, Firebird::ThrowStatusExceptionWrapper,
diff --git a/src/jrd/ProfilerSampler.cpp b/src/jrd/ProfilerSampler.cpp
new file mode 100644
index 00000000000..bf2d820a605
--- /dev/null
+++ b/src/jrd/ProfilerSampler.cpp
@@ -0,0 +1,518 @@
+/*
+ * The contents of this file are subject to the Initial
+ * Developer's Public License Version 1.0 (the "License");
+ * you may not use this file except in compliance with the
+ * License. You may obtain a copy of the License at
+ * http://www.ibphoenix.com/main.nfs?a=ibphoenix&page=ibp_idpl.
+ *
+ * Software distributed under the License is distributed AS IS,
+ * WITHOUT WARRANTY OF ANY KIND, either express or implied.
+ * See the License for the specific language governing rights
+ * and limitations under the License.
+ *
+ * The Original Code was created by Adriano dos Santos Fernandes
+ * for the Firebird Open Source RDBMS project.
+ *
+ * Copyright (c) 2026 Adriano dos Santos Fernandes
+ * and all contributors signed below.
+ *
+ * All Rights Reserved.
+ * Contributor(s): ______________________________________.
+ */
+
+#include "firebird.h"
+#include "../jrd/ProfilerSampler.h"
+#include "../common/ThreadStart.h"
+#include "../common/classes/array.h"
+#include "../common/classes/init.h"
+#include "../common/classes/semaphore.h"
+#include "../common/isc_proto.h"
+#include "../common/utils_proto.h"
+
+#ifdef WIN_NT
+#include
+#else
+#include
+#endif
+
+using namespace Jrd;
+using namespace Firebird;
+
+
+namespace
+{
+ // Upper bound of the sampler sleep, so a stop request is noticed even with large intervals.
+ constexpr SINT64 MAX_SLEEP_MICROSECONDS = 100'000;
+
+ // How long all states must be idle before the sampler sleeps until one becomes busy. Shorter idle periods,
+ // as between the requests of a client, are sampled as usual, as waking up the sampler costs more.
+ constexpr SINT64 IDLE_SLEEP_DELAY_MICROSECONDS = 10'000;
+
+ constexpr unsigned MAX_SNAPSHOT_RETRIES = 1000;
+
+ SINT64 microsecondsToTicks(SINT64 microseconds)
+ {
+ return MAX(microseconds * fb_utils::query_performance_frequency() / 1'000'000, 1);
+ }
+
+ class Sleeper
+ {
+ public:
+ Sleeper()
+ {
+#ifdef WIN_NT
+#ifdef CREATE_WAITABLE_TIMER_HIGH_RESOLUTION
+ timer = CreateWaitableTimerExW(nullptr, nullptr, CREATE_WAITABLE_TIMER_HIGH_RESOLUTION,
+ TIMER_MODIFY_STATE | SYNCHRONIZE);
+#endif
+ if (!timer)
+ timer = CreateWaitableTimerExW(nullptr, nullptr, 0, TIMER_MODIFY_STATE | SYNCHRONIZE);
+#endif
+ }
+
+ ~Sleeper()
+ {
+#ifdef WIN_NT
+ if (timer)
+ CloseHandle(timer);
+#endif
+ }
+
+ Sleeper(const Sleeper&) = delete;
+ Sleeper& operator=(const Sleeper&) = delete;
+
+ public:
+ void sleep(SINT64 ticks)
+ {
+ if (ticks <= 0)
+ return;
+
+ const SINT64 nanoseconds = ticks * fb_utils::BILLION / fb_utils::query_performance_frequency();
+
+#ifdef WIN_NT
+ if (timer)
+ {
+ LARGE_INTEGER dueTime;
+ dueTime.QuadPart = -MAX(nanoseconds / 100, 1); // relative, in 100 ns units
+
+ if (SetWaitableTimer(timer, &dueTime, 0, nullptr, nullptr, FALSE))
+ {
+ WaitForSingleObject(timer, INFINITE);
+ return;
+ }
+ }
+
+ Sleep(DWORD(MAX(nanoseconds * 1000 / fb_utils::BILLION, 1)));
+#else
+ timespec ts;
+ ts.tv_sec = time_t(nanoseconds / fb_utils::BILLION);
+ ts.tv_nsec = long(nanoseconds % fb_utils::BILLION);
+
+ nanosleep(&ts, nullptr);
+#endif
+ }
+
+ private:
+#ifdef WIN_NT
+ HANDLE timer = nullptr;
+#endif
+ };
+
+ class SamplerThread
+ {
+ public:
+ explicit SamplerThread(MemoryPool& pool)
+ : states(pool)
+ {
+ }
+
+ ~SamplerThread()
+ {
+ // States are removed by their ProfilerManager, but one left registered at shutdown
+ // must not keep the thread running with the members already destroyed.
+ fb_assert(states.isEmpty());
+
+ stopThread();
+
+ for (const auto state : states)
+ state->release();
+ }
+
+ SamplerThread(const SamplerThread&) = delete;
+ SamplerThread& operator=(const SamplerThread&) = delete;
+
+ public:
+ void wake() noexcept
+ {
+ try
+ {
+ wakeSemaphore.release();
+ }
+ catch (const Exception&)
+ {
+ // The sampler wakes up anyway after MAX_SLEEP_MICROSECONDS.
+ }
+ }
+
+ void add(ProfilerSampleState* state)
+ {
+ MutexLockGuard controlGuard(controlMutex, FB_FUNCTION);
+
+ if (shutdownDone)
+ return;
+
+ { // scope
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+ state->addRef();
+ states.add(state);
+ }
+
+ if (!thread.isValid())
+ {
+ stopRequested = false;
+ Thread::start(threadRoutine, this, THREAD_high, &thread);
+ }
+ }
+
+ void remove(ProfilerSampleState* state)
+ {
+ MutexLockGuard controlGuard(controlMutex, FB_FUNCTION);
+ bool wasLast;
+
+ { // scope
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+
+ FB_SIZE_T pos;
+ if (!states.find(state, pos))
+ return;
+
+ states.remove(pos);
+ state->release();
+
+ wasLast = states.isEmpty();
+ }
+
+ if (wasLast)
+ stopThread();
+ }
+
+ void shutdown()
+ {
+ MutexLockGuard controlGuard(controlMutex, FB_FUNCTION);
+
+ shutdownDone = true;
+ stopThread();
+
+ // Attachments not yet shut down remove their states later, finding them already gone.
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+
+ for (const auto state : states)
+ state->release();
+
+ states.clear();
+ }
+
+ private:
+ void stopThread()
+ {
+ if (thread.isValid())
+ {
+ stopRequested = true;
+ wakeSemaphore.release();
+ thread.waitForCompletion();
+ thread.detach(false);
+ }
+ }
+
+ static THREAD_ENTRY_DECLARE threadRoutine(THREAD_ENTRY_PARAM arg)
+ {
+ static_cast(arg)->run();
+ return 0;
+ }
+
+ void run()
+ {
+ Sleeper sleeper;
+ const SINT64 maxSleepTicks = microsecondsToTicks(MAX_SLEEP_MICROSECONDS);
+ const SINT64 idleSleepDelayTicks = microsecondsToTicks(IDLE_SLEEP_DELAY_MICROSECONDS);
+ SINT64 idleSinceTicks = 0; // 0 = some state is busy
+ bool errorLogged = false;
+
+ while (!stopRequested.load(std::memory_order_relaxed))
+ {
+ const SINT64 now = fb_utils::query_performance_counter();
+ SINT64 nextSampleTicks = now + maxSleepTicks;
+ bool allIdle = true;
+
+ // The thread is restarted only when all states are removed, so an error loses the samples
+ // of this pass, but doesn't stop the sampling. It's logged once until a pass succeeds.
+ try
+ {
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+
+ for (const auto state : states)
+ {
+ nextSampleTicks = MIN(nextSampleTicks, state->sample(now));
+ allIdle = allIdle && state->isIdle();
+ }
+
+ errorLogged = false;
+ }
+ catch (const Exception& ex)
+ {
+ allIdle = false;
+
+ if (!errorLogged)
+ {
+ iscLogException("Error in profiler sampler thread", ex);
+ errorLogged = true;
+ }
+ }
+
+ if (!allIdle)
+ idleSinceTicks = 0;
+ else if (!idleSinceTicks)
+ idleSinceTicks = now;
+ else if (now - idleSinceTicks >= idleSleepDelayTicks)
+ {
+ sleepWhileIdle();
+ idleSinceTicks = 0;
+ continue;
+ }
+
+ sleeper.sleep(nextSampleTicks - fb_utils::query_performance_counter());
+ }
+ }
+
+ // Sleeps until a state becomes busy, so idle attachments don't wake the sampler every interval.
+ void sleepWhileIdle()
+ {
+ ProfilerSampleState::samplerSleeping.store(true, std::memory_order_relaxed);
+
+ // Pairs with the fence in ProfilerSampleState::wakeSampler().
+ std::atomic_thread_fence(std::memory_order_seq_cst);
+
+ bool allIdle = true;
+
+ { // scope
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+
+ for (const auto state : states)
+ {
+ if (!state->isIdle())
+ {
+ allIdle = false;
+ break;
+ }
+ }
+ }
+
+ if (allIdle && !stopRequested.load(std::memory_order_relaxed))
+ wakeSemaphore.tryEnter(0, int(MAX_SLEEP_MICROSECONDS / 1000));
+
+ ProfilerSampleState::samplerSleeping.store(false, std::memory_order_relaxed);
+
+ const SINT64 now = fb_utils::query_performance_counter();
+
+ MutexLockGuard statesGuard(statesMutex, FB_FUNCTION);
+
+ for (const auto state : states)
+ state->restart(now);
+ }
+
+ private:
+ Mutex controlMutex; // serializes thread start and stop
+ Mutex statesMutex; // protects states
+ HalfStaticArray states;
+ Semaphore wakeSemaphore; // released to end sleepWhileIdle()
+ Thread thread;
+ std::atomic stopRequested = false;
+ bool shutdownDone = false; // protected by controlMutex
+ };
+
+ GlobalPtr samplerThread;
+}
+
+
+//--------------------------------------
+
+
+ProfilerSampleState::ProfilerSampleState()
+ : samples(*getDefaultMemoryPool())
+{
+}
+
+void ProfilerSampleState::setInterval(ULONG microseconds)
+{
+ intervalTicks.store(microsecondsToTicks(microseconds), std::memory_order_relaxed);
+}
+
+void ProfilerSampleState::takeSamples(SampleMap& target)
+{
+ MutexLockGuard guard(samplesMutex, FB_FUNCTION);
+ target.takeOwnership(samples);
+ samplesPending.store(false, std::memory_order_relaxed);
+}
+
+void ProfilerSampleState::clearSamples()
+{
+ MutexLockGuard guard(samplesMutex, FB_FUNCTION);
+ samples.clear();
+ samplesPending.store(false, std::memory_order_relaxed);
+}
+
+SINT64 ProfilerSampleState::sample(SINT64 now)
+{
+ if (now < nextSampleTicks)
+ return nextSampleTicks;
+
+ const SINT64 elapsed = lastSampleTicks ? now - lastSampleTicks : 0;
+
+ // The depth is read again by the snapshot, but checking it here avoids setting samplesPending when
+ // nothing is executing, so mayHaveSamples() remains false for requests that finish between samples.
+ if (elapsed <= 0 || isIdle())
+ {
+ lastSampleTicks = now;
+ nextSampleTicks = now + nextInterval();
+ return nextSampleTicks;
+ }
+
+ Frame snapshotFrames[MAX_DEPTH];
+ unsigned count;
+
+ // Keep the lock from the snapshot until the samples are stored, so a drain done after a frame
+ // is popped never misses a sample taken while the frame was present.
+ MutexLockGuard guard(samplesMutex, FB_FUNCTION);
+
+ // Set before the snapshot, so a writer that pops its frames and then finds it clear knows that
+ // no sample of them is pending. See mayHaveSamples().
+ samplesPending.store(true, std::memory_order_relaxed);
+ std::atomic_thread_fence(std::memory_order_seq_cst);
+
+ if (!snapshot(snapshotFrames, count))
+ {
+ // The attachment is changing its frames too fast to be read now. Retry soon, keeping
+ // lastSampleTicks, so the elapsed time is charged by the next sample instead of being lost.
+ nextSampleTicks = now + MAX(intervalTicks.load(std::memory_order_relaxed) / 16, 1);
+ return nextSampleTicks;
+ }
+
+ lastSampleTicks = now;
+ nextSampleTicks = now + nextInterval();
+
+ // The frames were popped after the depth was checked.
+ if (count == 0 && samples.isEmpty())
+ {
+ samplesPending.store(false, std::memory_order_relaxed);
+ return nextSampleTicks;
+ }
+
+ HalfStaticArray keys;
+
+ const auto addKey = [&](const Key& key)
+ {
+ // Recursion may show the same key more than once in a stack, but it must be charged once.
+ for (const auto& existing : keys)
+ {
+ if (existing == key)
+ return;
+ }
+
+ keys.add(key);
+ *samples.getOrPut(key) += elapsed;
+ };
+
+ for (unsigned i = 0; i < count; ++i)
+ {
+ const auto& frame = snapshotFrames[i];
+
+ switch (frame.kind)
+ {
+ case FrameKind::REQUEST:
+ addKey({frame.statementId, frame.requestId, 0, 0, KeyKind::REQUEST});
+
+ if (frame.a || frame.b)
+ addKey({frame.statementId, frame.requestId, frame.a, frame.b, KeyKind::LINE});
+ break;
+
+ case FrameKind::OPEN:
+ addKey({frame.statementId, frame.requestId, frame.a, frame.b, KeyKind::OPEN});
+ break;
+
+ case FrameKind::FETCH:
+ addKey({frame.statementId, frame.requestId, frame.a, frame.b, KeyKind::FETCH});
+ break;
+ }
+ }
+
+ return nextSampleTicks;
+}
+
+void ProfilerSampleState::restart(SINT64 now) noexcept
+{
+ // A state that became busy is sampled after one interval. Its time before it is not charged,
+ // but it's only the time to wake up the sampler.
+ lastSampleTicks = now;
+ nextSampleTicks = now + nextInterval();
+}
+
+void ProfilerSampleState::wakeSleepingSampler() noexcept
+{
+ // Only one of the writers that see the sampler sleeping releases it.
+ if (samplerSleeping.exchange(false, std::memory_order_relaxed))
+ samplerThread->wake();
+}
+
+bool ProfilerSampleState::snapshot(Frame* target, unsigned& count) const noexcept
+{
+ // Hot loops may change the frames every few nanoseconds, so a read often overlaps a write.
+ for (unsigned retry = 0; retry < MAX_SNAPSHOT_RETRIES; ++retry)
+ {
+ const unsigned startSeq = seq.load(std::memory_order_acquire);
+
+ if (startSeq & 1)
+ continue; // a write is in progress
+
+ count = MIN(depth.load(std::memory_order_relaxed), MAX_DEPTH);
+ memcpy(target, frames, count * sizeof(Frame));
+
+ std::atomic_thread_fence(std::memory_order_acquire);
+
+ if (seq.load(std::memory_order_relaxed) == startSeq)
+ return true;
+ }
+
+ return false;
+}
+
+SINT64 ProfilerSampleState::nextInterval() noexcept
+{
+ // Randomize the interval in [0.75, 1.25) of the configured one, so periodic code doesn't alias
+ // with the sampling period.
+ jitterState ^= jitterState << 13;
+ jitterState ^= jitterState >> 17;
+ jitterState ^= jitterState << 5;
+
+ const SINT64 interval = intervalTicks.load(std::memory_order_relaxed);
+
+ return MAX(interval * 3 / 4 + SINT64((jitterState % 1024) * (interval / 2) / 1024), 1);
+}
+
+
+//--------------------------------------
+
+
+void ProfilerSampler::add(ProfilerSampleState* state)
+{
+ samplerThread->add(state);
+}
+
+void ProfilerSampler::remove(ProfilerSampleState* state)
+{
+ samplerThread->remove(state);
+}
+
+void ProfilerSampler::shutdown()
+{
+ samplerThread->shutdown();
+}
diff --git a/src/jrd/ProfilerSampler.h b/src/jrd/ProfilerSampler.h
new file mode 100644
index 00000000000..92b603a79c1
--- /dev/null
+++ b/src/jrd/ProfilerSampler.h
@@ -0,0 +1,254 @@
+/*
+ * The contents of this file are subject to the Initial
+ * Developer's Public License Version 1.0 (the "License");
+ * you may not use this file except in compliance with the
+ * License. You may obtain a copy of the License at
+ * http://www.ibphoenix.com/main.nfs?a=ibphoenix&page=ibp_idpl.
+ *
+ * Software distributed under the License is distributed AS IS,
+ * WITHOUT WARRANTY OF ANY KIND, either express or implied.
+ * See the License for the specific language governing rights
+ * and limitations under the License.
+ *
+ * The Original Code was created by Adriano dos Santos Fernandes
+ * for the Firebird Open Source RDBMS project.
+ *
+ * Copyright (c) 2026 Adriano dos Santos Fernandes
+ * and all contributors signed below.
+ *
+ * All Rights Reserved.
+ * Contributor(s): ______________________________________.
+ */
+
+#ifndef JRD_PROFILER_SAMPLER_H
+#define JRD_PROFILER_SAMPLER_H
+
+#include "firebird.h"
+#include "../common/classes/alloc.h"
+#include "../common/classes/GenericMap.h"
+#include "../common/classes/locks.h"
+#include "../common/classes/RefCounted.h"
+#include
+
+namespace Jrd {
+
+
+// Where an attachment is executing, published by the attachment thread (the only writer) and read
+// by the sampler thread. The writer pays a few plain stores per event, protected by a seqlock.
+// The sampler charges the wall time elapsed since its previous sample to every frame it sees.
+class ProfilerSampleState final : public Firebird::RefCounted, public Firebird::GlobalStorage
+{
+public:
+ enum class FrameKind : UCHAR
+ {
+ REQUEST, // a = line, b = column of the current PSQL statement (0 = none)
+ OPEN, // a = record source id, b = cursor id
+ FETCH // a = record source id, b = cursor id
+ };
+
+ struct Frame
+ {
+ SINT64 statementId;
+ SINT64 requestId;
+ ULONG a;
+ ULONG b;
+ FrameKind kind;
+ };
+
+ enum class KeyKind : UCHAR
+ {
+ REQUEST, // whole request, a = b = 0
+ LINE, // a = line, b = column
+ OPEN, // a = record source id, b = cursor id
+ FETCH // a = record source id, b = cursor id
+ };
+
+ struct Key
+ {
+ SINT64 statementId;
+ SINT64 requestId;
+ ULONG a;
+ ULONG b;
+ KeyKind kind;
+
+ bool operator==(const Key& o) const noexcept
+ {
+ return requestId == o.requestId && statementId == o.statementId &&
+ a == o.a && b == o.b && kind == o.kind;
+ }
+
+ bool operator<(const Key& o) const noexcept
+ {
+ if (requestId != o.requestId)
+ return requestId < o.requestId;
+ if (statementId != o.statementId)
+ return statementId < o.statementId;
+ if (kind != o.kind)
+ return kind < o.kind;
+ if (a != o.a)
+ return a < o.a;
+ return b < o.b;
+ }
+
+ bool operator>(const Key& o) const noexcept
+ {
+ return o < *this;
+ }
+ };
+
+ using SampleMap = Firebird::NonPooledMap;
+
+ static constexpr unsigned MAX_DEPTH = 256;
+
+public:
+ ProfilerSampleState();
+
+ ProfilerSampleState(const ProfilerSampleState&) = delete;
+ ProfilerSampleState& operator=(const ProfilerSampleState&) = delete;
+
+public:
+ // Writer side (attachment thread).
+
+ // Returns the depth before the push, to be passed to popTo.
+ unsigned push(const Frame& frame) noexcept
+ {
+ const unsigned oldDepth = depth.load(std::memory_order_relaxed);
+
+ beginWrite();
+
+ if (oldDepth < MAX_DEPTH)
+ frames[oldDepth] = frame;
+
+ depth.store(oldDepth + 1, std::memory_order_relaxed);
+
+ endWrite();
+
+ if (oldDepth == 0)
+ wakeSampler();
+
+ return oldDepth;
+ }
+
+ void popTo(unsigned newDepth) noexcept
+ {
+ beginWrite();
+ depth.store(newDepth, std::memory_order_relaxed);
+ endWrite();
+ }
+
+ void setLine(unsigned frameIndex, ULONG line, ULONG column) noexcept
+ {
+ if (frameIndex < MAX_DEPTH)
+ {
+ beginWrite();
+ frames[frameIndex].a = line;
+ frames[frameIndex].b = column;
+ endWrite();
+ }
+ }
+
+ void setActive(bool value) noexcept
+ {
+ active.store(value, std::memory_order_relaxed);
+
+ if (value)
+ wakeSampler();
+ }
+
+ // Each session may have its own interval. A new interval is used from the next sample on.
+ void setInterval(ULONG microseconds);
+
+ // Moves the accumulated samples to the caller.
+ void takeSamples(SampleMap& target);
+
+ // Returns false when takeSamples would return nothing that involves frames popped before this call,
+ // so the caller can skip it.
+ bool mayHaveSamples() const noexcept
+ {
+ // Pairs with the fence in sample(): either this load sees samplesPending set, or the snapshot of
+ // the sampler sees the frames already popped.
+ std::atomic_thread_fence(std::memory_order_seq_cst);
+ return samplesPending.load(std::memory_order_relaxed);
+ }
+
+ // Discards the accumulated samples.
+ void clearSamples();
+
+ // Sampler side.
+
+ // Takes one sample if it's due. Returns the next due time.
+ SINT64 sample(SINT64 now);
+
+ // There is nothing to sample: the session is paused or finished, or nothing is executing.
+ bool isIdle() const noexcept
+ {
+ return !active.load(std::memory_order_relaxed) || depth.load(std::memory_order_relaxed) == 0;
+ }
+
+ // Starts sampling again after the sampler slept, without charging the time slept.
+ void restart(SINT64 now) noexcept;
+
+ // Set by the sampler before it sleeps because all states are idle. A state that becomes busy wakes it.
+ static inline std::atomic samplerSleeping = false;
+
+private:
+ void beginWrite() noexcept
+ {
+ seq.store(seq.load(std::memory_order_relaxed) + 1, std::memory_order_relaxed);
+ std::atomic_thread_fence(std::memory_order_release);
+ }
+
+ void endWrite() noexcept
+ {
+ seq.store(seq.load(std::memory_order_relaxed) + 1, std::memory_order_release);
+ }
+
+ static void wakeSampler() noexcept
+ {
+ // Pairs with the fence of the sampler before it sleeps: either it sees this state busy,
+ // or this sees it sleeping.
+ std::atomic_thread_fence(std::memory_order_seq_cst);
+
+ if (samplerSleeping.load(std::memory_order_relaxed))
+ wakeSleepingSampler();
+ }
+
+ static void wakeSleepingSampler() noexcept;
+
+ bool snapshot(Frame* target, unsigned& count) const noexcept;
+
+ SINT64 nextInterval() noexcept;
+
+private:
+ std::atomic seq = 0;
+ std::atomic depth = 0;
+ std::atomic active = false;
+ std::atomic intervalTicks = 0;
+ Frame frames[MAX_DEPTH];
+
+ // Owned by the sampler thread.
+ SINT64 nextSampleTicks = 0;
+ SINT64 lastSampleTicks = 0;
+ ULONG jitterState = 0x9E3779B9; // xorshift32 state of nextInterval(), any non-zero seed
+
+ Firebird::Mutex samplesMutex;
+ SampleMap samples;
+ std::atomic samplesPending = false; // set before a snapshot, cleared when samples are taken
+};
+
+
+// Process-wide thread that samples all registered states.
+class ProfilerSampler final
+{
+public:
+ static void add(ProfilerSampleState* state);
+ static void remove(ProfilerSampleState* state);
+
+ // Stops the thread at engine shutdown. States added after it are not sampled.
+ static void shutdown();
+};
+
+
+} // namespace Jrd
+
+#endif // JRD_PROFILER_SAMPLER_H
diff --git a/src/jrd/exe.cpp b/src/jrd/exe.cpp
index e68a98d85a3..e7129fff347 100644
--- a/src/jrd/exe.cpp
+++ b/src/jrd/exe.cpp
@@ -44,7 +44,6 @@
*/
#include "firebird.h"
-#include
#ifdef TIME_WITH_SYS_TIME
# include
# include
@@ -998,6 +997,10 @@ static void activate_request(thread_db* tdbb, Request* request, jrd_tra* transac
const auto dbb = tdbb->getDatabase();
const auto statement = request->getStatement();
+ // A request finished while its profiler session was paused keeps the profile of its previous id.
+ if (request->req_profiler_profile)
+ request->req_attachment->getProfilerManager(tdbb)->releaseStaleRequestProfile(request);
+
// Generate request id.
request->setRequestId(
request->isRequestIdUnassigned() && request->isRoot() ?
@@ -1029,6 +1032,7 @@ static void activate_request(thread_db* tdbb, Request* request, jrd_tra* transac
rpb.rpb_runtime_flags = 0;
request->req_profiler_ticks = 0;
+ request->req_profiler_sampled = false;
// Store request start time for timestamp work
request->validateTimeStamp();
@@ -1084,10 +1088,17 @@ void EXE_execute_function(thread_db* tdbb, Request* request, jrd_tra* transactio
const auto profilerManager = attachment->isProfilerActive() && !request->hasInternalStatement() ?
attachment->getProfilerManager(tdbb) : nullptr;
- const SINT64 profilerInitialTicks = profilerManager ? profilerManager->queryTicks() : 0;
- const SINT64 profilerInitialAccumulatedOverhead = profilerManager ?
+ const bool profilerSampled = profilerManager && profilerManager->isSampled();
+ const SINT64 profilerInitialTicks = profilerManager && !profilerSampled ?
+ profilerManager->beginInterval() : 0;
+ const SINT64 profilerInitialAccumulatedOverhead = profilerManager && !profilerSampled ?
profilerManager->getAccumulatedOverhead() : 0;
+ ProfilerManager::RequestFrame profilerFrame;
+
+ if (profilerSampled)
+ profilerFrame.push(profilerManager, request);
+
try
{
function->fun_external->execute(tdbb, request, transaction, inMsgLength, inMsg, outMsgLength, outMsg);
@@ -1118,11 +1129,12 @@ void EXE_execute_function(thread_db* tdbb, Request* request, jrd_tra* transactio
if (profilerInitialTicks && attachment->isProfilerActive())
{
- const SINT64 currentProfilerTicks = profilerManager->queryTicks();
- const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
- currentProfilerTicks, profilerInitialTicks, profilerInitialAccumulatedOverhead);
+ const SINT64 overheadStartTicks = profilerManager->queryTicks();
+
+ request->req_profiler_ticks += profilerManager->getElapsedTicksAndAdjustOverhead(
+ overheadStartTicks, profilerInitialTicks, profilerInitialAccumulatedOverhead);
- request->req_profiler_ticks += elapsedTicks;
+ profilerManager->endOverhead(overheadStartTicks);
}
request->adjustCallerStats();
@@ -1133,7 +1145,9 @@ void EXE_execute_function(thread_db* tdbb, Request* request, jrd_tra* transactio
request->req_flags &= ~req_active;
request->invalidateTimeStamp();
- if (profilerInitialTicks && attachment->isProfilerActive())
+ profilerFrame.pop();
+
+ if ((profilerInitialTicks || profilerSampled) && attachment->isProfilerActive())
{
ProfilerManager::Stats stats(request->req_profiler_ticks);
profilerManager->onRequestFinish(request, stats);
@@ -1257,7 +1271,8 @@ void EXE_unwind(thread_db* tdbb, Request* request)
const auto attachment = request->req_attachment;
- if (request->req_profiler_ticks && attachment->isProfilerActive() && !request->hasInternalStatement())
+ if ((request->req_profiler_ticks || request->req_profiler_sampled) &&
+ attachment->isProfilerActive() && !request->hasInternalStatement())
{
ProfilerManager::Stats stats(request->req_profiler_ticks);
attachment->getProfilerManager(tdbb)->onRequestFinish(request, stats);
@@ -1723,24 +1738,37 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
// Execute stuff until we drop
- ProfilerManager* profilerManager;
- SINT64 profilerInitialTicks, profilerInitialAccumulatedOverhead, profilerLastTicks, profilerLastAccumulatedOverhead;
+ ProfilerManager* profilerManager = nullptr;
+ SINT64 profilerInitialTicks = 0;
+ SINT64 profilerInitialAccumulatedOverhead = 0;
+ SINT64 profilerLastTicks = 0;
+ SINT64 profilerLastAccumulatedOverhead = 0;
+ bool profilerStarted = false;
- if (attachment->isProfilerActive() && !request->hasInternalStatement())
- {
+ // When sampling, the frame of this request is published for the sampler.
+ ProfilerManager::RequestFrame profilerFrame;
+
+ const auto profilerStart = [&] {
profilerManager = attachment->getProfilerManager(tdbb);
- profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
- profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
- profilerManager->getAccumulatedOverhead();
- }
- else
- {
- profilerManager = nullptr;
- profilerInitialTicks = 0;
- profilerLastTicks = 0;
- profilerInitialAccumulatedOverhead = 0;
- profilerLastAccumulatedOverhead = 0;
- }
+ profilerStarted = true;
+
+ if (profilerManager->isSampled())
+ {
+ profilerFrame.push(profilerManager, request);
+ profilerInitialTicks = 0;
+ }
+ else
+ {
+ profilerInitialTicks = profilerLastTicks = profilerManager->beginInterval();
+ profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
+ profilerManager->getAccumulatedOverhead();
+ }
+ };
+
+ const bool profilerCanBeActive = !request->hasInternalStatement();
+
+ if (profilerCanBeActive && attachment->isProfilerActive())
+ profilerStart();
const StmtNode* profileNode = nullptr;
@@ -1766,42 +1794,52 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
{
JRD_reschedule(tdbb);
- if (node->hasLineColumn)
+ if (node->flags & StmtNode::FLAG_LINE_COLUMN)
{
request->req_src_line = node->line;
request->req_src_column = node->column;
}
}
- std::optional cachedProfileMode;
-
- if (attachment->isProfilerActive() && !request->hasInternalStatement() &&
+ if (profilerCanBeActive && attachment->isProfilerActive() &&
(request->req_operation == Request::req_evaluate ||
((request->req_operation == Request::req_return ||
request->req_operation == Request::req_sync) &&
- *(cachedProfileMode = node->getProfileMode()) == StmtNode::ProfileMode::EVALUATE_RETURN)))
+ (node->flags & StmtNode::FLAG_PROFILE_ON_RETURN))))
{
- if (!profilerInitialTicks)
+ // Also restart the profiling when the request started a session with the other timing mode.
+ if (!profilerStarted || profilerManager->isSampled() != profilerFrame.isPushed())
{
- profilerManager = attachment->getProfilerManager(tdbb);
- profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
- profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
- profilerManager->getAccumulatedOverhead();
+ profilerFrame.pop();
+ profilerStart();
+ profileNode = nullptr;
}
- if (node->hasLineColumn &&
+ if ((node->flags & (StmtNode::FLAG_LINE_COLUMN | StmtNode::FLAG_NOT_PROFILED)) ==
+ StmtNode::FLAG_LINE_COLUMN &&
(exeState.forceProfileNextEvaluate ||
!profileNode ||
- !(node->line == profileNode->line && node->column == profileNode->column)) &&
- (cachedProfileMode.has_value() ? *cachedProfileMode : node->getProfileMode()) !=
- StmtNode::ProfileMode::NONE)
+ !(node->line == profileNode->line && node->column == profileNode->column)))
{
- profilerLastTicks = profilerCallAfterPsqlLineColumn();
- profilerLastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
- profileNode = node;
- exeState.forceProfileNextEvaluate = false;
+ if (profilerFrame.isPushed())
+ {
+ profileNode = node;
+ exeState.forceProfileNextEvaluate = false;
- profilerManager->beforePsqlLineColumn(request, profileNode->line, profileNode->column);
+ profilerManager->hitPsqlLine(request, profilerFrame.getState(), profilerFrame.getIndex(),
+ node->profileSlot, node->line, node->column);
+ }
+ else if (profilerInitialTicks)
+ {
+ const SINT64 overheadStartTicks = profilerCallAfterPsqlLineColumn();
+ profileNode = node;
+ exeState.forceProfileNextEvaluate = false;
+
+ profilerManager->beforePsqlLineColumn(request, profileNode->line, profileNode->column);
+
+ profilerLastTicks = profilerManager->endOverhead(overheadStartTicks);
+ profilerLastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
+ }
}
}
@@ -1809,12 +1847,14 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
if (exeState.exit)
{
- if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
+ if (profilerInitialTicks && profilerCanBeActive && attachment->isProfilerActive())
{
- const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
- profilerCallAfterPsqlLineColumn(), profilerInitialTicks, profilerInitialAccumulatedOverhead);
+ const SINT64 overheadStartTicks = profilerCallAfterPsqlLineColumn();
- request->req_profiler_ticks += elapsedTicks;
+ request->req_profiler_ticks += profilerManager->getElapsedTicksAndAdjustOverhead(
+ overheadStartTicks, profilerInitialTicks, profilerInitialAccumulatedOverhead);
+
+ profilerManager->endOverhead(overheadStartTicks);
}
return node;
@@ -1857,12 +1897,14 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
}
} // while()
- if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
+ if (profilerInitialTicks && profilerCanBeActive && attachment->isProfilerActive())
{
- const SINT64 elapsedTicks = profilerManager->getElapsedTicksAndAdjustOverhead(
- profilerCallAfterPsqlLineColumn(), profilerInitialTicks, profilerInitialAccumulatedOverhead);
+ const SINT64 overheadStartTicks = profilerCallAfterPsqlLineColumn();
+
+ request->req_profiler_ticks += profilerManager->getElapsedTicksAndAdjustOverhead(
+ overheadStartTicks, profilerInitialTicks, profilerInitialAccumulatedOverhead);
- request->req_profiler_ticks += elapsedTicks;
+ profilerManager->endOverhead(overheadStartTicks);
}
request->adjustCallerStats();
@@ -1890,7 +1932,10 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
request->invalidateTimeStamp();
release_blobs(tdbb, request);
- if (profilerInitialTicks && attachment->isProfilerActive() && !request->hasInternalStatement())
+ // The frame must be gone before the request finishes, so no sample is taken after its stats are delivered.
+ profilerFrame.pop();
+
+ if (profilerStarted && profilerCanBeActive && attachment->isProfilerActive())
{
ProfilerManager::Stats stats(request->req_profiler_ticks);
profilerManager->onRequestFinish(request, stats);
diff --git a/src/jrd/exe.h b/src/jrd/exe.h
index 8929bfbf466..b475a6895fb 100644
--- a/src/jrd/exe.h
+++ b/src/jrd/exe.h
@@ -594,8 +594,9 @@ class CompilerScratch : public pool_alloc
USHORT csb_g_flags;
MemoryPool& csb_pool; // Memory pool to be used by csb
Firebird::AutoPtr csb_dbg_info; // Debug information
- MapFieldInfo csb_map_field_info; // Map field name to field info
- MapItemInfo csb_map_item_info; // Map item to item info
+ ULONG csb_profile_slots = 0; // Number of StmtNode::profileSlot values assigned
+ MapFieldInfo csb_map_field_info; // Map field name to field info
+ MapItemInfo csb_map_item_info; // Map item to item info
// Map of message number to field number to pad for external routines.
Firebird::GenericMap > > csb_message_pad;
diff --git a/src/jrd/jrd.cpp b/src/jrd/jrd.cpp
index 154fd57a260..1d1fd407ede 100644
--- a/src/jrd/jrd.cpp
+++ b/src/jrd/jrd.cpp
@@ -114,6 +114,7 @@
#include "../jrd/ThreadCollect.h"
#include "../jrd/Database.h"
+#include "../jrd/ProfilerSampler.h"
#include "../jrd/WorkerAttachment.h"
#include "../common/config/config.h"
@@ -4741,6 +4742,8 @@ void JProvider::shutdown(CheckStatusWrapper* status, unsigned int timeout, const
shutdown_thread(NULL);
}
+ ProfilerSampler::shutdown();
+
// Do not put it into separate shutdown thread - during shutdown of TraceManager
// PluginManager wants to lock a mutex, which is sometimes already locked in current thread
TraceManager::shutdown();
diff --git a/src/jrd/par.cpp b/src/jrd/par.cpp
index 10ba77dfabc..ac7b89d0700 100644
--- a/src/jrd/par.cpp
+++ b/src/jrd/par.cpp
@@ -1762,7 +1762,14 @@ static void setNodeLineColumn(CompilerScratch* csb, DmlNode* node, ULONG blrOffs
if (node->getKind() == DmlNode::KIND_STATEMENT)
{
const auto stmt = static_cast(node);
- stmt->hasLineColumn = true;
+ stmt->flags |= StmtNode::FLAG_LINE_COLUMN;
+
+ // Statements past the limit share the last slot, which merges their line counters.
+ stmt->profileSlot = MIN(csb->csb_profile_slots, StmtNode::MAX_PROFILE_SLOT);
+
+ if (csb->csb_profile_slots < StmtNode::MAX_PROFILE_SLOT)
+ ++csb->csb_profile_slots;
+
propagateNodeLineColumn(stmt);
}
}
@@ -1775,12 +1782,13 @@ static void propagateNodeLineColumn(StmtNode* wrapper)
{
const auto inherit = [wrapper](StmtNode* child)
{
- if (!child || child->hasLineColumn)
+ if (!child || (child->flags & StmtNode::FLAG_LINE_COLUMN))
return;
child->line = wrapper->line;
child->column = wrapper->column;
- child->hasLineColumn = true;
+ child->profileSlot = wrapper->profileSlot;
+ child->flags |= StmtNode::FLAG_LINE_COLUMN;
propagateNodeLineColumn(child);
};
diff --git a/src/jrd/recsrc/Cursor.cpp b/src/jrd/recsrc/Cursor.cpp
index 652f58ac5aa..03601ab5488 100644
--- a/src/jrd/recsrc/Cursor.cpp
+++ b/src/jrd/recsrc/Cursor.cpp
@@ -51,7 +51,7 @@ namespace
{
public:
ProfilerSelectPrepare(thread_db* tdbb, const Select* select)
- : profilerManager(tdbb->getAttachment()->getActiveProfilerManagerForNonInternalStatement(tdbb))
+ : profilerManager(ProfilerManager::getActiveForNonInternalStatement(tdbb))
{
const auto request = tdbb->getRequest();
diff --git a/src/jrd/recsrc/RecordSource.cpp b/src/jrd/recsrc/RecordSource.cpp
index 2b852f703b7..0dcc7457976 100644
--- a/src/jrd/recsrc/RecordSource.cpp
+++ b/src/jrd/recsrc/RecordSource.cpp
@@ -122,6 +122,12 @@ RecordSource::RecordSource(CompilerScratch* csb)
void RecordSource::open(thread_db* tdbb) const
{
+ if (!tdbb->getAttachment()->isProfilerActive())
+ {
+ internalOpen(tdbb);
+ return;
+ }
+
ProfilerManager::RecordSourceStopWatcher profilerRecordSourceStopWatcher(tdbb, this,
ProfilerManager::RecordSourceStopWatcher::Event::OPEN);
@@ -130,6 +136,9 @@ void RecordSource::open(thread_db* tdbb) const
bool RecordSource::getRecord(thread_db* tdbb) const
{
+ if (!tdbb->getAttachment()->isProfilerActive())
+ return internalGetRecord(tdbb);
+
ProfilerManager::RecordSourceStopWatcher profilerRecordSourceStopWatcher(tdbb, this,
ProfilerManager::RecordSourceStopWatcher::Event::GET_RECORD);
diff --git a/src/jrd/req.h b/src/jrd/req.h
index 8fd0be17b5d..20bfc3f1449 100644
--- a/src/jrd/req.h
+++ b/src/jrd/req.h
@@ -51,6 +51,7 @@ class jrd_tra;
class Savepoint;
class Cursor;
class thread_db;
+class ProfilerRequestProfile;
// record parameter block
@@ -436,6 +437,9 @@ class Request : public pool_alloc
RuntimeStatistics req_base_stats;
AffectedRows req_records_affected; // records affected by the last statement
FB_UINT64 req_profiler_ticks; // profiler ticks
+ ProfilerRequestProfile* req_profiler_profile = nullptr; // sampling profiler counters, owned by ProfilerManager
+ ULONG req_profiler_generation = 0; // ProfilerManager generation of req_profiler_profile
+ bool req_profiler_sampled = false; // executed while the profiler samples timings
const StmtNode* req_next; // next node for execution
EDS::Statement* req_ext_stmt; // head of list of active dynamic statements
diff --git a/src/plugins/profiler/Profiler.cpp b/src/plugins/profiler/Profiler.cpp
index 9d29503d636..4d333961fd9 100644
--- a/src/plugins/profiler/Profiler.cpp
+++ b/src/plugins/profiler/Profiler.cpp
@@ -23,6 +23,8 @@
#include "firebird.h"
#include "firebird/Message.h"
#include
+#include
+#include
#include "../common/DeindentedStr.h"
#include "../common/Int128.h"
#include "../common/classes/ImplementHelper.h"
@@ -51,6 +53,9 @@ static constexpr UCHAR STREAM_BLOB_BPB[] = {
isc_bpb_type, 1, isc_bpb_type_stream,
};
+static constexpr auto SESSIONS_VIEW_COLUMNS =
+ "profile_id, attachment_id, user_name, description, start_timestamp, finish_timestamp, sampling_interval";
+
static const CInt128 ONE_SECOND_IN_NS{1'000'000'000};
static CInt128 ticksFrequency{0};
@@ -95,10 +100,24 @@ struct Stats
++counter;
}
+ // Aggregated hits with sampled time, so min and max are unknown.
+ void add(FB_UINT64 hits, FB_UINT64 elapsedTicks) noexcept
+ {
+ totalElapsedTicks += elapsedTicks;
+ counter += hits;
+ sampled = true;
+ }
+
+ bool isEmpty() const noexcept
+ {
+ return counter == 0 && totalElapsedTicks == 0;
+ }
+
FB_UINT64 counter = 0;
FB_UINT64 minElapsedTicks = 0;
FB_UINT64 maxElapsedTicks = 0;
FB_UINT64 totalElapsedTicks = 0;
+ bool sampled = false;
};
struct Cursor
@@ -121,6 +140,17 @@ struct RecordSourceStats
Stats fetchStats;
};
+// Record source stats of a cursor, indexed by record source id (dense, starts at 1).
+struct CursorStats
+{
+ explicit CursorStats(MemoryPool& pool)
+ : bySequence(PoolAllocator(pool))
+ {
+ }
+
+ std::vector> bySequence;
+};
+
struct Statement
{
unsigned level = 0;
@@ -132,8 +162,32 @@ struct Statement
string sqlText{defaultPool()};
};
-using LineColumnKey = NonPooledPair;
-using CursorRecSourceKey = NonPooledPair;
+struct UIntPairKey
+{
+ unsigned first;
+ unsigned second;
+
+ bool operator==(const UIntPairKey& o) const noexcept
+ {
+ return first == o.first && second == o.second;
+ }
+};
+
+struct UIntPairKeyHash
+{
+ size_t operator()(const UIntPairKey& k) const noexcept
+ {
+ const uint64_t h = (uint64_t(k.first) << 32 | k.second) * 0x9E3779B97F4A7C15ull;
+ return size_t(h ^ (h >> 32)); // fold high bits into the low ones, used by power of two bucket counts
+ }
+};
+
+template
+using UIntPairMap = std::unordered_map,
+ PoolAllocator>>;
+
+using LineColumnKey = UIntPairKey;
+using CursorRecSourceKey = UIntPairKey;
struct Request
{
@@ -145,8 +199,22 @@ struct Request
ISC_TIMESTAMP_TZ startTimestamp{};
std::optional finishTimestamp;
std::optional totalElapsedTicks;
- NonPooledMap recordSourcesStats{defaultPool()};
- NonPooledMap psqlStats{defaultPool()};
+ // Indexed by cursor id (dense, starts at 1).
+ std::vector> recordSourcesStats{PoolAllocator(defaultPool())};
+ UIntPairMap psqlStats{defaultPool()};
+
+ RecordSourceStats& getRecordSourceStats(unsigned cursorId, unsigned recSourceId)
+ {
+ if (cursorId >= recordSourcesStats.size())
+ recordSourcesStats.resize(cursorId + 1);
+
+ auto& bySequence = recordSourcesStats[cursorId].bySequence;
+
+ if (recSourceId >= bySequence.size())
+ bySequence.resize(recSourceId + 1);
+
+ return bySequence[recSourceId];
+ }
};
using StatementCursorKey = NonPooledPair;
@@ -225,10 +293,33 @@ class Session final :
const char* type, const char* schemaName, const char* packageName, const char* routineName,
const char* sqlText) override;
+ void addPsqlLineColumnStats(SINT64 statementId, SINT64 requestId, unsigned line, unsigned column,
+ FB_UINT64 counter, FB_UINT64 elapsedTicks) override;
+
+ void addRecordSourceOpenStats(SINT64 statementId, SINT64 requestId, unsigned cursorId, unsigned recSourceId,
+ FB_UINT64 counter, FB_UINT64 elapsedTicks) override;
+
+ void addRecordSourceGetRecordStats(SINT64 statementId, SINT64 requestId, unsigned cursorId, unsigned recSourceId,
+ FB_UINT64 counter, FB_UINT64 elapsedTicks) override;
+
+ void setSamplingInterval(unsigned microseconds) override
+ {
+ samplingInterval = microseconds;
+ dirty = true;
+ }
+
private:
Request* getRequest(SINT64 statementId, SINT64 requestId)
{
- return requests.get(detailedRequests ? requestId : -statementId);
+ const SINT64 key = detailedRequests ? requestId : -statementId;
+
+ if (lastRequest && lastRequestKey == key)
+ return lastRequest;
+
+ lastRequest = requests.get(key);
+ lastRequestKey = key;
+
+ return lastRequest;
}
public:
@@ -241,8 +332,18 @@ class Session final :
ISC_TIMESTAMP_TZ startTimestamp;
std::optional finishTimestamp;
string description{defaultPool()};
+ std::optional samplingInterval; // microseconds, 0 = measured timings
bool detailedRequests = false;
bool dirty = true;
+
+ void resetRequestCache() noexcept
+ {
+ lastRequest = nullptr;
+ }
+
+private:
+ Request* lastRequest = nullptr;
+ SINT64 lastRequestKey = 0;
};
class ProfilerPlugin final : public StdPlugin>
@@ -264,10 +365,14 @@ class ProfilerPlugin final : public StdPlugin transaction);
void upgradeMetadata(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction);
+ void migrateMetadata(ThrowStatusExceptionWrapper* status, RefPtr attachment,
+ RefPtr transaction, bool minMaxNotNull, bool samplingIntervalMissing);
void createMetadataTables(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction);
void recreateSnapshotViews(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction);
+ void recreateSnapshotView(ThrowStatusExceptionWrapper* status, RefPtr attachment,
+ RefPtr transaction, const char* viewName, const char* selectList, const char* tableName);
void recreateAggregateViews(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction);
@@ -300,6 +405,21 @@ void ProfilerPlugin::init(ThrowStatusExceptionWrapper* status, IAttachment* atta
rdb$relation_name = 'PLG$PROF_STATEMENTS_DATA' and
rdb$field_name = 'USER_NAME'
) secure_metadata_created,
+ exists(
+ select true
+ from system.rdb$relation_fields
+ where rdb$schema_name = 'PLG$PROFILER' and
+ rdb$relation_name = 'PLG$PROF_PSQL_STATS_DATA' and
+ rdb$field_name = 'MIN_ELAPSED_TIME' and
+ rdb$null_flag = 1
+ ) min_max_not_null,
+ not exists(
+ select true
+ from system.rdb$relation_fields
+ where rdb$schema_name = 'PLG$PROFILER' and
+ rdb$relation_name = 'PLG$PROF_SESSIONS_DATA' and
+ rdb$field_name = 'SAMPLING_INTERVAL'
+ ) sampling_interval_missing,
rdb$get_context('SYSTEM', 'DB_NAME') db_name,
(select rdb$owner_name
from system.rdb$relations
@@ -314,6 +434,8 @@ void ProfilerPlugin::init(ThrowStatusExceptionWrapper* status, IAttachment* atta
FB_MESSAGE(message, ThrowStatusExceptionWrapper,
(FB_BOOLEAN, metadataCreated)
(FB_BOOLEAN, secureMetadataCreated)
+ (FB_BOOLEAN, minMaxNotNull)
+ (FB_BOOLEAN, samplingIntervalMissing)
(FB_INTL_VARCHAR(MAXPATHLEN * 4, CS_METADATA), dbName)
(FB_INTL_VARCHAR(MAX_SQL_IDENTIFIER_LEN, CS_METADATA), ownerName)
(FB_INTL_VARCHAR(MAX_SQL_IDENTIFIER_LEN, CS_METADATA), currentRole)
@@ -346,8 +468,11 @@ void ProfilerPlugin::init(ThrowStatusExceptionWrapper* status, IAttachment* atta
roleInUse = message->roleInUse;
- if (message->metadataCreated && message->secureMetadataCreated)
+ if (message->metadataCreated && message->secureMetadataCreated &&
+ !message->minMaxNotNull && !message->samplingIntervalMissing)
+ {
break;
+ }
auto dispatcher = makeNoIncRef(MasterInterfacePtr()->getDispatcher());
const auto util = MasterInterfacePtr()->getUtilInterface();
@@ -371,6 +496,11 @@ void ProfilerPlugin::init(ThrowStatusExceptionWrapper* status, IAttachment* atta
createInitialMetadata(status, refAttachment, refTransaction);
else if (!message->secureMetadataCreated)
upgradeMetadata(status, refAttachment, refTransaction);
+ else if (message->minMaxNotNull || message->samplingIntervalMissing)
+ {
+ migrateMetadata(status, refAttachment, refTransaction,
+ message->minMaxNotNull, message->samplingIntervalMissing);
+ }
if (!roleInUse)
{
@@ -425,8 +555,8 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
{
static constexpr auto sessionSql = deindentStr(R"""(
update or insert into plg$profiler.plg$prof_sessions
- (profile_id, attachment_id, user_name, description, start_timestamp, finish_timestamp)
- values (?, current_connection, default, ?, ?, ?)
+ (profile_id, attachment_id, user_name, description, start_timestamp, finish_timestamp, sampling_interval)
+ values (?, current_connection, default, ?, ?, ?, ?)
matching (profile_id)
)""");
@@ -435,6 +565,7 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
(FB_INTL_VARCHAR(255 * 4, CS_UTF8), description)
(FB_TIMESTAMP_TZ, startTimestamp)
(FB_TIMESTAMP_TZ, finishTimestamp)
+ (FB_INTEGER, samplingInterval)
) sessionMessage(status, MasterInterfacePtr());
sessionMessage.clear();
@@ -691,6 +822,9 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
if (session->finishTimestamp.has_value())
sessionMessage->finishTimestamp = session->finishTimestamp.value();
+ sessionMessage->samplingIntervalNull = !session->samplingInterval.has_value();
+ sessionMessage->samplingInterval = (ISC_LONG) session->samplingInterval.value_or(0);
+
sessionStmt->execute(status, transaction, sessionMessage.getMetadata(),
sessionMessage.getData(), nullptr, nullptr);
@@ -902,48 +1036,58 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
profileRequest.dirty = false;
}
- for (const auto& [cursorRecSource, stats] : profileRequest.recordSourcesStats)
+ for (unsigned cursorId = 0; cursorId < profileRequest.recordSourcesStats.size(); ++cursorId)
{
- recSrcStatMessage->profileIdNull = FB_FALSE;
- recSrcStatMessage->profileId = session->getId();
+ const auto& cursorStats = profileRequest.recordSourcesStats[cursorId].bySequence;
+
+ for (unsigned recSourceId = 0; recSourceId < cursorStats.size(); ++recSourceId)
+ {
+ const auto& stats = cursorStats[recSourceId];
+
+ if (stats.openStats.isEmpty() && stats.fetchStats.isEmpty())
+ continue;
- recSrcStatMessage->statementIdNull = FB_FALSE;
- recSrcStatMessage->statementId = profileRequest.statementId;
+ recSrcStatMessage->profileIdNull = FB_FALSE;
+ recSrcStatMessage->profileId = session->getId();
- recSrcStatMessage->requestIdNull = FB_FALSE;
- recSrcStatMessage->requestId = profileRequestId;
+ recSrcStatMessage->statementIdNull = FB_FALSE;
+ recSrcStatMessage->statementId = profileRequest.statementId;
- recSrcStatMessage->cursorIdNull = FB_FALSE;
- recSrcStatMessage->cursorId = cursorRecSource.first;
+ recSrcStatMessage->requestIdNull = FB_FALSE;
+ recSrcStatMessage->requestId = profileRequestId;
- recSrcStatMessage->recordSourceIdNull = FB_FALSE;
- recSrcStatMessage->recordSourceId = cursorRecSource.second;
+ recSrcStatMessage->cursorIdNull = FB_FALSE;
+ recSrcStatMessage->cursorId = cursorId;
- recSrcStatMessage->openCounterNull = FB_FALSE;
- recSrcStatMessage->openCounter = stats.openStats.counter;
+ recSrcStatMessage->recordSourceIdNull = FB_FALSE;
+ recSrcStatMessage->recordSourceId = recSourceId;
- recSrcStatMessage->openMinElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->openMinElapsedTime = ticksToNanoseconds(stats.openStats.minElapsedTicks);
+ recSrcStatMessage->openCounterNull = FB_FALSE;
+ recSrcStatMessage->openCounter = stats.openStats.counter;
- recSrcStatMessage->openMaxElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->openMaxElapsedTime = ticksToNanoseconds(stats.openStats.maxElapsedTicks);
+ recSrcStatMessage->openMinElapsedTimeNull = stats.openStats.sampled;
+ recSrcStatMessage->openMinElapsedTime = ticksToNanoseconds(stats.openStats.minElapsedTicks);
- recSrcStatMessage->openTotalElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->openTotalElapsedTime = ticksToNanoseconds(stats.openStats.totalElapsedTicks);
+ recSrcStatMessage->openMaxElapsedTimeNull = stats.openStats.sampled;
+ recSrcStatMessage->openMaxElapsedTime = ticksToNanoseconds(stats.openStats.maxElapsedTicks);
- recSrcStatMessage->fetchCounterNull = FB_FALSE;
- recSrcStatMessage->fetchCounter = stats.fetchStats.counter;
+ recSrcStatMessage->openTotalElapsedTimeNull = FB_FALSE;
+ recSrcStatMessage->openTotalElapsedTime = ticksToNanoseconds(stats.openStats.totalElapsedTicks);
- recSrcStatMessage->fetchMinElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->fetchMinElapsedTime = ticksToNanoseconds(stats.fetchStats.minElapsedTicks);
+ recSrcStatMessage->fetchCounterNull = FB_FALSE;
+ recSrcStatMessage->fetchCounter = stats.fetchStats.counter;
- recSrcStatMessage->fetchMaxElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->fetchMaxElapsedTime = ticksToNanoseconds(stats.fetchStats.maxElapsedTicks);
+ recSrcStatMessage->fetchMinElapsedTimeNull = stats.fetchStats.sampled;
+ recSrcStatMessage->fetchMinElapsedTime = ticksToNanoseconds(stats.fetchStats.minElapsedTicks);
- recSrcStatMessage->fetchTotalElapsedTimeNull = FB_FALSE;
- recSrcStatMessage->fetchTotalElapsedTime = ticksToNanoseconds(stats.fetchStats.totalElapsedTicks);
+ recSrcStatMessage->fetchMaxElapsedTimeNull = stats.fetchStats.sampled;
+ recSrcStatMessage->fetchMaxElapsedTime = ticksToNanoseconds(stats.fetchStats.maxElapsedTicks);
- addBatch(recSrcStatBatch, recSrcStatBatchSize, recSrcStatMessage);
+ recSrcStatMessage->fetchTotalElapsedTimeNull = FB_FALSE;
+ recSrcStatMessage->fetchTotalElapsedTime = ticksToNanoseconds(stats.fetchStats.totalElapsedTicks);
+
+ addBatch(recSrcStatBatch, recSrcStatBatchSize, recSrcStatMessage);
+ }
}
profileRequest.recordSourcesStats.clear();
@@ -970,10 +1114,10 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
psqlStatMessage->counterNull = FB_FALSE;
psqlStatMessage->counter = statsIt.second.counter;
- psqlStatMessage->minElapsedTimeNull = FB_FALSE;
+ psqlStatMessage->minElapsedTimeNull = statsIt.second.sampled;
psqlStatMessage->minElapsedTime = ticksToNanoseconds(statsIt.second.minElapsedTicks);
- psqlStatMessage->maxElapsedTimeNull = FB_FALSE;
+ psqlStatMessage->maxElapsedTimeNull = statsIt.second.sampled;
psqlStatMessage->maxElapsedTime = ticksToNanoseconds(statsIt.second.maxElapsedTicks);
psqlStatMessage->totalElapsedTimeNull = FB_FALSE;
@@ -995,6 +1139,8 @@ void ProfilerPlugin::flush(ThrowStatusExceptionWrapper* status)
for (const auto requestId : finishedRequests)
session->requests.remove(requestId);
+ session->resetRequestCache();
+
++sessionIdx;
}
else
@@ -1038,6 +1184,45 @@ void ProfilerPlugin::createInitialMetadata(ThrowStatusExceptionWrapper* status,
transaction.clear();
}
+// Brings the secure metadata (created by createInitialMetadata or upgradeMetadata of older versions)
+// to the current version. Each step is applied only when the database doesn't have it yet.
+void ProfilerPlugin::migrateMetadata(ThrowStatusExceptionWrapper* status, RefPtr attachment,
+ RefPtr transaction, bool minMaxNotNull, bool samplingIntervalMissing)
+{
+ const auto execute = [&](const char* sql)
+ {
+ attachment->execute(status, transaction, 0, sql, SQL_DIALECT_CURRENT, nullptr, nullptr, nullptr, nullptr);
+ };
+
+ // Min/max times are unknown when timings are sampled, so they are stored as NULL.
+ if (minMaxNotNull)
+ {
+ execute("alter table plg$profiler.plg$prof_psql_stats_data alter column min_elapsed_time drop not null");
+ execute("alter table plg$profiler.plg$prof_psql_stats_data alter column max_elapsed_time drop not null");
+ execute("alter table plg$profiler.plg$prof_record_source_stats_data "
+ "alter column open_min_elapsed_time drop not null");
+ execute("alter table plg$profiler.plg$prof_record_source_stats_data "
+ "alter column open_max_elapsed_time drop not null");
+ execute("alter table plg$profiler.plg$prof_record_source_stats_data "
+ "alter column fetch_min_elapsed_time drop not null");
+ execute("alter table plg$profiler.plg$prof_record_source_stats_data "
+ "alter column fetch_max_elapsed_time drop not null");
+ }
+
+ // Sampling interval of the session, NULL for sessions recorded before this column existed.
+ if (samplingIntervalMissing)
+ {
+ execute("alter table plg$profiler.plg$prof_sessions_data add sampling_interval integer");
+
+ // No other view depends on it, so it can be recreated alone.
+ recreateSnapshotView(status, attachment, transaction,
+ "plg$prof_sessions", SESSIONS_VIEW_COLUMNS, "plg$prof_sessions_data");
+ }
+
+ transaction->commit(status);
+ transaction.clear();
+}
+
void ProfilerPlugin::upgradeMetadata(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction)
{
@@ -1174,6 +1359,7 @@ void ProfilerPlugin::createMetadataTables(ThrowStatusExceptionWrapper* status, R
description varchar(255) character set utf8,
start_timestamp timestamp with time zone not null,
finish_timestamp timestamp with time zone,
+ sampling_interval integer,
constraint plg$prof_sessions_data_profile_user_uk
unique (profile_id, user_name)
using index plg$prof_sessions_data_profile_user
@@ -1322,8 +1508,8 @@ void ProfilerPlugin::createMetadataTables(ThrowStatusExceptionWrapper* status, R
line_num integer not null,
column_num integer not null,
counter bigint not null,
- min_elapsed_time bigint not null,
- max_elapsed_time bigint not null,
+ min_elapsed_time bigint,
+ max_elapsed_time bigint,
total_elapsed_time bigint not null,
constraint plg$prof_psql_stats_data_pk
primary key (profile_id, statement_id, request_id, line_num, column_num)
@@ -1354,12 +1540,12 @@ void ProfilerPlugin::createMetadataTables(ThrowStatusExceptionWrapper* status, R
cursor_id integer not null,
record_source_id integer not null,
open_counter bigint not null,
- open_min_elapsed_time bigint not null,
- open_max_elapsed_time bigint not null,
+ open_min_elapsed_time bigint,
+ open_max_elapsed_time bigint,
open_total_elapsed_time bigint not null,
fetch_counter bigint not null,
- fetch_min_elapsed_time bigint not null,
- fetch_max_elapsed_time bigint not null,
+ fetch_min_elapsed_time bigint,
+ fetch_max_elapsed_time bigint,
fetch_total_elapsed_time bigint not null,
constraint plg$prof_record_source_stats_data_pk
primary key (profile_id, statement_id, request_id, cursor_id, record_source_id)
@@ -1411,31 +1597,12 @@ void ProfilerPlugin::createMetadataTables(ThrowStatusExceptionWrapper* status, R
void ProfilerPlugin::recreateSnapshotViews(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction)
{
- constexpr auto visibilityPredicate =
- "user_name = current_user or rdb$system_privilege(profile_any_attachment)";
-
- string statementsSql;
const auto addView = [&](const char* viewName, const char* selectList, const char* tableName)
{
- statementsSql.printf(
- "recreate view plg$profiler.%s as "
- "select %s from plg$profiler.%s where %s with check option",
- viewName, selectList, tableName, visibilityPredicate);
-
- attachment->execute(status, transaction, 0, statementsSql.c_str(), SQL_DIALECT_CURRENT,
- nullptr, nullptr, nullptr, nullptr);
-
- statementsSql.printf(
- "grant select, update, insert, delete on table plg$profiler.%s to plg$profiler",
- viewName);
-
- attachment->execute(status, transaction, 0, statementsSql.c_str(), SQL_DIALECT_CURRENT,
- nullptr, nullptr, nullptr, nullptr);
+ recreateSnapshotView(status, attachment, transaction, viewName, selectList, tableName);
};
- addView("plg$prof_sessions",
- "profile_id, attachment_id, user_name, description, start_timestamp, finish_timestamp",
- "plg$prof_sessions_data");
+ addView("plg$prof_sessions", SESSIONS_VIEW_COLUMNS, "plg$prof_sessions_data");
addView("plg$prof_statements",
"user_name, profile_id, statement_id, parent_statement_id, statement_type, schema_name, package_name, "
@@ -1467,6 +1634,30 @@ void ProfilerPlugin::recreateSnapshotViews(ThrowStatusExceptionWrapper* status,
"plg$prof_record_source_stats_data");
}
+void ProfilerPlugin::recreateSnapshotView(ThrowStatusExceptionWrapper* status, RefPtr attachment,
+ RefPtr transaction, const char* viewName, const char* selectList, const char* tableName)
+{
+ constexpr auto visibilityPredicate =
+ "user_name = current_user or rdb$system_privilege(profile_any_attachment)";
+
+ string statementsSql;
+
+ statementsSql.printf(
+ "recreate view plg$profiler.%s as "
+ "select %s from plg$profiler.%s where %s with check option",
+ viewName, selectList, tableName, visibilityPredicate);
+
+ attachment->execute(status, transaction, 0, statementsSql.c_str(), SQL_DIALECT_CURRENT,
+ nullptr, nullptr, nullptr, nullptr);
+
+ statementsSql.printf(
+ "grant select, update, insert, delete on table plg$profiler.%s to plg$profiler",
+ viewName);
+
+ attachment->execute(status, transaction, 0, statementsSql.c_str(), SQL_DIALECT_CURRENT,
+ nullptr, nullptr, nullptr, nullptr);
+}
+
void ProfilerPlugin::recreateAggregateViews(ThrowStatusExceptionWrapper* status, RefPtr attachment,
RefPtr transaction)
{
@@ -1768,6 +1959,8 @@ void Session::defineRecordSource(SINT64 statementId, unsigned cursorId, unsigned
void Session::onRequestStart(ThrowStatusExceptionWrapper* status, SINT64 statementId, SINT64 requestId,
SINT64 callerStatementId, SINT64 callerRequestId, ISC_TIMESTAMP_TZ timestamp)
{
+ resetRequestCache();
+
const auto request = requests.put(detailedRequests ? requestId : -statementId);
if (!request)
@@ -1799,7 +1992,7 @@ void Session::afterPsqlLineColumn(SINT64 statementId, SINT64 requestId,
{
if (const auto request = getRequest(statementId, requestId))
{
- const auto profileStats = request->psqlStats.getOrPut({line, column});
+ const auto profileStats = &request->psqlStats[{line, column}];
profileStats->hit(stats->getElapsedTicks());
}
}
@@ -1809,7 +2002,7 @@ void Session::afterRecordSourceOpen(SINT64 statementId, SINT64 requestId, unsign
{
if (const auto request = getRequest(statementId, requestId))
{
- const auto profileStats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
+ const auto profileStats = &request->getRecordSourceStats(cursorId, recSourceId);
profileStats->openStats.hit(stats->getElapsedTicks());
}
}
@@ -1819,11 +2012,32 @@ void Session::afterRecordSourceGetRecord(SINT64 statementId, SINT64 requestId, u
{
if (const auto request = getRequest(statementId, requestId))
{
- const auto profileStats = request->recordSourcesStats.getOrPut({cursorId, recSourceId});
+ const auto profileStats = &request->getRecordSourceStats(cursorId, recSourceId);
profileStats->fetchStats.hit(stats->getElapsedTicks());
}
}
+void Session::addPsqlLineColumnStats(SINT64 statementId, SINT64 requestId, unsigned line, unsigned column,
+ FB_UINT64 counter, FB_UINT64 elapsedTicks)
+{
+ if (const auto request = getRequest(statementId, requestId))
+ request->psqlStats[{line, column}].add(counter, elapsedTicks);
+}
+
+void Session::addRecordSourceOpenStats(SINT64 statementId, SINT64 requestId, unsigned cursorId, unsigned recSourceId,
+ FB_UINT64 counter, FB_UINT64 elapsedTicks)
+{
+ if (const auto request = getRequest(statementId, requestId))
+ request->getRecordSourceStats(cursorId, recSourceId).openStats.add(counter, elapsedTicks);
+}
+
+void Session::addRecordSourceGetRecordStats(SINT64 statementId, SINT64 requestId, unsigned cursorId,
+ unsigned recSourceId, FB_UINT64 counter, FB_UINT64 elapsedTicks)
+{
+ if (const auto request = getRequest(statementId, requestId))
+ request->getRecordSourceStats(cursorId, recSourceId).fetchStats.add(counter, elapsedTicks);
+}
+
//--------------------------------------
SimpleFactory factory;