CODEWITHSUNDEEP
postgresqlloggingtime
Michael Sheaver
Michael Sheaver

Reputation: 2119

PostgreSQL: Capture Run Time of Long Script with SQL Only

I want to be able to log how long it takes a script with lots of SQL commands to run. I have looked at EXPLAIN, but that is limited to a single command, and do not want to use PL/PGSQL since it does not seem to give me the functionality I need for this. And I will not be running these scripts in the psql client so the \set command will not work for me either.

This psuedo-code block should give you an idea of what I am trying to do:

-- beginning of script    
SET begin_time = NOW();

    ... execute a bunch of SQL commands

-- end of script
SET end_time =  NOW();

INSERT INTO execute_log (script_run_time)
  SELECT (end_time - start_time);

Is there any easy way to do this in PostgreSQL using just SQL? If not, how can I get the same results?

Upvotes: 1

Views: 711

Answers (3)

Michael Sheaver
Michael Sheaver

Reputation: 2119

Thanks to the great input from both of you! I decided to go with a hybrid approach, as so:

CREATE TABLE timenow (
  seq SERIAL NOT NULL PRIMARY KEY,
  starttime TIMESTAMP NOT NULL,
  stoptime TIMESTAMP NULL,
  runtime INTERVAL (3) NULL
);

-- set execution begin time
INSERT INTO timenow (starttime) SELECT clock_timestamp();

    ... execute a bunch of SQL commands

-- set execution end time
UPDATE timenow
  SET stoptime = clock_timestamp();
UPDATE timenow
  SET runtime = stoptime - starttime;

SELECT * FROM timenow;

Output:

 seq |           starttime           |           stoptime            |   runtime
-----+-------------------------------+-------------------------------+--------------
   1 | 2016-05-22 12:09:47.049678-04 | 2016-05-22 12:11:00.610502-04 | 00:01:13.561
(1 row)

Time: 0.338 ms

Of course, I will replace the 

CREATE TABLE timenow:

with instead:

TRUNCATE timenow;

in the production environment.

EDIT:

To capture the time and insert it into the log, I used:

INSERT INTO script_run_log (entry)
  SELECT 'Script #1 run time: ' || 
  TO_CHAR((SELECT runtime FROM timenow), 'MI:SS:MS');

Output:

| Script #1 run time: 01:11:554 |

Upvotes: 0

Abelisto
Abelisto

Reputation: 15614

Using custom configuration parameters:

select set_config('foo.bar', clock_timestamp()::text, false);
...
select current_setting('foo.bar')::timestamp;

Note that the dot in the name is required.

Upvotes: 0

wildplasser
wildplasser

Reputation: 44240

CREATE TABLE timenow
        ( seq serial NOT NULL PRIMARY KEY
        , starttime timestamptz NOT NULL
        , stoptime timestamptz NOT NULL
        );

BEGIN;
INSERT INTO timenow( starttime, stoptime) SELECT now(), clock_timestamp();

SELECT COUNT(*) from pg_class;

INSERT INTO timenow( starttime, stoptime) SELECT now(), clock_timestamp();
COMMIT;

SELECT * FROM timenow;

output:

CREATE TABLE
BEGIN
INSERT 0 1
 count 
-------
   577
(1 row)

INSERT 0 1
COMMIT
 seq |           starttime           |           stoptime            
-----+-------------------------------+-------------------------------
   1 | 2016-05-22 17:20:12.206513+02 | 2016-05-22 17:20:12.207037+02
   2 | 2016-05-22 17:20:12.206513+02 | 2016-05-22 17:20:12.207918+02
(2 rows)

Upvotes: 1

Related Questions