Postgres stored procedure returning same epoch for multiple calls to now()

Question

I wrote a code to get the execution time of procedure call using below stored procedure. But the problem is the output is showing start_time and end_time having same epoch value and hence the execution_time is always returned as 0. Could you please help me why I am getting same epoch value for both the calls to now() ?

CREATE OR REPLACE PROCEDURE public.calculate_execution_time()
LANGUAGE plpgsql
AS $procedure$
    DECLARE
        start_time float;
        end_time float;
    BEGIN
        SELECT extract(epoch from now()) into start_time;
        call public.another_stored_procedure();
        SELECT extract(epoch from now()) into end_time;
        raise notice 'Execution time = % - % = % seconds', end_time, start_time, (end_time - start_time);
    END;
$procedure$
;

Sample output of: call public.calculate_execution_time()

Execution time = 1620213218.485702 - 1620213218.485702 = 0 seconds

Answer 1

Having now() return a constant time -- when the transaction started -- is considered a feature rather than a bug. It is actually handy for long-running stored procedure.

You want clock_timestamp() instead:

BEGIN
    SELECT extract(epoch from clock_timestamp) into start_time;
    call public.another_stored_procedure;
    SELECT extract(epoch from clock_timestamp) into end_time;
    raise notice 'Execution time = % - % = % seconds', end_time, start_time, (end_time - start_time);
END;