12.2 new features: a first encounter with the new Cluster Health Advisor

One of the many new manuals that showed up in Oracle Database 12.2 is the Oracle Autonomous Health Framework User’s Guide. This book contains a lot of information, some of which we already know from previous releases, and some new stuff as well. One of the new chapters caught my eye in particular:

“Proactively Detecting and Diagnosing Performance Issues for Oracle RAC”

Said chapter 5 introduces a new feature, called the Cluster Health Advisor (CHA), that should help you understand the performance of your cluster better. Really? Time to start the VMs to create a test.

My system is based on Oracle Linux 7.3 with UEK4. I created a 2 node 12.2.0.1.0 RAC, there weren’t any patches out at the time of writing. In other words, this function might change a little. My database, named CDB, features 2 PDBs: swingbench1 and swingbench2 (you can already guess where this is heading). It appears that my cluster is a “flex cluster” operating in standard mode. You noticed during configuration that you defined the nodes as “HUB nodes”, didn’t you? I have print screens from my RAC installation that I’ll put into a blog post when I find the time. In the meantime head over to oracle-base.com where you can find a RAC 12.2 installation walkthrough for Oracle Linux on VirtualBox.

The plan for this post is to overload the system deliberately to provoke the health advisor to give me recommendations about the cluster and/or the database.

The official documentation is found here: https://docs.oracle.com/database/122/ATNMS/monitoring-rac-with-cha.htm

How is the Cluster Health Advisory implemented?

As per the documentation, there are Cluster Health Advisory daemon processes found on each node, and sure enough there are:

[oracle@rac122pri1 ~]$ crsctl stat res -t 
--------------------------------------------------------------------------------
Name           Target  State        Server                   State details       
--------------------------------------------------------------------------------
Local Resources
--------------------------------------------------------------------------------
ora.ASMNET1LSNR_ASM.lsnr
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.DATA.dg
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.LISTENER.lsnr
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.MGMT.dg
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.OCR.dg
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.RECO.dg
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.chad
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.net1.network
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.ons
               ONLINE  ONLINE       rac122pri1               STABLE
               ONLINE  ONLINE       rac122pri2               STABLE
ora.proxy_advm
               OFFLINE OFFLINE      rac122pri1               STABLE
               OFFLINE OFFLINE      rac122pri2               STABLE
...

The resource in question is “ora.chad”, and its profile defines dependencies to the GIMR or Grid Infrastructure Management Repository:

[oracle@rac122pri1 ~]$ crsctl stat res ora.chad -p | grep "DEPENDENCIES\b"
START_DEPENDENCIES=hard(global:ora.mgmtdb) pullup(global:ora.mgmtdb)
STOP_DEPENDENCIES=hard(global:intermediate:ora.mgmtdb)
[oracle@rac122pri1 ~]$ 

The documentation further states that the Health Advisor (CHA) Daemon automatically manages cluster nodes. Databases registered in Clusterware however must be registered specifically with the monitoring daemon.

The main tool to interact with the CHA is – chactl (there’s a surprise). It can take quite a few options:

[oracle@rac122pri1 bin]$ chactl -h
CLSCH-3659 : invalid command line syntax
Usage:
chactl monitor cluster [-model  [-force]]
chactl monitor database -db 
                        [-model  [-force]]
chactl unmonitor database -db 
chactl status [cluster|database [-db ]] [-verbose]
chactl config [cluster|database -db ]
chactl calibrate {cluster|database -db }
                 -model  [-force]
                 [-timeranges 'start=,end=,...']
                 [-kpiset 'name= min= max=,...' ]
    WHERE:
        -interval  : interval is in hrs
        -timeranges 'start=,end=,...' :
             Timestamp must be in format 'YYYY-MM-DD HH24:MI:SS'
    KPI for db:
        CPUPERCENT - CPU utilization - Percent
        IOREAD - Disk read - Mbyte/sec
        DBTIMEPERCALL - Database time per user call - usec/call
        IOWRITE - Disk write - Mbyte/sec
        IOTHROUGHPUT - Disk throughput - IO/sec
    KPI for cluster:
        CPUPERCENT - CPU utilization - Percent
        IOREAD - Disk read - Mbyte/sec
        IOWRITE - Disk write - Mbyte/sec
        IOTHROUGHPUT - Disk throughput - IO/sec
chactl query diagnosis [-cluster|-db ]
                       [-start  -end ]
                       [-htmlfile ]
