Bugs

Oracle Clusterware / ASM 11.1.0.7: ASM Instance crash

By | October 28th, 2009 | Category: 11g, Bugs, Linux, MetaLink, Oracle Database, Solaris, Unix | No Comments »

During a 11gR1 Clusterware installation for a Single Instance Failover Cluster at a customer site, I have experienced an interesting behaviour, which was caused by an Oracle Bug.

The environment was:

  • 2 Node Oracle Clusterware 11.1.0.7 Cluster on Linux x86_64 using latest Recommended Patches as of October 19th. (pre PSU 11.1.0.7.1)
  • Clusterware installed as unix user crs
  • ASM installed as unix user oracle

The ASM instances could be started with SQL*Plus without any problems, but if the ASM instances were started by means of clusterware using srvctl (either from root, crs or oracle) the  ASM instances would crash at diskgroup mount with:

ORA-07445: exception encountered: core dump  [sskgds_find_rtn_hdr()+1171]
[SIGBUS] [ADDR:0x2AACD701342C] [PC:0x25799DF]
[Non-existent physical address] []

Oracle Support identified this behaviour as Bug 6952915, for which there are patches for Linux x86, x86_64 and Solaris Sparc64.


High CPU Utilization – waits on cursor: pin S

By | August 11th, 2009 | Category: 10g, Bugs, MetaLink, Oracle Database | No Comments »

I have recently encountered a problem at a customer site, where the database instances resource utilization was so high that the application did not work anymore. Version was 10.2.0.4 on Linux with Oracle Recommended Generic Patches installed.

Unfortunately, the customer decided to bounce the instance, so that there is no possibility for intensive diagnosis. However, ASH report shows that a dozen sessions either waited on Wait event “cursor: pin S” or were active (ON CPU) without any SQL_ID. An AWR Report showed:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
cursor: pin S                   140,036,615      24,833      0 ######      Other
CPU time                                             19          72.9
log file sync                         8,767           8      1   30.2     Commit
log file parallel write               9,039           8      1   29.9 System I/O
control file parallel write           1,269           5      4   20.2 System I/O

Oracle Support confirmed that this is Bug 6904068 High CPU usage when there are “cursor: pin S” waits. We have filed a backport request for it, as there is no patch for our platform available yet.


Default 10gR2 RAC TNS Configuration can cause TCP Timeouts for application

By | May 12th, 2009 | Category: 10g, Bugs, Oracle Database, Real Application Clusters, Unix | No Comments »

The default RAC installation does normally not set “local_listener” init.ora parameter. If the listener is running on port 1521, then the database does not need the parameter in order to find and register with the local TNS listener process. However, if you have *not* set local_listener, it means that the database registers at the listener with the physical IP address instead of the virtual (vip) address.

You can determine if this happens when you take a look at “lsnrctl serv” output from your rac nodes:

Service "S_APP" has 1 instance(s).
  Instance "MDDB1", status READY, has 2 handler(s) for this service...
    Handler(s):
      "DEDICATED" established:0 refused:0 state:ready
         REMOTE SERVER
         (ADDRESS=(PROTOCOL=TCP)(HOST=ora-vm1.intra)(PORT=1521))

Instead of ora-vm1.intra, this should be ora-vm1-vip.intra.

Why should I care?

If you use the default configuration, then you are using the parameter “REMOTE_LISTENER” and therefore Server Side Connect Time Load Balancing. This means, that the listeners of all nodes receive load information from all instances of all nodes and they can redirect connections to the least loaded instance, even if the instance is on another node. But the connect string they then send back to the client contains the physical IP address instead of the virtual.

In case of node crashes or kernel panics, etc. the client has to wait for the TCP timeout until this is detected.

Solution

tnsnames.ora:

LISTENER_MDDB1 =
  (ADDRESS_LIST =
    (ADDRESS = (PROTOCOL = TCP)(HOST = ora-vm1-vip.intra)(PORT = 1521))
  )

LISTENER_MDDB2 =
  (ADDRESS_LIST =
    (ADDRESS = (PROTOCOL = TCP)(HOST = ora-vm2-vip.intra)(PORT = 1521))
  )


init.ora:
alter system set local_listener = 'LISTENER_MDDB1' sid='MDDB1';
alter system set local_listener = 'LISTENER_MDDB2' sid='MDDB2';

Your experience with RAC Dynamic Remastering (DRM) in 10gR2?

By | May 12th, 2009 | Category: 10g, Bugs, Linux, Linux Itanium, Oracle Database, Performance Tuning, Real Application Clusters, Unix | 5 comments

