Bugs

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

By Martin | 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 Martin | 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 Martin | 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 Martin | 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 Martin | April 9th, 2009 | Category: 10g, 11g, Bugs, MetaLink, Oracle Database | No 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 Martin | 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 Martin | 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


LMON: terminating instance due to error 481 after 10.2.0.4 Upgrade

By Martin | December 3rd, 2008 | Category: 10g, Bugs | No Comments »

I have recently come across this nasty bug, which occurred after upgrading the RAC cluster to 10.2.0.4. Out of nowhere the LMON process has terminated one cluster instance. After some research I found a matching bug from September 2008:

Bug 6500033 / MetaLink Note 6500033.8: LMON crash the instance with ORA-481 due to DRM sync timeout

alert_MDDB1.log:

Sun Oct 19 17:47:12 2008
LMON: terminating instance due to error 481

MDDB1_lmon_12345.trc:


-----------------------
sent synca inc 4 lvl 1308 (4,0/38/0)
kjfcdrmrfg: SYNC TIMEOUT (105441, 104540, 900), step 31
Submitting asynchronized dump request [28]
KJC Communication Dump:
state 0x5 flags 0x0 mode 0x0 inst 0 inc 4
nrcv 3 nsp 3 nrcvbuf 1000

It is fixed in RAC Recommended Bundle #2 (7573282), available for Linux x86-32/64, Solaris and HP-UX.


ORA-600 – be careful when dynamically resizing SGA structures

By Martin | October 25th, 2008 | Category: 10g, Bugs, MetaLink, Oracle Database | No Comments »

If you have Automatic Memory Management turned on (sga_target > 0) and you dynamically resize db_cache_size, you might – like me – encounter an instance crash with ORA-600 [Kmgs_pre_process_request_2]. Small change – big impact! Oracle tracks this problem with Bug 6597948 and Bug 5942310. There is a patch for HP-UX Itanium 10.2.0.3. It will be fixed in 10.2.0.5 and 11g. MetaLink Note 737458.1 gives more details.

An even more obscure problem occurs when sga_target is set to an exact multiple of 4 GB: Ora-600 [Kmgs_Pre_Process_Request_6] Terminates Instance When Resizing Caches. See MetaLink 373802.1.


Wait Event “cursor: pin S wait on X” suspected to be related with Automatic Memory Management

By Martin | October 25th, 2008 | Category: 10g, 11g, Bugs, MetaLink, Oracle Database | 1 Comment »

Quite a while ago, I experienced severe performance problems while processing peak workload with multiple sessions, all waiting on "pin S wait on X". Somehow I suspected that it might have to do with frequent Automatic Memory Management Resize operations. Therefore, we have disabled it with sga_target=0. After that, we did not experience these issues anymore.

As a responsible DBA I have opened a service request with Oracle and asked:

When looking for the wait event CURSOR: PIN S WAIT ON X on metalink, there are quite a few relations to the automatic shared memory management. Could you investigate, whether disabling ASMM would benefit regarding to these mutex waits?

Oracle replied:

Based on the uploaded systemstate and stacks it is no connection between the mutex waits and the ASMM.

Today, I have read a metalink note: 742599.1 – FREQUENT RESIZE OF SGA, which confirms my suspicion. The bug is tracked as Bug 6528336 – LARGE NUMBER OF SESSIONS WAITING ON CURSOR: PIN S WAIT ON X. There is a patch available for HP-UX Itanium on 10.2.0.3 but I would rather disable Automatic Memory Management and wait for it to be fixed with a later – and better tested – patchset.

Support however recommended to get systemstate level 266 dumps as soon as the problem occurs again and then look for the holder of the mutex. An example is given on MetaLink Note: 423153.1.

The correlation is done after th IDN as bellow:

To find more details use the idn=XXXXXX to search down in the systemstate (ie idn=535d1a6c)

KGX Atomic Operation Log 7000002e5b9d160
Mutex 7000002b8e92268(3094, 0) idn 535d1a6c oper GET_SHRD SID 3094 holds it
Cursor Pin uid 2489 efd 0 whr 5 slp 58733 SID 2489 wants it in Shared (GET_SHRD)
opr=2 pso=70000028c47def0 flg=0
pcs=7000002b8e92268 nxt=0 flg=34 cld=3 hd=70000030d6c6eb0 par=7000002eefe64d0
ct=31 hsh=0 unp=0 unn=0 hvl=b825a4d0 nhv=1 ses=700000309b42600
hep=7000002b8e922e8 flg=80 ld=1 ob=7000002de49f8a0 ptr=70000022cf39db8 fex=70000022cf390c8

To find the HOLDER, search for idn XXXXXXX oper until you find one which is held (ie not GET_XXX)(
ie idn 535d1a6c oper):-

KGX Atomic Operation Log 7000002cd934270
Mutex 7000002b8e92268(3094, 0) idn 535d1a6c oper EXCL SID 3094 holds in Exclusive (EXCL)
Cursor Pin uid 3094 efd 0 whr 7 slp 0
opr=3 pso=7000002a71c4180 flg=0
pcs=7000002b8e92268 nxt=0 flg=34 cld=3 hd=70000030d6c6eb0 par=7000002eefe64d0
ct=31 hsh=0 unp=0 unn=0 hvl=b825a4d0 nhv=1 ses=700000309b42600
hep=7000002b8e922e8 flg=80 ld=1 ob=7000002de49f8a0 ptr=70000022cf39db8 fex=70000022cf390c8

The wait event "cursor: pin S wait on X" is also related to two different bugs:

  • Bug 5485914 – MUTEX REPORTED SELF DEADLOCK AFTER
    DBMS_MONITOR.SESSION_TRACE_ENABLE
  • Bug 5907779 – Self deadlock hang on “cursor: pin S wait on X” (typically from DBMS_STATS). An excellent way to diagnose if you suffer from this bug is given here.

« Older articles
Newer articles »