chactl query model [-name  [-verbose]]
chactl query repository
chactl query calibration {-cluster|-db }
        [-timeranges 'start=,end=,...']
        [-kpiset 'name= min= max=,...' ]
        [-interval ]
    WHERE:
        -interval  : interval is in hrs
        -timeranges 'start=,end=,...' :
             Timestamp must be in format 'YYYY-MM-DD HH24:MI:SS'
    KPI for db:
        CPUPERCENT - CPU utilization - Percent
        IOREAD - Disk read - Mbyte/sec
        DBTIMEPERCALL - Database time per user call - usec/call
        IOWRITE - Disk write - Mbyte/sec
        IOTHROUGHPUT - Disk throughput - IO/sec
    KPI for cluster:
        CPUPERCENT - CPU utilization - Percent
        IOREAD - Disk read - Mbyte/sec
        IOWRITE - Disk write - Mbyte/sec
        IOTHROUGHPUT - Disk throughput - IO/sec
chactl remove model -name 
chactl rename model -from  -to 
chactl import model -name  -file  [-force]
chactl export model -name  -file 
chactl set maxretention -time 
chactl resize repository -entities 
   [-force | -eval]
[oracle@rac122pri1 bin]$

The output of the “help” command has been reformatted for readability.

And yes the documentation is right. At first only the cluster resource was monitored.

[oracle@rac122pri1 ~]$ chactl status
monitoring nodes rac122pri2, rac122pri1
not monitoring databases
[oracle@rac122pri1 ~]$ chactl status -verbose
monitoring nodes rac122pri2, rac122pri1 using model DEFAULT_CLUSTER
not monitoring databases
[oracle@rac122pri1 ~]$

Monitoring my database

In the next step I wanted to include my database to the monitoring configuration. That is easy:

[oracle@rac122pri1 ~]$ chactl monitor database -db CDB
[oracle@rac122pri1 ~]$ chactl status -verbose
monitoring nodes rac122pri2, rac122pri1 using model DEFAULT_CLUSTER
monitoring database cdb, instances CDB2, CDB1 using model DEFAULT_DB

Creating load and causing trouble

With the monitoring in place it was time to create some trouble. I started a swingbench run deliberately overloading the CPUs on my cluster. To add to the fun I rebooted a node during the swingbench execution. Although that didn’t stop processing (I used the connection pool method to establish sessions) I caused all of my sessions to pile up on the surviving node. It held its head up, but performance took a nosedive.

Any recommendations?

The Cluster Health Advisor can be interrogated using the “query diagnosis” command. After causing sufficient trouble I asked for a first assessment. Interestingly enough I hit the repository right after I rebooted node 2. I hadn’t checked at the time, but node 2 ran the GIMR – hence this output:

[oracle@rac122pri1 bin]$ chactl query diagnosis -db CDB\
> -start "2017-03-15 05:20:50" -end "2017-03-15 05:55:50"
CLSCH-2005 : Oracle Cluster Health Analysis Service (OCHAD) failed due to a Grid
Infrastructure Management Repository error.
Unable to start the Universal Connection Pool:
oracle.ucp.UniversalConnectionPoolException: Cannot get Connection from Datasource:
java.sql.SQLRecoverableException: Listener refused the connection with the following
error:

ORA-12514, TNS:listener does not currently know of service requested in connect descriptor

After a little while the failed resources were up again, and I could get some output:

[oracle@rac122pri1 bin]$ chactl query diagnosis -db CDB \
> -start "2017-03-15 05:20:50" -end "2017-03-15 05:55:50"
2017-03-15 05:54:40.0  Database cdb  DB Recovery Read IO Performance (CDB1) [detected]
2017-03-15 05:55:00.0  Database cdb  DB Recovery Read IO Performance (CDB1) [cleared]

Problem: DB Recovery Read IO Performance
Description: CHA detected that recovery reads are slower than expected.
Cause: The Cluster Health Advisor (CHA) detected that a database instance left the cluster
unexpectedly and instance recovery had a larger impact on performance than expected
because more database blocks than expected had to be recovered. The data blocks to which
recovery was applied were read from disk or from the global cache.
Action: Decrease the target for the mean time to recover ( MTTR target ) to increase the
incremental checkpointing rate.
[oracle@rac122pri1 bin]$

Spot on!

SQL> show parameter mttr

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
fast_start_mttr_target               integer     0
SQL> 

This is typical for DBCA created databases based on the General_Purpose.dbc template. Good catch!

Now the system was still struggling under load:


SQL> select count(*), a.inst_id, b.name from gv$session a, v$pdbs b
  2  where a.con_id = b.con_id and a.username = 'SOE' group by a.inst_id, b.name;

  COUNT(*)    INST_ID NAME
---------- ---------- ------------------------------
        75          1 SWINGBENCH1

