Using SQL*Plus Timers

SQL*Plus comes with a crude, built-in timing facility that allows you to measure the elapsed time of a script or any portion of a script. You can even have SQL*Plus report the elapsed execution time of every SQL query and PL/SQL block automatically after each statement has executed. Timers can be nested so you can time the overall execution of a script, as well as the execution time of each individual statement.

Timings can be useful in spotting trends. It may be helpful to know, for example, if a script is taking longer to run. Timings can help compare the relative efficiency of two SQL statements. If you have two statements that return equivalent results and one consistently runs faster than the other, that's the one you probably want to go with.

Take timing with a grain of salt, however. The timer measures elapsed time, sometimes called wall-clock time, not CPU time, and many factors can throw it off. The network throughput might vary between the execution of two queries. The load on the server might vary as well. For example, one query might run more slowly than another because many other users simultaneously happened to hit the database. Be skeptical of one-time results. Look for consistency over several timings.

12.1.1 The SET TIMING Command

You can have SQL*Plus automatically report the elapsed time it takes to execute every query by issuing the SET TIMING ON command:

SET TIMING ON

Now, whenever you execute a query, SQL*Plus will report the elapsed time. With older Windows versions of SQL*Plus, this time will be reported in milliseconds . The following example shows that it took two hundredths of a second for a query on dba_views to complete:

SELECT view_name FROM dba_views WHERE view_name = 'DBA_TABLES'; VIEW_NAME ------------------------------ DBA_TABLES Elapsed: 00:00:00.02

When timing is on, SQL*Plus reports the time it takes to execute a PL/SQL block:

BEGIN DBMS_OUTPUT.PUT_LINE('How long does this take?'); END; / How long does this take? PL/SQL procedure successfully completed. Elapsed: 00:00:00.04

To turn timing off, simply issue the SET TIMING OFF command as follows :

SET TIMING OFF

When you have timing turned on, SQL*Plus displays elapsed time only for statements executed by the database server. This includes SQL statements and PL/SQL blocks. Elapsed time for SQL*Plus commands, such as ACCEPT and DEFINE, is not reported.

12.1.2 The TIMING Command

The SQL*Plus TIMING command gives you complete control over when timing starts and stops and what is measured. With it, you can turn on a timer at any point in your script. You can display the elapsed time at any point after a timer is turned on, and you can nest timers. Nesting timers gives you a way to time a set of operations, maybe an entire script, while still allowing you to time each individual operation separately.

Think of timers as being implemented on a stack. Each time you issue a TIMING START command, you push a new timer onto the stack. The TIMING SHOW and TIMING STOP commands each operate on whatever timer is currently at the top of the stack. To find out how many timers you have currently running, enter the TIMING command with no arguments.

12.1.2.1 Starting and stopping a timer

Use the TIMING START command to start a timer. If you like, you can give the timer a name. Timing starts the moment the command is executed. The following example starts a new timer, and gives it a name of for_testing :

TIMING START for_testing

You stop the timer and display its final value by issuing the TIMING STOP command as follows:

SQL> TIMING STOP timing for: for_testing Elapsed: 00:00:07.72

In this case, the timer ran for a total elapsed time of 7.72 seconds.

12.1.2.2 Displaying the value of a timer

You can display the value of a timer without stopping it. This is useful if your script is executing several SQL queries and you want to see the cumulative elapsed time after each one:

SQL> TIMING START for_show SQL> TIMING SHOW timing for: for_show Elapsed: 00:00:02.61 SQL> TIMING SHOW timing for: for_show Elapsed: 00:00:04.97 SQL> TIMING SHOW timing for: for_show Elapsed: 00:00:06.33

You can see from this example that once I got going, it took me in the neighborhood of two seconds, give or take, to type each TIMING SHOW command.

12.1.2.3 Nesting timers

Timers can be nested, allowing you to time a group of operations while simultaneously timing each individual operation within the larger group . The following example shows a timer being started, and while that's running, two more timers are started and stopped. Finally, the first timer is stopped .

SQL> TIMING START first SQL> TIMING START second SQL> TIMING STOP timing for: second Elapsed: 00:00:03.66 SQL> TIMING START third SQL> TIMING STOP timing for: third Elapsed: 00:00:02.21 SQL> TIMING STOP timing for: first Elapsed: 00:00:17.14

The important thing to notice here is that the first timer kept running during this entire example. The total elapsed time was a bit over 17 seconds, while the two intermediate operations took 3.66 and 2.21 seconds respectively.

Example 12-1 shows how this nesting feature can be used. It creates a copy of each example table used for this book and reports the time needed for each copy, as well as the total elapsed time to run the entire script.

Example 12-1. Using nested timers to time a script and its operations

TIMING START entire_script --Drop old versions of the copies, if any exist DROP TABLE employee_copy; DROP TABLE project_copy; DROP TABLE project_hours_copy; --Copy the employee table TIMING START copy_employees CREATE TABLE employee_copy AS SELECT * FROM employee; TIMING STOP --Copy the project table TIMING START copy_project CREATE TABLE project_copy AS SELECT * FROM project; TIMING STOP --Copy the project_hours TIMING START copy_project_hours CREATE TABLE project_hours_copy AS SELECT * FROM project_hours; TIMING STOP TIMING STOP

Here is the output from running Example 12-1:

@ex12-1 Table dropped. Table dropped. Table dropped. Table created. timing for: copy_employees Elapsed: 00:00:00.07 Table created. timing for: copy_project Elapsed: 00:00:00.37 Table created. timing for: copy_project_hours Elapsed: 00:00:00.08 timing for: entire_script Elapsed: 00:00:00.73

You can see that the elapsed time was displayed for each table copy and for the script as a whole.

12.1.2.4 Finding out how many timers you have going

The TIMER command will cause SQL*Plus to report the number of active timers. The following example shows how the count goes up each time you start a timer and goes back down each time you stop one:

TIMING START TIMING 1 timing element in use TIMING START TIMING 2 timing elements in use TIMING STOP Elapsed: 00:00:00.05 TIMING 1 timing element in use TIMING STOP Elapsed: 00:00:00.14 TIMING no timing elements in use

12.1.2.5 Stopping all timers

You can stop and delete all timers with the CLEAR TIMING command. As each timer is stopped, its final value is displayed:

TIMING START first TIMING START second TIMING START third CLEAR TIMING timing for: third Elapsed: 00:00:00.02 timing for: second Elapsed: 00:00:00.06 timing for: first Elapsed: 00:00:00.10