May 4, 2014

Scaling application with paginated query using rownum

There was a case where one of the application modules getting slower day by day as the usage and data increased. The module is a mail like system where we show 20 items per page. The initial design was not that good, we fetched all the items from database and then paginated in application layer - 20 list item per page. This caused slower response for loading the inbox, specially for those people who had a large number of items.

Thought this can be improved if we fetch selective number of records from database. We show 20 records per page, so we should only try to bring 20 records, not all at the very beginning. For the first page, we will bring records from 1 to 20, for the next page (2nd page), we will bring records from 21 to 40 and so on. This helped a lot. The initial response time decreased from several minutes to just few seconds! I loved the response time graphs (see below) after we made the changes.


/** Old List query **/
SELECT mbox.id mbox_id, mbox.mailbox_type mbox_mailbox_type, mbox.read_date mbox_read_date, mbox.status mbox_status,...
FROM mailbox mbox
LEFT JOIN message msg on (mbox.message_id = msg.id)
LEFT JOIN user u ON (u.id = msg.sender_id )
LEFT JOIN recipient r on (r.message_id = msg.id AND r.idx=0)
LEFT JOIN user ur ON (ur.id = r.target_user_id)
WHERE mbox.user_id= :user
AND mbox.folder_id= :folder
AND msg.test = :test
AND msg.updated >= :dt
ORDER BY msg_updated DESC;



/** New paginated List query **/
SELECT *
  FROM (select /*+ FIRST_ROWS(20) */
  a.*, ROWNUM rnum
      from ( SELECT mbox.id mbox_id, mbox.mailbox_type mbox_mailbox_type, mbox.read_date mbox_read_date, mbox.status mbox_status,...
              FROM mailbox mbox
              LEFT JOIN message msg on (mbox.message_id = msg.id)
              LEFT JOIN user u ON (u.id = msg.sender_id )
              LEFT JOIN recipient r on (r.message_id = msg.id AND r.idx=0)
              LEFT JOIN user ur ON (ur.id = r.target_user_id)
              WHERE mbox.user_id= :user
              AND mbox.folder_id= :folder
              AND msg.test = :test
              AND msg.updated >= :dt
              ORDER BY msg_updated DESC ) a
      where ROWNUM <= 20 )
WHERE rnum  >= 1;


Similarly, the Count queries were improved fixing the count to 100. In that case, if there is more than 100 new items in inbox, we say 100+.

/** Old Count query **/
SELECT COUNT(id) inbox_lo
FROM mailbox mbx 
JOIN message msg ON (mbx.message_id = msg.id)
LEFT JOIN user l ON (l.id = msg.sender_id)
WHERE mbx.login_id = :login
AND mbx.folder_id = :folder
AND mbx.mailbox_type = :mailbox
AND mbx.status= :status
AND msg.test = :test
AND mbx.created >= :dt;


/** New Count query **/
SELECT /*+ FIRST_ROWS(100) */ COUNT(id) inbox_lo
FROM mailbox mbx 
JOIN message msg ON (mbx.message_id = msg.id)
LEFT JOIN user l ON (l.id = msg.sender_id)
WHERE mbx.login_id = :login
AND mbx.folder_id = :folder
AND mbx.mailbox_type = :mailbox
AND mbx.status= :status
AND msg.test = :test
AND mbx.created >= :dt
AND ROWNUM <= 100;


The response time improved amazingly - users now feel the difference!

***

Apr 28, 2014

TNS-12599: TNS:cryptographic checksum mismatch

After upgrading to 11.2.0.3.0, we had been receiving this error "TNS-12599: TNS:cryptographic checksum mismatch" quite frequently.

Found related information in Oracle support. The thing is - when Enterprise Manager logs in or out from a 11.1 (11gR1) or 11.2 (11gR2) target database or as the OMS database repository, it causes several TNS-12599 errors in the alert.log of the respective database.

This is for the bug 9953045.

Workaround:

1. On the target database side, set SQLNET.ENCRYPTION_TYPES_SERVER= (3DES168)  in sqlnet.ora

2. Patches for bug 9953045 will fix the problem.



Apr 2, 2014

Replacing SQL literals with Global Temporary Table backfired at the beginning

I always emphasize on understanding data and business domain for query optimization. One must have technical skills in combination with the domain knowledge. Other than the blend, who could tune at this level!

We planned to tune some of the queries where we use literals and can't use bind variables as those are inside 'IN clause', and we don't exactly know how many values would be there (dynamically added by the application). We decided to replace the literals in 'IN clause' by Global Temporary Table (GTT). That change made every other queries perform better or at least same as before other than the SQL I am going to talk below. Changing literals in 'IN clause' caused to SQL to come up with very wrong execution plan and blundered our system's stability - the frequency of execution was very high for the SQL, we could not afford the bad plan.

