How to Log the Time of the Query Execution in the Master Log

Products

• VMware Tanzu Greenplum

Issue/Introduction

This article describes how to log the time of the queries that are running for the longest time.

 

Environment

Resolution

The GUC "log_min_duration_statement" & "log_duration" can be used to control the relevant information.

log_duration logs the duration of each completed SQL statement. By Default, the value of log_duration is off, turning it on will result in all the completed SQL to log time.

log_min_duration_statement is defined as how many milliseconds the query has to run before it has to be logged. By Default, the value of log_min_duration_statement is -1 which means its disabled by default. Setting the parameter to Zero will result in all the query to log the time duration (which is same as setting log_duration=ON), but the use of the parameter comes when setting it to greater than Zero, results in logging time of that statements that cross beyond that time.

Example

-- Set the GUC on session level to report query running for more than 10 milliseconds:

flightdata=# set log_min_duration_statement=10;
SET
Time: 15.653 ms

-- Run a small query that runs less than 10ms:

flightdata=# explain analyze select * from pg_class limit 10;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..0.04 rows=10 width=204)
   Rows out:  10 rows with 0.017 ms to first row, 0.023 ms to end, start offset by 0.064 ms.
   ->  Seq Scan on pg_class  (cost=0.00..1198.30 rows=270920 width=204)
         Rows out:  10 rows with 0.016 ms to first row, 0.019 ms to end, start offset by 0.065 ms.
 Slice statistics:
   (slice0)    Executor memory: 74K bytes.
 Statement statistics:
   Memory used: 128000K bytes
 Total runtime: 0.088 ms
(9 rows)

Time: 0.722 ms

The output on the master log looks like below and there is no information on the query duration reported here:

2014-12-23 06:53:38.874378 PST,"gpadmin","flightdata",p3529,th752003232,"[local]",,2014-12-23 06:43:53 PST,15390,con11,cmd18,seg-1,,dx16,x15390,sx1,"LOG","00000","statement: explain analyze select * from pg_class limit 10;",,,,,,"explain analyze select * from pg_class limit 10;",0,,"postgres.c",1563,

Run a small query that runs greater than 10ms\:

flightdata=# insert into test values ( generate_series (1,10000000));
INSERT 0 10000000
Time: 7938.973 ms

The output on the master log looks like below, and the query duration reported here:

2014-12-23 06:54:55.165877 PST,"gpadmin","flightdata",p3529,th752003232,"[local]",,2014-12-23 06:43:53 PST,15391,con11,cmd20,seg-1,,dx17,x15391,sx1,"LOG","00000","statement: insert into test values ( generate_series (1,10000000));",,,,,,"insert into test values ( generate_series (1,10000000));",0,,"postgres.c",1563,
2014-12-23 06:55:03.104703 PST,"gpadmin","flightdata",p3529,th752003232,"[local]",,2014-12-23 06:43:53 PST,0,con11,cmd21,seg-1,,,,,"LOG","00000","duration: 7938.900 ms",,,,,,"insert into test values ( generate_series (1,10000000));",0,,"postgres.c",1833,

Additional Information

+ Environment:

Pivotal Greenplum Database (GPDB) all versions