--- title: Identifying SQL Execution Bottlenecks Scientifically description: Learn how to identify and tune SQL statements scientifically. Let's look at a simple case and then proceed to slightly more complex versions. --- [Blog | Pythian ](https://www.pythian.com/blog) # [Identifying SQL Execution Bottlenecks Scientifically](https://www.pythian.com/blog/identifying-sql-execution-bottlenecks-scientifically) Written by [Riyaj Shamsudeen](https://www.pythian.com/blog/author/riyaj-shamsudeen) | Apr 23, 2008 4:00:00 AM ## Background A few days ago, a developer and I had an interesting conversation. The developer was trying to tune an expensive SQL statement, using following trial-and-error method: ``` loop until acceptable performance explain plan -> execute SQL with sql trace -> tkprof -> rewrite end loop; ``` After looking at his method in amusement, I showed him how to identify and tune SQL statements scientifically, and decided to blog about it. Let’s look at a simple case and then proceed to slightly more complex versions. The following code fragment creates test tables, indices, and collects statistics on those tables. ``` create table t1_vc as select trunc(n/10000) n1, mod(n, 1000) n2 , lpad( n,255) c_filler from (select level n from dual connect by level <= 100001); create index t1_vc_i1 on t1_vc (n1); create table t2_vc as select trunc(n/ 100) n1, mod(n, 10000) n2 , lpad( n,255) c_filler from (select level n from dual connect by level null, cascade => true); exec dbms_stats.gather_table_stats(user, 't2_vc',estimate_percent => null, cascade => true); null, cascade => true); exec dbms_stats.gather_table_stats(user, 't2_vc',estimate_percent => null, cascade => true); ``` Simple SQL, but I had to use hints to illustrate the point I’m driving at. Let’s do an explain plan on this SQL. ``` ------------------------------------------------------------------------------------------ ``` The execution plan looks okay, but this statement is executed millions of times, so we need to reduce time as much as possible. Can this SQL be tuned further? ## Statistics_level Enter the `statistics_level` parameter, available from Oracle version 9i onwards. Step-level execution statistics are printed at each step if this parameter is set to all. Using this method to tune an SQL, identify the step taking the most time and reduce time in that step or completely eliminate it. The `statistics_level` parameter is session-modifiable and set to all to print more statistics in the trace file. (My recommendation is not to modify this parameter at instance or database level without extensive testing.) Let’s enable trace and `statistics_level` parameter in our session, followed by `tkprof`. Event 10046 is used to enable SQL trace. Other methods can be used to turn on SQL trace as well. ``` alter session set events '10046 trace name context forever, level 12'; alter session set statistics_level=all; select /*+ use_nl (t1_vc, t2_vc ) */ t1_vc.n1 , t2_vc.n2 from t1_vc, t2_vc where t1_vc.n1 = t2_vc.n1 and t1_vc.n2 between 101 and 105 and t1_vc.n1=1; tkprof orcl11g_ora_2988.trc orcl11g_ora_2988.trc.out ``` The following lines are from the `tkprof` output file generated above. ``` ------- ------ -------- ---------- ---------- ---------- ---------- ---------- ``` Let me explain this output. The execution plan printed above has a time component and shows how time is accumulated in each step. At step (1), 21970 microseconds are consumed, followed by step (2) at which the cumulative time consumption is 117,421 microseconds. At step (3), a nested loops join between row sources at step (2) and step (4), consumed a cumulative time of 175,734 microseconds. Also, note that step (4) contributed to a time consumption of 35,440 microseconds. In essence, cumulative time consumption is printed at parent nodes and time consumption at that step is printed in the leaf nodes of the execution tree. To tune this SQL, we need to look for the step with the biggest jump in time consumption, or the step that consumes a lot of time, then reduce or eliminate time spent in that step. Let’s examine the following few lines. ``` 50 TABLE ACCESS BY INDEX ROWID T1_VC (cr=482 pr=0 pw=0 time=117421 us cost=368 size=385 card=55) (2) 10000 INDEX RANGE SCAN T1_VC_I1 (cr=48 pr=0 pw=0 time=21970 us cost=18 size=0 card=9091)(object id 71043) (1) ``` At step (1) Index `t1_vc_i1` is scanned for rows with `n1=1` and 10,000 rows are returned. It took 21,970 microseconds in that step. The next step (2), accesses table block using rowids returned from the index. The cumulative time consumption jumped from 21,970 microseconds to 117,421 microseconds. This is a costlier step and to tune this SQL, we need to consider tuning these two steps first. Now, we have scientifically identified which step needs to be tuned. Note that step (1) fetched 10,000 rows. Step (2) is to access `t1_vc` table and 50 rows were retrieved in. In summary, 10,000 rows were returned scanning the index, and 9050 rows filtered out after accessing the table block. There seems to be quite a waste here. Is it possible to apply that filter in accessing the index itself? We need to add an index so that filtering can be done more efficiently at the index block itself. The rest is easy, we can add index on `n2` and `n1`. ``` create index t1_vc_i2 on t1_vc (n2,n1); exec dbms_stats.gather_table_stats(user, 't1_vc',estimate_percent => null, cascade => true); ``` The explain plan printed below and new index shows up in step (3) below. ``` ----------------------------------------------------------------------------------------- ``` Tracing with `statisics_level=all` again, shows that we have reduced time spent in that step. ``` ------- ------ -------- ---------- ---------- ---------- ---------- ---------- ``` In a nutshell, if you must tune SQL, use `statistics_level` and understand where the bottleneck is. Remove or tune that bottleneck to tune the SQL. ## More complex scenarios As the complexity of SQL increases (as in real world), this method is very useful. Consider the following query: using the time column printed in this explain plan, you could guess that the step with id (7) is consuming much time. But that could be wrong, since the explain plan is printing estimates from the CBO, not actual execution statistics. Execution plans with numerous table joins have incorrect cardinality estimates and so, any knowledge gained from the explain plan alone is not that useful. Even autotrace suffers from a few such issues. ``` ------------------------------------------------------------------------------------------------ ``` But let’s look at the step level timing information printed below. The second nested loop branch consumed 53 seconds (as against 3 minutes and 47 seconds in the plan printed above) and the `UNION ALL` step consumed 58 seconds. So, to tune this SQL, we need to find ways to eliminate waste or improve efficiency of operation. ``` ------- ------ -------- ---------- ---------- ---------- ---------- ---------- ``` ## Issues Of course, in a few situations, this method doesn’t provide the complete picture. 1. If time is spent in the column list, then these numbers are not accurate. In the example below, this SQL consumed over 150 seconds, but that is not reflected correctly in the plan. It seems as though this happens if time is spent in function calls from a `select` list. ``` ------- ------ -------- ---------- ---------- ---------- ---------- ---------- ``` 2. It is not possible to turn on the `statistics_level` parameter on an already-executing session. 3. If the SQL execution time is very small, then this parameter doesn’t print step level information correctly. If you want to read this in a document format, use this link: [how to tune sql statements scientifically](https://orainternals.wordpress.com/files/2008/04/tuning-statements-scientifically.pdf). ## Oracle Database Consulting Services Ready to optimize your Oracle Database for the future?   [View full post](https://www.pythian.com/blog/identifying-sql-execution-bottlenecks-scientifically) ```json { "@context" : "http://schema.org", "@type" : "BlogPosting", "author" : { "@type" : "Person", "name" : "Riyaj Shamsudeen" }, "dateModified" : "2026-03-21T05:42:13.010Z", "datePublished" : "2008-04-23T04:00:00Z", "headline" : "Identifying SQL Execution Bottlenecks Scientifically", "image" : { "@type" : "ImageObject", "height" : 60, "url" : "/hs/hsstatic/content_shared_assets/static-1.4092/img/default-amp-logo.png", "width" : 60 }, "mainEntityOfPage" : "https://www.pythian.com/blog/identifying-sql-execution-bottlenecks-scientifically", "publisher" : { "@type" : "Organization", "logo" : { "@type" : "ImageObject", "height" : 60, "url" : "/hs/hsstatic/content_shared_assets/static-1.4092/img/default-amp-logo.png", "width" : 60 }, "name" : "Pythian Blog" } } ```