After analyzing the plan, I found that the SQL with Global Temporary Table (GTT) doing unexpected Nested Loops at the very early state of execution order which was causing more data to process in other steps for the result. We know that, the join with GTT should be done at the later or last stage of execution order. And the best way (for the best selectivity) is to start execution with the underlying table mv_caseload_priv (through the index MV_PGM_CASE_I) we have in the client_access_role view. I drew the plan by hand and attached below for a clear understanding what was going on. The Nested Loop (NL, marked as red circle) was very unexpected, also the execution start point (marked as red cross) was not optimum.


The original SQL and the plan, only problem was not having bind variables, sometimes this 
ended up with terrible execution plan for some bind values in the SQL, was uncontrollable.

SQL > SELECT DISTINCT login_id
FROM client_access_role car
WHERE car.pgm_id = :pgm
AND car.role IN (21,22,112,......);


Elapsed: 00:00:00.11
------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                | Name                    | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                         |                         | 11900 |   429K|   678   (1)| 00:00:01 |       |       |
|   1 |  HASH UNIQUE                             |                         | 11900 |   429K|   678   (1)| 00:00:01 |       |       |
|*  2 |   HASH JOIN                              |                         | 11900 |   429K|   676   (1)| 00:00:01 |       |       |
|   3 |    INLIST ITERATOR                       |                         |       |       |            |          |       |       |
|*  4 |     INDEX RANGE SCAN                     | AR_ROLE_ACL_I           | 16724 |   130K|    31   (0)| 00:00:01 |       |       |
|   5 |    NESTED LOOPS                          |                         |  9589 |   271K|   643   (1)| 00:00:01 |       |       |
|   6 |     MAT_VIEW ACCESS BY GLOBAL INDEX ROWID| MV_CASELOAD_PRIV        |   279 |  3348 |    83   (0)| 00:00:01 | ROWID | ROWID |
|*  7 |      INDEX RANGE SCAN                    | MV_CASE_PRIV_PGM_I      |   279 |       |     3   (0)| 00:00:01 |       |       |
|*  8 |     INDEX RANGE SCAN                     | CA_CASELOAD_LOGIN_ACL_I |    34 |   578 |     2   (0)| 00:00:01 |       |       |
------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("CA"."ACL_ID"="R"."ACL_ID")
   4 - access("R"."ROLE"=21 OR "R"."ROLE"=22 OR "R"."ROLE"=112)
   7 - access("CP"."PGM_ID"=TO_NUMBER(:PGM))
   8 - access("CP"."CASELOAD_ID"="CA"."CASELOAD_ID")
Statistics
----------------------------------------------------------
          8  recursive calls
          0  db block gets
         97  consistent gets


Replaced 'IN clause' with a Global Temporary Table for generating fixed sort of plan, which 
backfired, caused severe performance problem for the unexpected terrible plan.

SQL> SELECT DISTINCT login_id
FROM client_access_role car
WHERE car.pgm_id = :pgm
AND car.role IN (SELECT value FROM gtt_in_list_2);


Elapsed: 00:00:18.98
Execution Plan
----------------------------------------------------------
Plan hash value: 1525097291
-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name            | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                 |     1 |    50 |    34   (3)| 00:00:01 |       |       |
|   1 |  HASH UNIQUE                    |                 |     1 |    50 |    34   (3)| 00:00:01 |       |       |
|   2 |   NESTED LOOPS                  |                 |     1 |    50 |    33   (0)| 00:00:01 |       |       |
|   3 |    NESTED LOOPS                 |                 |     1 |    38 |    32   (0)| 00:00:01 |       |       |
|   4 |     NESTED LOOPS                |                 |     1 |    21 |     1   (0)| 00:00:01 |       |       |
|   5 |      INDEX FULL SCAN            | GTT2_VAL_I      |     1 |    13 |     0   (0)| 00:00:01 |       |       |
|   6 |      TABLE ACCESS BY INDEX ROWID| ACL_ROLE        |     1 |     8 |     1   (0)| 00:00:01 |       |       |
|*  7 |       INDEX RANGE SCAN          | AR_ROLE         |  3787 |       |     1   (0)| 00:00:01 |       |       |
|   8 |     TABLE ACCESS BY INDEX ROWID | CASELOAD_ACCESS |   137 |  2329 |    31   (0)| 00:00:01 |       |       |
|*  9 |      INDEX RANGE SCAN           | CASE_ACC_ACL    |   137 |       |     2   (0)| 00:00:01 |       |       |
|  10 |    PARTITION HASH ITERATOR      |                 |     1 |    12 |     1   (0)| 00:00:01 |   KEY |   KEY |
|* 11 |     INDEX RANGE SCAN            | MV_PGM_CASE_I   |     1 |    12 |     1   (0)| 00:00:01 |   KEY |   KEY |
-------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   7 - access("R"."ROLE"="VALUE")
   9 - access("CA"."ACL_ID"="R"."ACL_ID")
  11 - access("CP"."PGM_ID"=TO_NUMBER(:PGM) AND "CP"."CASELOAD_ID"="CA"."CASELOAD_ID")
