SQLcl autotrace is way more than “just” (SQL*Plus) autotrace

As part of the research I did for the 2nd edition of our Exadata book I used session statistics quite heavily. Session statistics can provide additional insights in situations where the wait interface on its own doesn’t get you any further.

On the command line, my tools of choice are either Tanel Poder’s excellent Session Snapper or Adrian Billington’s mystats utility. There are of course others, it just so happened that I’ve been using the previous two quite heavily. If you prefer a graphical front-end such as SQL Developer, you can grab the change in session statistics easily as described in an earlier post.

I’m not sure why it never occurred to me to check if SQL Developer’s best friend, sqlcl, has the same functionality. Well it does, and that’s great news. The other great news is that you can download sqlcl directly from Oracle’s website now.

UPDATE when I first wrote about sqlcl‘s ability to display session statistics it had a problem getting the actual execution plan from the database (it used explain plan for <sql> internally. This is fixed with the current release. I updated the article accordingly.

Downloading SQLcl the new way

The first step to complete is to pull the latest version of sqlcl. Many thanks to Connor McDonald who told me there is a super-easy way to always get the latest version. Just use the following URL:

https://download.oracle.com/otn_software/java/sqldeveloper/sqlcl-latest.zip

Great! I don’t even need to worry about the version:

$ wget https://download.oracle.com/otn_software/java/sqldeveloper/sqlcl-latest.zip
--2021-07-29 17:11:23--  https://download.oracle.com/otn_software/java/sqldeveloper/sqlcl-latest.zip
Resolving download.oracle.com (download.oracle.com)... 104.76.200.85
Connecting to download.oracle.com (download.oracle.com)|104.76.200.85|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 37581054 (36M) [application/zip]
Saving to: ‘sqlcl-latest.zip’

sqlcl-latest.zip           100%[=====================================>]  35.84M  2.43MB/s    in 18s     

2021-07-29 17:11:42 (1.95 MB/s) - ‘sqlcl-latest.zip’ saved [37581054/37581054]

Note that I’m downloading sqlcl-latest.zip, which translates to 21.2.1.195.1252 at the time of writing:

$ cd sqlcl/bin && ./sql -V
SQLcl: Release 21.2.1.0 Production Build: 21.2.1.195.1252

With the latest sqlcl release unzipped it’s time to grab some session statistics.

Session Statistics, please!

To keep matters reasonably simple I’m using a non-partitioned table for my demonstration. As always, my examples use the excellent Swingbench (Order Entry) benchmark schema. Once connected to the database, I can start investigating. By the way I’m running this query on Oracle 19c in a VM on my laptop.

The first step is to enable auto-trace as shown here:

SQL> show version
Oracle SQLDeveloper Command-Line (SQLcl) version: 21.2.1.0 build: 21.2.1.195.1252
SQL> help set autotrace
SET AUTOTRACE
  SET AUTOT[RACE] {OFF|ON|TRACE[ONLY]}
SQL> set autotrace on 
Autotrace Enabled
Shows the execution plan as well as statistics of the statement.

Let’s run a query against the orders table:

SQL> var oid number
SQL> exec :oid := 1

PL/SQL procedure successfully completed.

SQL> select /*+ gather_plan_statistics */ /* sqlcl is cool */ 
  2* order_id, order_date, order_mode from soe.orders o where o.order_id = :oid;

   ORDER_ID                         ORDER_DATE    ORDER_MODE 
___________ __________________________________ _____________ 
          1 07-MAY-11 06.00.00.000000000 AM    direct        

PLAN_TABLE_OUTPUT 
______________________________________________________________________________________________________________ 
SQL_ID  f746puksv24jv, child number 0                                                                          
-------------------------------------                                                                          
select /*+ gather_plan_statistics */ /* sqlcl is cool */  order_id,                                            
order_date, order_mode from soe.orders o where o.order_id = :oid                                               
                                                                                                               
Plan hash value: 4043159647                                                                                    
                                                                                                               
-----------------------------------------------------------------------------------------------------------    
| Id  | Operation                   | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |    
-----------------------------------------------------------------------------------------------------------    
|   0 | SELECT STATEMENT            |          |      1 |        |      1 |00:00:00.01 |       4 |      3 |    
|   1 |  TABLE ACCESS BY INDEX ROWID| ORDERS   |      1 |      1 |      1 |00:00:00.01 |       4 |      3 |    
|*  2 |   INDEX UNIQUE SCAN         | ORDER_PK |      1 |      1 |      1 |00:00:00.01 |       3 |      2 |    
-----------------------------------------------------------------------------------------------------------    
                                                                                                               
Predicate Information (identified by operation id):                                                            
---------------------------------------------------                                                            
                                                                                                               
   2 - access("O"."ORDER_ID"=:OID)                                                                             
                                                                                                               

Statistics
-----------------------------------------------------------
               1  CPU used by this session
               1  CPU used when call started
               1  DB time
              44  Requests to/from client
              44  SQL*Net roundtrips to/from client
               3  buffer is not pinned count
            1299  bytes received via SQL*Net from client
           84726  bytes sent via SQL*Net to client
               4  calls to get snapshot scn: kcmgss
               4  calls to kcmgcs
           24576  cell physical IO interconnect bytes
               4  consistent gets
               4  consistent gets examination
               1  consistent gets examination (fastpath)
               4  consistent gets from cache
               1  enqueue releases
               1  enqueue requests
               4  execute count
             195  file io wait time
               3  free buffer requested
               1  index fetch by key
           32768  logical read bytes from cache
              56  non-idle wait count
               4  opened cursors cumulative
               1  opened cursors current
               4  parse count (total)
               3  physical read IO requests
           24576  physical read bytes
               3  physical read total IO requests
           24576  physical read total bytes
               3  physical reads
               3  physical reads cache
               1  rows fetched via callback
               4  session logical reads
               3  shared hash latch upgrades - no wait
               1  sorts (memory)
            2010  sorts (rows)
               1  table fetch by rowid
              46  user calls 

This is pretty nifty in my opinion. There’s an execution plan and a whole raft of relevant session statistics.

Unlike in earlier sqlcl releases the execution plan is now fetched from the database. I ran a sql trace to confirm although the presence of a SQL ID and a child number in the above output should indicate this is the “real” plan.

Happy Troubleshooting!

Advertisement