One of my customers is having severe RAC performance issues, which appeared a dozen times so far. Each time, the performance impact lasted around 10 minutes and caused basically a hang of the application. ASH investigation revealed that the time frame of performance issues exactly matches a DRM operation of the biggest segment of the database. During the problematic time period, there are 20-50 instead of 5-10 active sessions and they are mostly waiting for gc related events: “gc buffer busy”,”gc cr block busy”, “gc cr block 2-way”, “gc current block 2-way”, “gc current request”, “gc current grant busy”, etc.

In addition, there is one single session which has wait event “kjbdrmcvtq lmon drm quiesce: ping completion” (on instance 1) and 1-3 sessions with wait event “gc remaster“. (on instance 2) The cur_obj# of the session waiting on “gc remaster” is pointing to the segment being remastered.

Does anybody have any experience with DRM problems with 10.2.0.4 on Linux Itanium?

I know that it is possible to deactive DRM, but usually it should be beneficial to have it enabled. I could not find any reports of performance impact during DRM operation on metalink. Support is involved but clueless so far.

Regards,
Martin

http://forums.oracle.com/forums/message.jspa?messageID=3447436#3447436


RAC Deadlock Detection not working on 10.2.0.4 / Linux Itanium

By | May 12th, 2009 | Category: 10g, Bugs, Linux Itanium, Oracle Database | 4 comments

We recently experienced a big issue, when the production database was hung. It turned out that the database has deadlocked, but the GES did not detect the deadlock situation, so all the sessions were waiting on “enq: TX row lock contention”.

We could provide a reproducible testcase and it turned out to be bug 7014855. The bug is platform specific to Linux Itanium port and a patch is available.


Monitoring Index Usage not reliable in 10.2.0.4

By | May 12th, 2009 | Category: 10g, Bugs, Oracle Database | 3 comments

I recently had to analyze a system in respect of index utilization. The application has dozens of indexes and we have to find out, which ones are really needed and which ones are candidates for removal.

There is a nice feature, called Index Monitoring which switches a flag if the index is used.

1

ALTER INDEX schema.index MONITORING USAGE;

Internally, a recursive SQL Statement is executed for every parsing of a SQL:

1

UPDATE object_usage SET flags=flags+1 WHERE obj#=:1 AND bitand(flags, 1)=0;

To check whether the index was used, you can query the view v$object_usage. Unfortunately, the view definition contains a where clause to list only indexes of the current schema.

1

   WHERE    io.owner# = userenv('SCHEMAID')

Therefore, you can create a new view or just omit the limitation from the where clause:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

 CREATE OR REPLACE VIEW V$ALL_OBJECT_USAGE 
         (OWNER,
         INDEX_NAME, 
         TABLE_NAME, 
         MONITORING, 
         USED, 
         START_MONITORING, 
         END_MONITORING) 
         AS 
           SELECT u.name, io.name, t.name, 
           decode(bitand(i.flags, 65536), 0, 'NO', 'YES'), 
           decode(bitand(ou.flags, 1), 0, 'NO', 'YES'), 
           ou.start_monitoring, 
           ou.end_monitoring 
         FROM sys.user$ u, sys.obj$ io, sys.obj$ t, sys.ind$ i, sys.object_usage ou 
         WHERE i.obj# = ou.obj# 
         AND io.obj# = ou.obj# 
         AND t.obj# = i.bo#
         AND u.user# = io.owner#

However, what is less known is that the DBMS_STATS can in some cases manipulate these flags. The issue is tracked with “Bug 6798910 – DBMS_STATS or EXPLAIN PLAN trigger index usage monitoring”. If you are using 10.2.0.4 and you are gathering stats manually with “CASCADE=>TRUE”, then the monitoring flag is set to “YES”. Obviously, in this case you can not identify candidate indexes for removal.


Oracle RAC 10.2.0.4 bug when adding/dropping redo log groups

By | April 23rd, 2009 | Category: 10g, Bugs, MetaLink, Oracle Database | No Comments »

On the oracle-l list, there was a post about a nasty bug in Oracle RAC 10.2.0.4 which can cause LGWR errors, instance failures and redo log corruptions.

The bug occurs if you add/remove redo log groups on a cluster database, which has some of it´s instances shut down.

More information about this Bug, which is tracked with Bug ID 6786022 can be found on MetaLink. There is a patch for 10.2.0.4 and Linux x86-64 available.


ASSM Problem with too low PCTFREE