Statistics
----------------------------------------------------------
          8  recursive calls
          0  db block gets
    2817221  consistent gets


The tuned SQL by 'ORDERED' hint to guide the optimizer doing correct join order as we know best.

SQL> SELECT /*+ ORDERED */ DISTINCT login_id
FROM client_access_role c
JOIN gtt_in_list_2 x ON (c.role = x.value)
WHERE c.pgm_id = :pgm;



Elapsed: 00:00:00.08
Execution Plan
----------------------------------------------------------
Plan hash value: 3611759149
-------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                 | Name                    | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                          |                         |     1 |    50 |   771   (7)| 00:00:01 |       |       |
|   1 |  HASH UNIQUE                              |                         |     1 |    50 |   771   (7)| 00:00:01 |       |       |
|*  2 |   HASH JOIN                               |                         |     1 |    50 |   770   (7)| 00:00:01 |       |       |
|   3 |    INDEX FULL SCAN                        | GTT2_VAL_I              |     1 |    13 |     0   (0)| 00:00:01 |       |       |
|*  4 |    HASH JOIN                              |                         |   311K|    10M|   762   (6)| 00:00:01 |       |       |
|   5 |     NESTED LOOPS                          |                         |  9589 |   271K|   643   (1)| 00:00:01 |       |       |
|   6 |      MAT_VIEW ACCESS BY GLOBAL INDEX ROWID| MV_CASELOAD_PRIV        |   279 |  3348 |    83   (0)| 00:00:01 | ROWID | ROWID |
|*  7 |       INDEX RANGE SCAN                    | MV_CASE_PRIV_PGM_I      |   279 |       |     3   (0)| 00:00:01 |       |       |
|*  8 |      INDEX RANGE SCAN                     | CA_CASELOAD_LOGIN_ACL_I |    34 |   578 |     2   (0)| 00:00:01 |       |       |
|   9 |     TABLE ACCESS FULL                     | ACL_ROLE                |   571K|  4467K|   105  (23)| 00:00:01 |       |       |
-------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("R"."ROLE"="X"."VALUE")
   4 - access("CA"."ACL_ID"="R"."ACL_ID")
   7 - access("CP"."PGM_ID"=TO_NUMBER(:PGM))
   8 - access("CP"."CASELOAD_ID"="CA"."CASELOAD_ID")
Statistics
----------------------------------------------------------
          8  recursive calls
          0  db block gets
        705  consistent gets






And we are back with the super performance!
***

Mar 31, 2014

What happened when we received ORA-04030: out of process memory - trying to allocate 824504 bytes (pga heap,kco buffer)


Here goes the story in short -

We had to bump up Oracle memory to address buffer cache growth. So, in our Solaris database box, we increased Oracle project memory in /etc/project from 32 GB to 64 GB - we had enough physical memory in the server - 128 GB.

Then we increased SGA_MAX_SIZE from 28 GB to 36 GB and MEMORY_MAX_SIZE 28 GB to 42 GB. We did not set the target parameters as we had not been not using Automatic Memory Management (AMM) or Automatic Shared Memory Management (ASMM).

Then from the following day, we started receiving errors while running the RMAN backup jobs -


ORA-00603: ORACLE server session terminated by fatal error
ORA-27103: internal error
Solaris-AMD64 Error: 9: Bad file number
Additional information: 108
Additional information: 4456448

Also, receiving ORA-04030 error in alert_log file.

ORA-04030: out of process memory when trying to allocate 824504 bytes (pga heap,kco buffer)
ORA-27103: internal error
Solaris-AMD64 Error: 9: Bad file number

It was clear to me that some memory allocation issue we hit as auto allocation of PGA memory was failing. It's production box, and internal error, so interpretation should come from Oracle Support. We opened SR. Sent several trace  and alert logs. At the beginning, they thought that it's OS resource allocation problem, then support thought it's a RMAN backup problem and possibly a bug, and suggested several alternatives. That did not help at all. Finally they forwarded the SR to Solaris OS Memory Engineers. They found something interesting for us.

