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