By | April 9th, 2009 | Category: 10g, 11g, Bugs, MetaLink, Oracle Database | 3 comments

During the Hotsos Symposium 2009 Training Day, Jonathan Lewis presented a problem which appears even on current 10g/11g databases. What is especially interesting is how this issue can be diagnosed. I reproduced the problem in 11.1.0.7 and will provide the steps you can use to verify. The problem can be demonstrated best when comparing response time of an update statement for 8k blocksize and 16k blocksize.

  • 8k Blocksize

    • SQL> DROP TABLE t1_8k purge;
 
SQL> CREATE TABLESPACE DEMO8K datafile SIZE 128M blocksize 8192;
 
TABLESPACE created.
 
Elapsed: 00:00:07.35
 
SQL> CREATE TABLE mdecker.t1_8k
(n1 NUMBER,
 n2 NUMBER)
 TABLESPACE DEMO8K;
 
TABLE created.
 
Elapsed: 00:00:00.02
 
SQL> INSERT INTO t1_8k
SELECT TRUNC(dbms_random.VALUE(10000000,100000000)) n1,
           TO_NUMBER(NULL) AS n2
    FROM dual
CONNECT BY LEVEL <= 500000
/
 
 
500000 ROWS created.
 
Elapsed: 00:00:06.89
 
SQL> BEGIN dbms_stats.gather_table_stats(
        ownname => 'MDECKER',
        tabname => 'T1_8K',
        estimate_percent => 100);
END;
/
 
PL/SQL PROCEDURE successfully completed.
 
Elapsed: 00:00:02.13
 
SQL> SELECT num_rows,blocks FROM dba_tables WHERE table_name = 'T1_8K';
 
  NUM_ROWS     BLOCKS
---------- ----------
    500000        874
 
Elapsed: 00:00:00.15
SQL> UPDATE t1_8k SET n2 = n1;
 
500000 ROWS updated.
 
Elapsed: 00:01:09.04
SQL> COMMIT;

  • 16k Blocksize

    • SQL> CREATE TABLESPACE DEMO16K datafile SIZE 128M blocksize 16384;
 
TABLESPACE created.
 
Elapsed: 00:00:14.75
 
SQL> CREATE TABLE mdecker.t1_16k
(n1 NUMBER,
 n2 NUMBER)
 TABLESPACE DEMO16K;
 
TABLE created.
 
Elapsed: 00:00:00.03
 
SQL> INSERT INTO t1_16k
SELECT TRUNC(dbms_random.VALUE(10000000,100000000)) n1,
           TO_NUMBER(NULL) AS n2
    FROM dual
CONNECT BY LEVEL <= 500000
/  
 
 
500000 ROWS created.
 
Elapsed: 00:00:05.51
SQL> BEGIN dbms_stats.gather_table_stats(
        ownname => 'MDECKER',
        tabname => 'T1_16K',
        estimate_percent => 100);
END;
/  
 
PL/SQL PROCEDURE successfully completed.
 
Elapsed: 00:00:01.78
SQL> SELECT num_rows,blocks FROM dba_tables WHERE table_name = 'T1_16K';
 
  NUM_ROWS     BLOCKS
---------- ----------
    500000        436
 
Elapsed: 00:00:00.07
 
SQL>  UPDATE t1_16k SET n2 = n1;
 
500000 ROWS updated.
 
Elapsed: 00:20:20.89

    As you can see, the update statement for the 8k blocksize table took around 69 seconds whereas the same update for the table in the 16k tablespace took more than 20 minutes. When executing oradebug short_stack, you can see that for the 16k update, the stacktrace is similar for many executions. So, a lot of time is spent in the kernel functions ktspfsrch() and ktspscan_bmb().


    SQL> oradebug setospid 23668
    Oracle pid: 18, Unix process pid: 23668, image: oracle@ora-vm1.intra (TNS V1-V3)
    SQL> oradebug short_stack
    .....ktspfsrch()+559<-ktspscan_bmb()+315 .....
    SQL> oradebug short_stack
    .....ktspfsrch()+559<-ktspscan_bmb()+315 .....
    SQL> oradebug short_stack
    .....ktspfsrch()+559<-ktspscan_bmb()+315 .....

    It is important to understand that the problem is not necessarily related to the blocksize, but to the PCTFREE value. More information about this topic can be found here:

    http://structureddata.org/files/jl_test_case.html
    http://structureddata.org/2008/09/08/understanding-performance/
    http://www.oraclealchemist.com/oracle/hey-guys-does-size-matter/


Intelligent (aka adaptive) Cursor Sharing Problem