After 3 weeks back and forth information with Oracle Support, we have been told that, by setting SGA_MAX_SIZE & MEMORY_MAX_SIZE we had enabled Dynamic Intimate Shared Memory (DISM) feature of Oracle Solaris. And this may not work in Solaris 10 x86 based system, also not recommended. So, we need to disable DISM by NOT setting SGA_MAX_SIZE, SGA_TARGET, MEMORY_MAX_SIZE and MEMORY_MAX_TARGET.

The steps we followed to disable DISM -

1. Setting individual SGA components (like shared pool, buffer cache, large pool etc.)

2. Create a PFILE from the SPFILE

3. Removed all the four parameters SGA_MAX_SIZE, SGA_TARGET, MEMORY_MAX_SIZE and MEMORY_MAX_TARGET from PFILE and let Oracle compute the SGA_MAX_SIZE aggregating all individual SGA components

4. Startup using the edited PFILE

5. Creating SPFILE from the edited PFILE

6. Shutdown & restart again so that SPFILE takes effect


Details of DISM could be found in the following doc - Oracle support referred this.

http://www.oracle.com/technetwork/articles/systems-hardware-architecture/using-dynamic-intimate-memory-sparc-168402.pdf


***

Mar 22, 2014

Database query runs slow in second execution - why?

When a query returns result quickly in the first run but the same query runs slow in second execution or successive executions, it is probably for the cardinality feedback the query used for the other executions. We had a scenario recently.

The first execution returns in less than a second - 78 records. When the query goes for successive executions, it takes over 5 minutes to return the same result. This slow execution of the query slowed down one of the application servers and caused huge number of thread stuck and bog down the server at the end. I thought, this happened for the wrong cardinality feedback from the first execution of the query.

To become very sure about this, I did the following tests - 

SQL> alter session set statistics_level=all;
SQL> set autotrace traceon;

SQL> SELECT l.id, l.login_name, l.first_name, l.last_name, l.title_id, l.title 
FROM table_x l, view_y pr 
WHERE l.id = pr.login_id
AND pr.pgm_id IN (68894) 
AND l.enroll = 0 
AND l.status = 1 
ORDER BY l.last_name, l.first_name, l.login_name, l.title;

Elapsed: 00:00:00.78

Statistics
----------------------------------------------------------
          8  recursive calls
          3  db block gets
      16074  consistent gets
        629  physical reads
          0  redo size
       5783  bytes sent via SQL*Net to client
        575  bytes received via SQL*Net from client
          7  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
         79  rows processed

SQL> /

Elapsed: 00:05:49.29

Statistics
----------------------------------------------------------
       4069  recursive calls
          8  db block gets
      47259  consistent gets
     518490  physical reads
        272  redo size
       5783  bytes sent via SQL*Net to client
        575  bytes received via SQL*Net from client
          7  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
         79  rows processed

Note
-----
   - cardinality feedback used for this statement


To get rid of the cardinality feedback for this test case, I used hint with the query to tell the optimizer not to use the feedback. FYI - cardinality feedback could be turned off in session level and instance level by using ALTER SESSION SET "_OPTIMIZER_USE_FEEDBACK"=FALSE;


SQL> SELECT /*+ OPT_PARAM('_OPTIMIZER_USE_FEEDBACK' 'FALSE') */ l.id, l.login_name, l.first_name, l.last_name, l.title_id, l.title 
FROM table_x l, view_y pr 
WHERE l.id = pr.login_id
AND pr.pgm_id IN (68894) 
AND l.enroll = 0 
AND l.status = 1 
ORDER BY l.last_name, l.first_name, l.login_name, l.title;


Elapsed: 00:00:00.65

Statistics
----------------------------------------------------------
          0  recursive calls
          3  db block gets
      16069  consistent gets
          0  physical reads
         64  redo size
       5783  bytes sent via SQL*Net to client
        575  bytes received via SQL*Net from client
          7  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
         79  rows processed


A word about cardinality feedback

Cardinality feedback is introduced in Oracle 11g to make the optimizer working better. To describe the feature in short - when a query is being executed repetitively, it sends cardinality feedback if the estimated and actual rows have been revealed different in earlier executions. Anyways, we had a scenario related to cardinality feedback. We had complex SQLs which had been running in 1 to 2 seconds for the first run then suddenly it started taking several minutes!

Why cardinality feedback was being used?

