Diagnosing and Resolving “gc block lost”

karlarao's picture

Last week, one of our clients had a sudden slow down on all of their applications which is running on two node RAC environment

Below is the summary of the setup:
– Server and Storage: SunFire X4200 with LUNs on EMC CX300
– OS: RHEL 4.3 ES
– Oracle 10.2.0.3 (database and clusterware)
– Database Files, Flash Recovery Area, OCR, and Voting disk are located on OCFS2 filesystems
– Application: Forms and Reports (6i and also lower)

As per the DBA, the workload on the database was normal and there were no changes on the RAC nodes and on the applications. Hmm, I can’t really tell because I haven’t really looked into their workload so I don’t have past data to compare.

I first setup the OS Watcher on both nodes (with 60sec snapshot interval) to have an end-to-end view of the server performance while I’m doing the diagnosis on the database. It’s a cool tool and automatically gathers a lot of info when you start it (cpu, io, memory, network, process info), also this tool has a graphing facility which makes it faster to detect spikes and any trends.

Then, I looked into the database parameters and compared it with the RDA of the database I had before. This is just to check if there are any changes on the parameters that might cause the sudden slow down. Hmm…there was nothing new

Then, I queried on the V$SESSION

SQL> select count(*) from v$session;      -- server1

  COUNT(*)
----------
       385

SQL> select count(*) from v$session;     -- server2

  COUNT(*)
----------
    49

.
I was surprised! The session count on both servers show that there are more users connected on server1 (almost 89% of the total users). This could be because of
1) the clients having lower versions (< Sql*Plus 8.1 or OCI8, see Note 97926.1) that may not support TAF (FAILOVER_MODE) and Load Balancing (LOAD_BALANCE) or
2) they are using TNS entries explicitly connecting to server1
Since the RAC database has different applications connected to it, knowing which applications are on server1 and how many they are will be enough to determine which users on particular applications could be transferred to server2 to at least balance the number of users on both nodes, but doing this may still not solve the issue as I don’t have enough info that this is the root cause of the problem..

The query below shows that all the users don’t have FAILOVER capabilities which could be attributed by the two points I mentioned above

select distinct s.inst_id instance_id, s.failover_type failover_type, s.failover_method
failover_method, s.failed_over failed_over
from gv$session s;
INSTANCE_ID FAILOVER_TYPE        FAILOVER_METHOD      FAILED_OVER
----------- -------------------- -------------------- --------------------
          1 NONE                 NONE                 NO
          2 NONE                 NONE                 NO

.
Below query shows the distinct applications/modules and their count which are all on server1. Also you’ll notice that most of them are inactive (some of these users should connect to server2 to have balance on both nodes)

SQL> select distinct inst_id, module, program, status, count(*)
from gv$session
group by inst_id, module, program, status
order by 1,2,3,4;

   INST_ID MODULE                         PROGRAM                        STATUS       COUNT(*)
---------- -------------------------------------------------- -------------------------------------------------- ---------- ----------
     1 F45RUN32.EXE                       F45RUN32.EXE                   INACTIVE       23       

... output snipped ....

     1 xxxPgm                         xxxPgm                         INACTIVE       21      

... output snipped ....

     1 c:\xxxwin95\BIN\F45RUN32.EXE L:\xxx\VS\FORMS\MAI   c:\xxxwin95\BIN\F45RUN32.EXE L:\xxx\VS\FORMS\MAI   INACTIVE       44
     1 c:\xxxwin95\BIN\F45RUN32.EXE L:\MAIN.FMX       c:\xxxwin95\BIN\F45RUN32.EXE L:\MAIN.FMX       INACTIVE       31
     1 c:\xxxwin95\BIN\F45RUN32.EXE w:\xxxMENU.fmx       c:\xxxwin95\BIN\F45RUN32.EXE w:\xxxMENU.fmx     INACTIVE       14
     1 c:\xxxwin95\BIN\F45RUN32.EXE w:\xxxlogin.fmx       c:\xxxwin95\BIN\F45RUN32.EXE w:\xxxlogin.fmx   INACTIVE       96  

... output snipped ....

     1 c:\xxxwin95\BIN\R25SRV32.exe               c:\xxxwin95\BIN\R25SRV32.exe           INACTIVE       54      

... output snipped ....

     1 ifweb90.exe                        ifweb90.exe                    INACTIVE       11

.
Below info shows some data samples of DBA_HIST_ACTIVE_SESS_HISTORY which is graphed using Tanel Poder’s Perfsheet (could be found here and here) to clearly distinguish the distribution of the modules and number of users. Most of the users on server1 uses the “c:\xxxwin95\BIN\F45RUN32.EXE w:\xxxlogin.fmx”

GcBlocksLost_1_SessionCount

