Pivotal Knowledge Base

Follow

How to log the time of the query execution in master log

Goal

How do we log time of the queries that is running for the longest time ?

Solution

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 results in all the completed SQL to log time.

log_min_duration_statement is defined as how many milliseconds the query has to run before its 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 crosses beyond that time.

Example

-- Set the GUC on session level to report query running for more than 10 millisecond.

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

-- Run a small query that runs less than 10ms, for eg.

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 , NOTE: 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, for eg.

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 , NOTE: 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,

Comments

Powered by Zendesk