* We have very complex underlying predicates in the view - that's could be one reason for not estimating correct cardinality in the execution phase. For the complex view, when many rows returns in intermediate steps in the executions, that makes the cardinality estimation even worse in our case. 

* Stale statistics could be another reason for wrong cardinality estimation. But that was not in our case, I checked that, there was no stale statistics for the tables used in the query.


So, for the pr.pgm_id 68894, the first execution luckily ends up with best execution plan. Oracle optimizer is intelligent - it reports a mismatch in cardinality estimate in the first run and gives feedback for successive runs. The cardinality feedback drove the query to go for full table scans on the next run on several tables for the underlying complex view "view_y". For the pr.pgm_id 68894, the query had to process about 10 GB of data (detailed could be found in SQL Monitoring in OEM) when it went for full table scans. As it had to process that amount of data, it did not use regular buffer cache, instead it used available memory in PGA and temporary tablespace to hold and process those huge amount of data. That aggravated the situation slowing down for doing excessive physical reads. 

Now we'll fix this in the application code - we don't want to turn the cardinality feedback feature off at instance level for such discrete instance for a single query. 


***

Jan 31, 2014

Materialized view fast refresh slowness for not sharing child cursors in flashback queries

I have not found any good writeup on this in web which could lead me to some solution of this problem. I found my own ways to solve it. Thought to write down some of it so that it might be helpful for others. 

Let me try to put the long story in a vey short way.  

If I summarize, these were the sequence of events. One of my friends hit this problem and asked me to take a look at the database. There was a Materialized view which supposed to be refreshed in every few minutes. 

- I found that the following query ran slow (took 30 seconds and more) which is a system generated query related to materialized view refresh.