Having the graph above may lead us to conclusion that the significant number of users on server1 attributes to the slow down of the transactions. But as per the DBA, there were no changes made and they were running the same transactions as before on server1 which has acceptable response time. Also the OS Watcher shows that the CPU utilization (peak is 60% and most of the time at 40%) and run queue was low and the disk IO utilization and service time were average (always 10ms below), and there were enough memory on the server (3GB free out of 12GB.. the SGA is 2GB) and no swapping.

Hmm…Drilling down on the wait interface and on per session level that is doing the important business operations will give us a definite conclusion on what is really the bottleneck on the database.

The graph below is another sample from DBA_HIST_ACTIVE_SESS_HISTORY that shows server1 (in blue box) is suffering from “gc cr block lost” and “gc cr multi block request” from 7am to 4pm. The “Metalink Doc ID: 563566.1 gc lost blocks diagnostics” indicates that it is a cluster problem which could be a problem on the network interconnect

GcBlocksLost_2_server1waits

To confirm the bottleneck shown from the sample of DBA_HIST_ACTIVE_SESS_HISTORY (above), the output of ADDM and AWR report from a peak period was analyzed (from 2-3 & 3-4 pm). Below are the output of ADDM and AWR reports:

ADDM output:

          DETAILED ADDM REPORT FOR TASK 'TASK_137854' WITH ID 137854
          ----------------------------------------------------------

              Analysis Period: 28-MAY-2009 from 13:58:59 to 14:59:12
         Database ID/Instance: 3967623528/2
      Database/Instance Names: xxx
                    Host Name: xxx
             Database Version: 10.2.0.3.0
               Snapshot Range: from 15642 to 15643
                Database Time: 3710 seconds
        Average Database Load: 1 active sessions

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

FINDING 1: 52% impact (1917 seconds)
------------------------------------
Cluster multi-block requests were consuming significant database time.

   RECOMMENDATION 1: SQL Tuning, 37% benefit (1389 seconds)
      ACTION: Run SQL Tuning Advisor on the SQL statement with SQL_ID
         "0h0fn2d19adtk". Look for an alternative plan that does not use
         object scans.
         RELEVANT OBJECT: SQL statement with SQL_ID 0h0fn2d19adtk

         ... output snipped ... 

   RECOMMENDATION 2: SQL Tuning, 8.4% benefit (310 seconds)
      ACTION: Run SQL Tuning Advisor on the SQL statement with SQL_ID
         "8jd43xr4rp00u". Look for an alternative plan that does not use
         object scans.
         RELEVANT OBJECT: SQL statement with SQL_ID 8jd43xr4rp00u

         ... output snipped ... 

   RECOMMENDATION 3: SQL Tuning, 4.6% benefit (172 seconds)
      ACTION: Run SQL Tuning Advisor on the SQL statement with SQL_ID
         "6wpgf3s0vzuks". Look for an alternative plan that does not use
         object scans.
         RELEVANT OBJECT: SQL statement with SQL_ID 6wpgf3s0vzuks

         ... output snipped ... 

   SYMPTOMS THAT LED TO THE FINDING:
      SYMPTOM: Inter-instance messaging was consuming significant database
               time on this instance. (94% impact [3488 seconds])
         SYMPTOM: Wait class "Cluster" was consuming significant database
                  time. (94% impact [3488 seconds])

FINDING 2: 51% impact (1874 seconds)
------------------------------------
Global Cache Service Processes (LMSn) in other instances were not processing
requests fast enough.

   RECOMMENDATION 1: DB Configuration, 51% benefit (1874 seconds)
      ACTION: Increase throughput of the Global Cache Service (LMSn)
         processes. Increase the number of Global Cache Service processes by
         increasing the value of the parameter "gcs_server_processes".
         Alternatively, if the host is CPU bound consider increasing the OS
         priority of the Global Cache Service processes.
      RATIONALE: The value of parameter "gcs_server_processes" was "2" during
         the analysis period.

   SYMPTOMS THAT LED TO THE FINDING:
      SYMPTOM: Inter-instance messaging was consuming significant database
               time on this instance. (94% impact [3488 seconds])
         SYMPTOM: Wait class "Cluster" was consuming significant database
                  time. (94% impact [3488 seconds])

FINDING 3: 36% impact (1330 seconds)
------------------------------------
Cluster communications that were retried due to lost blocks consumed
significant database time.

   RECOMMENDATION 1: Host Configuration, 36% benefit (1330 seconds)
      ACTION: Check the configuration of the cluster interconnect. Check OS
         setup like adapter setting, firmware and driver release. Check that
         the OS's socket receive buffers are large enough to store an entire
         multiblock read. The value of parameter
         "db_file_multiblock_read_count" may be decreased as a workaround.
      RATIONALE: The instance was consuming 477 kilo bits per second of
         interconnect bandwidth.

   SYMPTOMS THAT LED TO THE FINDING:
      SYMPTOM: Inter-instance messaging was consuming significant database
               time on this instance. (94% impact [3488 seconds])
         SYMPTOM: Wait class "Cluster" was consuming significant database
                  time. (94% impact [3488 seconds])

