Case study—implementing a stopwatch with SQL

You sometimes want to time a sequence of several SQL statements, issued from ysqlsh, and to record the time in the spool file. The \timing on metacommand doesn't help here because it reports the time after every individual statement and, on Unix-like operating systems, does this using stderr. The \o metacommand doesn't redirect stderr to the spool file. This case study shows you how to implement a SQL stopwatch that allows you to start it with a procedure call before starting what you want to time and to read it with a select statement when what you want to time finishes. This reading goes to the spool file along with all other select results.

How to read the wall-clock time and calculate the duration of interest

There are various built-in SQL functions for reading the wall-clock time because there are different notions of currency: "right now at the instant of reading , independently of statements and transactions", "as of the start of the current individual SQL statement", or "as of the start of the current transaction". A generic elapsed time stopwatch is best served by reading the wall-clock as it stands at the instant of reading, even as time flows on while a SQL statement executes. The clock_timestamp() function does just this. Try this:

Here's a typical result:

    t0    | slept |    t1    
----------+-------+----------
 20:13:54 | true  | 20:13:59

(The pg_sleep() built-in function returns void, and the ::text typecast of void is the empty string.) You can see that t1 is five seconds later than t0, just as the invocation of pg_sleep() requests.

The return data type of clock_timestamp() is timestamptz. (You can confirm this with the \df metacommand.) Try this.

Notice the use of the at time zone operator to interpret a timestamptz value as a plain timestamp value local to the specified timezone. In this use of the operator (converting from timestamptz to plain timestamp), its effect is insensitive to the session's TimeZone setting. Here's a typical result:

         LAX         |         HEL         
---------------------+---------------------
 2021-07-30 10:26:39 | 2021-07-30 20:26:39

The reported local time in Helsinki is ten hours later than the reported local time in Los Angeles, as is expected around the middle of the summer.

You might be worried by the fact that the text rendition of the clock_timestamp() return value depends on the session's TimeZone setting. And you might think that this could confound the attempt to measure elapsed time by subtracting the reading at the start from the reading at the finish of the to-be-timed statements unless care is taken to ensure that the TimeZone setting is identical at the start and the end of the timed duration. The simplest way to side-step this concern is to record the value of this expression at the start and at the finish:

extract(epoch from clock_timestamp())

This evaluates to the number of seconds (as a double precision value with microsecond precision) of the specified moment from the so-called start of the epoch (00:00:00 on 1-Jan-1970 UTC). The plain timestamp and timestamptz data types section explains, and demonstrates, that the result of "extract(epoch from timestamptz_value)" is insensitive to the session's TimeZone setting. Try this, using the LAX and HEL results from the previous query as the timestamptz literals.

with c as (
  select
    '2021-07-30 10:26:39 America/Los_Angeles'::timestamptz as t1,
    '2021-07-30 20:26:39 Europe/Helsinki'    ::timestamptz as t2
    )
select (
    extract(epoch from t1) =
    extract(epoch from t2)
  )::text as same
from c;

The result is true. This reflects the fact that extract() accesses the internal representation of the timestamptz value and this is normalized to UTC when it's recorded.

Notice that, if you insist, you could subtract the start timestamptz value directly from the finish timestamptz value to produce an interval value. But you’d have to reason rather more carefully to prove that your timing results are unaffected by the session’s timezone setting—particularly in the rare, but perfectly possible, event that a daylight savings boundary is crossed, in the regime of the session’s TimeZone setting, while the to-be-timed operations execute. (Reasoning does show that these tricky details don’t affect the outcome. But it would be unkind to burden readers of your code with needing to understand this when a more obviously correct approach is available.) Further, the duration_as_text() user-defined function (below) to format the result using appropriate units would be a little bit harder to write when you start with an interval value than when you start with a scalar seconds value.

How to note the wall-clock time so that you can read it back after several SQL statements have completed

PostgreSQL doesn't provide any construct to encapsulate PL/pgSQL functions and procedures and to represent state that these can jointly set and read that persists across the boundaries of invocations of these subprograms. YSQL inherits this limitation. (Other database programming environments do provide such schemes. For example, Oracle Database's PL/SQL provides the package for this purpose.) However, PostgreSQL and YSQL do support the so-called user-defined run-time parameter. This supports the representation of session-duration, session-private, state as a text value. Here's a simple example:

This is the result:

 current value of 'my_namespace.my_value' 
------------------------------------------
 Some text.

You don't have to declare the namespace or items within it. They come in to being implicitly when you first write to them. Notice that the effect of the set statement is governed by ordinary transaction semantics. Try this (with autocommit set to on, following the usual convention):

This is the result:

 current value of 'my_namespace.my_value' 
------------------------------------------
 First value.

The duration_as_text() formatting function

The implementation and testing of this function are utterly straightforward—but a fair amount of typing is needed. The code presented here can save you that effort. You may prefer to use it as a model for implementing your own formatting rules.

Create function duration_as_text()