By | March 12th, 2009 | Category: 11g, Bugs, MetaLink, Oracle Database | 4 comments

Today, at the last day of Hotsos Symposium 2009 Ric van Dyke presented on “Intelligent (aka adaptive) Cursor Sharing”, a new feature of Oracle Database 11g. The feature was created to fix the shortcomings of bind peeking on columns with histograms. Tom Kyte presented a few years ago on this topic when he talked about the impact of the wheather on Oracle database performance.

During the very interesting presentation Ric presented with a demo how this feature works but also showed a nasty side effect. He tested it on a million row table with a column “object type”, which was skewed. He bound several different values to the object_type bind variable causing 2 different execution plans to be used for the same sql_id. The problem with it was that he ended up with dozens of child cursors showing V$SQL.IS_SHARABLE => N.

It was not known whether this is a bug or whether the whole concept is flawed. I searched on metalink and found the appropriate document:

Bug 6644714 – High number of child cursors with adaptive cursor sharing
This issue is fixed in

* 11.2 (Future Release)
* 11.1.0.7 (Server Patch Set)
Lots of child cursors may be produced with adaptive cursor sharing enabled,
sometimes with overlapping or same bind value selectivity ranges (in v$sql_cs_selectivity).
This problem shows as LOAD_OPTIMIZER_STATS=’Y’ for many of the cursors in V$SQL_SHARED_CURSOR.

– and –

Bug 7213010 – Adaptive cursor sharing generates lots of child cursors

This issue is fixed in

* 11.2 (Future Release)
* 11.1.0.7 (Server Patch Set)

Lots of child cursors may be produced for a query with bind variables
appearing in at least two simple relational predicates
(eg. col :b).

v$sql_cs_selectivity shows that there are multiple equivalent / overlapping
ranges for a single cursor. The number of ranges gets bigger and bigger
as the query is run more times.

I then tried to verify if the problem indeed is gone in 11.1.0.7 and found out, that it isn´t.

Here is my testcase:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434

SQL> @/tmp/setup.sql
Connected.
SQL> DROP TABLE tab1 purge;
 
TABLE dropped.
 
SQL> CREATE TABLE tab1 (a INT,
  2                     b varchar2(20),
  3                                     padding varchar2(200))
  4  tablespace USERS;
 
TABLE created.
 
SQL>
SQL> DROP SEQUENCE myid;
 
SEQUENCE dropped.
 
SQL> CREATE SEQUENCE myid cache 1000;
 
SEQUENCE created.
 
SQL>
SQL> BEGIN
  2  FOR i IN 1..100000
  3  loop
  4          INSERT INTO tab1 VALUES (myid.nextval,
  5                                                           'AAAAAAAAAA',
  6                                                           rpad('*',200,'*'));
  7  END loop;
  8
  9  FOR i IN 1..1000
 10  loop
 11          INSERT INTO tab1 VALUES (myid.nextval,
 12                                                           'BBBBBBBBBB',
 13                                                           rpad('*',200,'*'));
 14  END loop;
 15
 16  FOR i IN 1..1000
 17  loop
 18          INSERT INTO tab1 VALUES (myid.nextval,
 19                                                           'CCCCCCCCCC',
 20                                                           rpad('*',200,'*'));
 21  END loop;
 22
 23  FOR i IN 1..100
 24  loop
 25          INSERT INTO tab1 VALUES (myid.nextval,
 26                                                           'DDDDDDDDDD',
 27                                                           rpad('*',200,'*'));
 28  END loop;
 29
 30  FOR i IN 1..10
 31  loop
 32          INSERT INTO tab1 VALUES (myid.nextval,
 33                                                           'EEEEEEEEEE',
 34                                                           rpad('*',200,'*'));
 35  END loop;
 36
 37  INSERT INTO tab1 VALUES (myid.nextval,
 38                                                           'FFFFFFFFFF',
 39                                                           rpad('*',200,'*'));
 40
 41  commit;
 42  END;
 43  /
 
PL/SQL PROCEDURE successfully completed.
 
SQL>
SQL> CREATE INDEX tab1_idx1 ON tab1 (b);
 
INDEX created.
 
SQL>
SQL> BEGIN dbms_stats.gather_table_stats(ownname => 'MDECKER',
  2                                          tabname => 'TAB1',
  3                                          method_opt =>'FOR ALL COLUMNS SIZE 254',
  4                                          cascade=> TRUE,
  5                                          estimate_percent => 100,
  6                                          no_invalidate => FALSE);
  7  END;
  8  /
 
