Awesome
slonik-interceptor-query-logging
Logs Slonik queries.
[!WARNING] Deprecated in favor of https://github.com/gajus/slonik monorepo.
API
import {
createQueryLoggingInterceptor
} from 'slonik-interceptor-query-logging';
/**
* @property logValues Dictates whether to include parameter values used to execute the query. (default: true)
*/
type UserConfigurationType = {|
+logValues: boolean
|};
(userConfiguration: UserConfigurationType) => InterceptorType;
Example usage
Note: You must export ROARR_LOG=true
environment variable for logs to be printed. Refer to Roarr documentation for more information.
import {
createPool
} from 'slonik';
import {
createQueryLoggingInterceptor
} from 'slonik-interceptor-query-logging';
const interceptors = [
createQueryLoggingInterceptor()
];
const pool = createPool('postgres://', {
interceptors
});
await connection.any(sql`
SELECT
id,
code_alpha_2
FROM country
`);
Produces log:
{"context":{"package":"slonik","poolId":"01D4G1EHYPYX1DZ073G08QEPED","logLevel":30,"processId":769420982,"stats":{"idleConnectionCount":0,"totalConnectionCount":1,"waitingRequestCount":0}},"message":"created a new client connection","sequence":0,"time":1551021590799,"version":"1.0.0"}
{"context":{"package":"slonik","poolId":"01D4G1EHYPYX1DZ073G08QEPED","logLevel":30,"processId":769420982,"stats":{"idleConnectionCount":0,"totalConnectionCount":1,"waitingRequestCount":0}},"message":"client is checked out from the pool","sequence":1,"time":1551021590801,"version":"1.0.0"}
{"context":{"package":"slonik","poolId":"01D4G1EHYPYX1DZ073G08QEPED","connectionId":"01D4G1EJ8DZFX79EN8CRE5Z7VS","queryId":"01D4G1EJB9P3SJ3V0SSVRTZ800","logLevel":20,"sql":"SELECT id, code_alpha_2 FROM country","stackTrace":[],"values":[]},"message":"executing query","sequence":2,"time":1551021590890,"version":"1.0.0"}
{"context":{"package":"slonik","poolId":"01D4G1EHYPYX1DZ073G08QEPED","connectionId":"01D4G1EJ8DZFX79EN8CRE5Z7VS","queryId":"01D4G1EJB9P3SJ3V0SSVRTZ800","logLevel":20,"executionTime":"65ms","rowCount":250},"message":"query execution result","sequence":3,"time":1551021590918,"version":"1.0.0"}
{"context":{"package":"slonik","poolId":"01D4G1EHYPYX1DZ073G08QEPED","logLevel":30,"processId":769420982,"stats":{"idleConnectionCount":0,"totalConnectionCount":0,"waitingRequestCount":0}},"message":"client connection is closed and removed from the client pool","sequence":4,"time":1551021600922,"version":"1.0.0"}
Use roarr-cli
to pretty print the logs.
Using roarr pretty-print
will produce logs in the following format:
[2019-02-24T15:19:50.799Z] INFO (30) (@slonik): created a new client connection
poolId: 01D4G1EHYPYX1DZ073G08QEPED
processId: 769420982
stats:
idleConnectionCount: 0
totalConnectionCount: 1
waitingRequestCount: 0
[2019-02-24T15:19:50.801Z] INFO (30) (@slonik): client is checked out from the pool
poolId: 01D4G1EHYPYX1DZ073G08QEPED
processId: 769420982
stats:
idleConnectionCount: 0
totalConnectionCount: 1
waitingRequestCount: 0
[2019-02-24T15:19:50.890Z] DEBUG (20) (@slonik): executing query
poolId: 01D4G1EHYPYX1DZ073G08QEPED
connectionId: 01D4G1EJ8DZFX79EN8CRE5Z7VS
queryId: 01D4G1EJB9P3SJ3V0SSVRTZ800
sql: SELECT id, code_alpha_2 FROM country
stackTrace:
(empty array)
values:
(empty array)
[2019-02-24T15:19:50.918Z] DEBUG (20) (@slonik): query execution result
poolId: 01D4G1EHYPYX1DZ073G08QEPED
connectionId: 01D4G1EJ8DZFX79EN8CRE5Z7VS
queryId: 01D4G1EJB9P3SJ3V0SSVRTZ800
executionTime: 65ms
rowCount: 250
[2019-02-24T15:20:00.922Z] INFO (30) (@slonik): client connection is closed and removed from the client pool
poolId: 01D4G1EHYPYX1DZ073G08QEPED
processId: 769420982
stats:
idleConnectionCount: 0
totalConnectionCount: 0
waitingRequestCount: 0
Logging auto_explain
executionTime
log property describes how long it took for the client to execute the query, i.e. it includes the overhead of waiting for a connection and the network latency, among other things. However, it is possible to get the real query execution time by using auto_explain
module.
There are several pre-requisites:
-- Load the extension.
LOAD 'auto_explain';
-- or (if you are using AWS RDS):
LOAD '$libdir/plugins/auto_explain';
-- Enable logging of all queries.
SET auto_explain.log_analyze=true;
SET auto_explain.log_format=json;
SET auto_explain.log_min_duration=0;
SET auto_explain.log_timing=true;
-- Enables Slonik to capture auto_explain logs.
SET client_min_messages=log;
This can be configured using afterPoolConnection
interceptor, e.g.
const pool = createPool('postgres://localhost', {
interceptors: [
{
afterPoolConnection: async (connection) => {
await connection.query(sql`LOAD 'auto_explain'`);
await connection.query(sql`SET auto_explain.log_analyze=true`);
await connection.query(sql`SET auto_explain.log_format=json`);
await connection.query(sql`SET auto_explain.log_min_duration=0`);
await connection.query(sql`SET auto_explain.log_timing=true`);
await connection.query(sql`SET client_min_messages=log`);
}
}
]
});
Slonik logging interceptor recognises and parses the auto_explain
JSON message e.g.
[2018-12-31T21:15:21.010Z] INFO (30) (@slonik): notice message
notice:
level: notice
message:
Query Text: SELECT count(*) FROM actor
Plan:
Node Type: Aggregate
Strategy: Plain
Partial Mode: Simple
Parallel Aware: false
Startup Cost: 4051.33
Total Cost: 4051.34
Plan Rows: 1
Plan Width: 8
Actual Startup Time: 26.791
Actual Total Time: 26.791
Actual Rows: 1
Actual Loops: 1
Plans:
-
Node Type: Seq Scan
Parent Relationship: Outer
Parallel Aware: false
Relation Name: actor
Alias: actor
Startup Cost: 0
Total Cost: 3561.86
Plan Rows: 195786
Plan Width: 0
Actual Startup Time: 0.132
Actual Total Time: 15.29
Actual Rows: 195786
Actual Loops: 1