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.

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-06-10 14:37:29--  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: 36960602 (35M) [application/zip]
Saving to: ‘sqlcl-latest.zip’

sqlcl-latest.zip          100%[====================================>]  35.25M  6.35MB/s    in 5.7s    

2021-06-10 14:37:35 (6.19 MB/s) - ‘sqlcl-latest.zip’ saved [36960602/36960602]

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

$ cd sqlcl/bin && ./sql -V
SQLcl: Release 21.1.1.0 Production Build: 21.1.1.113.1704

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.1.1.0 build: 21.1.1.113.1704
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> select count(*) from soe.orders;

   COUNT(*) 
___________ 
   17157480 

Explain Plan
-----------------------------------------------------------
Plan hash value: 508073128                                                
                                                                          
----------------------------------------------------------------------    
| Id  | Operation          | Name    | Rows  | Cost (%CPU)| Time     |    
----------------------------------------------------------------------    
|   0 | SELECT STATEMENT   |         |     1 | 62161   (1)| 00:00:03 |    
|   1 |  SORT AGGREGATE    |         |     1 |            |          |    
|   2 |   TABLE ACCESS FULL| ORDERS  |    17M| 62161   (1)| 00:00:03 |    
----------------------------------------------------------------------    

Statistics
-----------------------------------------------------------
             103  CPU used by this session
             104  CPU used when call started
          209348  Cached Commit SCN referenced
               4  Commit SCN cached
             510  DB time
         4171496  Effective IO time
            3587  Number of read IOs issued
              42  Requests to/from client
              42  SQL*Net roundtrips to/from client
               2  buffer is not pinned count
             587  bytes received via SQL*Net from client
           79087  bytes sent via SQL*Net to client
               3  calls to get snapshot scn: kcmgss
               8  calls to kcmgcs
      1870921728  cell physical IO interconnect bytes
               4  cleanout - number of ktugct calls
               4  cleanouts only - consistent read gets
               4  commit txn count during cleanout
          228394  consistent gets
          228384  consistent gets direct
               4  consistent gets examination
               4  consistent gets examination (fastpath)
              10  consistent gets from cache
               6  consistent gets pin
               6  consistent gets pin (fastpath)
               1  cursor authentications
               2  enqueue releases
               2  enqueue requests
               2  execute count
         6884470  file io wait time
               4  immediate (CR) block cleanout applications
           81920  logical read bytes from cache
          228380  no work - consistent read gets
            7233  non-idle wait count
             418  non-idle wait time
               2  opened cursors cumulative
               1  opened cursors current
               1  parse count (hard)
               2  parse count (total)
               1  parse time elapsed
            3587  physical read IO requests
      1870921728  physical read bytes
            3587  physical read total IO requests
      1870921728  physical read total bytes
            3578  physical read total multi block requests
          228384  physical reads
          228384  physical reads direct
               6  process last non-idle time
               1  recursive calls
          228394  session logical reads
               1  sorts (memory)
            2010  sorts (rows)
          228384  table scan blocks gotten
        17157480  table scan disk non-IMC rows gotten
        17157480  table scan rows gotten
               1  table scans (direct read)
               1  table scans (long tables)
             418  user I/O wait time
              43  user calls
SQL> 

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

I wouldn’t trust the execution plan too much as it’s generated by an “explain plan for” statement as a reader pointed out. So I guess I’ll still use Tanel’s tpt-oracle scripts for more accurate information.

Happy Troubleshooting!