PL/SQL PROCEDURE successfully completed.
 
SQL>
SQL> SET LINES 300
SQL> col TABLE_NAME format a10
SQL> col owner format a8
SQL> SELECT owner, TABLE_NAME,num_rows, blocks, round((blocks*8192)/1024/1024) AS MB
  2  FROM dba_tables WHERE TABLE_NAME = 'TAB1' AND owner = 'MDECKER';
 
OWNER    TABLE_NAME   NUM_ROWS     BLOCKS         MB
-------- ---------- ---------- ---------- ----------
MDECKER  TAB1           102111       3268         26
 
SQL>
SQL> prompt "Press Enter to continue"
"Press Enter to continue"
SQL> pause
 
SQL>
SQL> /*
SQL> OWNER       TABLE_NAME   NUM_ROWS  BLOCKS         MB
SQL> -------- ---------- ---------- ---------- ----------
SQL> MDECKER  TAB1           102111       3268         26
SQL>
SQL> */
SQL>
SQL>
SQL>
SQL> SELECT b , COUNT(*) FROM mdecker.tab1 GROUP BY b ORDER BY 1 DESC;
 
B                      COUNT(*)
-------------------- ----------
FFFFFFFFFF                    1
EEEEEEEEEE                   10
DDDDDDDDDD                  100
CCCCCCCCCC                 1000
BBBBBBBBBB                 1000
AAAAAAAAAA               100000
 
6 ROWS selected.
 
SQL>
SQL> /*
SQL> B                      COUNT(*)
SQL> -------------------- ----------
SQL> FFFFFFFFFF                    1
SQL> EEEEEEEEEE                   10
SQL> DDDDDDDDDD                  100
SQL> CCCCCCCCCC                 1000
SQL> BBBBBBBBBB                 1000
SQL> AAAAAAAAAA               100000
SQL>
SQL> 6 rows selected.
SQL>
SQL> */
SQL>
SQL> prompt "Press Enter to continue"
"Press Enter to continue"
SQL> pause
 
SQL> SELECT num_buckets, histogram FROM dba_tab_col_statistics WHERE TABLE_NAME = 'TAB1' AND column_name = 'B';
 
NUM_BUCKETS HISTOGRAM
----------- ---------------
          6 FREQUENCY
 
SQL>
SQL> /*
SQL> NUM_BUCKETS HISTOGRAM
SQL> ----------- ---------------
SQL>           6 FREQUENCY
SQL> */
SQL>
SQL>
SQL>
SQL>
SQL>
SQL> SHOW USER
USER IS "MDECKER"
SQL> @/tmp/sql1.txt
SQL> SET LINES 300
SQL> SET echo ON
SQL> SET pages 10000
SQL> col bind format a120
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL>
SQL> variable myvar varchar2(20)
SQL> EXEC :myvar := 'AAAAAAAAAA';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 0
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 2211052296
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | ROWS  | Bytes | Cost (%CPU)| TIME     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   889 (100)|          |
|*  1 |  TABLE ACCESS FULL| TAB1 |   100K|    20M|   889   (1)| 00:00:11 |
--------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   1 - FILTER("B"=:MYVAR)
 
 
18 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
 
SQL>
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL> EXEC :myvar := 'BBBBBBBBBB';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 0
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 2211052296
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | ROWS  | Bytes | Cost (%CPU)| TIME     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   889 (100)|          |
|*  1 |  TABLE ACCESS FULL| TAB1 |   100K|    20M|   889   (1)| 00:00:11 |
--------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   1 - FILTER("B"=:MYVAR)
 
 
18 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
 
SQL>
SQL> EXEC :myvar := 'CCCCCCCCCC';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 1
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 1918680838
 
-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | ROWS  | Bytes | Cost (%CPU)| TIME     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |    36 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| TAB1      |  1000 |   210K|    36   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | TAB1_IDX1 |  1000 |       |     4   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - access("B"=:MYVAR)
 
 
19 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'CCCCCCCCCC', ANYDATA()))           1918680838            1
 
SQL>
SQL> EXEC :myvar := 'DDDDDDDDDD';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 2
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 1918680838
 
-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | ROWS  | Bytes | Cost (%CPU)| TIME     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     5 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| TAB1      |   100 | 21600 |     5   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | TAB1_IDX1 |   100 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - access("B"=:MYVAR)
 
 
19 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'CCCCCCCCCC', ANYDATA()))           1918680838            1
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'DDDDDDDDDD', ANYDATA()))           1918680838            2
 
