Hello,
in a system in which I am currently trying to optimize some queries I see a strange effect: selects on v$sql are very slow - a simple select count(*) from v$sql takes ~ 25 seconds. Here are some details:
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE 11.2.0.2.0 Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production
SQL> select count(*) from v$sql;
COUNT(*)
----------
1686
Elapsed: 00:00:24.82
select component, current_size
from v$memory_dynamic_components
where current_size > 0 order by 2 desc;
COMPONENT |
CURRENT_SIZE |
SGA Target |
19595788288 |
DEFAULT buffer cache |
16441671680 |
PGA Target |
10468982784 |
shared pool |
2483027968 |
java pool |
67108864 |
large pool |
67108864 |
streams pool |
67108864 |
select name, bytes
from v$sgastat
where pool = 'shared pool'
and bytes > 30000000
order by bytes desc;
NAME |
BYTES |
free memory |
1017996032 |
KGH: NO ACCESS |
719376832 |
KGLH0 |
692973984 |
KGLHD |
160077936 |
db_block_hash_buckets |
93327360 |
FileOpenBlock |
63749664 |
kglsim object batch |
56897400 |
SQLA |
41651024 |
dbwriter coalesce buffer |
33587200 |
My Interpretation would be that SQLA is the library cache and its size of 40MB is rather small (for a shared pool with 2,4G) - and the size should not be a reason for a slow access on v$sql - or the underlying X$KGLCURSOR_CHILD. I used two snapshots of v$sesstat (before and after the execution of my select count(*) from v$sql) to get additional details of the resource usage:
NAME |
VALUE |
session pga memory |
78708736 |
session uga memory |
78520104 |
session uga memory max |
76115040 |
session pga memory max |
75497472 |
cell physical IO interconnect bytes |
24576 |
physical read total bytes |
24576 |
physical read bytes |
24576 |
CPU used by this session |
2506 |
CPU used when call started |
2506 |
DB time |
2506 |
bytes received via SQL*Net from client |
724 |
bytes sent via SQL*Net to client |
543 |
recursive calls |
294 |
sorts (rows) |
178 |
consistent gets from cache |
44 |
consistent gets |
44 |
session logical reads |
44 |
file io wait time |
41 |
buffer is not pinned count |
37 |
no work - consistent read gets |
26 |
consistent gets from cache (fastpath) |
23 |
cluster key scan block gets |
18 |
parse count (total) |
16 |
consistent gets - examination |
16 |
opened cursors cumulative |
16 |
execute count |
14 |
calls to get snapshot scn: kcmgss |
13 |
session cursor cache count |
12 |
sorts (memory) |
8 |
index fetch by key |
6 |
table fetch by rowid |
6 |
non-idle wait count |
6 |
cluster key scans |
6 |
workarea executions - optimal |
5 |
index scans kdiixs1 |
5 |
user calls |
4 |
buffer is pinned count |
4 |
physical read IO requests |
3 |
free buffer requested |
3 |
session cursor cache hits |
3 |
SQL*Net roundtrips to/from client |
3 |
enqueue releases |
3 |
parse count (hard) |
3 |
physical read total IO requests |
3 |
enqueue requests |
3 |
physical reads cache |
3 |
physical reads |
3 |
sql area evicted |
2 |
shared hash latch upgrades - no wait |
2 |
parse time elapsed |
1 |
parse time cpu |
1 |
recursive cpu usage |
1 |
There are some surprises - starting with the execute count = 14 where I would expect 1 (and some corresponding numbers: parse count (total), calls to get snapshot scn: kcmgss). But the most irritating number still is 2506 for "CPU used by this session".
For the sake of completeness: there are no fixed table statistics created for X$KGLCURSOR_CHILD (and I can not create them) and the execution plan is boring:
---------------------------------------------------------------------------------------
Plan hash value: 1001747286
---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 13 | 0 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
|* 2 | FIXED TABLE FULL| X$KGLCURSOR_CHILD | 1 | 13 | 0 (0)| 00:00:01 |
---------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("INST_ID"=USERENV('INSTANCE'))
Note
-----
- automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold
I can't remember having seen a similar behaviour before (and could not find an explanation in MOS) - so my question is: has someone an explanation for this pattern?
Regards
Martin Preiss