Don't display queries in PARSE or PLAN state, to keep it consistent
with previous behavior, this avoids showing intermediate scripts like
part of a procedure, such as:
$1
$1 := $3
Whenever a new query is added to a query buffer, record the position
in which the query was inserted, we can then use this information to
locate the query in a faster way later on when required.
This allowed to simplify the logic in hash_entry_dealloc(), after
creating the list of pending queries, as the list is scanned we can copy
the query from the previous query buffer to the new one by using the
query position (query_pos), this avoids scanning the whole query buffer
when looking up for the queryid.
Also, when moving a query to a new buffer (copy_query), we update
the query_pos for the hash table entry, so it points to the right place
in the new query buffer.
read_query() function was updated to allow query position to be passed
as argument, if pos != 0 use it to locate the query directly, otherwise
fallback to the previous mode of scanning the whole buffer.
SaveQueryText() was updated to pass a reference to the query position as
argument, this value is updated after the function finishes with the
position that the query was stored into the buffer.
There was no necessity for using a separate hash table to keep track
of queries as all the necessary information is already available in
the pgss_hash table.
The code that moves pending queries' text in hash_query_entry_dealloc
was merged into hash_entry_dealloc.
Couple functions were not necessary anymore, thus were removed:
- hash_create_query_entry
- pgss_store_query_info
- pgss_get_entry (this logic was added directly into pgss_store).
We simplified the logic in pgss_store, it basically works as follows:
1. Create a key (bucketid, queryid, etc...) for the query event.
2. Lookup the key in pgss_hash, if no entry exists for the key, create a
new one, save the query text into the current query buffer.
3. If jstate == NULL, then update stats counters for the entry.
There were many variables being initialized in pgss_store() before
checking if the module was actually active, this would waste cpu
processor if the module is disabled.
To fix that, declare variables and initialize them only after check
that pg_stat_monitor is active.
Added code to move all pending queries text from an expired bucket's query
buffer to the next, active query buffer.
The previous implementation was not very efficient, it worked like this,
as soon as a query is processed and a bucket expires:
1. Allocate memory to save the contents of the next query buffer.
2. Clear the next query buffer.
3. Iterate over pgss_query_hash, then, for each entry:
- If the entry's bucket id is equal to the next bucket then:
-- If the query for this entry has finished or ended in error, then
remove it from the hash table.
-- Else, if the query is not yet finished, copy the query from the
backup query buffer to the new query buffer.
Now, this copy was really expensive, because it was implemented
using read_query() / SaveQueryText(), and read_query() scans the
whole query buffer looking for some query ID, since we do this
extra lookup loop for each pending query we end up with a O(n^2)
algorithm.
4. Release the backup query buffer.
Since now we always move pending queries from an expired bucket to the
next one, there is no need to scan the next query buffer for pending
queries (the pending queries are always in the current bucket, and when
it expires we move them to the next one).
Taking that into consideration, the new implementation works as follows,
whenever a bucket expires:
1. Clear the next query buffer (all entries).
2. Define an array to store pending query ids from the expired bucket,
we use this array later on in the algorithm.
3. Iterate over pgss_query_hash, then, for each entry:
- If the entry's bucket id is equal to the next bucket then:
-- If the query for this entry has finished or ended in error, then
remove it from the hash table. This is equal to the previous
implementation.
- Else, if the entry's bucket id is equal to the just expired bucket
id (old bucket id) and the query state is pending (not yet finished),
then add this query ID to the array of pending query IDs.
Note: We define the array to hold up to 128 pending entries, if there
are more entries than this we try to allocate memory in the heap to
store them, then, if the allocation fails we manually copy every
pending query past the 128th to the next query buffer, using the
previous algorithm (read_query() / SaveQueryText), this should be a
very rare situation.
4. Finally, if there are pending queries, copy them from the previous
query buffer to the next one using copy_queries.
Now, copy_queries() is better than looping through each query entry and
calling read_query() / SaveQueryText() to copy each of them to the new
buffer, as explained, read_query() scans the whole query buffer for
every call.
copy_queries(), instead, scans the query buffer only once, and for every
element it checks if the current query id is in the list of queries to
be copied, this is an array of uint64 that is small enough to fit in L1
cache.
Another important fix in this commit is the addition of the line 1548 in
pg_stat_monitor.c / pgss_store():
query_entry->state = kind;
Before the addition of this line, all entries in the pgss_query_hash
hash table were not having their status updated when the query entered
execution / finished or ended in error, effectively leaving all entries
as pending, thus whenever a bucket expired all entries were being copied
from the expired bucket to the next one.
The if condition bellow in geta_next_wbucket() was subject to a race
condition:
if ((current_usec - pgss->prev_bucket_usec) > (PGSM_BUCKET_TIME * 1000 *
1000))
Two or more threads/processes could easily evaluate this condition to
true, thus executing more than once the block that would calculate a
new bucket id, clear/move old entries in the pgss_query_hash and
pgss_hash hash tables.
To avoid this problem, we define prev_bucket_usec and current_wbucket
variables as atomic and execute a loop to check if another thread has
updated prev_bucket_usec before the current one.
A problem during bucket management was allowing some queries to be
duplicated, old entries would sit around without having their statistics
updated.
The problem would arise during the following chain of events:
1. A query goes through pgss_post_parse_analyze, in this stage (PGSS_PARSE)
we only save the query into the query buffer and create an entry in the
query hash table.
2. The query then goes through pgss_ExecutorStart (PGSS_EXEC), in this stage
we create an entry for query statistic counters with default values,
all time stats equal zero, etc.
3. The query then goes through pgss_ExecutorEnd (PGSS_FINISH), in this stage
we update the query statistis, no. calls, total time taken, min_time, etc.
The problem is that between steps 2 and 3, the current bucket ID timer may
have been expired.
For example, during steps 1 and 2 the query may have been stored in
bucket ID 1, but when the query is finished (pgss_ExecutorEnd) the
current bucket ID may have been updated to 2.
This is leaving an entry for the query in bucket ID 1 with state ACTIVE,
with time statistics not updated yet.
This is also creating an entry for the query in the bucket ID 2, with all
statistics (time and others) being updated for this entry.
To solve this problem, during transition to a new bucket id, we scan all
pending queries in the previous bucket id and move them to the new
bucket id.
This way finished queries will always be associated with the bucket id
that was active at the time they've finished.
The deadlock scenario is describe below:
1. pgss_store is called, it acquires the lock pgss->lock.
2. An error ocurr, mostly out of memory when accessing internal hash
tables used to store internal data, on functions
pgss_store_query_info and pgss_get_entry.
3. Call elog() to report out of memory error.
4. Our pgsm_emit_log_hook is called, it calls pgss_store_error, which in
turn calls pgss_store.
5. Try to acquire already acquired lock pgss->lock, deadlock happens.
To fix the problem, there are two modifications worth mentioning done by
this commit:
1. We are now passing HASH_ENTER_NULL flag to hash_search, instead of
HASH_ENTER, as read in postgresql sources, this prevents this
function from reporting error when out of memory, but instead it will
only return NULL if we pass HASH_ENTER_NULL, so we can handle the
error ourselves.
2. In pgss_store, if an error happens after the pgss->lock is acquired,
we only set a flag, then, after releasing the lock, we check if the
flag is set and report the error accordingly.
There were two objects leaking memory in this function, the comments
variable of type char * allocated using palloc0, and the regular
expression object preg.
If the regcomp function failed, the function was returning without
releasing the comments variable allocated previously.
If the regexec function failed, the function was returning without
releasing the preg object and the comments variable.
This commit does two changes, first it turns the comments in
extract_query_comments an argument to the function, in pgss_store we
declare the comments variable in the stack, so it will clean up after
itself.
The second change was to move the regular expression object to global
scope, this way we compile the object only once, during module
initialization.
With these two changes we fix the memory leak and avoid
allocating/releasing memory for every call to this function.
We redefine macro _snprintf to use memcpy, which performs better, we
also update call sites using this macro to add the null terminator
'\0' to the source string length, this way memcpy also correctly
copies the null terminator to the destination string.
We update _snprintf2 macro to use strlcpy, the reason we don't use
memcpy here is because in the place where this macro is called,
pgss_update_entry, only the maximum string length of REL_LEN=1000 is
specified as an upper bound to copy the relations string vector to the
destination counters, but since this data is string, we don't need to
copy 1k bytes for every entry, by using strlcpy the copy ends as soon as
the null terminator '\0' is found in the source string.
These variables can't be in shared state, as the following problem was
taking place:
1. Process1 call pgss_ExecutorCheckPerms(), acquire lock, update
relations and num_relations, release lock.
2. Process 2 call pgss_ExecutorCheckPerms(), acquire lock, update
num_relations = 0;
3. Process 1 read num_relations = 0 in pgss_update_entry, this value is
wrong as it was updated by Process 2.
Even if we acquire the lock in pgss_update_entry to read num_relations
and relations variable, Process 1 may end up acquiring the lock after
Process 2 has ovewritten the variable values, leading to Process 1
reading of wrong data.
By defining relations and num_relations to be static and global in
pg_stat_monitor.c we take advantage that each individual PostgreSQL
backend will have its own copy of this data, which allows us to remove
the locking in pgss_ExecutorCheckPerms to update these variables,
improving pg_stat_monitor overall performance.
Added a new view 'pg_stat_monitor_hook_stats' that provide execution
time statistics for all hooks installed by the module, following is a
description of the fields:
- hook: The hook function name.
- min_time: The fastest execution time recorded for the given hook.
- max_time: The slowest execution time recorded for the given hook.
- total_time: Total execution time taken by all calls to the hook.
- avg_time: Average execution time of a call to the hook.
- ncalls: Total number of calls to the hook.
- load_comparison: A percentual of time taken by an individual hook
compared to every other hook.
To enable benchmark, code must be compiled with -DBENCHMARK flag, this
will make the hook functions to be replaced by a function with the same
name plus a '_benchmark' suffix, e.g. hook_function_benchmark.
The hook_function_benchmark will call the original function and
calculate the amount of time it took to execute, than it will update
statistics for that hook.
The query_txt variable is allocated at the beginning of the
pg_stat_monitor_internal() function and released at the end, but an
extra malloc call to allocate it was added within an internal loop in
the funcion, thus allocating memory for every loop iteration, without
releasing the memory in the loop.
The query_txt variable can be reused inside the loop body, so this
commit removes the redundant declaration of query_txt from inside the
loop, which also fixes the leak.
Add application name to the key used to identify queries in the hash
table, this allows different applications to have separate entries in
pg_stat_monitor view if they issued the same query.
If pg_stat_monitor is loaded after pg_stat_statement, then it will end
up calling standard_planner function twice in the pgss_planner_hook()
function, this will trigger an assertion failure from PostgreSQL as this
function expects an untouched Query* object, and the first call to
standard_planner() done by pg_stat_statements modifies the object.
To address the problem, we avoid calling standard_planner function twice
in pg_stat_monitor, if a previous handler is installed for the hook
planner_hook, then we assume that this previous hook has already called
standard_planner function and don't do it again.
Jira: PG-141
There is lock conflict, so used LW_EXCLUSIVE instead of LW_SHARED. This
need to be investigated again and check the possibility to use a shared lock.
Issue - (#16): PG-112: Change the column name "ip" to "client_ip" for readability purpose.
Issue - (#17): PG-111: Show all the queries from complete and incomplete buckets.
Issue - (#18): PG-108: Log the bucket start time.
Issue - (#19): PG-99: Response time histogram.
Issue - (#20): PG-97: Log CPU time for a query.
Issue - (#21): PG-96: Show objects(tables) involved in the query.
Issue - (#22): PG-93: Retain the bucket, and don't delete the bucket automatically.
Issue - (#23): PG-91: Log queries of all the databases.
Issue - (#24): PG-116: Restrict the query size.
Issue - (#3) : README file update.
Support for database/user/client based aggregates added to access
these statistics with three new views added. Some new counters added
including min/max/mean's time histograms. We are saving the parameters
of the slow queries, which can be tested later. Did some refactoring
of the code, by renaming the whole extension from pg_stat_statement to
pg_stat_monitor.
Diego Fronza
Ibrar Ahmed
Andrew Pogrebnoy
Hamid Akhtar
Martin Sun