Performance issues with the Sequence NEXTVAL call

Is SELECTing from a sequence your Oracle Performance Problem? The answer to that question is: it might be!

You wouldn’t expect a sequence select to be a significant problem but recently we saw that it was—and in two different ways. The issue came to light when investigating a report performance issue on an Oracle 11.2.0.4 non-RAC database. Investigating the original report problem required an AWR analysis and a SQL trace (actually a 10046 level 12 trace – tracing the bind variables was of critical importance in troubleshooting the initial problem with the report).

First problem: if SQL_ID = 4m7m0t6fjcs5x appears in the AWR reports

SELECTing a sequence value using the NEXTVAL function is supposed to be a fairly lightweight process. The sequence’s last value is stored in memory and a certain definable number of values are pre-fetched and cached in memory (default is CACHE=20). However when those cached values are exhausted the current sequence value must be written to disk (so duplicate values aren’t given upon restarts after instance crashes). And that’s done via an update on the SYS.SEQ$ table. The resulting SQL_ID and statement for this recursive SQL is:

SQL_ID   = 4m7m0t6fjcs5x

SQL Text = update seq$ set increment$=:2, minvalue=:3, maxvalue=:4, cycle#=:5, order$=:6,
           cache=:7, highwater=:8, audit$=:9, flags=:10 where obj#=:1

This is recursive SQL and consequently it and the corresponding SQL_ID is consistent between databases and even between Oracle versions.

Hence seeing SQL_ID 4m7m0t6fjcs5x as one of the top SQL statements in the AWR report indicates a possible problem. In our case it was the #1 top statement in terms of cumulative CPU. The report would select a large number of rows and was using a sequence value and the NEXTVAL call to form a surrogate key.

So what can be done about this? Well like most SQL tuning initiatives one of the best ways to tune a statement is to run it less frequently. With SQL_ID 4m7m0t6fjcs5x that’s easy to accomplish by changing the sequence’s cache value.

In our case, seeing SQL_ID 4m7m0t6fjcs5x as the top SQL statement quickly lead us to check the sequence settings and saw that almost all sequences had been created with the NOCACHE option. Therefore no sequence values were being cached and an update to SEQ$ was necessary after every single NEXTVAL call. Hence the problem.

Caching sequence values adds the risk of skipped values (or a sequence gap due to the loss of the cached values) when the instance crashes. (Note, no sequence values are lost when the database is shutdown cleanly.)  However in this case, since the sequence is just being used as a surrogate key this was not a problem for the application.

Changing the sequences CACHE setting to 100 completely eliminated the problem, increased the overall report performance, and removed SQL_ID 4m7m0t6fjcs5x from the list of top SQL in AWR reports.

Lesson learned: if you ever see SQL_ID 4m7m0t6fjcs5x in any of the top SQL sections in an AWR or STATSPACK report, double check the sequence CACHE settings.

Next problem: significant overhead of tracing the sequence update

Part of investigating a bind variable SQL regression problem with the report required a SQL trace. The report was instrumented with:

alter session set events '10046 trace name context forever, level 12';

The tracing made the report run over six times longer. This caused the report to overrun it’s allocated execution window and caused other job scheduling and SLA problems.

Normally we’d expect some overhead of a SQL trace due to the synchronous writes to the trace file, but over a 500% increase was far more than expected. From the developer’s viewpoint the report was essentially just executing a single query. The reality is that it was slightly more complicated than that as the top level query accessed a view. Still the view was not overly complex and hence the developer believed that the report was query intensive. Not executing many queries: just the original top level call and the view SQL.

Again the issue is largely related to the sequence, recursive SQL from the sequence, and specifically statement 4m7m0t6fjcs5x.

Starting with an AWR SQL report of SQL_ID 4m7m0t6fjcs5x from two report executions, one with and one without SQL trace enabled showed:

Without tracing:
Elapsed Time (ms):      278,786
CPU Time (ms):          278,516
Executions:             753,956
Buffer Gets:          3,042,991
Disk Reads:                   0
Rows:                   753,956

With tracing:
Elapsed Time (ms):    2,362,227
CPU Time (ms):        2,360,111
Executions:             836,182
Buffer Gets:          3,376,096
Disk Reads:                   5
Rows:                   836,182

