9. Database Forensics and Tuning Using AWR Analysis: Part I
Oracle utilities such as Statspack and Automatic Workload Repository (AWR) reports provide the database administrator (DBA) or tuner detailed information concerning a snapshot of database execution time. This snapshot provides statistics on wait events, latches, storage input and output volumes and timings, as well as various views of memory and SQL activities.
The statistics and insights into the memory, I/O, and SQL performance characteristics are invaluable aids in determining whether a database is functioning optimally. Unfortunately, there is such a plethora of data in most AWR reports that DBAs often feel overwhelmed and may miss important clues about database performance issues.
This chapter provides a guide to interpreting the AWR results so that even a novice DBA can glean valid, actionable results from review of an AWR report.
What Is AWR?
The AWR provides a set of tables in which snapshots of system statistics are kept. Generally, these snapshots are taken on an hourly basis, but the DBA can use the DBMS_WORKLOAD_REPOSITORY package to change internal settings. Following is an example:
BEGIN
DBMS_WORKLOAD_REPOSITORY.MODIFY_SNAPSHOT_SETTINGS(
retention => 44640,interval => 15, topnsql => 50,
dbid => 6611949349);
END;
/
This code would reset the retention of data from the default of 7 days to 31 days, the interval between collection of datasets from every 60 minutes to every 15 minutes, and the number of SQL statements collected to the top 50 statements in each category for the database whose ID is 6611949349. The dbid doesn’t have to be included if you are modifying the default instance.
The statistics gathered include wait interface statistics, top SQL statements, tablespace- and object-level I/O and memory, and cumulative I/O information up to the time of the capture. The basic AWR report process takes the cumulative data from two snapshots, subtracts the earlier snapshot’s cumulative data from the later snapshot, and then generates a delta report showing the statistics and information relevant for the time period requested. AWR is a more advanced version of the old Statspack reports that has been automated and made integral to Oracle’s automated tuning processes.
The AWR reports can be run manually from SQL scripts contained in the $ORACLE_HOME/rdbms/admin directory on Linux, UNIX, HP-UX, and AIX systems. The basic reports are generated by the following SQL scripts:
awrrpt.sql: Standard default, single-instance, two-dataset delta report
awrrpti.sql: Standard specific-instance, two-dataset delta report
awrsqrpt.sql: Report for a single specified SQL statement in default instance
awrsqrpti.sql: Report for a single specified-instance single SQL statement, for a range of snapshot IDs
awrddrpt.sql: Report on default instance comparing two intervals
awrddrpi.sql: Report for a specific instance for a specified set of two intervals
awrgrpt.sql: Global report for all instances in the default RAC database
awrgdrpt.sql: Global report for all instances in a specific RAC database
The global reports collect the basic statistics for an Oracle Real Application Cluster (RAC) database set of instances.
Note
The global reports do not contain as rich a set of data as is available in single-instance reports. A single-instance report can be run in a RAC environment, and running single reports for each instance in the RAC database can provide better insights into some problems than running the global reports.
AWR reports are run internally each hour, and the findings are reported to the OEM interface. The user can use the Oracle Enterprise Manager (OEM) or manual processes to create a full AWR report either in text or in HTML format. These text or HTML reports are what we will be examining in this chapter and the next.
Knowing What to Look For
Before examining AWR reports, DBAs should be familiar with the basic wait events that Oracle may encounter and the typical latches that may cause performance issues. They also should be aware of what a typical performance profile looks like for their system. Usually, by examining several AWR reports from periods of normal or good performance, DBAs can acquaint themselves with the basic performance profile of their database.
Generally, DBAs should examine AWR reports from each of their production databases several times a week. These examinations should be quick and isolated to specific indicators that are helpful in the specific environment. For example, the majority physical I/O statistic for a non-Exadata online transaction processing system should be db file sequential read. By knowing the usual duration of a specific timeframe and what the average latency for this type of wait usually is, a DBA can determine if performance is becoming abnormal should this statistic start showing anomalous behavior.
On Exadata, the cell single-block physical read and cell multiblock physical read indicate that the Exadata system is not doing scans but instead is doing physical single-block and multiblock reads, which aren’t as efficient.
Things to notice in the baseline reports are normal levels of specific wait events and latches and what is the normal I/O profile (normal I/O rates and timings for the database files). Other items to look at are the number and types of sorts and the memory layout and program global area (PGA) activity levels.
Note
To learn which waits, latches, and statistics are significant, it is suggested that DBAs become familiar with the Oracle Tuning Guide and Concepts Manual (https://docs.oracle.com/cd/E11882_01/server.112/e41573.pdf). Tuning books by outside authors can also provide more detailed insight into Oracle tuning techniques and concepts.
The use of the Oracle Grid Control graphics for performance can also help DBAs spot anomalous behavior and allow them to drill down into AWR, Active Session History (ASH), and Automatic Database Diagnostic Monitor (ADDM) reports to analyze the cause.
Header Section
Unless you are looking for a specific problem, such as a known SQL issue, it is usually best to start with the topmost data in the AWR report and drill down into the later sections, as indicated by the wait events and latch data. The first section of an AWR report shows general data about the instance. Listing 9.1 shows an example header section.
WORKLOAD REPOSITORY report for
DB Name DB Id Instance Inst Num Startup Time Release RAC
------------ ----------- -------- -------- --------------- ----------- ---
AULTDB 4030696936 aultdb1 1 04-Aug-08 10:16 11.1.0.6.0 YES
Host Name Platform CPUs Cores Sockets Memory(GB)
---------------- --------------------------- ---- ----- ------- ----------
aultlinux3 Linux IA (32-bit) 2 1 1 2.97
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 91 04-Aug-08 12:00:15 41 1.2
End Snap: 92 04-Aug-08 13:00:28 47 1.1
Elapsed: 60.22 (mins)
DB Time: 139.52 (mins)
Cache Sizes Begin End
~~~~~~~~~~~ ------- ----------
Buffer Cache: 1,312M 1,312M Std Block Size: 8K
Shared Pool Size: 224M 224M Log Buffer: 10,604K
The report header gives us information about the instance upon which this report was run. The AWR header was expanded to include data about the platform, CPUs, cores, and sockets as well as memory available in the server. The instance number, whether this is a RAC database, and the release level of the database are shown here. The header also includes startup time as well as the times for the two snapshots used to generate the report. The delta-t between the snapshots is also calculated and displayed. Following the instance and snapshot data, the cache sizes section gives basic data about the buffer pool, shared pool, standard block, and log buffer sizes.
Tip
All of this information in the first part of the header of the AWR report forms the foundation that we draw from to gauge whether a statistic is reasonable. For example, if we see that the system is a RAC-based system, then we know to expect RAC-related statistics to be included in the report. If we see a large number of CPUs, then we might expect to see parallel query–related numbers. The knowledge of whether a system is Linux, UNIX, AIX, Windows, or some other supported platform is also valuable in tracking down platform-specific issues.
You should pay attention to the duration of a snapshot window the report was run against. If the window is too long, then too much averaging of values could distort the true problem; if the period is too short, important events may have been missed. All in all, you need to understand why a report was generated: Was it for a specific SQL statement? If so, it might be a short duration report. Was it for a non-specific problem you are trying to isolate? Then it could be from 15 minutes to a couple of hours in duration.
Also pay attention to the number of sessions at the beginning and end of the report. This can tell you if the load was constant, increasing, or decreasing during the report period.
The second section of the report header contains load information and is shown in Listing 9.2.
Listing 9.2 Load-Related Statistics in Header
Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ ------------- --------------- ---------- ----------
DB Time(s): 2.3 7.1 0.63 1.05
DB CPU(s): 0.3 0.9 0.07 0.13
Redo size: 800.5 2,461.8
Logical reads: 6,307.6 19,396.7
Block changes: 3.6 10.9
Physical reads: 2,704.9 8,317.8
Physical writes: 86.9 267.3
User calls: 2.2 6.8
Parses: 2.0 6.1
Hard parses: 0.0 0.1
W/A MB processed: 932,965.4 2,868,990.9
Logons: 0.1 0.2
Executes: 3.7 11.3
Rollbacks: 0.1 0.3
Transactions: 0.3
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 99.97
Buffer Hit %: 96.09 In-memory Sort %: 100.00
Library Hit %: 98.17 Soft Parse %: 97.88
Execute to Parse %: 45.80 Latch Hit %: 99.95
Parse CPU to Parse Elapsd %: 0.00 % Non-Parse CPU: 99.77
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 81.53 85.39
% SQL with executions>1: 79.29 79.48
% Memory for SQL w/exec>1: 76.73 78.19
Load Profile
The critical things to watch for in the load section depend on the type of application issue you are trying to resolve. For example, in the header section in Listing 9.2, we see a large number of physical reads and logical reads with few block changes. This profile is typical for a reporting environment such as a data warehouse or decision support system (DSS). Seeing this large number of logical and physical reads should key us to look at I/O-related issues for any database performance problems. An additional sign that this is probably a warehouse or DSS environment is the large amount of work area (W/A) processing occurring, which indicates a high number of sort operations are taking place. A further indicator is that the user calls and parses are low, indicating that the transactions contain few statements and are long running.
In a predominantly online transaction processing (OLTP) system, we would expect to see more logical reads; few physical reads; many user calls, parses, and executes; as well as rollbacks and transactions. Generally, report environments have fewer and longer transactions that utilize the work area, whereas OLTP environments tend to have numerous small transactions with many commits and rollbacks.
Instance Efficiencies
The next section of the header shows us the instance efficiency percentages; generally, you want these as close as possible to 100 percent. As you can see, all of our efficiencies are near to 100 percent with the exception of execute to parse and parse CPU to parse elapsed. Since we are dealing with a reporting system, it will probably generate a great number of ad-hoc reports. By their nature, ad-hoc reports are not reusable, so we will have low values for parse-related efficiencies in this type of system. In an OLTP system, where transactions are usually repeated over and over again, we would expect the parse-related efficiencies to be high as long as cursor sharing and bind variables were being properly utilized.
If we saw that the buffer nowait and buffer hit percentages were low (less than 95), we would investigate whether the data block buffers were being properly used and whether we might need to increase data block buffer sizes.
If the library hit percentage was low, we would consider increasing the shared pool allocation or at least look into why its percentage was low (as it could be improper bind variable usage).
The redo nowait percentage tells us how efficiently our redo buffers are being utilized, and if the percentage is low, we need to look at tuning the redo log buffers and redo logs. If processes are waiting on redo, then either the buffers are too small or something is blocking the redo logs from being reused in a proper manner. For example, in an archive log situation, if there are insufficient logs, then the system may have to wait on the archive log process while it copies a log to the archive location, decreasing the nowait percentage.
The memory sort percentage tells us if our PGA_AGGREGATE_TARGET or—if manual settings are used—SORT_AREA_SIZE, HASH_AREA_SIZE, and bitmap settings need to be examined. Numbers less than 100 for the sort percentage indicate that sorts are going to disk. Sorts going to disk are slow and can cause significant performance issues.
Note
Even 1 to 2 percent of sorts or temporary segments going to storage rather than memory can entail a huge amount of I/O, and you need to find and mitigate sorts and temporary segments to storage as much as possible.
The soft parse percentage tells us how often the SQL statement we submit is being found in the cursor caches. This statistic is directly related to proper bind variable usage and how much ad-hoc SQL generation is taking place in our system. Hard parses cause recursive SQL statements and are quite costly in processing time. In a system where SQL is being reused efficiently, this statistic should be near one hundred percent.
Latch hit percentage tells us how often we are waiting on latches. If we are frequently spinning on latches, this value decreases. If this percentage is low, look for CPU-bound processes and issues with latching.
The non-parse CPU percentage tells us how much of the time the CPU is spending on processing of our request versus how much time it is spending doing things like recursive SQL. If this percentage is low, look at the parse-related percentages, as they too will be low. When this percentage is low, it indicates the system is spending too much time processing SQL statements and not enough time doing real work.
Shared Pool Memory
The next section of the header shows us the shared pool memory statistics. One of the main purposes of the shared pool is to provide a preparsed pool of SQL statements that can quickly be reused. This header section shows the amount of memory that is being utilized for reusable statements. Generally, if the percentages are in the 70 to 80 percent range or higher, good reuse is occurring in the database. If the percentages are less than 70 percent, the application should be reviewed for proper SQL statement reuse techniques, such as Procedural Language/Structured Query Language (PL/SQL) encapsulation and bind variable utilization.
Wait Events
The next few sections of the header really help point the DBA or tuning user to the source of problems causing the performance issues in the database. This next section is shown in Listing 9.3.
Listing 9.3 Wait, CPU, and Memory Statistics
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
Wait % DB
Event Waits Time (s) (ms) Time Wait Class
------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 465,020 3,969 9 47.4 User I/O
DB CPU 995 11.9
db file parallel read 2,251 322 143 3.8 User I/O
db file scattered read 15,268 153 10 1.8 User I/O
gc current block 2-way 108,739 116 1 1.4 Cluster
Host CPU (CPUs: 2 Cores: 1 Sockets: 1)
~~~~~~~~ Load Average
Begin End %User %System %WIO %Idle
--------- --------- --------- --------- --------- ---------
0.37 3.05 10.6 6.7 45.3 82.6
Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 14.8
% of busy CPU for Instance: 85.0
%DB time waiting for CPU - Resource Mgr: 0.0
Memory Statistics
~~~~~~~~~~~~~~~~~ Begin End
Host Mem (MB): 3,041.4 3,041.4
SGA use (MB): 1,584.0 1,584.0
PGA use (MB): 169.0 301.7
% Host Mem used for SGA+PGA: 57.64 57.64
Of the statistics in this next section of the header, the top five wait statistics are probably the most important. The wait interface in Oracle stores counters for waits and timings for several hundred wait events that instrument the internals of the database. By examining the wait statistics, you can quickly find the pinch points for performance in your database. In our example in Listing 9.3, we can see the following statistics are the dominant waits:
Avg
Wait % DB
Event Waits Time (s) (ms) Time Wait Class
------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 465,020 3,969 9 47.4 User I/O
db file parallel read 2,251 322 143 3.8 User I/O
db file scattered read 15,268 153 10 1.8 User I/O
Notice that all of the events are dealing with the I/O subsystem. In this system, the I/O subsystem consists of dual 1 Gb host bus adapters (HBAs) on each node using multipath talking through a Brocade 2250 switch to two JBOD (just a bunch of disks) arrays, one holding 18 to 72 Gb 10-K disks and one holding 8 to 72 Gb 10-K disks. The disks are using the “stripe and mirror everything” (SAME) methodology as implemented through Oracle ASM: two of the disks are being used for voting and cluster configuration files for the cluster ready services, leaving 24 disks to service the database in two-disk groups, one with 16 disks using normal redundancy and the other using 8 disks with external redundancy. Obviously, with 54 percent of the wait activity (and probably more) being I/O related, our I/O subsystem on this RAC setup is being stressed.
Note
The CPU is showing 11.9 percent usage during this period. In a properly tuned system, the CPU should show the dominant time percentage.
Other wait events that could dominate a RAC environment could be redo log related, interconnect related, or undo tablespace related. Note that the fifth-largest wait was gc current block 2-way. This indicates that the same block was being shared back and forth across the interconnect. Of course, since this is a parallel query environment with the parallel query being not only cross table and cross index but also cross node, some amount of interconnect-related waits are expected. However, if gc-related waits dominated the top five wait events section, this would indicate there was definite stress on the interconnect and it was a significant source of wait issues.
In this case, the predominant wait is db file sequential read, which indicates that single-block reads (i.e., index reads) are causing issues. Normally, this would be resolved by adding more DB block cache memory (server memory); however, our system is memory constrained, so if we can’t remove the waits, we must look to reducing the wait time per incident. By increasing the number of disks in the array and increasing the spread of the files causing the reads, we could possibly get this wait to as small as 5 ms (maybe lower if we move to a more expensive cached storage area network [SAN] setup), but this would be the limit in a disk-based system. The only way to further reduce the value would be to increase the amount of server memory through a server upgrade or decrease the read latency by moving to something like all flash arrays. The other read-based waits would also benefit from either more memory or faster I/O subsystems.
The other major wait that is usually seen when an I/O subsystem is stressed is db file scattered read, which indicates full table or index scans are occurring. Full table scans can usually be corrected by proper indexing. However, in DSS or warehouse situations, this may not always be possible. In the case of DSS or data warehouses, use of partitioning can reduce the amount of data scanned. However, each disk read is going to require at least 5 ms, and the only way to beat that is through large-scale caching or the use of all flash arrays to reduce latency.
Tip
In DSS systems, the schema should be in what is known as a star configuration in which a central fact table is surrounded by many dimension tables. The fact table acts as an intersection table for the dimensions. By putting bitmap indexes on the foreign keys and setting the initialization parameter STAR_TRANSFORMATION_ENABLED to TRUE, Oracle can use highly efficient star transformation queries to process the large queries related to DSS systems in a fraction of the time and I/O required by full table scans.
When db file sequential read or db file scattered read are the significant wait sources, the DBA needs to look in the SQL sections of the report to review the top SQL statement that is generating excessive logical or physical reads. Usually, if a SQL statement shows up in two or more of the SQL subsections, it is a top candidate for tuning actions.
A key indicator of log file stress (redo logs) would be the log file sync, log file parallel write, log file sequential write, log file single write, or log file switch completion wait events being dominant in the top five wait event listing. However, you must make sure that the wait is truly from I/O-related issues, and not issues such as archive logging, before taking proper action. Usually, log file stress occurs when the log files are being placed on the same physical disks as the data and index files and can usually be relieved by moving the logs to their own disk array section or utilizing a single logical unit number (LUN) for redo logs separate from other files when dealing with a flash memory–based storage system. However, if high wait times for log-related events occur, then moving the logs to a lower-latency I/O subsystem is indicated.
Load Average
The next section of the report shows the breakdown of the CPU timing and run queue status (load average) for the time interval. In this case, the load average corresponds to the ratio of DB time to the amount of time expected to be provided by a single CPU. Since DB time is made up of DB CPU, I/O wait, and non-idle event time, it can reflect excessive I/O wait and not high CPU usage when load is high.
Note
If the period of the report covers more than one AWR collection interval, the Load section will show an entry for each collection.
Host CPU (CPUs: 2 Cores: 1 Sockets: 1)
~~~~~~~~ Load Average
Begin End %User %System %WIO %Idle
--------- --------- --------- --------- --------- ---------
0.37 3.05 10.6 6.7 45.3 82.6
The run queue tells you how many processes are waiting to execute. If the run queue exceeds the number of available CPUs, and CPU is not idle, then increasing the number of CPUs or upgrading the speed of CPUs is indicated, assuming all other tuning actions, such as reducing recursion, have been accomplished. As you can see from the report, our CPU was 83 percent idle during the period, while I/O waits was 45 percent; thus, CPU stress was not causing the run queue of 3: it was most likely I/O-related wait activity.
The other statistics in the section show the amount of time utilized in user and system modes of the CPU as well as the percentage of time the CPU was idle and the average I/O wait. If the I/O wait percentage is high, then increasing the number of disks (after proper tuning has occurred) may help. If you have already tuned SQL and reduced I/O to its lowest possible value through tuning and I/O wait is still a large percentage of the total waits, then your only choice is moving to a lower-latency I/O subsystem, such as an all flash array.
Instance CPU
Following the CPU timing section is the Instance CPU section, which shows how efficiently this instance was using the CPU it was given:
Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 14.8
% of busy CPU for Instance: 85.0
%DB time waiting for CPU - Resource Mgr: 0.0
This instance utilized the total CPU time available for only 14.8 percent of the time; of that 14.8 percent CPU, it utilized the time 85 percent for processing. Since no resource groups are in use in the database, zero percent of the CPU was used for resource management using the resource manager. This again points out that the system was I/O bound, leaving the system basically idle while it waited on disks to serve data.
Memory Statistics
The last section of the header deals with memory usage:
Memory Statistics
~~~~~~~~~~~~~~~~~ Begin End
Host Mem (MB): 3,041.4 3,041.4
SGA use (MB): 1,584.0 1,584.0
PGA use (MB): 169.0 301.7
% Host Mem used for SGA+PGA: 57.64 57.64
According to Oracle you should use only about 60 percent of the memory in your system for Oracle. However, as memory sizes increase, this old saw is showing its age. In memory-constrained 32-bit systems such as the one this report came from, 60 percent is probably a good point to shoot for with Oracle memory usage. As you can see, this instance is using 57.64 percent, so it is pretty close to the 60 percent limit. The rest of the memory is reserved for process and operating system requirements. We can see that our system global area (SGA) remained fairly stable at 1,584 MB, while our PGA usage grew from 169 to 302 MB. This again points to the system being a report DSS or data warehouse system that is utilizing a lot of sort area.
RAC-Specific Pages
After the header and system profiles area is a RAC-specific section that will not be present if RAC is not being used. The first part of the RAC-specific statistics deal with profiling the global cache load. This section of the report is shown in Listing 9.4.
RAC Statistics DB/Inst: AULTDB/aultdb1 Snaps: 91-92
Begin End
----- -----
Number of Instances: 2 2
Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 26.51 81.54
Global Cache blocks served: 26.02 80.01
GCS/GES messages received: 156.31 480.68
GCS/GES messages sent: 157.74 485.06
DBWR Fusion writes: 0.01 0.04
Estd Interconnect traffic (KB) 481.59
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 95.44
Buffer access - remote cache %: 0.65
Buffer access - disk %: 3.91
RAC Statistics (CPU)
The first part of the listing shows how many instances we started with in the RAC environment and how many we ended up with. This information is important because cross-instance parallel operations would be directly affected with loss of or addition of any instances to the RAC environment.
Global Cache Load Statistics
The next section of the RAC report is the Global Cache Load Profile. This profile shows how stressed the global cache may have been during the period monitored. In the report previously shown, we transferred only 481 KB/sec across an interconnect capable of handling 100 MB/sec, so we were hardly using the interconnect in spite of our cross-instance parallel operations. This is further shown by the low Buffer Access – Remote cache statistic of 0.65 percent, which tells us only 0.65 percent of our blocks came from the other node’s RAC instance.
Things to watch out for in this section are severe instance unbalancing where the Global Cache blocks received versus the Global Cache blocks served is way out of alignment (they should be roughly equal). Another possible indication of problems is excessive amounts of database writer (DBWR) fusion writes; fusion writes should be done only for cache replacement, which should be an infrequent operation.
Tip
If fusion writes are excessive, it could indicate inadequately sized DB block cache areas, excessive checkpointing, excessive commits, or a combination of all three.
Global Cache and Enqueue Services
The next RAC-specific section deals with the actual timing statistics associated with the global cache. You need to pay close attention to the various block service timings. If the time it takes to serve a block across the interconnect exceeds the time it would take to read it from disk, then the interconnect is becoming a bottleneck instead of a benefit. The section is shown in Listing 9.5.
Listing 9.5 Global Cache and Enqueue Workload Section
Global Cache and Enqueue Services - Workload Characteristics
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg global enqueue get time (ms): 0.2
Avg global cache cr block receive time (ms): 1.8
Avg global cache current block receive time (ms): 1.8
Avg global cache cr block build time (ms): 0.0
Avg global cache cr block send time (ms): 0.1
Global cache log flushes for cr blocks served %: 0.8
Avg global cache cr block flush time (ms): 17.5
Avg global cache current block pin time (ms): 0.0
Avg global cache current block send time (ms): 0.1
Global cache log flushes for current blocks served %: 0.0
Avg global cache current block flush time (ms): 20.0
Global Cache and Enqueue Services - Messaging Statistics
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg message sent queue time (ms): 1.1
Avg message sent queue time on ksxp (ms): 1.3
Avg message received queue time (ms): 0.1
Avg GCS message process time (ms): 0.0
Avg GES message process time (ms): 0.0
% of direct sent messages: 35.13
% of indirect sent messages: 64.34
% of flow controlled messages: 0.54
-------------------------------------------------------------
The most important statistics in this section are the following:
Avg global cache cr block receive time (ms): 1.8
Avg global cache current block receive time (ms): 1.8
These should be compared to an AWR report run on the other instance:
Avg global cache cr block receive time (ms): 2.1
Avg global cache current block receive time (ms): 1.7
If the numbers on both or all RCA instances aren’t similar, then this could indicate a problem with the interconnect either at the OS buffer level or the NIC or interface cards themselves.
Notice the high flush values in Listing 9.5. These are not the correct values and probably point to an issue with the way AWR is collecting the data, since they are a direct input to the product that results in the receive times, which are not more than 3 ms.
The global enqueue timing numbers should be less than 2 to 3 ms in most cases. If they get anywhere near the 20 ms, as stated in the Oracle documents, you have a serious issue with the Global Enqueue Service (GES) part of the global dictionary.
Cluster Interconnects
The last part of this RAC-specific section deals with the interconnect:
Cluster Interconnect
~~~~~~~~~~~~~~~~~~~~
Begin End
---------------------------------------------- -----------
Interface IP Address Pub Source IP Pub Src
---------- --------------- --- -------------c------------- --- --- ---
eth0 11.1.1.1 N Oracle Cluster Repository
You should verify that the interconnect is the proper private interconnect and that it is not a public Ethernet. If you see excessive Global Cache Service (GCS) values in previous sections, be sure that the proper interconnect is being used.
Time Model Statistics
Another nice addition to the statistics in AWR over Statspack are the time breakdown statistics that show the components of CPU, OS, and other time fields. The first shown is the CPU statistics breakdown, shown in Listing 9.6.
Listing 9.6 CPU Time Breakdown
Time Model Statistics DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> Total time in database user-calls (DB Time): 8371.3s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name
Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 8,145.5 97.3
DB CPU 995.1 11.9
parse time elapsed 7.4 .1
hard parse elapsed time 5.2 .1
PL/SQL execution elapsed time 4.8 .1
Java execution elapsed time 0.7 .0
hard parse (sharing criteria) elapsed time 0.2 .0
sequence load elapsed time 0.1 .0
repeated bind elapsed time 0.1 .0
PL/SQL compilation elapsed time 0.0 .0
failed parse elapsed time 0.0 .0
hard parse (bind mismatch) elapsed time 0.0 .0
DB time 8,371.3
background elapsed time 214.7
background cpu time 75.8
-------------------------------------------------------------
Much of how Oracle determines CPU seconds is a black box; for example, how Oracle can tell us in one section that the CPU was utilized only 14.8 percent for this instance and yet shows sql execute elapsed time as 8,145.5 seconds when with 2 CPUs there are only 7,200 seconds of CPU time in an hour is a real mystery. It may be including all calls that completed during the interval, which of course may then include calls whose majority of time was actually outside of the measurement interval; however, that is a topic for another discussion.
In the report excerpt shown in Listing 9.6, we see that a majority of the CPU time that was allotted to us for this measurement interval (97.3%) was spent in SQL execute elapsed time, and this really is precisely where we want the CPU to be spending its time. If we saw that parse time elapsed or hard parse elapsed time was consuming a large portion of time, that would indicate that we had an ad-hoc environment with a majority of unique SQL statements or that our application is not using bind variables properly. Of course, if the CPU was spending its time in any of the other areas for a majority of the reported time, that segment of processing should be investigated.
If parse time elapsed and hard parse elapsed time are close in value, then excessive hard parses are happening. Hard parses are a drain on CPU and I/O resources, and you should review the SQL versioning and look at shared pool reloads and invalidations for possible clues.
Operating System Statistics
The next section of the AWR report shows OS-related settings and statistics. Listing 9.7 shows an example report section for OS statistics.
Operating System Statistics DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> *TIME statistic values are diffed.
All others display actual values. End Value is displayed if different
-> ordered by statistic type (CPU Use, Virtual Memory, Hardware Config), Name
Statistic Value End Value
------------------------- ---------------------- ----------------
BUSY_TIME 126,029
IDLE_TIME 597,505
IOWAIT_TIME 327,861
NICE_TIME 766
SYS_TIME 48,452
USER_TIME 76,784
LOAD 0 3
PHYSICAL_MEMORY_BYTES 3,189,190,656
NUM_CPUS 2
NUM_CPU_CORES 1
NUM_CPU_SOCKETS 1
GLOBAL_RECEIVE_SIZE_MAX 4,194,304
GLOBAL_SEND_SIZE_MAX 262,144
TCP_RECEIVE_SIZE_DEFAULT 87,380
TCP_RECEIVE_SIZE_MAX 1,048,576
TCP_RECEIVE_SIZE_MIN 4,096
TCP_SEND_SIZE_DEFAULT 65,536
TCP_SEND_SIZE_MAX 1,048,576
TCP_SEND_SIZE_MIN 4,096
-------------------------------------------------------------
Operating System Statistics - Detail DB/Inst: AULTDB/aultdb1 Snaps: 91-92
Snap Time Load %busy %user %sys %idle %iowait
--------------- -------- -------- -------- -------- -------- --------
04-Aug 12:00:15 0.4 N/A N/A N/A N/A N/A
04-Aug 13:00:28 3.0 17.4 10.6 6.7 45.3 82.6
-------------------------------------------------------------
The OS section of the report gives us the time breakdown in CPU ticks to support the percentages claimed in the other sections of the report. The correlation of reported ticks to actual ticks is still a bit foggy. However, examination of this section still shows that the system being examined is not CPU bound but is suffering from I/O contention, since both the idle time and I/O wait time statistics are larger than the busy time value. This part of the report also shows the TCP/UDP buffer settings, which are useful when determining issues in RAC.
Tip
If you don’t have access to Oracle Grid Control, you can get a multihour or multiday AWR report and use the Operating System Statistics - Detail section to pinpoint where the load and I/O stress are the highest for further analysis with more targeted reports.
One problem that has been noted is that the I/O wait time reported in this section may not be accurate and should not be used for analysis.
Foreground Wait Events
The next section of the AWR report shows the wait events that occur in foreground processes. Foreground processes are the user- or application-level processes. Listing 9.8 shows an excerpt from the report we are analyzing.
Listing 9.8 Foreground Wait Events
Foreground Wait Class DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> s - second, ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Captured Time accounts for 68.9% of Total DB time 8,371.33 (s)
-> Total FG Wait Time: 4,770.85 (s) DB CPU time: 995.13 (s)
Avg
% Time Total Wait Wait
Wait Class Waits -outs Time (s) (ms) % DB Time
--------------- ---------------- ------ ---------------- -------- ---------
User I/O 518,267 0 4,449 9 53.1
DB CPU 995 11.9
Cluster 188,753 9 173 1 2.1
Other 3,806,446 100 146 0 1.7
Concurrency 1,854 2 2 1 0.0
Commit 15 0 1 39 0.0
Application 740 0 0 0 0.0
System I/O 40 0 0 3 0.0
Network 6,970 0 0 0 0.0
Configuration 0 0 0.0
-------------------------------------------------------------
Foreground Wait Events DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> s - second, ms - millisecond - 1000th of a second
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Avg
% Time Total Wait Wait Waits % DB
Event Waits -outs Time (s) (ms) /txn Time
------------------------- ----------- ------ ---------- ---- ------- ------
db file sequential read 465,020 0 3,969 9 395.8 47.4
db file parallel read 2,251 0 322 143 1.9 3.8
db file scattered read 15,268 0 153 10 13.0 1.8
gc current block 2-way 108,739 11 116 1 92.5 1.4
PX Deq: reap credit 3,247,703 100 107 0 2,764.0 1.3
gc cr grant 2-way 57,265 7 28 0 48.7 .3
gc cr multi block request 22,451 6 23 1 19.1 .3
enq: BF - allocation conte 14 93 14 983 0.0 .2
PX qref latch 555,843 100 9 0 473.1 .1
IPC send completion sync 1,070 52 8 8 0.9 .1
gc remaster 22 0 5 221 0.0 .1
The wait events that accounted for less than 0.1 percent of DB time have been omitted for brevity (the actual listing is two pages long). The thing to note about this section of the report is that we have already looked at the main top five events, which are where we should focus our tuning efforts. However, if you are attempting to tune some specific operation or database section, the other waits in this section may apply to that effort.
If you see a large number of waits in a RAC environment for the read by other session event, this usually indicates your block size or latency is too large, which is resulting in contention. If you see that read by other session is one of the predominant waits events, look to the Segments by x sections of the AWR reports for guidance on which tables and indexes are being heavily utilized. Consider moving these segments to a tablespace with a smaller-than-default block size, such as 4 KB or even 2 KB, or to lower latency storage, such as IBM FlashSystem, to reduce this contention.
Background Wait Events
Background wait events, as their name implies, are waits generated by the numerous background processes in the Oracle process stack. DBWR, log writer (LGWR), system monitor (SMON), process monitor (PMON), and so on, all contribute to the background wait events. The report excerpt, limited to the events with at least 0.1 percent of database time, is shown in Listing 9.9.
Listing 9.9 Background Wait Events Section
Background Wait Events DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> ordered by wait time desc, waits desc (idle events last)
-> Only events with Total Wait Time (s) >= .001 are shown
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Avg
% Time Total Wait Wait Waits % bg
Event Waits -outs Time (s) (ms) /txn Time
-------------------------- ------ ------ ---------- ------- -------- ------
control file sequential re 8,336 0 72 9 7.1 33.5
control file parallel writ 1,287 0 31 24 1.1 14.5
db file parallel write 792 0 11 14 0.7 5.3
log file parallel write 701 0 11 15 0.6 4.9
events in waitclass Other 44,191 98 5 0 37.6 2.5
library cache pin 449 0 2 4 0.4 .8
db file sequential read 221 0 2 7 0.2 .8
gc cr multi block request 1,915 0 2 1 1.6 .7
os thread startup 19 0 1 56 0.0 .5
gc cr block 2-way 246 0 0 1 0.2 .2
db file scattered read 18 0 0 12 0.0 .1
db file parallel read 3 0 0 59 0.0 .1
gc current grant 2-way 98 0 0 1 0.1 .1
As we can see, the events that dominate the background waits are also I/O related. If the events that are at the top in the foreground are similar (such as both being control file–related), then that is the I/O area in which we should concentrate our tuning efforts. As we can see from the report excerpt, while the I/O related waits are similar, the predominant ones in each section are different, indicating a general I/O issue rather than an issue with a specific set of files.
Wait Event Histograms
In the next section of the AWR report, Oracle provides a time-based histogram report for the wait events. If the histogram report were ordered by the predominant wait events by time, it would be more useful; instead, it is ordered by event name, making us have to search for the important events. For brevity, the unimportant events have been removed from the example in Listing 9.10.
Listing 9.10 Event Time Histograms
Wait Event Histogram DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
-> % of Waits: value of .0 indicates value was <.05%. Value of null is truly 0
-> % of Waits: column heading of <=1s is truly <1024ms, >1s is truly >=1024ms
-> Ordered by Event (idle events last)
% of Waits
-----------------------------------------
Total
Event Waits <1ms <2ms <4ms <8ms <16ms <32ms <=1s >1s
-------------------------- ----- ---- ---- ---- ---- ----- ----- ---- ----
control file parallel writ 1287 59.0 24.1 16.9
control file sequential re 9147 23.4 21.3 23.3 22.3 6.8 2.9 .0
db file parallel read 2256 .3 1.0 7.4 32.6 56.8 1.9
db file parallel write 792 .5 .8 4.2 28.7 50.0 8.8 7.1
db file scattered read 15K .4 2.7 31.5 59.2 5.8 .5
db file sequential read 465K .0 .6 2.2 49.5 45.0 2.3 .4
gc cr grant 2-way 50K 87.2 11.1 1.3 .3 .2 .0
gc cr multi block request 24K 59.0 36.8 3.0 .5 .6 .0
gc current block 2-way 84K 6.5 87.7 5.2 .3 .2 .0
library cache lock 488 82.8 10.9 4.9 1.0 .2 .2
library cache pin 4371 77.6 11.1 7.4 3.1 .6 .0
gcs remote message 274K 28.5 15.4 9.9 11.6 7.5 5.8 21.4
ges remote message 53K 11.4 3.3 2.7 1.9 1.8 2.1 76.8
-------------------------------------------------------------
The most important events in the excerpt are in bold. Notice that the read events are more important than the write events. Unless we are talking about direct writes, direct write temp, undo or redo log writes, or control file writes, Oracle uses the concept of delayed block cleanout, writing blocks to disk only when absolutely needed. This delayed block cleanout mechanism means that for most data-related writes, we aren’t too concerned with write times unless our application does frequent commits and the data is needed nearly immediately after the commit.
Since this application is a read-dominated application, there aren’t a lot of redo log–related and undo tablespace–related events. In an OLTP type environment, we would expect to see log writes and log syncs to rise to the top in an I/O-bound system as dominant events. In systems that generate a lot of transactions, we would also expect undo tablespace–related events to be more prevalent.
By looking at the histograms, we can see that our read events are taking anywhere from 4 ms to 1 s to complete; this is a typical disk-based histogram. However, in our histogram, the largest number of reads by percentage are taking greater than 8 ms to complete; this indicates disk stress is happening. We could possibly reduce this to nearer to 5 ms by increasing the number of disks in our disk array. However, you cannot expect a disk-based system to get to less than 5 ms read or write times unless you place a large amount of cache in front of the disks. Another option, which can be more cost effective and allow greater I/O operations per second (IOPS), is to use IBM FlashSystem technology, which should provide less than 0.5 ms latency.
Service-Related Statistics
Since Oracle Database10g, Oracle is increasingly using the concept of a database “service.” A service is a group of processes that are used to provide a common function. For example, all of the parallel query slaves and processes used to provide the results for a series of SQL statements for the same user could be grouped into a service. Listing 9.11 shows the service-related section for our example report.
Listing 9.11 Service-Related Statistics Section
Service Statistics DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> ordered by DB Time
Physical Logical
Service Name DB Time (s) DB CPU (s) Reads (K) Reads (K)
---------------------- ------------ ------------ ------------ ------------
aultdb 8,344 981 9,769 22,715
SYS$USERS 23 12 1 56
SYS$BACKGROUND 1 0 1 17
aultdbXDB 0 0 0 0
-------------------------------------------------------------
Service Wait Class Stats DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> Wait Class info for services in the Service Statistics section.
-> Total Waits and Time Waited displayed for the following wait
classes: User I/O, Concurrency, Administrative, Network
-> Time Waited (Wt Time) in seconds
Service Name
----------------------------------------------------------------
User I/O User I/O Concurcy Concurcy Admin Admin Network Network
Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time
--------- -------- --------- -------- --------- ------- --------- --------
aultdb
517710 4446 234 1 0 0 5828 0
SYS$USERS
555 3 1615 1 0 0 1140 0
SYS$BACKGROUND
350 3 3486 4 0 0 0 0
-------------------------------------------------------------
The service-related statistics allow you to see which users are consuming the most resources. By knowing which users are consuming the most resources, you can concentrate your tuning activities on the hard hitters. In the report excerpt in Listing 9.11, we see the generic service aultdb, which holds all the user processes that are non-background and non-sys owned.
Since there was only one set of processes (we know this because we are good DBAs who keep tabs on what is happening in our system), we can track the usage back to a user called tpch. From looking at the second half of the report, we can see that our user experienced over 517,710 I/O-related waits for a total effective wait time of 4,446 seconds, or 8.59 ms per wait.
Since we know that the best wait time we can get with a disk-based, non-cached system is 5 ms, a wait time of 8.59 ms shows the disks are experiencing some stress. The higher this type of wait is, the more stress is being experienced by the I/O subsystem. This section of the report can show where the timing issues are occurring.
The SQL Sections
The next sections of the report slice and dice the SQL in the shared pool by several different statistics. By using the waits and other statistics we have discussed so far, you can usually figure out which SQL area to examine. A general rule of thumb is that if a SQL statement appears in the top five statements in two or more areas, it is a prime candidate for tuning. The sections are
Total Elapsed Time
Total CPU Time
Total Buffer Gets
Total Executions
Total Parse Calls
Total Sharable Memory
Total Version Count
Total Cluster Wait Time
Let’s look at each section and discuss the indicators that would lead you to consider investigating the SQL in each.
Total Elapsed Time
If a SQL statement appears in the Total Elapsed Time area of the report, this means its CPU time plus any other wait times moved it to the top of the pile. If for some reason it is at the top of the Total Elapsed Time but not at the top of Total CPU Time, this indicates that an issue with recursion is associated with this statement. Generally, the same SQL will be in both the Total Elapsed Time and Total CPU Time sections. If you see high recursion indicators such as suboptimal parse ratios in the Instance Activity Statistics (the section following the SQL areas), the recursive calls or recursive CPU usage statistics are high.
Total CPU Time
When a statement appears in the Total CPU Time section, this indicates it used excessive CPU cycles during its processing. Excessive CPU processing time can be caused by sorting, excessive functions, or long parse times. Indicators that you should be looking at in this section for SQL tuning candidates are high CPU percentages in the services section for the service associated with this SQL statement. To reduce total CPU time, reduce sorting by using multicolumn indexes that can act as sort eliminators and use bind variables to reduce parse times.
Tip
If the SQL is uppercase, it probably comes from a user or application; if it is lowercase, it usually comes from internal or background processes. SQL with all Table fields with single quotes around them are usually generated from user tools.
Total Buffer Gets
High total buffer gets mean a SQL statement is reading a lot of information from the DB block buffers. Generally speaking, buffer gets (or logical reads in Statspack) are desirable, except when they become excessive. Like excessive disk reads, excessive buffer gets can cause performance issues, and they are reduced in the same way. To reduce excessive total buffer gets, use partitioning, use indexes, and look at optimizing SQL to avoid excessive full table scans. Total buffer gets are typified by high logical reads, high buffer cache hit ratios (when they are driven by a poor selectivity index), and high CPU usage.
Total Disk Reads
High total disk reads mean a SQL statement is reading a lot of information from storage rather than from the DB block buffers. Generally speaking, storage reads (or physical reads in Statspack) are undesirable, especially when they become excessive. Excessive storage reads cause performance issues. To reduce excessive storage, use partitioning, use indexes, and look at optimizing SQL to avoid excessive full table scans. You can also increase the DB buffer cache if memory is not an issue. Total disk reads are typified by high physical reads, low buffer cache hit ratios, and low CPU usage with high I/O wait times. If storage reads are a part of your database (such as DSS or data warehouses where full table scans are a natural result of their structure), then moving to an all flash array would improve performance, sometimes dramatically.
Total Executions
High total executions can be an indicator that something in the SQL is incorrect in the database. Statements with high numbers of executions usually are being properly reused. However, be sure that it’s okay that statements with high numbers of executions are executed multiple times. For example, a SQL statement might execute over and over again in a PL/SQL or Java, or in a C routine in a loop, when it should only be executed once. Statements with high executions and high logical and/or physical reads are candidates for review to make sure they are not being executed multiple times when a single execution would serve. If the database is seeing excessive physical and logical reads or excessive I/O wait times, then look at the SQL statements that show excessive executions and show high physical and logical reads.
Parse Calls
Whenever a statement is issued by a user or process, regardless of whether it is in the SQL pool, it undergoes a parse. The parse can be a hard parse or a soft parse. If Oracle cannot find an identical hash signature in the SQL pool, it does a hard parse with loads of recursive SQL and all the rest of the parse baggage. If it finds the SQL in the pool, then it simply does a soft parse with minimal recursion to verify user permissions on the underlying objects. Excessive parse calls usually go with excessive executions. If the statement is using what are known as unsafe bind variables, then the statement will be reparsed each time. If the header parse ratios are low, look here and in the version count areas.
Shareable Memory
The shareable memory area provides information on SQL statements that are reused and the amount of memory in the shared pool that they consume. Only statements with greater than 1,048,576 bytes of shared memory usage are shown in the report. Usually, high memory consumption is a result of poor coding or overly large SQL statements that join many tables. In a DSS or data warehouse environment, large complex statements may be normal. In an OLTP database, large or complex statements are usually the result of overnormalization of the database design, using an OLTP system as a data warehouse or DSS, or poor coding techniques. Usually, large statements result in excessive parsing, recursion, and large CPU usage.
Version Count
High version counts are usually due to multiple identical-schema databases, unsafe bind variables, or Oracle bugs. In Oracle 9 and Oracle 10, there are bugs that result in unsafe bind variables driving multiple versions. Multiple versions eat up SQL memory space in the shared pool. High version counts can also result in excessive parsing.
Tip
Setting the undocumented parameter _sqlexec_progression_cost to higher than the default of 1,000 decreases versioning in susceptible versions.
High values for sharable memory in the SQL pool can indicate issues if you aren’t seeing good performance along with high sharable memory for statements with executions greater than 1.
Cluster Wait Time
As the name implies, the cluster wait time will be present only if you are using a RAC system. SQL that transfers a large number of SQL statements across the interconnect will be listed in this section. High levels of block transfer occur if the block size is too large, the DB caches on each server are too small, or the SQL is using too much of the table data. Large update statements may appear here, as updates require block transfers in many cases for current blocks. High levels of global cache–type wait events indicate you need to check this section for causative SQL statements.
Instance Activity Statistics
The next section deals with instance activity statistics. The biggest problem with the instance activity statistics is that there are so many of them, and many are not useful except in specific tuning situations that may never occur in a normal database. The example excerpt from the report we have been examining is presented in Listing 9.12. Statistics that aren’t normally a concern have been removed.
Listing 9.12 Instance Activity Statistics Section
Instance Activity Stats DB/Inst: AULTDB/aultdb1 Snaps: 91-92
Statistic Total per Second per Trans
-------------------------------- ------------ -------------- -------------
CPU used by this session 77,997 21.6 66.4
CPU used when call started 288,270 79.8 245.3
Number of read IOs issued 27,685 7.7 23.6
SQL*Net roundtrips to/from client 6,970 1.9 5.9
bytes received via SQL*Net from 2,385,638 660.2 2,030.3
bytes sent via SQL*Net to client 2,595,626 718.4 2,209.0
consistent gets 22,777,682 6,303.9 19,385.3
consistent gets - examination 6,073,207 1,680.8 5,168.7
consistent gets direct 3,277,142 907.0 2,789.1
consistent gets from cache 14,648,585 4,054.1 12,466.9
consistent gets from cache (fast 193,221 53.5 164.4
db block changes 12,812 3.6 10.9
db block gets 13,389 3.7 11.4
db block gets from cache 13,364 3.7 11.4
db block gets from cache (fastpa 3,512 1.0 3.0
dirty buffers inspected 825 0.2 0.7
enqueue timeouts 40 0.0 0.0
enqueue waits 499 0.1 0.4
execute count 13,287 3.7 11.3
free buffer inspected 556,747 154.1 473.8
free buffer requested 731,667 202.5 622.7
gc CPU used by this session 11,859 3.3 10.1
gc blocks lost 0 0.0 0.0
gc cr block build time 1 0.0 0.0
gc cr block flush time 7 0.0 0.0
gc cr block receive time 66 0.0 0.1
gc cr block send time 3 0.0 0.0
gc cr blocks received 361 0.1 0.3
gc cr blocks served 522 0.1 0.4
gc current block flush time 2 0.0 0.0
gc current block pin time 205 0.1 0.2
gc current block receive time 16,726 4.6 14.2
gc current block send time 577 0.2 0.5
gc current blocks received 95,445 26.4 81.2
gc current blocks served 93,484 25.9 79.6
index fast full scans (direct re 90 0.0 0.1
index fast full scans (full) 4 0.0 0.0
index fast full scans (rowid ran 90 0.0 0.1
index fetch by key 3,086,965 854.3 2,627.2
index scans kdiixs1 29,551 8.2 25.2
leaf node 90-10 splits 19 0.0 0.0
leaf node splits 26 0.0 0.0
opened cursors cumulative 13,077 3.6 11.1
parse count (failures) 2 0.0 0.0
parse count (hard) 153 0.0 0.1
parse count (total) 7,202 2.0 6.1
parse time cpu 227 0.1 0.2
parse time elapsed 399 0.1 0.3
physical read IO requests 550,974 152.5 468.9
physical read bytes 32,562,569,216 9,011,916.7 27,712,824.9
physical read total IO requests 605,019 167.4 514.9
physical read total bytes 32,711,421,952 9,053,112.7 27,839,508.0
physical read total multi block 30,330 8.4 25.8
physical reads 9,773,380 2,704.9 8,317.8
physical reads cache 572,745 158.5 487.4
physical reads cache prefetch 153,965 42.6 131.0
physical reads direct 3,402,178 941.6 2,895.5
physical reads direct temporary 124,434 34.4 105.9
physical reads prefetch warmup 58,580 16.2 49.9
physical write IO requests 4,983 1.4 4.2
physical write bytes 1,037,123,584 287,031.1 882,658.4
physical write total IO requests 15,031 4.2 12.8
physical write total bytes 1,085,801,472 300,503.1 924,086.4
physical write total multi block 4,062 1.1 3.5
physical writes 314,090 86.9 267.3
physical writes direct 124,459 34.4 105.9
physical writes direct (lob) 0 0.0 0.0
physical writes direct temporary 124,434 34.4 105.9
physical writes from cache 2,143 0.6 1.8
physical writes non checkpoint 124,952 34.6 106.3
recursive calls 78,415 21.7 66.7
recursive cpu usage 77,189 21.4 65.7
redo entries 7,832 2.2 6.7
redo log space requests 2 0.0 0.0
redo log space wait time 28 0.0 0.0
redo size 2,892,568 800.5 2,461.8
redo synch time 66 0.0 0.1
redo synch writes 72 0.0 0.1
redo wastage 196,192 54.3 167.0
redo write time 1,110 0.3 0.9
redo writes 701 0.2 0.6
rollback changes - undo records 0 0.0 0.0
session cursor cache hits 12,415 3.4 10.6
session logical reads 22,791,070 6,307.6 19,396.7
sorts (memory) 3,875 1.1 3.3
sorts (rows) 1,460,468 404.2 1,243.0
summed dirty queue length 3,284 0.9 2.8
table fetch by rowid 1,322,667 366.1 1,125.7
table fetch continued row 13 0.0 0.0
table scan blocks gotten 2,780,775 769.6 2,366.6
table scan rows gotten 158,164,979 43,773.3 134,608.5
table scans (direct read) 776 0.2 0.7
table scans (long tables) 776 0.2 0.7
table scans (rowid ranges) 776 0.2 0.7
table scans (short tables) 2,255 0.6 1.9
transaction rollbacks 0 0.0 0.0
undo change vector size 1,870,904 517.8 1,592.3
user I/O wait time 445,246 123.2 378.9
user calls 7,943 2.2 6.8
user commits 794 0.2 0.7
user rollbacks 381 0.1 0.3
workarea executions - onepass 6 0.0 0.0
workarea executions - optimal 2,323 0.6 2.0
-------------------------------------------------------------
Instance Activity Stats - Absolute Values
DB/Inst: AULTDB/aultdb1 Snaps: 91-9
-> Statistics with absolute values (should not be diffed)
Statistic Begin Value End Value
-------------------------------- --------------- ---------------
session pga memory max 544,192,924 4,940,081,136
session cursor cache count 2,266 8,279
session uga memory 73,033,165,084 3.393545E+11
opened cursors current 48 54
workarea memory allocated 0 16,041
logons current 41 47
session uga memory max 4,427,536,236 5,963,059,828
session pga memory 390,773,148 826,689,340
-------------------------------------------------------------
Instance Activity Stats - Thread Activity
DB/Inst: AULTDB/aultdb1 Snaps: 91-92
-> Statistics identified by '(derived)' come from sources other than SYSSTAT
Statistic Total per Hour
-------------------------------- ------------------ ---------
log switches (derived) 1 1.00
-------------------------------------------------------------
It is best to focus on the larger summary-type statistics, at least at first, when dealing with this section of the reports. Even the pared-down list in Listing 9.12 still has many entries that may not really help novices find problems with their database.
Note
One of the biggest hurdles to understanding the statistics in the Instance Activity section is knowing what the time units are for the time-based statistics. Generally, if they aren’t stated, they will be in milliseconds for some RAC reports and in centiseconds for single-instance reports.
The DB time value of 8,371.3 seconds is made up of user I/O time of 4,452.46 seconds plus CPU time of 995 seconds, and the remainder is classified as non-idle, non-I/O wait time.
So what else is contained in the mine of data? We have an effective IO time and the number of I/Os issued. From this we can see that each I/O cost an effective time of 32 milliseconds. No wonder we spent about 45 percent of the time waiting on I/O!
By looking at SQLNet roundtrips, we can tell if our application is making effective use of array processing. If it is taking hundreds or thousands of roundtrips per transaction, then we really need to examine how our application is handling arrays. By default, languages such as C and Java process only 10 to 20 records at a time. SQL*Plus defaults to 10. By increasing array processing via precompiler flags or by the SET ARRRAYSIZE command in SQL*Plus, we can greatly reduce roundtrips and improve performance.
Bytes sent to and received from the clients via SQLNet can be used with roundtrips to see how large a chunk is being shipped between the client and the server, allowing insight into possible network tuning. In addition this information can be used to see if the network is being strained (generally, 1 Gb Ethernet can handle transfers of about 100 MB/sec).
Consistent Get Statistics
Consistent gets deal with logical reads and can be heavyweight (using two latches, as in a normal, consistent get) or lightweight (using one latch, as in a consistent get). Large numbers of consistent gets can be good or, if they are excessive because of poor index or database design, bad because they can consume CPU best used for other things. These statistics are used in conjunction with others, such as those involving heavy-hitter SQL statements, to diagnose database issues.
DB Block Get Statistics
DB block gets are current mode gets. A current mode get is for the data block in its current incarnation, with incarnation defined as all permanent changes applied (i.e., if the database shut down now and restarted, this is the block you would get). Now, this block can be from cache, from another instance cache, from the file system cache, or from disk. Sometimes it will result in a disk read or a block transfer from another instance’s cache, as there can be only one version of the current block in the cache of an instance at a time.
Dirty Block Statistics
The dirty buffers inspected statistic tells you how many times a dirty buffer (one that has changes) was looked at when the processes were trying to find a clean buffer. If this statistic is large, then you probably don’t have enough buffers assigned, as the processes are continually looking at dirty buffers to find clean ones.
Enqueue Statistics
The enqueue statistics dealing with deadlocks, timeouts, and waits tell you how often processes where waiting on enqueues and if they were successful. High numbers of enqueue deadlocks indicate there may be application-locking issues. High numbers of waits and failures indicate high levels of contention. You need to look in the enqueue section of the report to see the specific enqueues that are causing the problems.
Execution Count
The execution count statistic is used with other statistics to develop ratios to show on average how much of a specific resource or statistic applies to a single execution. This count can be misleading, however, if there are several long-running transactions and many short, supporting transactions. For example, a large DSS query that requires a number of recursive SQL operations to parse it will drive the executions up, but you are really only interested in the large DSS query and not the underlying recursive transactions unless they contribute to the DSS transaction itself.
Free Buffer Statistics
The free buffers requested and the free buffers inspected statistics show how many buffers, while not actually dirty, were being used by other processes and had to be skipped when searching for a free buffer. If the free buffers inspected is overly large and the dirty buffers inspected is also large, then look at commit frequency as well as possibly increasing total DB block buffers, as the cache is probably congested.
Global Cache (GC) Statistics
The GC statistics show the components that make up the send times for the consistent read (CR) and current blocks. The statistics for build, flush, and send for the respective type of block (CR or current) are added together and divided by the blocks of that type sent to determine the latency for that operation. The receive times can be divided by the number of blocks received to determine that latency (and should be compared with the send latency as calculated from the other instance’s AWR report). By seeing the components of the latency for send operations, you can determine if the issue is internal (build or flush times are large) or external (the send time is large). The GC and global enqueue statistics will be present only if RAC is being utilized.
Remember that if send or receive times are greater than the average disk latency, then the interconnect has become a source of performance bottlenecks and needs to be tuned or replaced with a higher-speed/larger-bandwidth interconnect, such as InfiniBand. If only one node is showing issues (send times excessive point to this node, receive times excessive point to the other nodes) then look to excessive load, TCP buffer settings, or NIC issues on that node.
The global enqueue statistics haven’t been shown because they are not a large source of performance issues. If the messaging shows large latencies, it will also be shown in the global cache services, since global cache activity depends on the global enqueue service.
Index fetch by key: This statistic is incremented for each INDEX (UNIQUE SCAN) operation that is part of a SELECT or data manipulation language (DML) statement execution plan.
Index scans kdiixs1: This statistic is incremented for each index range scan operation that is not of the types index fast full scans, index full scan, and index unique scan.
By comparing the two values, you get an idea of the ratio of single index lookups verses range scan. In most systems single index lookups should predominate since they are usually more efficient. However, in DSS or data warehouse systems, scans or fast scans may become the dominant type of index activity.
Leaf Node Statistics
The leaf node statistics refer to index leaf nodes and tell you how much insert activity is happening in your database. The 10–90 splits show activity for monotonically increasing indexes (those that use sequences or dates, generally), and the 50–50 splits show other types of index activity such as text or random value indexes. If you see heavy 10–90 split operations, then you might want to look at index management operations to be sure your indexes aren’t getting too broad due to excessive unused space in your sequence or date-based indexes. Usually, index rebuilds are required only in databases that have monotonically increasing indexes that also undergo large amounts of random deletions resulting in numerous partially filled blocks.
Open Cursors
The open cursors cumulative statistic is used with other statistics to calculate ratios for resources used per cursor or cursors open per login, for example.
Parse Statistics
The parse statistics are used to show how efficiently you are using parses. If you have large numbers of parse count failures or large numbers of hard parses, it could indicate a large number of ad-hoc queries. A large number of hard parses (greater than 10 percent of parses) indicates that the system probably isn’t using bind variables efficiently. If there is a large discrepancy between parse CPU and parse elapsed times, it indicates that the system is overloaded and may be CPU bound.
Physical Read and Write Statistics
There are several types of physical read and write statistics, defined as follows:
Physical reads: Shows the total number of data blocks read from disk. This value can be greater than the value of physical reads direct plus physical reads cache, as reads into process private buffers are also included in this statistic.
Physical read bytes: Shows the total size in bytes of all disk reads by application activity (and not other instance activity) only.
Physical read I/O requests: Shows the number of read requests for application activity (mainly buffer cache and direct load operation) that read one or more database blocks per request. This is a subset of the physical read total I/O requests statistic.
Physical read total bytes: Shows the total size in bytes of disk reads by all database instance activity including application reads, backup and recovery, and other utilities. The difference between this value and physical read bytes gives the total read size in bytes by non-application workload.
Physical read total I/O requests: Shows the number of read requests that read one or more database blocks for all instance activity including application, backup and recovery, and other utilities. The difference between this value and physical read total multiblock requests gives the total number of single-block read requests.
Physical read total multiblock requests: Shows the total number of Oracle instance read requests that read in two or more database blocks per request for all instance activity including application, backup and recovery, and other utilities.
Physical reads cache: Shows the total number of data blocks read from disk into the buffer cache. This is a subset of the physical reads statistic.
Physical reads direct: Shows the number of reads directly from disk, bypassing the buffer cache. For example, in high bandwidth, data-intensive operations such as parallel query, reads of disk blocks bypass the buffer cache to maximize transfer rates and to prevent the premature aging of shared data blocks resident in the buffer cache.
Physical reads prefetch warmup: Shows the number of data blocks that were read from the disk during the automatic prewarming of the buffer cache.
Physical write bytes: Shows the total size in bytes of all disk writes from the database application activity (and not other kinds of instance activity).
Physical write I/O requests: Shows the number of write requests for application activity (mainly buffer cache and direct load operation) that wrote one or more database blocks per request.
Physical write total bytes: Shows the total size in bytes of all disk writes for the database instance including application activity, backup and recovery, and other utilities. The difference between this value and physical write bytes gives the total write size in bytes by non-application workload.
Physical write total I/O requests: Shows the number of write requests that wrote one or more database blocks from all instance activity including application activity, backup and recovery, and other utilities. The difference between this stat and physical write total multiblock requests gives the number of single-block write requests.
Physical write total multi block requests: Shows the total number of Oracle instance write requests that wrote two or more blocks per request to the disk for all instance activity including application activity, recovery and backup, and other utilities.
Physical writes: Shows the total number of data blocks written to disk. This statistic’s value equals the sum of physical writes direct and physical writes from cache values.
Physical writes direct: Shows the number of writes directly to disk, bypassing the buffer cache (as in a direct load operation).
Physical writes from cache: Shows the total number of data blocks written to disk from the buffer cache. This value is a subset of the physical writes statistic.
Physical writes non-checkpoint: Shows the number of times a buffer is written for reasons other than advancement of the checkpoint. It is used as a metric for determining the I/O overhead imposed by setting the FAST_START_IO_TARGET parameter to limit recovery I/Os. (Note that FAST_START_IO_TARGET is a deprecated parameter.) Essentially, this statistic measures the number of writes that would have occurred had there been no checkpointing. Subtracting this value from physical writes gives the extra I/O for checkpointing.
Tip
To determine the average I/O unit for reads and writes, use the ratios of physical read total bytes and physical read total I/O requests, and physical write total bytes and physical write total I/O requests.
Recursive Statistics
The recursive calls statistics can be used in ratio with the user calls statistic to get the number of recursive calls per user call. If the number of recursive calls is high for each user call, then this indicates you are not reusing SQL very efficiently. In our example printout, the ratio is about 10 to 1, which is fine; if the ratio was 50 to 1 or greater, it would bear investigation.
Essentially, you need to determine what is a good ratio of recursive calls to user calls for your system, as it will depend on the number of tables on average in your queries, the number of indexes on those tables, and whether or not Oracle has to reparse the entire statement or can instead use a soft parse. This ratio is actually reported in the header information. We have already shown how the recursive CPU statistic is used with the CPU usage and other CPU-related timings.
Redo-Related Statistics
The redo-related statistics can be used to determine the health of the redo log activity and the LGWR processes. By dividing redo log space wait time by redo log space requests, you can determine the wait time per space request. If this time is excessive, it shows that the redo logs are under I/O stress and should be moved to less active disks or flash memory–based assets. In a similar calculation, the redo synch time can be divided by the redo synch writes to determine the time taken during each redo sync operation; this too is an indicator of I/O stress if it is excessive. A final indicator of I/O stress is a ratio of redo write time to redo writes giving the time for each redo write. The redo wastage statistic shows the amount of unused space in the redo logs when they were written. Excessive values of redo wastage per redo write indicates that the LGWR process is being stressed.
The rollback changes – undo records statistics is actually rollback changes - undo records applied, according to Jonathan Lewis. If a session’s user rollbacks is large, but its rollback changes - undo records applied is small (and those numbers are relative to your system), then most of the rollbacks are doing nothing. So by comparing these two metrics, you can determine, relative to your system, if you have an undo issue.
Undo issues deal with rollback commands either explicit or implicit. Explicit are generated by issuing the rollback command, whereas implicit can be from data definition language (DDL), data control language (DCL), or improper session terminations.
Session Cursor Statistic
The session cursor cache hits statistic shows how often a statement issued by a session was actually found in the session cursor cache. The session cursor cache is controlled by the session_cached_cursors setting and defaults (usually) to 50. If session cursor cache hits divided by the sum of user calls plus recursive calls is low, then you need to increase the setting of session_cached_cursors. Settings from 100 to 150 or higher are usually recommended.
Sort Statistics
The sorts statistics—sorts (rows), sorts (memory), and sorts (disk)—show how the system is doing sorts. In later versions, you may see sorts (disk) replaced by the work area executions–one pass and work area executions–multipass statistics. Ideally, you want no sorts (disk) or work area executions–one pass or work area executions–mulitpass; however, in reality, this may be impossible to achieve, so seek to set sort_area_size, hash_area_size, merge_bitmap_area_size, create_bitmap_area_size, or pga_aggregate_target to large enough values to reduce sorts to disk as much as possible. Note that no statistic really tracks bitmap, hash, or global temporary table operations that overflow to disk, so it is possible to get temporary tablespace IOPS while having zero values for all disk-related sort and work area statistics.
Tip
The sort segment histogram section of the report will help you determine settings for the sort individual or the PGA aggregate parameter settings.
Summed Dirty Queue Length
The summed dirty queue length statistic can be used in concert with the physical writes from cache statistic to determine if the DBWR process is being stressed. If the ratio of summed dirty queue length to physical writes from cache is greater than 100, then more DBWR processes are needed.
Table Fetch Statistics
The table fetch statistics provide details on how table data has been accessed:
Statistic Total per Second per Trans
-------------------------------- ------------ -------------- -------------
table fetch by rowid 1,322,667 366.1 1,125.7
table fetch continued row 13 0.0 0.0
table scan blocks gotten 2,780,775 769.6 2,366.6
table scan rows gotten 158,164,979 43,773.3 134,608.5
table scans (direct read) 776 0.2 0.7
table scans (long tables) 776 0.2 0.7
table scans (rowid ranges) 776 0.2 0.7
table scans (short tables) 2,255 0.6 1.9
The three most important statistics are as follows:
Table fetch by rowid: This is the cumulative number of rows fetched by index lookup of rowid.
Table scan rows gotten: This shows the number of rows retrieved via table scan operations (full table scans).
Table fetch continued row: This shows the number of row fetches that resulted in a continued row read, essentially doubling (or more) the I/Os. This could be an indication of chained rows, chained blocks, or binary large object (BLOB) activity.
Depending on your database type, you could have more index-based reads (usually OLTP) or more table scan–based reads (DWH, DSS). It is important to have a feeling for the ratio of these two statistics (index versus scan rows) so any change in the profile will alert you to possible index issues. Also, monitoring the ratio of continued row reads to the sum of scan and index row reads will inform you if you are getting excessive chained row activity.
Table scans (direct reads) are usually indicative of parallel query activity. Table scans (rowed ranges) are usually also caused by parallel query operations.
The two table type scans, long and short, are based on whether a table is less than a certain percentage of the size of the DB cache. For example, some releases set the boundary between short and long table scans at 2 percent of the DB cache size. Generally, the number of short table scans should be much greater than long table scans in a properly indexed environment.
Transaction Rollback
The transaction rollbacks statistic is for rollbacks that actually do work. This statistic will also track the rollbacks done automatically. For example, when an update occurs for multiple rows but has to be backed out and restarted by Oracle because of blocking locks, as this attempt to update-block-rollback may occur several times for a single transaction, you will see several transaction rollback increments even though a single transaction actually occurred. If this statistic is high, then check for conflicting transactions that lock many rows.
Undo Change Vector Statistic
The undo change vector size statistic is a cumulative count in bytes of the size of undo records. By calculating a ratio of undo change vector size to user calls, you can get an idea of the amount of undo being generated per user call. If the undo being generated is large, then look for excessive write activity to the undo tablespace, as this could be slowing down your transactions and causing stress on the I/O subsystem. If your application generates large amounts of undo by nature, consider moving the undo tablespace to high-speed disk or flash-based assets.
User Statistics
The user I/O wait time statistic is the cumulative I/O wait time. Use this statistic with user calls to determine the average I/O wait time per user call. This can also be used with the physical reads plus the physical writes to determine the average I/O wait time per I/O. If the I/O wait time becomes an issue, you can add physical storage (disks), increase the amount of disk caching, or place hot tables and indexes on flash-based storage.
Note
The user I/O wait time statistic has been removed from the report starting in Oracle Datable 11.2.0.4. You will need to sum the I/O wait times in the service-related statistics to get this information in releases 11.2.0.4 and later.
The user commits and user rollbacks are used with other statistics to determine weighting. If the number of user rollbacks is high compared to user commits, look to ad-hoc SQL or improper session termination as the possible cause. Before the Oracle database supported the MERGE and UPSERT commands, programmers would process to an exception for INSERT and UPDATE decisions; in other words, they would attempt an INSERT and, if it failed giving an exception, then the transaction would roll back and the programmer would then trigger an update. This type of processing results in large amounts of undo activity and should be avoided.
Work Area Statistics
The work area statistics were already discussed in the section on sort statistics. Essentially, the most desired work area statistic is workarea executions–optimal, as these were done within the PGA_AGGREGATE_TARGET settings in memory. Any of the other work area statistics indicate a sort to storage. If there seem to be excessive workarea executions-optimal, then look to eliminate unneeded sorts such as the use of distinct from improper joins, sorts that could be eliminated using a multicolumn index or unneeded order by and group by operations.
Instance Activity Statistics—Absolute Values
The absolute values show the high-watermarks for various memory, login, and other cumulative statistics that cannot be diffed. Using ratios of logins to the various PGA and user global area (UGA) memory allocations can show possible settings for PGA_AGGREGATE_TARGET values or sort area values. Remember that these values are incremented each time a process is created and adds to its PGA or UGA areas. That contribution is not removed once the session logs out, so the actual totals may bear little resemblance to the real values. Use these statistics for information only.
Instance Activity Statistics—Thread Activity
The thread activity statistic shows the number of (projected) redo logs switched per hour. The old way was to have redo logs switch every 15 minutes. This rule of thumb to switch every 15 minutes may or may not apply to your database—it is best to tune redo log size according to the needs of your system. However, excessive redo log switching (such as once a minute with a 5 MB log) should be avoided, as this generates lots of I/O, latch, and CPU overhead.