PostgreSQL: Capture Run Time of Long Script with SQL Only

Question

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?

Note: now() gives you the timestamp when the transaction was started. For the actual wall-time you will need clock_timestamp(). — wildplasser
– wildplasser, Commented May 22, 2016 at 15:22

wildplasser · Accepted Answer · 2016-05-22 15:25:12Z

1

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)

answered May 22, 2016 at 15:25

wildplasser

44.5k9 gold badges72 silver badges116 bronze badges

Sign up to request clarification or add additional context in comments.

Comments

Abelisto · Accepted Answer · 2016-05-22 15:32:46Z

0

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.

answered May 22, 2016 at 15:32

Abelisto

15.8k3 gold badges38 silver badges47 bronze badges

Comments

Michael Sheaver · Accepted Answer · 2016-05-22 16:47:03Z

0

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 |

edited May 22, 2016 at 16:47

answered May 22, 2016 at 16:23

Michael Sheaver

2,1495 gold badges28 silver badges43 bronze badges

1 Comment

Jay K Over a year ago

I'd probably do CREATE TEMPORARY TABLE instead of keeping it there and truncating it each time, just to keep things a little cleaner.

Collectives™ on Stack Overflow

PostgreSQL: Capture Run Time of Long Script with SQL Only

3 Answers 3

Comments

Comments

1 Comment

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

Comments

Comments

1 Comment

Your Answer

Sign up or log in

Post as a guest

Related