Performance issues with the Sequence NEXTVAL call

by Simon Pane on Dec 18, 2014 12:00:00 AM

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):

Cache Size	No Trace	10046 level 8	10046 level 12
0	31.94	58.71	94.57
20	7.53	15.29	20.13
100	4.85	13.36	13.50
1000	3.93	10.61	11.93
10000	3.70	10.96	12.20

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.

No Comments Yet

Let us know what you think

Share this