SQL>
SQL> EXEC :myvar := 'EEEEEEEEEE';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 3
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 1918680838
 
-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | ROWS  | Bytes | Cost (%CPU)| TIME     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| TAB1      |    10 |  2160 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | TAB1_IDX1 |    10 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - access("B"=:MYVAR)
 
 
19 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'CCCCCCCCCC', ANYDATA()))           1918680838            1
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'DDDDDDDDDD', ANYDATA()))           1918680838            2
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'EEEEEEEEEE', ANYDATA()))           1918680838            3
 
SQL>
SQL> EXEC :myvar := 'FFFFFFFFFF';
 
PL/SQL PROCEDURE successfully completed.
 
SQL> prompt "Press enter to run"
"Press enter to run"
SQL> pause
 
SQL> SET termout off
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());
 
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------   -----------------------------------------------------------------
SQL_ID  fhtgpcv2m2j4s, child NUMBER 4
-------------------------------------
SELECT /* MD_TESTCASE */ * FROM tab1 WHERE b = :myvar
 
Plan hash VALUE: 1918680838
 
-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | ROWS  | Bytes | Cost (%CPU)| TIME     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| TAB1      |     1 |   216 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | TAB1_IDX1 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - access("B"=:MYVAR)
 
 
19 ROWS selected.
 
SQL> SELECT sql_id, is_obsolete, is_bind_sensitive, is_bind_aware, is_shareable, dbms_sqltune.extract_binds(bind_data) bind, plan_hash_value, child_number FROM
  2   v$sql WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------
fhtgpcv2m2j4s N Y N Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'CCCCCCCCCC', ANYDATA()))           1918680838            1
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'DDDDDDDDDD', ANYDATA()))           1918680838            2
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'EEEEEEEEEE', ANYDATA()))           1918680838            3
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'FFFFFFFFFF', ANYDATA()))           1918680838            4

You can see that after parsing for bind CCCCCCCC, the execution plan changes from full table scan to index range scan. Moreover child cursor 1 is marked “is_bind_aware=Y”. When now bind DDDDDDDD is used, there is a new child (#2) and child 1 is set to is_sharable=N. After using bind EEEEEEEE, child #2 is set to sharable=N and a new child #3 is created. This repeats until there are 5 child cursors, 2 of which are set to is_sharable=Y. When the script is executed multiple times, there is even a sixth child cursor.

1
2
3
4
5
6
7
8

SQL_ID        I I I I BIND(NAME, POSITION, DUP_POSITION, DATATYPE, DATATYPE_STRING, CHARACTER_SID, PRECISION, SCALE, MAX_LENGTH, LAST_CAPTURED PLAN_HASH_VALUE CHILD_NUMBER EXECUTIONS
------------- - - - - ------------------------------------------------------------------------------------------------------------------------ --------------- ------------ ----------
fhtgpcv2m2j4s N Y N N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            0          2
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'CCCCCCCCCC', ANYDATA()))           1918680838            1          1
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'DDDDDDDDDD', ANYDATA()))           1918680838            2          1
fhtgpcv2m2j4s N Y Y N SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'EEEEEEEEEE', ANYDATA()))           1918680838            3          1
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'FFFFFFFFFF', ANYDATA()))           1918680838            4         16
fhtgpcv2m2j4s N Y Y Y SQL_BIND_SET(SQL_BIND(NULL, 1, NULL, 1, 'VARCHAR2(32)', 178, NULL, NULL, 32, '12-MAR-09', 'AAAAAAAAAA', ANYDATA()))           2211052296            5          3

I wondered why the cursors are not sharable and queried v$sql_shared_cursor:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47

SQL>   SELECT * FROM v$sql_shared_cursor WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        ADDRESS  CHILD_AD CHILD_NUMBER U S O O S L F E B P I S T A B D L T R I I R L I O E M U T N F A I T D L D B P C S C P T M B M R O P M F L P L A F L R L H
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
fhtgpcv2m2j4s 23F4E438 23F4DAB0            0 N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N Y N N N N N N
fhtgpcv2m2j4s 23F4E438 23D924D8            1 N N N N N N N N N N N N N N N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
fhtgpcv2m2j4s 23F4E438 23D7E888            2 N N N N N N N N N N N N N N N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
fhtgpcv2m2j4s 23F4E438 23D6B8C8            3 N N N N N N N N N N N N N N N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
fhtgpcv2m2j4s 23F4E438 23D574D8            4 N N N N N N N N N N N N N N N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
fhtgpcv2m2j4s 23F4E438 23B983B0            5 N N N N N N N N N N N N N N N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
 
