Performance After Streams Disabling

Yesterday, user running report called and told that his report is taking too much time. Previously it do completed in 10-15 Minutes approximately but today it ran for almost 1hr 30 minutes. Before going further a brief history on this database.

We were using bi-directional streams for replication but for few reasons to test we had drop stream’s configuration. We didn’t drop entirely just disabled apply and capture process. So, this was the only change we made nothing else was changed for this and reports started running slow.

Meanwhile asked user to run report again and saw some sequential reads nothing much. But, read time was high then it used to be. Other thing i though let’s see what’s happening with all other session

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629680 file#= 59          block#= 9591       blocks= 1

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629682 file#= 59          block#= 9591       blocks= 1
USERX@XXXXXX > @sw  196

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629729 file#= 59          block#= 9591       blocks= 1

USERX@XXXXXX > @sw  196
    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    196 WORKING On CPU / runqueue                               994      629925 file#= 59          block#= 9591       blocks= 1

Strange, May be something is wrong. Let’s Look at all session (Mostly All connected User)

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    117 WORKING On CPU / runqueue                               397      531751 file#= 59          block#= 9591       blocks= 1
     96 WORKING On CPU / runqueue                               685      191592 file#= 59          block#= 9591       blocks= 1
    251 WORKING On CPU / runqueue                               989       22991 file#= 59          block#= 9591       blocks= 1
    105 WORKING On CPU / runqueue                               966      197314 file#= 59          block#= 9591       blocks= 1
    113 WORKING On CPU / runqueue                               494      539386 file#= 59          block#= 9591       blocks= 1
    115 WORKING On CPU / runqueue                               427      189900 file#= 59          block#= 9591       blocks= 1
    117 WORKING On CPU / runqueue                               397      531763 file#= 59          block#= 9591       blocks= 1
    119 WORKING On CPU / runqueue                               547      520586 file#= 59          block#= 9591       blocks= 1
    126 WORKING On CPU / runqueue                               586        7956 file#= 59          block#= 9591       blocks= 1
    127 WORKING On CPU / runqueue                               348      710021 file#= 59          block#= 9591       blocks= 1
    132 WORKING On CPU / runqueue                              1087       18968 file#= 59          block#= 9591       blocks= 1
    104 WORKING On CPU / runqueue                               583      454268 file#= 59          block#= 9591       blocks= 1
    245 WORKING On CPU / runqueue                               669      454299 file#= 59          block#= 9591       blocks= 1
    237 WORKING On CPU / runqueue                              1085      438102 file#= 59          block#= 9591       blocks= 1
    236 WORKING On CPU / runqueue                              1168      453030 file#= 59          block#= 9591       blocks= 1
    231 WORKING On CPU / runqueue                               548      454175 file#= 59          block#= 9591       blocks= 1
    227 WORKING On CPU / runqueue                               600      526299 file#= 59          block#= 9591       blocks= 1
    215 WORKING On CPU / runqueue                               378      515927 file#= 59          block#= 9591       blocks= 1
    211 WORKING On CPU / runqueue                               265        7486 file#= 59          block#= 9591       blocks= 1
    198 WORKING On CPU / runqueue                              1186       21824 file#= 59          block#= 9591       blocks= 1
    196 WORKING On CPU / runqueue                               994      630006 file#= 59          block#= 9591       blocks= 1
    184 WORKING On CPU / runqueue                              1077      449734 file#= 59          block#= 9591       blocks= 1
    182 WORKING On CPU / runqueue                               372      713555 file#= 59          block#= 9591       blocks= 1
    178 WORKING On CPU / runqueue                              1206      454466 file#= 59          block#= 9591       blocks= 1
    175 WORKING On CPU / runqueue                               988      543158 file#= 59          block#= 9591       blocks= 1
    150 WORKING On CPU / runqueue                               595      452974 file#= 59          block#= 9591       blocks= 1
    151 WORKING On CPU / runqueue                               957       22541 file#= 59          block#= 9591       blocks= 1
    157 WORKING On CPU / runqueue                               234        3261 file#= 59          block#= 9591       blocks= 1
    163 WORKING On CPU / runqueue                               582      452932 file#= 59          block#= 9591       blocks= 1
    170 WORKING On CPU / runqueue                               650      449652 file#= 59          block#= 9591       blocks= 1
    202 WORKING On CPU / runqueue                              1093      716105 file#= 59          block#= 9592       blocks= 5

This is Strange. Something must be going on. Also, tried to see what other stats are there picking up any one session but no luck. Nothing was happening. But Yes CPU usage was much high. It’s time to look more

Start dump data blocks tsn: 101 file#: 59 minblk 9591 maxblk 9591
buffer tsn: 101 rdba: 0x0ec02577 (59/9591)
scn: 0x057c.82828596 seq: 0x02 flg: 0x04 tail: 0x85962302
frmt: 0x02 chkval: 0x56c5 type: 0x23=PAGETABLE SEGMENT HEADER
Hex dump of block: st=0, typ_found=1

USERX@XXXXXX > @oid 114474

owner                     object_name                    object_type        CREATED    LAST_DDL_T status    DATA_OBJECT_ID
------------------------- ------------------------------ ------------------ ---------- ---------- --------- --------------
XDB                       XDB$SCHEMA                     TABLE              11/23/2006 11/23/2006 VALID             114474

USERX@XXXXXX > select segment_name,header_file, header_block from dba_segments where owner='XDB' and segment_name='XDB$SCHEMA';