update sys.sumpartlog$ s set s.timestamp = :1, s.scn = :2  
where  rowid in  (select rowid from sumpartlog$ AS OF SNAPSHOT(:3) s1  
where s1.bo# = :4   and s1.timestamp >= to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'))

- From several database reports like AWR, ADDM - I found that, most of the database time was being spent on "soft parse" and the only top queries was the materialized view refresh, was taking more than 50% of database resources most of the times. 

- To investigate the soft parse issue, I queried the V$SQL dictionary view. I found that, there were more than 5000 child cursors for the parent cursor. I collected the sql_id of the query. However, there were three other queries having huge humber of child cursors. 

- To investigate why child cursor were not being shared, I queried V$SQL_SHARED_CURSOR dictionary view. Out of about 50 reasons for not sharing child cursors, I found that FLASHBACK_CURSOR attribute was being set to 'Y' which means cursor not shared due to flashback query. 

- I knew that in flashback queries, the cursors are not shared, that's how it works and Oracle think this the right way of doing flashback queries. 

- Materialized view usage the flashback query techniques which is being used to look at old data for refresh operations. 

- Then I looked at the Oracle support documentations and found that, some people report this as an Oracle problem. From some earlier release, Oracle started using child cursor concepts I believe. Oracle workaround is to upgrade to 11.2.0.2.0 version where child cursors has come max limits and then automatically discarded. Oracle Doc ID: 1051346.1

- I knew that, in the latest Oracle release, database maintains a list of child cursors, if it crosses the threshold of 100, it discards the child cursors. 

- I knew that, too many child cursors sometimes could slow down soft parsing as it needs to loop through the shared pool hash chain to find the right cursor for the right plan. 

- Then I thought, if I could get rid of those excessive cursors, the query parse time would be reduced, and thus i improve response time. 

- Then I query the V$SQLAREA to find the query address and hash value of those queries having over 5000+ cursors. I wrote a cron job to purge those parent cursors from shared pool periodically - once in a hour using the Oracle dbms_shared_pool package. 

DECLARE

 addhash varchar2(50);
BEGIN
 select address||','||hash_value into addhash from v$sqlarea where sql_id = 'chbgkk6myytz';
 dbms_shared_pool.purge(addhash,'C');
END;
/
- That solved this particular parsing problem for the Oracle internal queries used in refreshing Materialized view. 

Jul 9, 2012

Concurrency waits "library cache: mutex x" for sequence

Let me share my scenario. Some background info –

We have a n-tier J2EE web application and we use spring jdbc templates. We use connection pool, however we don’t use statement caching. We have a statement like this which runs about 10 to 30 times per second (and commits as well) during peak hours.

INSERT INTO lb_stat (id, lb_id, login_id, read_date, lb_ufid, lb_created) VALUES (lb_status_seq.NEXTVAL, :1, :2, :3, :4, :5);

The table where we insert, is a nested partitioned one (range- hash). We have one unique local index on that table. Currently the table contains around 51 million records.



Most of the times, I see some concurrency waits associated with this insert statement when I look at OEM Top Activity. The waits are on “library cache: mutex x”. Sometimes this problem goes very severe and database load spikes and connection pool exhausts. I made sure we did not do anything wrong which allure Oracle to behave like this. I have checked, as we are using bind variables properly, the statement is not producing many child cursors, and not invalidating those child. People have been saying, there might have mutex problems while there are many child cursors – which is not our case, anyways.

We have been using Oracle version 11.2.0.2.0 fresh - no PSU or CPU.   My guess is - probably we hit the bug on this - Bug 13524966 or Bug 12966939  or something similar - there are tons of mutex bug reported to Oracle support.

To analyze further, I looked at the web and found some really nice articles on mutex problem. Here is one -

http://andreynikolaev.wordpress.com/2011/05/01/divide-and-conquer-the-true-mutex-contention

To conclude that it's a bug - I exchanged a couple of mails with the writer who is an expert on mutex problem - thanks to Andrey! :-)

It finally revealed that, when there are many calls on that particular  sequence, the mutex holds on that and holding time sometimes over 1 ms - which is huge in mutex world. We planned to get rid of the sequence in next release. Also, will be upgrading to 11.2.0.3.0 soon.


Here is some handy scripts I collected to initiate the mutex waits investigation.

/* Library Cache Object heavily accessed */

col name format a20
col cursor format a12 noprint
col type format a7
col LOCKED_TOTAL heading Locked format 99999
col PINNED_TOTAL heading Pinned format 99999999
col EXECUTIONS heading Executed format 99999999
col NAMESPACE heading Nsp format 999
set wrap on
set linesize 200

set pagesize 1000
 

select * from (
select case when (kglhdadr =  kglhdpar) then 'Parent' else 'Child '||kglobt09 end cursor,
              kglhdadr ADDRESS,substr(kglnaobj,1,20) name, kglnahsh hash_value,kglobtyd type,kglobt23 LOCKED_TOTAL,kglobt24 PINNED_TOTAL,kglhdexc EXECUTIONS,kglhdnsp NAMESPACE
                from x$kglob
                order by kglobt24 desc)
    where rownum <= 10;


ADDRESS          NAME                 HASH_VALUE TYPE    Locked    Pinned  Executed  Nsp                                                                                                               
---------------- -------------------- ---------- ------- ------ --------- --------- ----                                                                                                               
00000005D1875E38 SELECT 'x' FROM DUAL 4261573303 CURSOR  ###### #########   5232320    0                                                                                                               
00000006119FB278 UA_SEQ               1535242682 SEQUENC ###### #########         0    1                                                                                                               
                                                 E                                                                                                                                                     
                                                                                                                                                                                                       
000000061190AF30 select login0_.id as  459939420 CURSOR  ######  65289824   5911243    0                                                                                                               
000000064F4643F0 MGMT_NOTIFY_Q        1523339315 QUEUE   ######  63487340       249   10                                                                                                               
00000005F66D2308 select login0_.id as  459939420 CURSOR  ######  58493935  12382999    0                                                                                                               
000000065FACDD90 select /*+ connect_b  487379649 CURSOR  ######  47798467   6782438    0                                                                                                               
00000005AE8F3F68 LB_STATUS_SEQ        3672626424 SEQUENC ######  40551649         0    1                                                                                                               
                                                 E                                                            
                                                            
/* Mutex ASH Wsits in last 30 min */

col sample_id noprint format 9999999
col sample_time format a8
col session_id heading "SID" format 9999
col session_serial# noprint format 9999
col event format a19
col blocking_sid heading "BLKS" format 9999
col shared_refcount noprint heading "RFC" format 99
col location_id heading "LOC" format 99
col sleeps  noprint format 99999
col mutex_object format a15
set pagesize 1000

set wrap off
 

SELECT sample_id,to_char(sample_time,'hh24:mi:ss') sample_time,session_id,session_serial#,sql_id,event,p1 IDN,
             FLOOR (p2/POWER(2,4*ws)) blocking_sid,MOD (p2,POWER(2,4*ws)) shared_refcount,
             FLOOR (p3/POWER (2,4*ws)) location_id,MOD (p3,POWER(2,4*ws)) sleeps,
             CASE WHEN (event LIKE 'library cache:%' AND p1 <= power(2,17)) THEN  'library cache bucket: '||p1
                 ELSE  (SELECT kglnaobj FROM x$kglob WHERE kglnahsh=p1 AND (kglhdadr = kglhdpar) and rownum=1) END mutex_object
            FROM (SELECT DECODE (INSTR (banner, '64'), 0, '4', '8') ws FROM v$version WHERE ROWNUM = 1) wordsize,
                   v$active_session_history
            WHERE p1text='idn' AND session_state='WAITING'
            AND sample_time BETWEEN (sysdate - 30/1440) AND sysdate
           ORDER BY sample_id;



SAMPLE_T   SID SQL_ID        EVENT                      IDN  BLKS LOC MUTEX_OBJECT                                                                                                                     
-------- ----- ------------- ------------------- ---------- ----- --- ---------------                  

07:26:55  1207 09h36susy1t4n library cache: mute 3672626424   162   0 LB_STATUS_SEQ                                                                                                                    
07:27:05  1487 09h36susy1t4n library cache: mute 3672626424  1476   0 LB_STATUS_SEQ                                                                                                                    
07:28:57  1480               library cache: mute 2321070391   658   0 PROD                                                                                                                           
07:28:57   658               library cache: mute 2321070391  1429   0 PROD                                                                                                                            
07:28:58  1429               library cache: mute 2924456787  1480   0 DATABASE                                                                                                                         
07:29:19   637 09h36susy1t4n library cache: mute 3672626424   435   0 LB_STATUS_SEQ                                                                                                                    
07:32:18   171 09h36susy1t4n library cache: mute 3672626424   373   0 LB_STATUS_SEQ                                                                                                                    
07:33:20  1426 bg7mbt0mq5j75 library cache: mute 2321070391   645   0 PROD                                                                                                                            
07:33:58   931               library cache: mute 2321070391  1003   0 PROD                                                                                                                            
07:33:58   803               library cache: mute 2321070391   931   0 PROD                                                                                                                            
07:34:26   236 09h36susy1t4n library cache: mute 3672626424   715   0 LB_STATUS_SEQ                                                                                                                    
07:38:57  1272               library cache: mute 2321070391   914   0 PROD                                                                                                                            
07:38:57   449               library cache: mute 2321070391   914   0 PROD                                                                                                                            
07:39:43   517 09h36susy1t4n library cache: mute 3672626424   804   0 LB_STATUS_SEQ                                                                                                                    
07:39:46   507 09h36susy1t4n library cache: mute 3672626424  1004   0 LB_STATUS_SEQ                                                                                                                    
07:39:53   665 09h36susy1t4n library cache: mute 3672626424   914   0 LB_STATUS_SEQ                                                                                                                    
07:40:40   592               library cache: mute 2924456787   720   0 DATABASE                                                                                                                         
07:41:06   990 09h36susy1t4n library cache: mute 3672626424   221   0 LB_STATUS_SEQ      
   

                                                                          
/* Mutex impact */

select event, p1,cnt,
    CASE WHEN (event LIKE 'library cache:%' AND p1 <= power(2,17)) THEN
    'library cache bucket: '||p1   ELSE  (SELECT kglnaobj FROM x$kglob WHERE
    kglnahsh=p1 AND (kglhdadr = kglhdpar) and rownum=1) END mutex_object
    from (select p1,event,count(*) cnt from v$active_session_history where
    p1text='idn' and session_state='WAITING'
    group by p1,event)
    order by cnt desc;


EVENT                       P1        CNT MUTEX_OBJECT                                                                                                                                                 
------------------- ---------- ---------- ---------------                                                                                                                                              
library cache: mute 2321070391        286 PROD                                                                                                                                                       
library cache: mute 2924456787        269 DATABASE                                                                                                                                                     
library cache: mute 3672626424        100 LB_STATUS_SEQ                                                                                                                                                
library cache: mute 1535242682         16 UA_SEQ                                                                                                                                                       
library cache: mute  370351507          5 select substrb(                                                                                                                                              
library cache: mute  950094862          4 select min(minb                                                                                                                                              
library cache: mute      57559          3 library cache b                                                                                                                                              
library cache: mute 1455413935          3 select min(minb                                                                                                                                              
library cache: mute  459016664          2 SYS_GROUP                                                                                    



And of course this mutex_stats.sql useful script by Andrey.

SQL> @mutex_stats.sql mutex_identifier=3672626424
Connected.

--------------------------------------------                                  
Statistics for "Library Cache" mutex                                           
idn: 3672626424 address  0x00000005AE8F4098                                    
Interval:   31.8 s,  gets: 1471, sleeps:4300
                                 

Requests rate:                  lambda=        46.3 Hz                         
Sleeps rate:                    omega=        135.3 Hz                         
Utilization:                    rho=    .040000                                
Exclusive Utilization:          rho_x=  .040000                                
Shared Utilization:             rho_s=  .000000                                
Avg. holding time:              S=     864.45 us                               
Service rate:                   mu=          1156.8 Hz                         
Spin inefficiency:              k=    #########                                

Secondary statistics:                                                         
Slps /Miss:               kappa=#########                                      
Spin_gets/miss:           sigma=#########                                      
correction coeff.         eta= 1.0                                             
Secondary sleeps ratio          .745                                           

--------------------------------------------                                  
Avg. number of  sessions waiting:         .02                                  

Library cache object related to  mutex idn 3672626424 :
                     

SEQUENCE: PROD.LB_STATUS_SEQ                                                  

ADDR:              TYPE        PIN/s:    LOCK/s:    EXEC/s: Namespc           
-------------------------------------------------------------------            
00000005AE8F3F68   Parent          15          0          0       1            

Mutex related parameters:
_kgl_mutex_wait_time=0 _wait_yield_hp_mode=yield    
_wait_yield_mode=yield _wait_yield_sleep_freq=100 _wait_yield_sleep_time_msecs=1
_wait_yield_yield_freq=20                                                      

PL/SQL procedure successfully completed.




***

Jul 5, 2012

SQL with high version count

I was looking at different things when investigating "library cache : mutex x" wait issue. One of the problems were SQL with high version counts. In simple terms it means - for repeated execution of the SQL, child cursor could not be reused and thus a large number of new child cursors have been generated along with the executions.


I found that, one of our SQLs had over 1600 child cursors - which is too much!

SQL> select * from (
select count(sc.sql_id) cursor_count, a.sql_id, a.sql_text
from v$sqlarea a, v$sql_shared_cursor sc
where  a.sql_id = sc.sql_id
group by a.sql_id, a.sql_text
order by cursor_count desc)
where rownum <=10; 

CURSOR_COUNT SQL_ID        SQL_TEXT
------------ ------------- ------------------------------------------------------------
        1693 2vzfs9ww6u3xw INSERT INTO admin_record (id, clnt, clnt_display
                           _name, pr_id, mar_id, mar_medication_id, medication_name,
                           prescriber_id, prescriber_display_name, dosage, total_dosage
                           , total_unit, measurement_unit, form_of_dosage, other_form_o
                           f_dosage, route, other_route, frequency, medication_type, ad
                           minister_time, scheduled_time, record_type, comments, admini
                           stered_by, administered_by_display_name, user_initial, recor
                           ded_by, recorded_by_display_name, updated_by, administer_dat
                           e, record_date, updated_date, administer_date_int, record_da
                           te_int, tz, status, test_form, version, mar_med_row_num, mar
                           _med_column_num, scheduled_entry, schede_date, scheduled_b
                           y_id) VALUES (admin_rec_seq.nextval, :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)



The insert statement consumes the highest amount of shared pool memory by producing so many child cursors. This is because, we are not able to reuse cursors even though we use bind variables. During yesterday problem, the number of child cursors were 1693. Producing so many child cursors (and searching within the list) may causes shared pool mutex waits. This is an issue with 11g where database does not automatically obsolete a parent cursor "anymore" when it reaches 1024 child cursors.

The main problem with this SQL is - there are bind mismatch in most cases when the SQL comes into database for an execution with all its 42 bind variables.


SQL> select bind_mismatch, bind_length_upgradeable
from  v$sql_shared_cursor
where sql_id = '2vzfs9ww6u3xw'
and rownum <=20; 
B B
- -
Y Y
Y N
Y Y
Y Y
Y N
Y N
Y Y
Y Y
Y Y
Y N
Y Y
Y N
Y N
Y N
Y N
Y N
......

......


This should not be happening as we use bind variables. Then I looked at our application code. I found that, the developer picks column values from objects and those values could be null. I found that we need to change the jdbc prepared statement coding style and need to use "java.sql.Types" to set null values when object values are null. This way cursor will understand the bind type and won't create  child cursors for type mismatch caused by setting 'null' explicitly.


For example, for a column we use -

preparedStatement.setObject(

index++, record.getAdministeredBy() != null ? record.getAdministeredBy().getId() : null);


We need to program like -
preparedStatement.setNull(index++, java.sql.Types.INTEGER); 
when the object is null so that the cursor understand the datatype for the bind 
variable.

We are going to fix this soon in production!

Here is a nice article related with high number of child cursor problems.

http://www.usn-it.de/index.php/2010/08/04/oracle112-mutex-s-too-many-child-cursors/

***