The pool was set to 75 users, but should have been split between both nodes. With the second node down however there was only one to run on.

The operating system didn’t look too happy either:

[root@rac122pri1 trace]# top -b  -n 1 | head -n 15
top - 06:05:08 up 21:14,  2 users,  load average: 15.47, 13.66, 8.69
Tasks: 1403 total,  10 running, 1393 sleeping,   0 stopped,   0 zombie
%Cpu(s):  5.0 us,  2.2 sy,  0.0 ni, 92.5 id,  0.2 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem : 16167836 total,  5510468 free,  4714544 used,  5942824 buff/cache
KiB Swap:   782332 total,   782332 free,        0 used.  7338672 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
10339 root      20   0  158952   5516   3608 R  16.7  0.0   0:00.03 top
10341 root      20   0   28604   5428   3728 R  11.1  0.0   0:00.02 perl
20798 oracle    20   0 2545588 812828 805112 S  11.1  5.0   0:40.34 oracle_20798_cd
20824 oracle    20   0 2543552 817728 809924 S  11.1  5.1   0:40.01 oracle_20824_cd
20828 oracle    20   0 2545592 810800 803068 S  11.1  5.0   0:39.88 oracle_20828_cd
24365 oracle    20   0 2543524 588452 581008 S  11.1  3.6   0:22.72 oracle_24365_cd
24457 oracle    20   0 2543748 596728 588752 S  11.1  3.7   0:22.56 oracle_24457_cd
28569 oracle    20   0 2543524 552440 545016 S  11.1  3.4   0:20.18 oracle_28569_cd
[root@rac122pri1 trace]#

Although I guess that is not too bad for a VM with only 4 cores! Inevitably though there is trouble (but it seems to be over)

[oracle@rac122pri1 bin]$ chactl query diagnosis -db CDB \
> -start "2017-03-15 05:20:00" -end "2017-03-15 06:20:00"
2017-03-15 05:54:40.0  Database cdb  DB Recovery Read IO Performance (CDB1) [detected]
2017-03-15 05:55:00.0  Database cdb  DB Recovery Read IO Performance (CDB1) [cleared]
2017-03-15 05:58:55.0  Database cdb  Long Waits for Global Cache Message Requests (CDB1) [detected]
2017-03-15 05:58:55.0  Database cdb  Long Redo Log Sync Wait (CDB1) [detected]
2017-03-15 06:04:25.0  Database cdb  Long Waits for Global Cache Message Requests (CDB1) [cleared]
2017-03-15 06:04:25.0  Database cdb  Long Redo Log Sync Wait (CDB1) [cleared]

Problem: DB Recovery Read IO Performance
Description: CHA detected that recovery reads are slower than expected.
Cause: The Cluster Health Advisor (CHA) detected that a database instance left the cluster
unexpectedly and instance recovery had a larger impact on performance than expected because
more database blocks than expected had to be recovered. The data blocks to which recovery
was applied were read from disk or from the global cache.
Action: Decrease the target for the mean time to recover ( MTTR target ) to increase the
incremental checkpointing rate.

Problem: Long Waits for Global Cache Message Requests
Description: CHA detected that global cache messages are taking a long time.
Cause: The Cluster Health Advisor (CHA) detected that global cache messages have not
completed and are blocking database processes. It is likely that Global Cache Server
Processes (LMS) on another node are unresponsive or are waiting for CPU or Memory.
Action: Check whether CHA reports any issues related to severe performance degradation
caused by CPU or memory starvation on other nodes in the cluster and follow the suggestions
to resolve those problems.

Problem: Long Redo Log Sync Wait
Description: CHA detected that commits are blocked for several seconds.
Cause: The Cluster Health Advisor (CHA) detected that commits are blocked for several
seconds because cluster commit progagation messages are very slow. It is likely that a
Global Cache Server Process (LMS) on another node is unresponsive or is waiting for CPU
or Memory.
Action: Check whether CHA reports any issues related to severe performance degradation
on other nodes in the cluster. Resolve the problems found on other nodes and instances
of this database in the cluster.
[oracle@rac122pri1 bin]$

I really like the text representation because I like the command line. For those of us who prefer a more aesthetically pleasing representation of the data, you can also create a HTML version of the findings specifying the htmlfile flag.

What else?

Going over the list of options again I found a few more that look interesting. For instance, what’s the footprint of this information in the repository? Query it:

[oracle@rac122pri1 bin]$ chactl query repository

specified max retention time(hrs): 72
available retention time(hrs)    : 307
available number of entities     : 17
allocated number of entities     : 4
total repository size(gb)        : 15.00
allocated repository size(gb)    : 1.29
[oracle@rac122pri1 bin]$ 

