21

I have a procedure that contains code like this:

processStart := current_timestamp;
-- run statement(s)
processEnd := current_timestamp;
elapsed := processEnd - processStart;
raise notice 'My Statement, elapsed time: %', elapsed;

The idea is, I want to get the amount of time it takes for a statement or collection of statements to run.

The problem is, this returns 00:00:00 for subsecond elapsed times. I really want to see the milliseconds. How can I do this?

There's questions and answers about using EXTRACT and EPOCH, but this seems to be at the "second" level, and that is not granular enough for my purposes.

UPDATE

Using @twn08's answer, I ultimately arrived at the following solution:

I declared the following variables:

declare
    processStart timestamp;
    elapsed numeric(18,3);
    processFinish timestamp;

then, prior to starting the process:

processStart := clock_timestamp();

after the process was finished, I ran this:

processFinish := clock_timestamp();
elapsed := cast(extract(epoch from (processFinish - processStart)) as numeric(18,3));
raise notice 'My Statement, elapsed time: % ms', elapsed;

this worked swimmingly.

Jeremy Holovacs
  • 22,480
  • 33
  • 117
  • 254

4 Answers4

23
with t as
 (select
    Now() as tend, 
    Now() - interval '10 seconds 552 milliseconds' as tstart
 )

select
  extract('epoch' from tend)  - extract('epoch' from tstart) 
from 
  t

Note:

For version 9.0+ you can read in documentation the following example:

SELECT EXTRACT(EPOCH FROM TIMESTAMP WITH TIME ZONE '2001-02-16 20:38:40.12-08');
Result: 982384720.12

Before 9.0 there is:

SELECT EXTRACT(EPOCH FROM TIMESTAMP WITH TIME ZONE '2001-02-16 20:38:40-08');
Result: 982384720

Based on this it is not entirely clear whether my example will work prior to version 9.0

Tomas Greif
  • 21,685
  • 23
  • 106
  • 155
9

Here's a one-liner to calculate the elapsed time in milliseconds from a past TIMESTAMP to now():

SELECT ROUND((EXTRACT (EPOCH FROM now()) - EXTRACT (EPOCH FROM pg_last_xact_replay_timestamp())) * 1000) AS "replication_lag (ms)";

The above example calculates the replication lag between a primary and standby PostgreSQL server, so simply replace pg_last_xact_replay_timestamp() with your TIMESTAMP.

To see what it's doing a bit more clearly:

SELECT
    ROUND ((
        EXTRACT (EPOCH FROM now()) -
        EXTRACT (EPOCH FROM pg_last_xact_replay_timestamp())
    ) * 1000)
AS "replication_lag (ms)";

Output:

 replication_lag (ms) 
----------------------
                  562
(1 row)
liquidki
  • 1,234
  • 16
  • 16
4

Based on @TomasGreif's answer, I made a little datediff function in case you need to do millisecond datediffs often:

create function datediff_ms(timestamptz, timestamptz) returns INTEGER as
$$
    begin
        return (EXTRACT('epoch' from $2) - EXTRACT('epoch' from $1)) * 1000;
    end;
$$ LANGUAGE plpgsql;

Usage:

select datediff_ms(time1, time2)
from sometables;
Shaul Behr
  • 36,951
  • 69
  • 249
  • 387
2

Note that you can extract the epoch from the interval, which might make the syntax a bit more concise.

select extract('epoch' from (t2-t1))

versus

select extract('epoch' from t2) - extract('epoch' from t1)
Anssssss
  • 3,087
  • 31
  • 40