6 ROWS selected.
 
SQL> SELECT sql_id, address, child_number, LOAD_OPTIMIZER_STATS, row_level_sec_mismatch FROM v$sql_shared_cursor WHERE sql_id = 'fhtgpcv2m2j4s';
 
SQL_ID        ADDRESS  CHILD_NUMBER L R
------------- -------- ------------ - -
fhtgpcv2m2j4s 245CE53C            0 Y N
fhtgpcv2m2j4s 245CE53C            1 N Y
fhtgpcv2m2j4s 245CE53C            2 N Y
fhtgpcv2m2j4s 245CE53C            3 N Y
fhtgpcv2m2j4s 245CE53C            4 N Y
fhtgpcv2m2j4s 245CE53C            5 N Y
 
SQL> SELECT * FROM v$sql_cs_statistics WHERE sql_id = 'fhtgpcv2m2j4s';
 
ADDRESS  HASH_VALUE SQL_ID        CHILD_NUMBER BIND_SET_HASH_VALUE P EXECUTIONS ROWS_PROCESSED BUFFER_GETS   CPU_TIME
-------- ---------- ------------- ------------ ------------------- - ---------- -------------- ----------- ----------
245CE53C 3308340376 fhtgpcv2m2j4s            5          3946114705 N          1              0           2          0
245CE53C 3308340376 fhtgpcv2m2j4s            5          2785428864 Y          1              0           2          0
245CE53C 3308340376 fhtgpcv2m2j4s            4          1680726256 Y          1              2           3          0
245CE53C 3308340376 fhtgpcv2m2j4s            3          1438126164 Y          1             20           5          0
245CE53C 3308340376 fhtgpcv2m2j4s            2           451655377 Y          1            200          21          0
245CE53C 3308340376 fhtgpcv2m2j4s            1          4078512309 Y          1           2000         169          0
245CE53C 3308340376 fhtgpcv2m2j4s            0           479772785 Y          1         100000        9823          0
 
7 ROWS selected.
 
SQL> SELECT * FROM v$sql_cs_selectivity WHERE sql_id = 'fhtgpcv2m2j4s';
 
ADDRESS  HASH_VALUE SQL_ID        CHILD_NUMBER PREDICATE                                  RANGE_ID LOW        HIGH
-------- ---------- ------------- ------------ ---------------------------------------- ---------- ---------- ----------
245CE53C 3308340376 fhtgpcv2m2j4s            5 =MYVAR                                            0 0.000004   0.010773
245CE53C 3308340376 fhtgpcv2m2j4s            4 =MYVAR                                            0 0.000009   0.010773
245CE53C 3308340376 fhtgpcv2m2j4s            3 =MYVAR                                            0 0.000088   0.010773
245CE53C 3308340376 fhtgpcv2m2j4s            2 =MYVAR                                            0 0.000881   0.010773
245CE53C 3308340376 fhtgpcv2m2j4s            1 =MYVAR                                            0 0.008814   0.010773

It is not clear, why the cursors are not shared and why this is expressed in the flag “row_level_sec_mismatch”. From these tests we can see that the number of child cursors is still quite high.


Session waiting for “enq: RO – fast object reuse” – DBWR Process spinning on CPU

By | January 20th, 2009 | Category: 10g, Bugs, HP-UX, Linux, Linux Itanium, MetaLink, Oracle Database, Solaris, Unix | 3 comments

I have encountered the following problem on a 10.2.0.4 database on Linux x86_64 today:
A user session has been waiting for “enq: RO – fast object reuse” for almost 60 minutes while executing a “truncate table” SQL statement.

SQL> select username, event, sql_id, taddr, last_call_et from v$session where sid = 234;

USERNAME EVENT SQL_ID TADDR LAST_CALL_ET
———- —————————– ————- —————- ————
MD enq: RO – fast object reuse ljk299jlkj003 0000000153264570 3542

SQL> select sql_text from v$sqlstats where sql_id = ‘ljk299jlkj003’;

SQL_TEXT
————————————-
truncate table tab1

The Session was blocked by the CKPT process:

SQL> select * from dba_waiters;

WAITING_SESSION HOLDING_SESSION LOCK_TYPE MODE_HELD MODE_REQUESTED LOCK_ID1 LOCK_ID2
————— ————— ————————– —————————————- —————————————- ———- ———-
234 423 RO Row-S (SS) Exclusive 65573 1

SQL> select sid, serial#, sql_id, last_call_et, machine, program, username from v$session where sid = 423;

