SQL*PLUS Basics – ways to measure time

Here is a quick overview about commands in SQL*plus that help to track and measure time.

set time on/off

This displays a prompt in front of each statement with the current time. Be aware that it is not the time, when the statement was executed, but the time when the line in sql*plus was created. This difference is usually not relevant when running scripts, just something to be aware of when manually typing and executing statements in sql*plus.

SQL> set time on;
10:56:02 SQL>
10:56:10 SQL> execute dbms_session.sleep(3);

PL/SQL procedure successfully completed.

10:56:23 SQL>

The prompt shows that 13 seconds passed by. However the sleep time specified was only 3 seconds. The reason is it took me approximately 10 seconds to type the statement.

set timing on/off

The result is the runtime of a sql statement or an anonymous plsql block in SQL*plus.

SQL> set timing on;
SQL> execute dbms_session.sleep(3);

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.02
SQL>

After any SQL statement or anonymous plsql blocks, sql*plus shows the elapsed time for that command.

The elapsed time is not shown after SQL*PLUS commands (like SET or SPOOL).

The time is measured on the client. So it includes the time to send the command to the server, execute the command there and move the resulting information from the database server back to the sql*plus client. When very exact measurements are needed network issues will make this elapsed time fluctuate a little more than what is useful.

timing start+stop

Timing start+stop is very similar to set timing on/off. It starts a timer with timing start and shows the elpased time after the timing stop command. This allows to measure the time to run multiple commands. Wheras set timing on/off only measures a single command.

SQL> set time on;
11:14:37 SQL> timing start
11:14:45 SQL> execute dbms_session.sleep(3);

PL/SQL procedure successfully completed.

11:14:55 SQL> select * from dual;

D
-
X

11:15:00 SQL> execute dbms_session.sleep(1);

PL/SQL procedure successfully completed.

11:15:12 SQL> timing stop;
Elapsed: 00:00:31.48
11:15:17 SQL>

We can compare the measurement from timing with the times shown by set time on.
From 11:14:45 to 11:15:17 there are 32 seconds. Which matches perfectly the elapsed time or 31.48 seconds shown by timing start+stop.

_DATE

This is a predefined sql*plus variable that holds the current time. It uses the sessions nls settings as display format.

SQL> prompt &_DATE
27-APR-22
SQL> alter session set nls_date_format = 'dd-mm-yyyy HH24:MI:SS';

Session altered.

SQL> prompt &_DATE
27-04-2022 11:22:20

SQL> set pagesize 10
SQL> ttitle "Important list of numbers &_DATE."
SQL> select level as num from dual connect by level <= 10;
Important list of numbers 27-04-2022 11:59:56
       NUM
----------
         1
         2
         3
         4
         5
         6

Important list of numbers 27-04-2022 11:59:56
       NUM
----------
         7
         8
         9
        10

10 rows selected.
SQL> ttitle OFF

Useful when one wants to add the day and/or time to the name of a log file for example.

sysdate/systimestamp

These are SQL pseudofunctions that give the current datetime. Sysdate delivers a date (incl. time up to the second), systimestamp delivers also fractional seconds. The time is derived from the servers time settings. So client settings do not influence the value. However client nls settings effect the conversion to strings.

SQL> select sysdate from dual;

SYSDATE
---------
27-APR-22

SQL> alter session set nls_date_format='DD-MM-YYYY HH24:MI:SS';

Session altered.
SQL> select sysdate from dual;

SYSDATE
-------------------
27-04-2022 14:33:03

SQL> select to_char(sysdate,'FMDay, DDth Month YYYY') from dual;

TO_CHAR(SYSDATE,'FMDAY,DDTHMONTHYYYY')
-----------------------------------------
Wednesday, 27TH April 2022

SQL> select systimestamp from dual;

SYSTIMESTAMP
-----------------------------------------
27-APR-22 02.33.10.675396 PM +02:00

SQL> alter session set nls_timestamp_tz_format='DD-MM-YYYY HH24:MI:SSXFF';

Session altered.

SQL> select systimestamp from dual;

SYSTIMESTAMP
------------------------------------------
27-04-2022 14:33:18.033306

SQL> select to_char(systimestamp,'FMDay, DDth Month YYYY HH24:MI:SSXFF TZR') from dual;

TO_CHAR(SYSTIMESTAMP,'FMDAY,DDTHMONTHYYYYHH24:MI:SSXFFTZR')
------------------------------------------
Wednesday, 27TH April 2022 14:33:22.260310 +02:00

dbms_utility.get_time

A possibility to measure very exact times (1/100 of a second) in plsql.

SQL>declare
2   time number;
3 begin
4   time:=dbms_utility.get_time;
5   dbms_session.sleep(3);
6   dbms_output.put_line('Elapsed in sec: '||to_char((dbms_utility.get_time - time)/100));
7 end;
8 /
Elapsed in sec: 3.04

PL/SQL procedure successfully completed.

SQL>

Be aware that the numbers returned by get_time are often negative integers, like -1618843773.

We can also use this to measure the time between several sql*plus calls by storing the first time in a sql*plus variable. So it doesn’t need to be a single large plsql block.

SQL> var stime number;
SQL> exec :stime := dbms_utility.get_time;

PL/SQL procedure successfully completed.

SQL> exec dbms_session.sleep(3);

PL/SQL procedure successfully completed.

SQL> select * from dual;

D
-
X

SQL> exec dbms_output.put_line('Elapsed in sec: '||to_char((dbms_utility.get_time - :stime)/100));
Elapsed in sec: 18.62

PL/SQL procedure successfully completed.

SQL>

Serveroutput needs to be switched on to see the result of dbms_output.

Recommendations

  • For crude but easy performance time measurements set time on and set timing on are solid.
  • For exact and comparable measurements on the database use dbms_utility.get_time.
  • To show date and time in scripts sometimes _DATE is a little easier to use than sysdate.
  • To add the full runtime of a script to the end of a spooled logfile timing start+stop can be used.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.