diff --git a/Makefile b/Makefile index ac1225d..5a3278c 100644 --- a/Makefile +++ b/Makefile @@ -1,7 +1,7 @@ # contrib/pg_stat_monitor/Makefile MODULE_big = pg_stat_monitor -OBJS = hash_query.o guc.o pg_stat_monitor.o $(WIN32RES) +OBJS = hash_query.o guc.o pgsm_errors.o pg_stat_monitor.o $(WIN32RES) EXTENSION = pg_stat_monitor DATA = pg_stat_monitor--1.0.sql diff --git a/hash_query.c b/hash_query.c index 29d0cc8..bf488e6 100644 --- a/hash_query.c +++ b/hash_query.c @@ -17,13 +17,13 @@ #include "postgres.h" #include "nodes/pg_list.h" +#include "pgsm_errors.h" #include "pg_stat_monitor.h" static pgssSharedState *pgss; static HTAB *pgss_hash; -static HTAB* hash_init(const char *hash_name, int key_size, int entry_size, int hash_size); /* * Copy query from src_buffer to dst_buff. * Use query_id and query_pos to fast locate query in source buffer. @@ -66,7 +66,9 @@ pgss_startup(void) if (!found) { /* First time through ... */ - pgss->lock = &(GetNamedLWLockTranche("pg_stat_monitor"))->lock; + LWLockPadded *pgsm_locks = GetNamedLWLockTranche("pg_stat_monitor"); + pgss->lock = &(pgsm_locks[0].lock); + pgss->errors_lock = &(pgsm_locks[1].lock); SpinLockInit(&pgss->mutex); ResetSharedState(pgss); } @@ -86,6 +88,8 @@ pgss_startup(void) pgss_hash = hash_init("pg_stat_monitor: bucket hashtable", sizeof(pgssHashKey), sizeof(pgssEntry), MAX_BUCKET_ENTRIES); + psgm_errors_init(); + LWLockRelease(AddinShmemInitLock); /* @@ -144,10 +148,14 @@ hash_entry_alloc(pgssSharedState *pgss, pgssHashKey *key, int encoding) { pgssEntry *entry = NULL; bool found = false; + long bucket_entries_cnt; - if (hash_get_num_entries(pgss_hash) >= MAX_BUCKET_ENTRIES) + bucket_entries_cnt = hash_get_num_entries(pgss_hash); + + if (bucket_entries_cnt >= MAX_BUCKET_ENTRIES) { - elog(DEBUG1, "%s", "pg_stat_monitor: out of memory"); + pgsm_log_error("hash_entry_alloc: BUCKET OVERFLOW. entries(%d) >= max_entries(%d)", + bucket_entries_cnt, MAX_BUCKET_ENTRIES); return NULL; } /* Find or create an entry with desired hash code */ @@ -165,7 +173,8 @@ hash_entry_alloc(pgssSharedState *pgss, pgssHashKey *key, int encoding) entry->encoding = encoding; } if (entry == NULL) - elog(DEBUG1, "%s", "pg_stat_monitor: out of memory"); + pgsm_log_error("hash_entry_alloc: OUT OF MEMORY"); + return entry; } @@ -230,7 +239,7 @@ hash_entry_dealloc(int new_bucket_id, int old_bucket_id, unsigned char *query_bu if (!bkp_entry) { /* No memory, remove pending query entry from the previous bucket. */ - elog(ERROR, "hash_entry_dealloc: out of memory"); + pgsm_log_error("hash_entry_dealloc: out of memory"); entry = hash_search(pgss_hash, &entry->key, HASH_REMOVE, NULL); continue; } @@ -261,7 +270,7 @@ hash_entry_dealloc(int new_bucket_id, int old_bucket_id, unsigned char *query_bu new_entry = (pgssEntry *) hash_search(pgss_hash, &old_entry->key, HASH_ENTER_NULL, &found); if (new_entry == NULL) - elog(DEBUG1, "%s", "pg_stat_monitor: out of memory"); + pgsm_log_error("hash_entry_dealloc: out of memory"); else if (!found) { /* Restore counters and other data. */ diff --git a/pg_stat_monitor--1.0.sql.in b/pg_stat_monitor--1.0.sql.in index fd2495d..06d0c9a 100644 --- a/pg_stat_monitor--1.0.sql.in +++ b/pg_stat_monitor--1.0.sql.in @@ -244,10 +244,28 @@ $$ language plpgsql; -- ROUND(CAST(total_time / greatest(sum(total_time) OVER(), 0.00000001) * 100 as numeric), 2)::text || '%' as load_comparison -- FROM pg_stat_monitor_hook_stats(); +CREATE FUNCTION pg_stat_monitor_errors( + OUT message text, + OUT msgtime text, + OUT calls int8 +) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_monitor_errors' +LANGUAGE C STRICT VOLATILE PARALLEL SAFE; + +CREATE VIEW pg_stat_monitor_errors AS SELECT + message, msgtime, calls +FROM pg_stat_monitor_errors(); + +CREATE FUNCTION pg_stat_monitor_reset_errors() +RETURNS void +AS 'MODULE_PATHNAME' +LANGUAGE C PARALLEL SAFE; + GRANT SELECT ON pg_stat_monitor TO PUBLIC; GRANT SELECT ON pg_stat_monitor_settings TO PUBLIC; +GRANT SELECT ON pg_stat_monitor_errors TO PUBLIC; -- Don't want this to be available to non-superusers. REVOKE ALL ON FUNCTION pg_stat_monitor_reset() FROM PUBLIC; - - +REVOKE ALL ON FUNCTION pg_stat_monitor_reset_errors() FROM PUBLIC; diff --git a/pg_stat_monitor.c b/pg_stat_monitor.c index ec43578..1584117 100644 --- a/pg_stat_monitor.c +++ b/pg_stat_monitor.c @@ -22,6 +22,7 @@ #include /* clock() */ #endif #include "commands/explain.h" +#include "pgsm_errors.h" #include "pg_stat_monitor.h" PG_MODULE_MAGIC; @@ -75,7 +76,6 @@ static struct pg_hook_stats_t *pg_hook_stats; static void extract_query_comments(const char *query, char *comments, size_t max_len); static int get_histogram_bucket(double q_time); -static bool IsSystemInitialized(void); static bool dump_queries_buffer(int bucket_id, unsigned char *buf, int buf_len); static double time_diff(struct timeval end, struct timeval start); @@ -262,8 +262,8 @@ _PG_init(void) * the postmaster process.) We'll allocate or attach to the shared * resources in pgss_shmem_startup(). */ - RequestAddinShmemSpace(hash_memsize() + HOOK_STATS_SIZE); - RequestNamedLWLockTranche("pg_stat_monitor", 1); + RequestAddinShmemSpace(hash_memsize() + pgsm_errors_size() + HOOK_STATS_SIZE); + RequestNamedLWLockTranche("pg_stat_monitor", 2); /* * Install hooks. @@ -486,7 +486,7 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) uint64 queryId = queryDesc->plannedstmt->queryId; if(getrusage(RUSAGE_SELF, &rusage_start) != 0) - elog(DEBUG1, "pg_stat_monitor: failed to execute getrusage"); + pgsm_log_error("pgss_ExecutorStart: failed to execute getrusage"); if (prev_ExecutorStart) prev_ExecutorStart(queryDesc, eflags); @@ -674,7 +674,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) */ InstrEndLoop(queryDesc->totaltime); if(getrusage(RUSAGE_SELF, &rusage_end) != 0) - elog(DEBUG1, "pg_stat_monitor: failed to execute getrusage"); + pgsm_log_error("pgss_ExecutorEnd: failed to execute getrusage"); sys_info.utime = time_diff(rusage_end.ru_utime, rusage_start.ru_utime); sys_info.stime = time_diff(rusage_end.ru_stime, rusage_start.ru_stime); @@ -1549,7 +1549,7 @@ pgss_store(uint64 queryid, if (!SaveQueryText(bucketid, queryid, pgss_qbuf[bucketid], query, query_len, &qpos)) { LWLockRelease(pgss->lock); - elog(DEBUG1, "pg_stat_monitor: insufficient shared space for query."); + pgsm_log_error("pgss_store: insufficient shared space for query."); return; } @@ -1560,7 +1560,6 @@ pgss_store(uint64 queryid, /* Restore previous query buffer length. */ memcpy(pgss_qbuf[bucketid], &prev_qbuf_len, sizeof(prev_qbuf_len)); LWLockRelease(pgss->lock); - elog(DEBUG1, "pg_stat_monitor: out of memory"); return; } entry->query_pos = qpos; @@ -1683,7 +1682,10 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, /* Build a tuple descriptor for our result type */ if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) - elog(ERROR, "pg_stat_monitor: return type must be a row type"); + { + pgsm_log_error("pg_stat_monitor_internal: call_result_type must return a row type"); + return; + } if (tupdesc->natts != 51) elog(ERROR, "pg_stat_monitor: incorrect number of output arguments, required %d", tupdesc->natts); @@ -1724,10 +1726,24 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, if (read_query(buf, queryid, query_txt, entry->query_pos) == 0) { - int rc; - rc = read_query_buffer(bucketid, queryid, query_txt, entry->query_pos); - if (rc != 1) - snprintf(query_txt, 32, "%s", ""); + /* + * Failed to locate the query in memory, + * If overflow is enabled we try to find the query in a dump file in disk. + */ + if (PGSM_OVERFLOW_TARGET == OVERFLOW_TARGET_DISK) + { + int rc; + rc = read_query_buffer(bucketid, queryid, query_txt, entry->query_pos); + if (rc != 1) + { + pgsm_log_error("pg_stat_monitor_internal: can't find query in dump file."); + continue; + } + } else + { + pgsm_log_error("pg_stat_monitor_internal: insufficient shared space."); + continue; + } } /* copy counters to a local variable to keep locking time short */ @@ -1749,12 +1765,20 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, if (tmp.info.parentid != UINT64CONST(0)) { - int rc = 0; if (read_query(buf, tmp.info.parentid, parent_query_txt, 0) == 0) { - rc = read_query_buffer(bucketid, tmp.info.parentid, parent_query_txt, 0); - if (rc != 1) - snprintf(parent_query_txt, 32, "%s", ""); + if (PGSM_OVERFLOW_TARGET == OVERFLOW_TARGET_DISK) + { + int rc; + rc = read_query_buffer(bucketid, tmp.info.parentid, parent_query_txt, 0); + if (rc != 1) + { + pgsm_log_error("pg_stat_monitor_internal: can't find parent query in dump file."); + } + } else + { + pgsm_log_error("pg_stat_monitor_internal: insufficient shared space for parent query."); + } } } /* bucketid at column number 0 */ @@ -2216,7 +2240,7 @@ JumbleRangeTable(JumbleState *jstate, List *rtable) APP_JUMB_STRING(rte->enrname); break; default: - elog(ERROR, "unrecognized RTE kind: %d", (int) rte->rtekind); + pgsm_log_error("JumbleRangeTable: unrecognized RTE kind: %d", (int) rte->rtekind); break; } } @@ -2717,7 +2741,7 @@ JumbleExpr(JumbleState *jstate, Node *node) break; default: /* Only a warning, since we can stumble along anyway */ - elog(INFO, "unrecognized node type: %d", + pgsm_log_error("JumbleExpr: unrecognized node type: %d", (int) nodeTag(node)); break; } @@ -3086,11 +3110,6 @@ read_query(unsigned char *buf, uint64 queryid, char * query, size_t pos) rlen += query_len; } exit: - if (PGSM_OVERFLOW_TARGET == OVERFLOW_TARGET_NONE) - { - sprintf(query, "%s", ""); - return -1; - } return 0; } @@ -3196,10 +3215,16 @@ pg_stat_monitor_settings(PG_FUNCTION_ARGS) /* Build a tuple descriptor for our result type */ if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) - elog(ERROR, "pg_stat_monitor: return type must be a row type"); + { + pgsm_log_error("pg_stat_monitor_settings: return type must be a row type"); + return (Datum) 0; + } if (tupdesc->natts != 7) - elog(ERROR, "pg_stat_monitor: incorrect number of output arguments, required %d", tupdesc->natts); + { + pgsm_log_error("pg_stat_monitor_settings: incorrect number of output arguments, required: 7, found %d", tupdesc->natts); + return (Datum) 0; + } tupstore = tuplestore_begin_heap(true, false, work_mem); rsinfo->returnMode = SFRM_Materialize; @@ -3259,10 +3284,16 @@ pg_stat_monitor_hook_stats(PG_FUNCTION_ARGS) /* Build a tuple descriptor for our result type */ if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) - elog(ERROR, "pg_stat_monitor: return type must be a row type"); + { + pgsm_log_error("pg_stat_monitor_hook_stats: return type must be a row type"); + return (Datum) 0; + } if (tupdesc->natts != 5) - elog(ERROR, "pg_stat_monitor: incorrect number of output arguments, required %d", tupdesc->natts); + { + pgsm_log_error("pg_stat_monitor_hook_stats: incorrect number of output arguments, required: 5, found %d", tupdesc->natts); + return (Datum) 0; + } tupstore = tuplestore_begin_heap(true, false, work_mem); rsinfo->returnMode = SFRM_Materialize; diff --git a/pg_stat_monitor.h b/pg_stat_monitor.h index 84ed936..508ed43 100644 --- a/pg_stat_monitor.h +++ b/pg_stat_monitor.h @@ -313,6 +313,7 @@ typedef struct pgssSharedState uint64 bucket_entry[MAX_BUCKETS]; int64 query_buf_size_bucket; char bucket_start_time[MAX_BUCKETS][60]; /* start time of the bucket */ + LWLock *errors_lock; /* protects errors hashtable search/modification */ } pgssSharedState; #define ResetSharedState(x) \ @@ -374,6 +375,7 @@ bool SaveQueryText(uint64 bucketid, void init_guc(void); GucVariable *get_conf(int i); +bool IsSystemInitialized(void); /* hash_create.c */ bool IsHashInitialize(void); void pgss_shmem_startup(void); diff --git a/pgsm_errors.c b/pgsm_errors.c new file mode 100644 index 0000000..5706748 --- /dev/null +++ b/pgsm_errors.c @@ -0,0 +1,215 @@ +/*------------------------------------------------------------------------- + * + * pgsm_errors.c + * Track pg_stat_monitor internal error messages. + * + * Copyright © 2021, Percona LLC and/or its affiliates + * + * Portions Copyright (c) 1996-2020, PostgreSQL Global Development Group + * + * Portions Copyright (c) 1994, The Regents of the University of California + * + * IDENTIFICATION + * contrib/pg_stat_monitor/pgsm_errors.c + * + *------------------------------------------------------------------------- + */ + +#include +#include +#include +#include +#include + +#include +#include +#include +#include + +#include "pg_stat_monitor.h" +#include "pgsm_errors.h" + + +PG_FUNCTION_INFO_V1(pg_stat_monitor_errors); +PG_FUNCTION_INFO_V1(pg_stat_monitor_reset_errors); + + +/* + * Maximum number of error messages tracked. + * This should be set to a sensible value in order to track + * the different type of errors that pg_stat_monitor may + * report, e.g. out of memory. + */ +#define PSGM_ERRORS_MAX 128 + +static HTAB *pgsm_errors_ht = NULL; + +void psgm_errors_init(void) +{ + HASHCTL info; + + memset(&info, 0, sizeof(info)); + info.keysize = ERROR_MSG_MAX_LEN; + info.entrysize = sizeof(ErrorEntry); + pgsm_errors_ht = ShmemInitHash("pg_stat_monitor: errors hashtable", + PSGM_ERRORS_MAX, /* initial size */ + PSGM_ERRORS_MAX, /* maximum size */ + &info, + HASH_ELEM | HASH_STRINGS); +} + +size_t pgsm_errors_size(void) +{ + return hash_estimate_size(PSGM_ERRORS_MAX, sizeof(ErrorEntry)); +} + +void pgsm_log_error(const char *format, ...) +{ + char key[ERROR_MSG_MAX_LEN]; + ErrorEntry *entry; + bool found = false; + va_list ap; + int n; + struct timeval tv; + struct tm *lt; + pgssSharedState *pgss; + + va_start(ap, format); + n = vsnprintf(key, ERROR_MSG_MAX_LEN, format, ap); + va_end(ap); + + if (n < 0) + return; + + pgss = pgsm_get_ss(); + LWLockAcquire(pgss->errors_lock, LW_EXCLUSIVE); + + entry = (ErrorEntry *) hash_search(pgsm_errors_ht, key, HASH_ENTER_NULL, &found); + if (!entry) + { + LWLockRelease(pgss->errors_lock); + /* + * We're out of memory, can't track this error message. + * In this case we must fallback to PostgreSQL log facility. + */ + elog(WARNING, "pgsm_log_error: "); + return; + } + + if (!found) + entry->calls = 0; + + /* Update message timestamp. */ + gettimeofday(&tv, NULL); + lt = localtime(&tv.tv_sec); + snprintf(entry->time, sizeof(entry->time), + "%04d-%02d-%02d %02d:%02d:%02d", + lt->tm_year + 1900, + lt->tm_mon + 1, + lt->tm_mday, + lt->tm_hour, + lt->tm_min, + lt->tm_sec); + + entry->calls++; + + LWLockRelease(pgss->errors_lock); +} + +/* + * Clear all entries from the hash table. + */ +Datum +pg_stat_monitor_reset_errors(PG_FUNCTION_ARGS) +{ + HASH_SEQ_STATUS hash_seq; + ErrorEntry *entry; + pgssSharedState *pgss = pgsm_get_ss(); + + /* Safety check... */ + if (!IsSystemInitialized()) + ereport(ERROR, + (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE), + errmsg("pg_stat_monitor: must be loaded via shared_preload_libraries"))); + + LWLockAcquire(pgss->errors_lock, LW_EXCLUSIVE); + + hash_seq_init(&hash_seq, pgsm_errors_ht); + while ((entry = hash_seq_search(&hash_seq)) != NULL) + entry = hash_search(pgsm_errors_ht, &entry->message, HASH_REMOVE, NULL); + + LWLockRelease(pgss->errors_lock); + PG_RETURN_VOID(); +} + +/* + * Invoked when users query the view pg_stat_monitor_errors. + * This function creates tuples with error messages from data present in + * the hash table, then return the dataset to the caller. + */ +Datum +pg_stat_monitor_errors(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + TupleDesc tupdesc; + Tuplestorestate *tupstore; + MemoryContext per_query_ctx; + MemoryContext oldcontext; + HASH_SEQ_STATUS hash_seq; + ErrorEntry *error_entry; + pgssSharedState *pgss = pgsm_get_ss(); + + /* Safety check... */ + if (!IsSystemInitialized()) + ereport(ERROR, + (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE), + errmsg("pg_stat_monitor: must be loaded via shared_preload_libraries"))); + + /* check to see if caller supports us returning a tuplestore */ + if (rsinfo == NULL || !IsA(rsinfo, ReturnSetInfo)) + ereport(ERROR, + (errcode(ERRCODE_FEATURE_NOT_SUPPORTED), + errmsg("pg_stat_monitor: set-valued function called in context that cannot accept a set"))); + + /* Switch into long-lived context to construct returned data structures */ + per_query_ctx = rsinfo->econtext->ecxt_per_query_memory; + oldcontext = MemoryContextSwitchTo(per_query_ctx); + + /* Build a tuple descriptor for our result type */ + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) + elog(ERROR, "pg_stat_monitor: return type must be a row type"); + + if (tupdesc->natts != 3) + elog(ERROR, "pg_stat_monitor: incorrect number of output arguments, required 3, found %d", tupdesc->natts); + + tupstore = tuplestore_begin_heap(true, false, work_mem); + rsinfo->returnMode = SFRM_Materialize; + rsinfo->setResult = tupstore; + rsinfo->setDesc = tupdesc; + + MemoryContextSwitchTo(oldcontext); + + LWLockAcquire(pgss->errors_lock, LW_SHARED); + + hash_seq_init(&hash_seq, pgsm_errors_ht); + while ((error_entry = hash_seq_search(&hash_seq)) != NULL) + { + Datum values[3]; + bool nulls[3]; + int i = 0; + memset(values, 0, sizeof(values)); + memset(nulls, 0, sizeof(nulls)); + + values[i++] = CStringGetTextDatum(error_entry->message); + values[i++] = CStringGetTextDatum(error_entry->time); + values[i++] = Int64GetDatumFast(error_entry->calls); + + tuplestore_putvalues(tupstore, tupdesc, values, nulls); + } + + LWLockRelease(pgss->errors_lock); + /* clean up and return the tuplestore */ + tuplestore_donestoring(tupstore); + + return (Datum)0; +} \ No newline at end of file diff --git a/pgsm_errors.h b/pgsm_errors.h new file mode 100644 index 0000000..9956fdf --- /dev/null +++ b/pgsm_errors.h @@ -0,0 +1,53 @@ +/*------------------------------------------------------------------------- + * + * pgsm_errors.h + * Track pg_stat_monitor internal error messages. + * + * Copyright © 2021, Percona LLC and/or its affiliates + * + * Portions Copyright (c) 1996-2020, PostgreSQL Global Development Group + * + * Portions Copyright (c) 1994, The Regents of the University of California + * + * IDENTIFICATION + * contrib/pg_stat_monitor/pgsm_errors.h + * + *------------------------------------------------------------------------- + */ + +#ifndef PGSM_ERRORS_H +#define PGSM_ERRORS_H + +#include + +#include + + +/* Maximum allowed error message length. */ +#define ERROR_MSG_MAX_LEN 128 + +typedef struct { + char message[ERROR_MSG_MAX_LEN]; /* message is also the hash key (MUST BE FIRST). */ + char time[60]; /* last timestamp in which this error was reported. */ + int64 calls; /* how many times this error was reported. */ +} ErrorEntry; + +/* + * Must be called during module startup, creates the hash table + * used to store pg_stat_monitor error messages. + */ +void psgm_errors_init(void); + +/* + * Returns an estimate of the hash table size. + * Used to reserve space on Postmaster's shared memory. + */ +size_t pgsm_errors_size(void); + +/* + * Add an error message to the hash table. + * Increment no. of calls if message already exists. + */ +void pgsm_log_error(const char *format, ...); + +#endif /* PGSM_ERRORS_H */ \ No newline at end of file