Inside Documentum

Assessing Query Performance

In yesterday’s post I talked about the potential performance problems with a particular query. I noticed this problem whilst reviewing a trace file for a batch process I was testing. Since this was a log4j trace the trace lines were output with detailed timings on each line. The trace file consistently had 2 lines that were separated by 8 or more seconds. I wondered what was happening in this period since if this was all time running database queries that’s an awful lot of processing going on.

I captured a dmcl trace whilst running the process and put the output through the Xense Profiler (a DMCL trace profiling tool). The top 10 queries report showed a single query consuming most of the time (our friend the ORed Folder query from yesterday), so I derived the SQL and set to work in SQL Plus to look at the performance of the query.

SQL Plus has a very useful feature called ‘autotrace’. When you execute a query in SQL Plus with autotrace on SQL Plus will output a query execution plan and some very useful execution statistics. The execution statistics from running the problem query were:

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
     655992  consistent gets
          0  physical reads
          0  redo size
       3528  bytes sent via SQL*Net to client
        558  bytes received via SQL*Net from client
          7  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        132  rows processed

The key statistic here is the 655,992 consistent gets. Each consistent get is a fetch of a database buffer from the database buffer cache (AKA logical IO). This is a large amount of work to retrieve just 132 rows. This explained why the query was taking so long (as a very rough rule of thumb Oracle running on a reasonably fast processor might be able to perform between 50,000 and 100,000 logical IOs). Notice that there were no ‘costly’ physical reads, the time was all spent thrashing through cached data buffers.

Still this is only 8 seconds and this is only a batch process, why worry?

Three reasons:

• There were no physical reads in the execution statistics because the only query I had been running on the test system was this one. In a real life system there are likely to be many other queries running all utilising the buffer cache. There is a good chance that running this query in a real life production system will mean many of the logical IOs will turn into physical IOs. Even if only 5% become physical reads (i.e. we have a ‘good’ buffer cache hit ratio for this query) that’s 30,000 physical IOs – our query suddenly starts taking a lot longer to execute.
• The system I was testing on had a relatively small number of objects (about 150,000). Since a production system is likely to be much bigger and probably growing, the number of logical IOs required to complete the query will grow in proportion. This is a consequence of the execution plan for the query; with dm_sysobject_r or dm_sysobject_s as the first table in the join we are effectively scanning through a table that grows in proportion to the size of the docbase.
• It is always a good idea to seek to reduce the workload placed on the database. This improves scalability and general responsiveness of the system

So what happened after restructuring the query? SQL Plus with autotrace gave:

Statistics
----------------------------------------------------------
         14  recursive calls
          0  db block gets
       1032  consistent gets
          0  physical reads
          0  redo size
       3528  bytes sent via SQL*Net to client
        558  bytes received via SQL*Net from client
          7  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        132  rows processed

Only 1032 logical IOs and since the query can drive through an index on dm_folder_r the performance is largely unaffected by increases in the size of the docbase.