SID SERIAL# SQL_ID LAST_CALL_ET MACHINE PROGRAM
———- ———- ————- ———— —————- ——————————–
423 1 4133636 ora-vm1.intra oracle@ora-vm1.intra (CKPT)

The checkpoint process was waiting for database writer DBWR process, which was spinning on one cpu:

top

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
10712 oracle 25 0 2201m 1.7g 1.7g R 99.5 21.7 108:18.03 oracle

PID 10712 maps to DBW0:

[oracle@ora-vm1 ]$ ps -ef|grep 10712
oracle 10712 1 0 2008 ? 03:23:05 ora_dbw0_MDDB01

mpstat

Linux 2.6.9-78.ELsmp (ora-vm1.intra) 01/20/2009

02:21:56 PM CPU %user %nice %system %iowait %irq %soft %idle intr/s
02:21:57 PM all 49.75 0.00 0.00 0.00 0.00 0.00 50.25 1055.00
02:21:57 PM 0 0.00 0.00 0.00 0.00 0.00 0.00 100.00 1006.00
02:21:57 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 49.00

02:21:57 PM CPU %user %nice %system %iowait %irq %soft %idle intr/s
02:21:58 PM all 50.75 0.00 0.00 0.50 0.00 0.00 48.76 1161.00
02:21:58 PM 0 1.00 0.00 0.00 1.00 0.00 0.00 98.00 1087.00
02:21:58 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 74.00

The stack of dbw0 during the time showed these signatures:

[oracle@ora-vm1 oracle]$ pstack 10712
#0 0x000000000074b7fb in kslfre ()
#1 0x00000000010ccc3b in kcbo_exam_buf ()
#2 0x00000000010d0d62 in kcbo_service_ockpt ()
#3 0x0000000001080cd7 in kcbbdrv ()
#4 0x00000000007ddcc2 in ksbabs ()
#5 0x00000000007e4b32 in ksbrdp ()
#6 0x0000000002efcb50 in opirip ()
#7 0x00000000012da326 in opidrv ()
#8 0x0000000001e62456 in sou2o ()
#9 0x00000000006d2555 in opimai_real ()
#10 0x00000000006d240c in main ()
[oracle@ora-vm1 oracle]$ pstack 10712
#0 0x000000000074b36d in kslfre ()
#1 0x00000000010cc203 in kcbo_write_process ()
#2 0x00000000010ce608 in kcbo_write_q ()
#3 0x0000000001080a6d in kcbbdrv ()
#4 0x00000000007ddcc2 in ksbabs ()
#5 0x00000000007e4b32 in ksbrdp ()
#6 0x0000000002efcb50 in opirip ()
#7 0x00000000012da326 in opidrv ()
#8 0x0000000001e62456 in sou2o ()
#9 0x00000000006d2555 in opimai_real ()
#10 0x00000000006d240c in main ()
[oracle@ora-vm1 oracle]$ pstack 10712
#0 0x00000000010ccb60 in kcbo_exam_buf ()
#1 0x00000000010d0d62 in kcbo_service_ockpt ()
#2 0x0000000001080cd7 in kcbbdrv ()
#3 0x00000000007ddcc2 in ksbabs ()
#4 0x00000000007e4b32 in ksbrdp ()
#5 0x0000000002efcb50 in opirip ()
#6 0x00000000012da326 in opidrv ()
#7 0x0000000001e62456 in sou2o ()
#8 0x00000000006d2555 in opimai_real ()
#9 0x00000000006d240c in main ()
[oracle@ora-vm1 oracle]$ pstack 10712
#0 0x00000000010d0da5 in kcbo_service_ockpt ()
#1 0x0000000001080cd7 in kcbbdrv ()
#2 0x00000000007ddcc2 in ksbabs ()
#3 0x00000000007e4b32 in ksbrdp ()
#4 0x0000000002efcb50 in opirip ()
#5 0x00000000012da326 in opidrv ()
#6 0x0000000001e62456 in sou2o ()
#7 0x00000000006d2555 in opimai_real ()
#8 0x00000000006d240c in main ()

A MetaLink Research for the term “kcbo_service_ockpt” leads to Bug 7376934, which is a duplicate of Bug 7385253 – DBWR IS CONSUMING HIGH CPU.

Patch 7385253 is available for Linux x86_64, HP-UX, Solaris, AIX.
Reference:
MetaLink Note 762085.1 – Subject: ‘enq: RO – fast object reuse’ contention when gathering schema/table statistics in parallel


« Older articles
Newer articles »