And what are these models I see when querying the status? DEFAULT_DB and DEFAULT_CLUSTER exist:

[oracle@rac122pri1 bin]$ chactl query model
Models: DEFAULT_CLUSTER, DEFAULT_DB

[oracle@rac122pri1 bin]$ chactl query model -name DEFAULT_DB
Model: DEFAULT_DB
Target Type: DATABASE
Version: 12.2.0.1_0
OS Calibrated on: 
Calibration Target Name: 
Calibration Date: 
Calibration Time Ranges: 
Calibration KPIs: 
[oracle@rac122pri1 bin]$ 

The documentation elaborates, it is possible to calibrate the tool to better reflect the environment.

This is actually quite useful, however I doubt many clusters will deviate from the standard model. Anyway, if you want to calibrate your cluster to a specific workload, you start of querying CHA to check if it has sufficient data. In my case I could dream up a scenario called “swingbench run”.

The cluster as such comes first:

[oracle@rac122pri1 bin]$ chactl query calibration -cluster -timeranges 
>'start=2017-03-15 05:20:00,end=2017-03-15 06:20:00'

Cluster name : rac122pri
Start time : 2017-03-15 05:20:00
End time : 2017-03-15 06:30:00
Total Samples : 1647
Percentage of filtered data : 100%

1) Disk read (ASM) (Mbyte/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
1.19      0.45      3.71      0.00      86.69   

<25       <50       <75       =100    
99.64%    0.18%     0.12%     0.06%     0.00%    

2) Disk write (ASM) (Mbyte/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
3.14      0.42      4.67      0.00      61.67   

<50       <100      <150      =200    
99.94%    0.06%     0.00%     0.00%     0.00%    

3) Disk throughput (ASM) (IO/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
339.59    100.00    512.97    0.00      9700.00 

<5000     <10000    <15000    =20000  
99.88%    0.12%     0.00%     0.00%     0.00%    

4) CPU utilization (total) (%)

MEAN      MEDIAN    STDDEV    MIN       MAX     
37.89     16.80     33.90     4.30      99.90   

<20       <40       <60       =80     
55.68%    7.35%     3.76%     4.74%     28.48%   

[oracle@rac122pri1 bin]$ 

As per the command’s help message you can limit the output of KPIs. Similarly you can check if you have enough data for the database.

[oracle@rac122pri1 bin]$ chactl query calibration -db CDB -timeranges \
> 'start=2017-03-15 05:20:00,end=2017-03-15 06:20:00'
Database name : cdb
Start time : 2017-03-15 05:20:00
End time : 2017-03-15 06:30:00
Total Samples : 1632
Percentage of filtered data : 100%

1) Disk read (ASM) (Mbyte/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
1.16      0.46      3.61      0.00      86.69   

<25       <50       <75       =100    
99.69%    0.12%     0.12%     0.06%     0.00%    

2) Disk write (ASM) (Mbyte/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
3.17      0.43      4.69      0.00      61.67   

<50       <100      <150      =200    
99.94%    0.06%     0.00%     0.00%     0.00%    

3) Disk throughput (ASM) (IO/sec)

MEAN      MEDIAN    STDDEV    MIN       MAX     
341.61    100.00    514.31    0.00      9700.00 

<5000     <10000    <15000    =20000  
99.88%    0.12%     0.00%     0.00%     0.00%    

4) CPU utilization (total) (%)

MEAN      MEDIAN    STDDEV    MIN       MAX     
37.94     16.75     33.99     4.30      99.90   

<20       <40       <60       =80     
55.82%    7.17%     3.62%     4.66%     28.74%   

5) Database time (per user call) (usec/call)

MEAN      MEDIAN    STDDEV    MIN       MAX     
108878.33  6712.80   2778378.28  0.00      93077792.00

<10000000  <20000000  <30000000  <40000000  <50000000  <60000000  =70000000
99.88%    0.00%     0.00%     0.00%     0.00%     0.00%     0.06%     0.06%    

[oracle@rac122pri1 bin]$ 

Be careful though, sometimes you don’t have enough data! I saw a message like this when setting the window to 30 minutes:

[oracle@rac122pri1 ~]$ chactl query calibration -cluster \
> -timeranges 'start=2017-03-15 05:50:00,end=2017-03-15 06:20:00'

Cluster name : rac122pri
Start time : 2017-03-15 05:50:00
End time : 2017-03-15 06:20:00
Total Samples : 687
Percentage of filtered data : 100%
The number of data samples may not be sufficient for calibration.
...

It looks like you can leave it at that, or create a new, more accurate model with finer granularity. Interesting new features await!