So when the report ran with tracing enabled it ran 4m7m0t6fjcs5x 836K times instead of 753K times during the previous non-traced run: a 10.9% increase due to underlying application data changes between the runs. Yet 2.36M ms vs 278K ms in both CPU and elapsed times: a 847% increase!

The question was then: could this really be due to the overhead of tracing or something else? And should all of those recursive SQL update statements materialize as CPU time in the AWR reports? To confirm this and prove it to the developers a simplified sequence performance test was performed on a test database:

The simplified test SQL was:

create sequence s;
declare
   x integer;
begin
   for i in 1 .. 5000000
   loop
      x := s.nextval;
   end loop;
end;
/

From AWR SQL reports on SQL_ID 4m7m0t6fjcs5x:

Without tracing:

Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                            10,259            0.0     7.1
CPU Time (ms)                                 9,373            0.0     6.7
Executions                                  250,005            N/A     N/A
Buffer Gets                                 757,155            3.0    74.1
Disk Reads                                        0            0.0     0.0
Parse Calls                                       3            0.0     0.3
Rows                                        250,005            1.0     N/A


With tracing:

Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                            81,158            0.3    20.0
CPU Time (ms)                                71,812            0.3    17.9
Executions                                  250,001            N/A     N/A
Buffer Gets                                 757,171            3.0    74.4
Disk Reads                                        0            0.0     0.0
Parse Calls                                       1            0.0     0.1
Rows                                        250,001            1.0     N/A

Same number of executions and buffer gets as would be expected but 7.66 times the CPU and 7.91 times the elapsed time just due to the SQL trace!  (Similar results to the 8.47 times increase we saw with the actual production database report execution.)

And no surprise, the resulting trace file is extremely large. As we would expect, since the sequence was created with the default CACHE value of 20 it’s recording each UPDATE with the set of binds followed by 20 NEXTVAL executions:

=====================
PARSING IN CURSOR #140264395012488 len=100 dep=0 uid=74 oct=47 lid=74 tim=1418680119565405 hv=152407152 ad='a52802e0' sqlid='dpymsgc4jb33h'
declare
   x integer;
begin
   for i in 1 .. 5000000
   loop
      x := s.nextval;
   end loop;
end;
END OF STMT
PARSE #140264395012488:c=0,e=256,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1418680119565401
=====================
PARSING IN CURSOR #140264395008592 len=26 dep=1 uid=74 oct=3 lid=74 tim=1418680119565686 hv=575612948 ad='a541eed8' sqlid='0k4rn80j4ya0n'
Select S.NEXTVAL from dual
END OF STMT
PARSE #140264395008592:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3499163060,tim=1418680119565685
EXEC #140264395008592:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3499163060,tim=1418680119565807
=====================
PARSING IN CURSOR #140264395000552 len=129 dep=2 uid=0 oct=6 lid=0 tim=1418680119566005 hv=2635489469 ad='a575c3a0' sqlid='4m7m0t6fjcs5x'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1
END OF STMT
PARSE #140264395000552:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1935744642,tim=1418680119566003
BINDS #140264395000552:
 Bind#0
  oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=a52eb120  bln=22  avl=02  flg=09
  value=1
 Bind#1
  oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=a52eb132  bln=22  avl=02  flg=09
  value=1
 Bind#2
  oacdty=02 mxl=22(15) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=a52eb144  bln=22  avl=15  flg=09
  value=9999999999999999999999999999
 Bind#3
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=7f91d96ca6b0  bln=22  avl=01  flg=05
  value=0
 Bind#4
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=7f91d96ca6c8  bln=22  avl=01  flg=01
  value=0
 Bind#5
  oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=a52eb156  bln=22  avl=02  flg=09
  value=20
 Bind#6
  oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=a52eb168  bln=22  avl=05  flg=09
  value=5000021
 Bind#7
  oacdty=01 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=178 siz=32 off=0
  kxsbbbfp=a52eb17a  bln=32  avl=32  flg=09
  value="--------------------------------"
 Bind#8
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=7f91d96ca668  bln=22  avl=02  flg=05
  value=8
 Bind#9
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=7f91d96ca680  bln=22  avl=04  flg=01
  value=86696