The return data type of the extract() operator is double precision. But it’s better to implement duration_as_text() with a numeric input formal parameter because of this datatype’s greater precision and accuracy. This makes behavior with input values that are very close to the units boundaries that the inequality tests define more accurate than if double precision is used. Of course, this doesn’t matter when the function is used for its ultimate purpose because ordinary stochastic timing variability will drown any concerns about the accuracy of the formatting. But testing is helped when results with synthetic data agree reliably with what you expect.

As is often the case with formatting code, the readability benefits from trivial encapsulations of the SQL built-in functions that it uses—in this case to_char() and ltrim(). First create this overload-pair of helpers:

Now create duration_as_text() itself:

Create function duration_as_text_test_report()

It’s convenient to encapsulate the tests for the function duration_as_text() using a table function to generate a nicely formatted report. The readability of this reporting function, too, benefits from a dedicated helper function along the same lines as the helpers for the duration_as_text() function.

Now create and execute the duration_as_text_test_report() table function itself:

This is the result:

  s (in seconds)   duration_as_text(s)
  --------------   -------------------
        0.019999 :: less than ~20 ms
 
        0.020000 :: 20 ms
        4.999999 :: 5000 ms
 
        5.000000 :: 5.00 ss
        9.999999 :: 10.00 ss
 
       10.000000 :: 10.0 ss
       59.900000 :: 59.9 ss
       59.999999 :: 60.0 ss
 
       60.000000 :: 01:00 mi:ss
     3599.000000 :: 59:59 mi:ss
     3599.999999 :: 60:00 mi:ss
 
     3600.000000 :: 01:00 hh:mi
    86340.000000 :: 23:59 hh:mi
    86399.999999 :: 24:00 hh:mi
 
    86400.000000 :: 1 days 00:00 hh:mi
   202608.000000 :: 2 days 08:17 hh:mi

PL/pgSQL encapsulations for starting and reading the stopwatch

Create a the procedure start_stopwatch(), the function stopwatch_reading_as_dp(), and the function stopwatch_reading().

Create procedure start_stopwatch()

This reads the wall-clock time and records it in a dedicated user-defined run-time parameter:

Create function stopwatch_reading_as_dp()

This reads the current wall-clock time, reads the start time from the user-defined run-time parameter, and returns the elapsed time as a double precision value:

Create function stopwatch_reading()

This is a simple wrapper for stopwatch_reading_as_dp() that returns the elapsed time since the stopwatch was started as a text value by applying the function duration_as_text() to the stopwatch_reading_as_dp() return value:

End-to-end test

The first execution of a PL/pgSQL unit in a session can be slower than subsequent executions because of the cost of compiling it. In a timing test like this, it therefore makes sense deliberately to warm up before recording the timings.

Here is a typical result, as reported in the file stopwatch.txt:

 stopwatch_reading 
-------------------
 6.79 ss

As explained, the "\timing on" output isn't captured in the spool file. But here's what you typically see in the terminal window:

Time: 6783.047 ms (00:06.783)

The elapsed times that "\timing on" and the SQL stopwatch report are in good agreement with each other. And both are a little longer that the argument that was used for pg_sleep() because of the times for the client-server round trips.

What to do when the to-be-timed operations are done in two or several successive sessions

Sometimes you want to time operations that are done in two or several successive sessions. Installation scripts do this when they need to create objects with two or several different owners. It won't work, in such scenarios, to record the starting wall-clock time using a user-defined run-time parameter because this has only session duration. Both psql and (therefore) ysqlsh support client-side variables—and these survive across session boundaries.

Using the \gset and \set ysqlsh metacommands

You can assign the result column(s) of a select statement to such variables with the \gset metacommand. The select statement isn't terminated by the usual semicolon. Rather, the \gset metacommand acts: both as the directive to assign the value of the select list item s0 to the variable stopwatch_s0; and as the terminator for the select statement.

Create a new double precision overload for the function stopwatch_reading() to return the elapsed time like this:

Test it like this:

You'll get a result that reflects the time that it took you to read the few sentences above and to copy-and-paste the code.

It's convenient to assign the SQL statements that start and read the stopwatch to variables so that you can then use these as shortcut commands, to save typing:

and:

You can define these shortcuts in the psqlrc file (on the postgres/etc directory under the directory where you've installed the YugabyteDB client code).

End-to-end test

To be convincing, the end-to-end test needs to connect as at least two different users in the same database. Because session creation brings a noticeable cost, this drowns the first-use cost of invoking PL/pgSQL code—and so the test has no warm-up code.

The test assumes that two ordinary users, u1 and u2 exist in the database demo, that the stopwatch code is on the search path for both of these users, and that both of these have sufficient privileges to execute the code. Try this:

The test-cross-session-stopwatch.txt spool file will contain a result like this:

 stopwatch_reading 
-------------------
 6.86 ss

In this example, session creation cost explains the fact that the reported time, 6.86 seconds, is longer than the total requested sleep time, 6.5 seconds.

Download the code kit

The code that this page explains isn't referenced elsewhere in the overall date-time section. You might like to install it in any database that you use for development and testing. (This is strongly encouraged.) For this reason, it's bundled for a one-touch installation, separately from the downloadable date-time utilities code.