I have been troubleshooting a performance issue in a DWH environment, which is quite interesting. It was a query on DBA_SEGMENTS in 11gR2 with lots of partitions and it was taking almost 10 minutes versus only a few seconds in 10gR2. The problem could be stripped downt to this SQL query:
select bytes from dba_segments
The dba_segment view can be seen in DBA_VIEWS:
SELECT ...
decode(bitand(segment_flags, 131072), 131072, blocks,
(decode(bitand(segment_flags,1),1,
<strong>dbms_space_admin.segment_number_blocks</strong>(tablespace_id, relative_fno,
header_block, segment_type_id, buffer_pool_id, segment_flags,
segment_objd, blocks), blocks)))*blocksize,
...
FROM sys_dba_segs |
select ...
decode(bitand(segment_flags, 131072), 131072, blocks,
(decode(bitand(segment_flags,1),1,
<strong>dbms_space_admin.segment_number_blocks</strong>(tablespace_id, relative_fno,
header_block, segment_type_id, buffer_pool_id, segment_flags,
segment_objd, blocks), blocks)))*blocksize,
...
from sys_dba_segs
The response time was dominated by Waits for “db file sequential reads” taking almost all of the response time.
11gR2:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 12563 23.17 546.74 157447 580414 1 188421
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12565 23.17 546.74 157447 580414 1 188421 |
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 12563 23.17 546.74 157447 580414 1 188421
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12565 23.17 546.74 157447 580414 1 188421
10gR2:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 5104 1.77 2.54 0 96688 0 76542
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5106 1.83 2.61 0 96688 0 76542 |
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 5104 1.77 2.54 0 96688 0 76542
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5106 1.83 2.61 0 96688 0 76542
The 10046 Trace File contains more data regarding those waits:
WAIT #4: nam='db file sequential read' ela= 134 file#=21 block#=2313482 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 120 file#=15 block#=2128019 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 128 file#=21 block#=2313490 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 372 file#=21 block#=2313498 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 108 file#=21 block#=2313506 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 130 file#=21 block#=2313514 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 132 file#=21 block#=2313522 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 121 file#=21 block#=2313530 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 158 file#=15 block#=2128003 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 146 file#=21 block#=2313538 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 116 file#=21 block#=2313546 blocks=1 obj#=-1
(Output modified for formatting) |
WAIT #4: nam='db file sequential read' ela= 134 file#=21 block#=2313482 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 120 file#=15 block#=2128019 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 128 file#=21 block#=2313490 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 372 file#=21 block#=2313498 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 108 file#=21 block#=2313506 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 130 file#=21 block#=2313514 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 132 file#=21 block#=2313522 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 121 file#=21 block#=2313530 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 158 file#=15 block#=2128003 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 146 file#=21 block#=2313538 blocks=1 obj#=-1
WAIT #4: nam='db file sequential read' ela= 116 file#=21 block#=2313546 blocks=1 obj#=-1
(Output modified for formatting)
Strange thing that obj# is -1. I made some block dumps of those blocks and found out that all those blocks (file#/block#) have something in common: They were all segment header blocks. Another strange thing was that when the query was executed a second time, all those I/O requests were performed again – so no caching.
At that point, I opened a Support service request. After a couple of weeks, Support suggested running this for each tablespace of the user segments:
EXEC dbms_space_admin.TABLESPACE_FIX_SEGMENT_EXTBLKS('<tablespace_name>'); |
exec dbms_space_admin.TABLESPACE_FIX_SEGMENT_EXTBLKS('<tablespace_name>');
Finally this fixed the problem. Now, we are trying to find out why this was necessary for a database, that was freshly created with dbca 11.2.0.2 from the seeded template and filled with data pump import.