#######################################################################

          DETAILED ADDM REPORT FOR TASK 'TASK_137874' WITH ID 137874
          ----------------------------------------------------------

              Analysis Period: 28-MAY-2009 from 14:59:12 to 15:58:44
         Database ID/Instance: 3967623528/2
      Database/Instance Names: xxx
                    Host Name: xxx
             Database Version: 10.2.0.3.0
               Snapshot Range: from 15643 to 15644
                Database Time: 1563 seconds
        Average Database Load: .4 active sessions

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

FINDING 1: 42% impact (654 seconds)
-----------------------------------
Cluster communications that were retried due to lost blocks consumed
significant database time.

   RECOMMENDATION 1: Host Configuration, 42% benefit (654 seconds)
      ACTION: Check the configuration of the cluster interconnect. Check OS
         setup like adapter setting, firmware and driver release. Check that
         the OS's socket receive buffers are large enough to store an entire
         multiblock read. The value of parameter
         "db_file_multiblock_read_count" may be decreased as a workaround.
      RATIONALE: The instance was consuming 134 kilo bits per second of
         interconnect bandwidth.

   SYMPTOMS THAT LED TO THE FINDING:
      SYMPTOM: Inter-instance messaging was consuming significant database
               time on this instance. (88% impact [1371 seconds])
         SYMPTOM: Wait class "Cluster" was consuming significant database
                  time. (88% impact [1372 seconds])

.
AWR output:

WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
xxxxx         3967623528 xxxxxx              2 10.2.0.3.0  YES xxx

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     15642 28-May-09 13:58:58        57      27.0
  End Snap:     15643 28-May-09 14:59:12        64      28.7
   Elapsed:               60.23 (mins)
   DB Time:               61.83 (mins)

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc cr multi block request            19,644       1,902     97   51.3    Cluster
gc cr block lost                      1,011       1,117   1104   30.1    Cluster
enq: WF - contention                    626         268    429    7.2      Other
gc current block lost                   186         203   1089    5.5    Cluster
cr request retry                        678         162    240    4.4      Other

Per Wait Class
~~~~~~~~~~~~~~~~~~
                                                                  Avg
                                       %Time       Total Wait    wait     Waits
Wait Class                      Waits  -outs         Time (s)    (ms)      /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster                        34,450    7.0            3,385      98       6.8
Other                          91,292   64.7              467       5      18.1
User I/O                       26,510     .0              102       4       5.3
Concurrency                    29,668     .0               54       2       5.9
System I/O                     13,360     .0               11       1       2.6
Commit                          1,313     .0                4       3       0.3
Application                     2,374     .0                2       1       0.5
Network                       129,774     .0                0       0      25.7
Configuration                      20     .0                0       0       0.0

#######################################################################

WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
xxxxx         3967623528 xxxxxx              2 10.2.0.3.0  YES xxx

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     15643 28-May-09 14:59:12        64      28.7
  End Snap:     15644 28-May-09 15:58:43        64      29.6
   Elapsed:               59.53 (mins)
   DB Time:               26.05 (mins)

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc cr block lost                        389         429   1103   27.5    Cluster
gc cr multi block request             2,360         422    179   27.0    Cluster
enq: WF - contention                    510         212    416   13.6      Other
gc current block lost                   188         204   1084   13.0    Cluster
cr request retry                        326         181    554   11.6      Other

Per Wait Class
~~~~~~~~~~~~~~~~~~
                                                                  Avg
                                       %Time       Total Wait    wait     Waits
Wait Class                      Waits  -outs         Time (s)    (ms)      /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster                        10,239    8.9            1,247     122       2.1
Other                         153,082   71.9              468       3      31.0
Application                     1,784   18.0              161      90       0.4
Concurrency                    33,014     .0               53       2       6.7
User I/O                        4,246     .0               27       6       0.9
System I/O                     13,648     .0               14       1       2.8
Commit                          1,546     .0                4       3       0.3
Network                       138,333     .0                1       0      28.0
Configuration                      16     .0                0       4       0.0

.
The only thing that is left to do is to drill down on the complaining users and check on the network performance and interconnect… unfortunately the users were going home and I can’t see any significant database activity. So I called it a night, and just analyzed my activity log and read on Metalink Doc ID 563566.1. Also I advised the DBA to divide the users across the nodes.

Next day afternoon, and it’s time to do the drill down. You can see on the graph below (a sample from GV$SESSION) that the users were already distributed, but still there is a performance problem. I told you this will not solve the issue ! </p />
</p></div>
    <div class=»

To prevent automated spam submissions leave this field empty.