EXEC #140264395000552:c=1000,e=798,p=0,cr=1,cu=2,mis=0,r=1,dep=2,og=4,plh=1935744642,tim=1418680119566897
STAT #140264395000552 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  SEQ$ (cr=1 pr=0 pw=0 time=233 us)'
STAT #140264395000552 id=2 cnt=1 pid=1 pos=1 obj=79 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=23 us cost=0 size=69 card=1)'
CLOSE #140264395000552:c=0,e=3,dep=2,type=3,tim=1418680119567042
FETCH #140264395008592:c=1000,e=1319,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,plh=3499163060,tim=1418680119567178
STAT #140264395008592 id=1 cnt=1 pid=0 pos=1 obj=86696 op='SEQUENCE  S (cr=1 pr=0 pw=0 time=1328 us)'
STAT #140264395008592 id=2 cnt=1 pid=1 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=1 us cost=2 size=0 card=1)'
CLOSE #140264395008592:c=0,e=1,dep=1,type=3,tim=1418680119567330
EXEC #140264395008592:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3499163060,tim=1418680119567378
FETCH #140264395008592:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=3499163060,tim=1418680119567425
CLOSE #140264395008592:c=0,e=1,dep=1,type=3,tim=1418680119567458
...
< Repeats #140264395008592 18 more times due to CACHE=20 >

From the trace, it’s apparent that not only is there the overhead of updating the SEQ$ table but maintaining the I_SEQ1 index as well. A tkprof on the test shows us the same information:

declare
   x int;
begin
   for i in 1..5000000 loop
      x := s.nextval;
   end loop;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1    241.55     247.41          0     250003          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2    241.56     247.41          0     250005          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 74

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.01          0.01
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

SQL ID: 0k4rn80j4ya0n Plan Hash: 3499163060

Select S.NEXTVAL
from
 dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 5000000     35.37      30.49          0          0          0           0
Fetch   5000000     50.51      45.81          0          0     250000     5000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   10000001     85.88      76.30          0          0     250000     5000000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 74     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SEQUENCE  S (cr=1 pr=0 pw=0 time=910 us)
         1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch free                                      1        0.00          0.00
********************************************************************************

SQL ID: 4m7m0t6fjcs5x Plan Hash: 1935744642

update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,
  cache=:7,highwater=:8,audit$=:9,flags=:10
where
 obj#=:1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute 250000     71.81      81.15          0     250003     507165      250000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   250000     71.81      81.15          0     250003     507165      250000

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  log file switch (checkpoint incomplete)         1        0.19          0.19
  log file switch completion                      4        0.20          0.75
********************************************************************************

So clearly we can see a lot of additional overhead when performing a SQL trace of the many calls to the sequence NEXTVAL function. Of course the overhead is due to recursive SQL and the synchronous write of the trace file. It just wasn’t obvious that a simple query could generate that much recursive DML and trace data.

Combining the two issues

The next question is what is the effect of the CACHE setting for the sequence as well as the different between a LEVEL 8 and LEVEL 12 trace. Using a similar PL/SQL test block but with only 100,000 executions on a lab database showed the following results measuring CPU time (in seconds):

Hence we can see that with even an extremely high CACHE setting for the sequence, the 10046 trace adds roughly 300% to 400% overhead for this one particular statement. And that the caching sweet-spot seems to be around 100.

Conclusions

We often take the Oracle sequence for granted assume that it’s an optimized and efficient internal structure—and for the most part it is. But depending on how it’s implemented, it can be problematic.

If we ever see SQL_ID 4m7m0t6fjcs5x as one of our worst performing SQL statements, we should double check the sequence configuration and usage. Was the CACHE value set low by design, or inadvertently? Is the risk of a sequence gap after an instance crash worth the overhead of a low CACHE value? Perhaps the settings need to be reconsidered and changed?

And a caution about enabling a SQL trace. It’s something we expect to add some overhead. But not 3x to 10x which may make the tracing process unreasonable.  Of course the tracing overhead will be dependent on the actual workload.  But for those that are sequence NEXTVAL heavy, don’t underestimate the underlying recursive SQL as the overhead can be significant—and much more than one may think.