Saturday, January 10, 2009

Recursive SQL statement: update seq$

Last Friday, one of our production database experienced slowness in about 1 hours time period. During that period of time, there were 60+ blocking sessions. One of the blocking session was issuing the following statment:


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 looks like having somthing to do with the sequences. Our team leader suggested that we should increase the cache size for two relevant sequences to proactively avoid the problem. I acutally opened a SR with Oracle, asking what this statment is doing. But they did not give direct answer to this specific question so far. On the other hand, the guy suggested we should increase the log file size to reduce "log file sync" wait event, which appears at the top of the wait event in our statspack report. His suggestions is obviously nonsense. He must have no idea about what "log file sync" wait event is. I am disappointed with the support.

To understand this update statment, I did a test today. I created a table T and a sequence T_SEQ:



labadmin@DB10G> desc t;
Name Null? Type
------------------------- -------- ------------------------------------
ID NUMBER
VALUE VARCHAR2(20)

labadmin@DB10G> select * from user_sequences;

SEQUENCE_NAME MIN_VALUE MAX_VALUE INCREMENT_BY C O CACHE_SIZE LAST_NUMBER
--------------------- ---------- ---------- ------------ - - ---------- -----------
T_SEQ 1 1.0000E+27 1 N N 20 904821



 

Then I have 20 sessions repeatedly executing the following insert statment simutaneouly:

isnert into t values(t_seq.nextval, 'xxxx');

I can observe there is one blocking sessions from time to time, for example:


Lock Time Held
SID Lock Type Requested Lock Held (minutes) Block
------ --------- --------- --------- --------- -----
126 SQ None Exclusive 0 Yes
99 SQ Exclusive None 0 No
124 SQ Exclusive None 0 No
123 SQ Exclusive None 0 No
128 SQ Exclusive None 0 No
158 SQ Exclusive None 0 No
109 SQ Exclusive None 0 No
159 SQ Exclusive None 0 No
130 SQ Exclusive None 0 No
114 SQ Exclusive None 0 No
131 SQ Exclusive None 0 No
....k



I traced one of the 20 sessions, found that:



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 561 0.03 0.05 0 0 0 0
Execute 561 2.04 8.81 0 561 1132 561
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1122 2.07 8.87 0 561 1132 561

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

Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE SEQ$ (cr=1 pr=0 pw=0 time=339 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=40 us)(object id 102)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: undo global data 2 0.00 0.00
latch: library cache 1 0.01 0.01
log buffer space 8 1.00 6.39
latch: library cache pin 2 0.10 0.10
********************************************************************************

INSERT INTO T
VALUES
(T_SEQ.NEXTVAL, :B1 )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 9026 8.51 351.24 0 211 21192 9026
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9026 8.51 351.24 0 211 21192 9026

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 102 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: SQ - contention 775 3.07 258.38
latch: enqueue hash chains 6 0.03 0.06
log buffer space 38 1.36 21.72
latch: library cache pin 3 0.01 0.01
latch free 12 0.40 1.52
free buffer waits 1717 0.08 25.67
latch: library cache 10 0.15 0.62
latch: In memory undo latch 8 1.27 2.56
latch: redo copy 6 0.33 0.41
buffer busy waits 19 0.98 4.37
latch: undo global data 4 0.07 0.09
enq: FB - contention 2 0.82 0.98
enq: TX - contention 2 0.22 0.22
enq: HW - contention 2 0.45 0.45
latch: session allocation 1 0.00 0.00
********************************************************************************



 

So it can be seen that the "update seq$ ..." statement is a recursive sql issued by Oracle sys user to update dictionary table about sequence.

I did a further test:

I set the cache of t_seq to be 20, and I trace the session when executing following statement:

insert into t
select t_seq.nextval, 'qqq' from all_objects where rownum <=100;

I found the 'update seq$' statment executed 5 times.

Then I set the cache of t_seq to be 50, I found the 'update seq$' executed 2 time.

Thus, it looks like that every time that the cached sequence number is used up, Oracle should do the caching again and issue this statment to update dictionary table.

2 comments:

Raining Phoenix Tree said...

Hi,is this issue resolved and can you please let me know.

yds said...

Yes, resolved by increasing sequences cache sizes