Why does the now() function return the same value for multiple inserted rows?

Question

Perhaps there's a more idiomatic approach to this in Postgres, but the pattern is reasonably common so I expected it to work.

Here's the code:

drop table if exists tbl;
create temporary table tbl as select time, NULL as time_ts
from generate_series(1,20000000) as g(time);

drop table if exists timing; 
create table timing(
    info text, 
    n_rows integer, 
    iteration integer,
    time timestamptz);


select now() as before;

DO
$body$
DECLARE
    _value_array integer[] := '{
    100,
    20000,
    5000000
    }
    ';
    t INTEGER;
    iterator integer := 0;
    table_name text := 'test_table';
BEGIN
   FOREACH t IN ARRAY _value_array
   LOOP
      -- add to time table
      insert into timing(info, n_rows, iteration, time) 
      values (format('(%I) before', table_name), t, iterator, now());
      -- Run update
      EXECUTE format(
            'with cte as( '
                'select time '
                'from tbl '
                'where time_ts '
                'is null '
                'limit %s '
            ') '
            'update tbl '
            'set time_ts = cte.time '
            'from cte '
            'where tbl.time = cte.time;', t);
      -- add to time table
      insert into timing(info, n_rows, iteration, time) 
      values (format('(%I) after', table_name), t, iterator, now());
      iterator := iterator + 1;
   END LOOP;
END
$body$;


select now() as after;

For which I get the output:

            before             
───────────────────────────────
 2023-01-17 01:14:17.056198+00
(1 row)

             after             
───────────────────────────────
 2023-01-17 01:14:44.871277+00
(1 row)

And the timing table has the content:

        info         │ n_rows  │ iteration │             time              
─────────────────────┼─────────┼───────────┼───────────────────────────────
 (test_table) before │     100 │         0 │ 2023-01-17 01:14:27.756752+00
 (test_table) after  │     100 │         0 │ 2023-01-17 01:14:27.756752+00
 (test_table) before │   20000 │         1 │ 2023-01-17 01:14:27.756752+00
 (test_table) after  │   20000 │         1 │ 2023-01-17 01:14:27.756752+00
 (test_table) before │ 5000000 │         2 │ 2023-01-17 01:14:27.756752+00
 (test_table) after  │ 5000000 │         2 │ 2023-01-17 01:14:27.756752+00
(6 rows)

The time within the timing table is at least somewhere between before and after, but I don't understand why they're all exactly the same time.

The output that I'm expecting to see is for each row to have a different time in it, as I would like to know how long each iteration took.

Answer 1

The answer, as is sometimes the case, can be found in the documentation:

now() is a traditional PostgreSQL equivalent to transaction_timestamp()

and

transaction_timestamp() is equivalent to CURRENT_TIMESTAMP, but is named to clearly reflect what it returns

which is, subject to the SQL standard

the start time of the current transaction

There are other functions that you can use instead:

PostgreSQL also provides functions that return the start time of the current statement, as well as the actual current time at the instant the function is called [...] statement_timestamp() returns the start time of the current statement [...] clock_timestamp() returns the actual current time, and therefore its value changes even within a single SQL command

---

P.S. It is a bad form to use SQL keywords, such as "time", for object names.