SEGMENT_NAME                                                                      HEADER_FILE HEADER_BLOCK
--------------------------------------------------------------------------------- ----------- ------------
XDB$SCHEMA                                                                                 59         9591

And this object is nothing but table of xmltype. Looking at this it seems like a corruption issue. Verified and this is not the case. Hmmm let’s see what sessions are doing.

USERX@XXXXXX > @usql 117

HASH_VALUE   CH#  PLAN_HASH SQL_TEXT
---------- ----- ---------- --------------------------------------------------------------------------------------------------------------
3767872888     0  677615252 select s.synonym_name object_name, o.object_type from all_synonyms s,      sys.all_objects o where s.owner in
                            ('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
                            ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')

3767872888     1  677615252 select s.synonym_name object_name, o.object_type from all_synonyms s,      sys.all_objects o where s.owner in
                            ('PUBLIC', :schema) and o.owner = s.table_owner and o.object_name = s.table_name and o.object_type in
                            ('TABLE', 'VIEW', 'PACKAGE','TYPE', 'PROCEDURE', 'FUNCTION', 'SEQUENCE')

Tried to run this query manually.

USERX@XXXXXX > select s.synonym_name object_name, o.object_type
  2    from all_synonyms s, sys.all_objects o
  3   where s.owner in ('PUBLIC', 'USERX') <<-- This Bind Variable is Replaced
  4     and o.owner = s.table_owner
  5     and o.object_name = s.table_name
  6     and o.object_type in ('TABLE',
  7                           'VIEW',
  8                           'PACKAGE',
  9                           'TYPE',
 10                           'PROCEDURE',
 11                           'FUNCTION',
 12                           'SEQUENCE');

It hangs And session spins on CPU

USERX@XXXXXX > @sw  176

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                 P2                 P3                 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
    176 WORKING On CPU / runqueue                              1049          66 file#= 59          block#= 9591       blocks= 1

And here is the actual Query which is hanging

 select count(*)  from user$ u, xdb.xdb$schema s  where u.user# = :1  and   u.name  = s.xmldata.schema_owner  and
 (xdb.xdb$Extname2Intname(s.xmldata.schema_url, s.xmldata.schema_owner) = :2)

We are not getting anywhere and still our original problem regarding reports still we haven’t touch itself. Let’s see what our report is doing. The reason why we are leaving this alone is just to solve first user issue and investigate this latter. Also, the report session is not experiencing this thing. I let the system as it is for 1.5 hrs till report complete. Here is the one SQL from report which is running slow and many more.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute    335      0.85       0.81          0          0          0           0
Fetch      335    222.43    2452.93     608516   10434554          0         335
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      670    223.28    2453.75     608516   10434554          0         335

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 1094     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    607989        0.37       2272.88
  gc cr grant 2-way                            7435        0.04          4.63
  latch: cache buffers chains                    21        0.00          0.00
  latch: library cache                            2        0.00          0.00
  latch: gcs resource hash                       17        0.00          0.00

So, Sequential read is the culprit. This what this says. May be we can rewrite or throw some more better index to resolve this. Also, Let’s see statspack report also as we  are having other problem too.

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file scattered read            1,834,168       3,321      2  167.2   User I/O
db file sequential read             383,394       1,443      4   72.7   User I/O
CPU time                                            370          18.6
gc current block 2-way              166,656         122      1    6.2    Cluster
os thread startup                     1,375          79     58    4.0 Concurrenc

cache buffer handles              2,746    0.0    N/A      0            0    N/A
cache buffers chains         77,966,867    0.0    0.0      0   28,852,899    0.0
cache buffers lru chain          10,382    0.5    0.0      0   30,691,321    0.1
cache table scan latch                0    N/A    N/A      0    1,833,334    0.0
channel handle pool latc          2,934    0.0    N/A      0            0    N/A
channel operations paren        326,804    0.0    0.0      0            0    N/A
checkpoint queue latch          105,819    0.0    N/A      0        2,036    0.0

           Tablespace                      Subobject  Obj.      Physical
Owner         Name    Object Name            Name     Type         Reads  %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
STRM       USERS      AQ$_CAPTURE_SDOLTS01            TABLE   14,149,682   92.99
xxxxx      DATA_      AF                              TABLE      726,962    4.78

What wait’s are showing and statspack is showing are somehow different. After looking many other things found that streams’s propagation was still enable and there were lot’s of failed attempt to ping remote server.

So, Disabled and dropped that propagation. Voila, wait on that block was gone and CPU came down instantly. So, called user to try and run report again without changing anything. Same SQL took very less time.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    636      1.79       1.67          0          0          0           0
Fetch      636    185.53     386.00     264380   18954114          0         636
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1273    187.32     387.67     264380   18954114          0         636

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 1094     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                  1        0.00          0.00
  gc cr grant 2-way                            6449        0.00          2.88
  db file sequential read                    264013        0.13        178.93
  gc cr multi block request                       1        0.00          0.00
  db file scattered read                          1        0.00          0.00
  gc current block 2-way                      51453        0.64         39.90

And, report ran in 12 Minutes. Good Lesson learn.

Advertisements

About Taral
I am Rookie to Oracle Technology so let's see where it goes

One Response to Performance After Streams Disabling

  1. Hi great blog! Does running a blog such as this
    require a massive amount work? I have absolutely no expertise in computer programming but I
    was hoping to start my own blog soon. Anyways, should you have any suggestions or techniques for new blog owners please share.
    I understand this is off topic but I simply
    needed to ask. Kudos!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: