Tuesday, November 17, 2009

Response-Time Analysis Made Easy in Oracle Database 10g



With Oracle Database 10g, many previously difficult-to-attain response-time metrics are now at your fingertips.

Historically, in trying to achieve maximum database performance, Oracle DBAs and performance analysts have fought an uphill battle to obtain solid response time metrics for system as well as user session activity. The problem facing DBAs has always had two facets: first, determining exactly "where" the database or user sessions have been spending their time; and second, determining the objective nature of the user experience.

Given all the possible activities and interactions within the database, these tasks are far from trivial. The Oracle Wait Interface, which was introduced many versions ago, has been a great jump-start for admins who know how to use it, but even it has lacked the ideal ability to tell a DBA how well the system or user sessions have efficiently processed transactions or queries. Enabling and poring over trace files can garner this level of detail, but for most overworked DBAs who have to manage large database farms, this exercise is a luxury.

Fortunately, those Oracle DBAs who have upgraded to Oracle Database 10g will find major response-time enhancements that allow a much better picture to be presented about system and session-level response-time metrics. Most significantly, the Oracle Automatic Database Diagnostic Monitor (ADDM) provides insights into response times and much more by automatically analyzing collected statistics, identifying problem areas, and even providing recommendations through the Oracle Enterprise Manager Grid Control GUI.

Furthermore, and most relevant to our discussion here, historical mechanisms in Oracle Database 10g allow DBAs to look back in time to perform their own response-time trend analysis, which helps them determine peak and nonpeak transaction/system times as well as locate rogue processes and SQL that elongate batch cycles or ETL jobs.
In this article, I'll explore the use of some of these historical mechanisms at the system, session, and SQL levels. For more information about ADDM, see the Oracle documentation as well as the "ADDM and SQL Tuning Advisor" installment of Arup Nanda's "Oracle Database 10g: Top 20 Features for DBAs."

System-Level Response-Time Analysis

Starting at the global or system level, DBAs typically want answers to these questions:
  • In general, how well is my database running? What defines efficiency?
  • What average response time are my users experiencing?
  • Which activities affect overall response time the most?

The answers to these questions have been fairly elusive for DBAs before Oracle Database 10g, but now such metrics can be somewhat easy to capture if you happen to be using the latest and greatest Oracle database.
First of all, part of the answer to how well, in general, a database is running can be obtained by issuing this query in Oracle Database 10g:
 
select  METRIC_NAME,
        VALUE
from    SYS.V_$SYSMETRIC
where   METRIC_NAME IN ('Database CPU Time Ratio',
                        'Database Wait Time Ratio') AND
        INTSIZE_CSEC = 
        (select max(INTSIZE_CSEC) from SYS.V_$SYSMETRIC); 
 
METRIC_NAME                         VALUE
------------------------------ ----------
Database Wait Time Ratio                6
Database CPU Time Ratio                94

The Oracle Database 10g V$SYSMETRIC view contains several excellent response-time metrics, two of which are the Database Wait Time Ratio and Database CPU Time Ratio. The query above shows the latest snapshot of these two statistics, which help you determine if your database is currently experiencing a high percentage of waits/bottlenecks vs. smoothly running operations. The Database CPU Time Ratio is calculated by dividing the amount of CPU expended in the database by the amount of "database time," which is defined as the time spent by the database on user-level calls (with instance background process activity being excluded). High values (90-95+ percent) are good and indicate few wait/bottleneck actions, but take this threshold only as a general rule of thumb because every system is different.

You can also take a quick look over the last hour to see if the database has experienced any dips in overall performance by using this query:
 
select  end_time,
        value
from    sys.v_$sysmetric_history
where   metric_name = 'Database CPU Time Ratio'
order by 1;
 
END_TIME                  VALUE
-------------------- ----------
22-NOV-2004 10:00:38         98
22-NOV-2004 10:01:39         96
22-NOV-2004 10:02:37         99
22-NOV-2004 10:03:38        100
22-NOV-2004 10:04:37         99
22-NOV-2004 10:05:38         77
22-NOV-2004 10:06:36        100
22-NOV-2004 10:07:37         96
22-NOV-2004 10:08:39        100
.
.
And, you can get a good idea of the minimum, maximum, and average values of overall database efficiency by querying the V$SYSMETRIC_SUMMARY view with a query such as this:
 
select  CASE METRIC_NAME
            WHEN 'SQL Service Response Time' then 'SQL Service Response Time (secs)'
            WHEN 'Response Time Per Txn' then 'Response Time Per Txn (secs)'
            ELSE METRIC_NAME
            END METRIC_NAME,
                    CASE METRIC_NAME
            WHEN 'SQL Service Response Time' then ROUND((MINVAL / 100),2)
            WHEN 'Response Time Per Txn' then ROUND((MINVAL / 100),2)
            ELSE MINVAL
            END MININUM,
                    CASE METRIC_NAME
            WHEN 'SQL Service Response Time' then ROUND((MAXVAL / 100),2)
            WHEN 'Response Time Per Txn' then ROUND((MAXVAL / 100),2)
            ELSE MAXVAL
            END MAXIMUM,
                    CASE METRIC_NAME
            WHEN 'SQL Service Response Time' then ROUND((AVERAGE / 100),2)
            WHEN 'Response Time Per Txn' then ROUND((AVERAGE / 100),2)
            ELSE AVERAGE
            END AVERAGE
from    SYS.V_$SYSMETRIC_SUMMARY 
where   METRIC_NAME in ('CPU Usage Per Sec',
                      'CPU Usage Per Txn',
                      'Database CPU Time Ratio',
                      'Database Wait Time Ratio',
                      'Executions Per Sec',
                      'Executions Per Txn',
                      'Response Time Per Txn',
                      'SQL Service Response Time',
                      'User Transaction Per Sec')
ORDER BY 1
 
METRIC_NAME                       MINIMUM    MAXIMUM    AVERAGE
------------------------------ ---------- ---------- ----------
CPU Usage Per Sec                       0          7          1
CPU Usage Per Txn                       1         29          8
Database CPU Time Ratio                61        100         94
Database Wait Time Ratio                0         39          5
Executions Per Sec                      2         60          8
Executions Per Txn                     16        164         41
Response Time Per Txn (secs)            0        .28        .08
SQL Service Response Time (sec          0          0          0
User Transaction Per Sec                0          1          0

The query above contains more response-time metrics than simply the Database CPU and Wait Time Ratios (we'll cover those later), but you can see the benefit in being able to acquire this information. For this particular instance, the average Database CPU Time Ratio is 94, which is well within our acceptable limits.

The next question DBAs pose at the system level involves the average level of response time that their user community is experiencing. (Prior to Oracle Database 10g this type of data was difficult to capture, but not anymore.) The query shown above that interrogates the V$SYSMETRIC_SUMMARY view tells us what we need to know. If complaints of unacceptable response times are mounting from users, the DBA can check the Response Time Per Txn and SQL Service Response Time metrics to see if a database issue exists. For example, the statistics shown above report that the maximum response time per user transaction has been only .28 second, with the average response time being a blazing .08 second. Oracle certainly wouldn't be to blame in this case.

If, however, response times are longer than desired, the DBA will then want to know what types of user activities are responsible for making the database work so hard. Again, before Oracle Database 10g, this information was more difficult to acquire, but now the answer is only a query away:
 
select  case db_stat_name
            when 'parse time elapsed' then 
                'soft parse time'
            else db_stat_name
            end db_stat_name,
        case db_stat_name
            when 'sql execute elapsed time' then 
                time_secs - plsql_time 
            when 'parse time elapsed' then 
                time_secs - hard_parse_time
            else time_secs
            end time_secs,
        case db_stat_name
            when 'sql execute elapsed time' then 
                round(100 * (time_secs - plsql_time) / db_time,2)
            when 'parse time elapsed' then 
                round(100 * (time_secs - hard_parse_time) / db_time,2)  
            else round(100 * time_secs / db_time,2)  
            end pct_time
from
(select stat_name db_stat_name,
        round((value / 1000000),3) time_secs
    from sys.v_$sys_time_model
    where stat_name not in('DB time','background elapsed time',
                            'background cpu time','DB CPU')),
(select round((value / 1000000),3) db_time 
    from sys.v_$sys_time_model 
    where stat_name = 'DB time'),
(select round((value / 1000000),3) plsql_time 
    from sys.v_$sys_time_model 
    where stat_name = 'PL/SQL execution elapsed time'),
(select round((value / 1000000),3) hard_parse_time 
    from sys.v_$sys_time_model 
    where stat_name = 'hard parse elapsed time')
order by 2 desc;
 
 
DB_STAT                          TIME_SECS       PCT_TIME
-----------------------------    ---------       --------
sql execute elapsed time         13263.707       45.84                                 
PL/SQL execution elapsed time    13234.738       45.74                                 
hard parse elapsed time           1943.687        6.72                                  
soft parse time                    520.584         1.8
.
.

The example output above shows a database that has spent the vast majority of its time handling SQL and PL/SQL requests. Complete descriptions of all the statistics supported by the V$SYS_TIME_MODEL view can be found here.

In addition to active time, a DBA will want to know the global wait times as well. Prior to Oracle Database 10g, a DBA had to view individual wait events to understand waits and bottlenecks, but now Oracle provides a summary/rollup mechanism for waits via wait classes:
 
select  WAIT_CLASS,
        TOTAL_WAITS,
        round(100 * (TOTAL_WAITS / SUM_WAITS),2) PCT_WAITS,
        ROUND((TIME_WAITED / 100),2) TIME_WAITED_SECS,
        round(100 * (TIME_WAITED / SUM_TIME),2) PCT_TIME
from
(select WAIT_CLASS,
        TOTAL_WAITS,
        TIME_WAITED
from    V$SYSTEM_WAIT_CLASS
where   WAIT_CLASS != 'Idle'),
(select  sum(TOTAL_WAITS) SUM_WAITS,
        sum(TIME_WAITED) SUM_TIME
from    V$SYSTEM_WAIT_CLASS
where   WAIT_CLASS != 'Idle')
order by 5 desc;
 
WAIT_CLASS      TOTAL_WAITS  PCT_WAITS TIME_WAITED_SECS   PCT_TIME
--------------- ----------- ---------- ---------------- ----------
User I/O            2245204       7.48          4839.43      54.39
System I/O          2438387       8.12          2486.21      27.94
Application          920385       3.07           513.56       5.77
Other                 39962        .13           422.36       4.75
Commit               200872        .67           284.76        3.2
Network            24133213      80.38           162.26       1.82
Concurrency            6867        .02           102.63       1.15
Configuration         39377        .13            86.21        .97

It's much easier to tell now that the bulk of overall wait time is due, for example, to user I/O waits than to try to tally individual wait events to get a global picture. As with response-time metrics, you can also look back in time over the last hour with a query like this one:
 
select  to_char(a.end_time,'DD-MON-YYYY HH:MI:SS') end_time,
        b.wait_class,
        round((a.time_waited / 100),2) time_waited 
from    sys.v_$waitclassmetric_history a,
        sys.v_$system_wait_class b
where   a.wait_class# = b.wait_class# and
        b.wait_class != 'Idle'
order by 1,2;
 
END_TIME             WAIT_CLASS      TIME_WAITED
-------------------- --------------- -----------
22-NOV-2004 11:28:37 Application               0
22-NOV-2004 11:28:37 Commit                  .02
22-NOV-2004 11:28:37 Concurrency               0
22-NOV-2004 11:28:37 Configuration             0
22-NOV-2004 11:28:37 Network                 .01
22-NOV-2004 11:28:37 Other                     0
22-NOV-2004 11:28:37 System I/O              .05
22-NOV-2004 11:28:37 User I/O                  0
.
.

You can, of course, just focus on a single SID with the V$SESS_TIME_MODEL view and obtain data for all statistical areas of a session. You can also view current session wait activity using the new wait classes using the following query:
 
select  a.sid,
        b.username,
        a.wait_class,
        a.total_waits,
        round((a.time_waited / 100),2) time_waited_secs
from    sys.v_$session_wait_class a,
        sys.v_$session b
where   b.sid = a.sid and
        b.username is not null and
        a.wait_class != 'Idle'
order by 5 desc;
 
SID USERNAME   WAIT_CLASS      TOTAL_WAITS TIME_WAITED_SECS
--- ---------- --------------- ----------- ----------------
257 SYSMAN     Application          356104            75.22
255 SYSMAN     Commit                14508            25.76
257 SYSMAN     Commit                25026            22.02
257 SYSMAN     User I/O              11924            19.98
.
.
.

After this stage, you can check the standard individual wait events as you've been able to do in earlier versions of Oracle with V$SESSION_WAIT and V$SESSION_EVENT. You'll also find the new wait classes in these two modified views with Oracle Database 10g.

If you need to look back in time to discover what sessions were logged on and consuming the most resources, you can use the following query. In the example below, we're looking at activity from midnight to 5 a.m. on November 21, 2004, that involved user I/O waits:
 
select  sess_id,
        username,
        program,
        wait_event,
        sess_time,
        round(100 * (sess_time / total_time),2) pct_time_waited
from
(select a.session_id sess_id,
        decode(session_type,'background',session_type,c.username) username,
        a.program program,
        b.name wait_event,
        sum(a.time_waited) sess_time
from    sys.v_$active_session_history a,
        sys.v_$event_name b,
        sys.dba_users c
where   a.event# = b.event# and
        a.user_id = c.user_id and
        sample_time > '21-NOV-04 12:00:00 AM' and 
        sample_time < '21-NOV-04 05:00:00 AM' and
        b.wait_class = 'User I/O'
group by a.session_id,
        decode(session_type,'background',session_type,c.username),
        a.program,
        b.name),
(select sum(a.time_waited) total_time
from    sys.v_$active_session_history a,
        sys.v_$event_name b
where   a.event# = b.event# and
        sample_time > '21-NOV-04 12:00:00 AM' and 
        sample_time < '21-NOV-04 05:00:00 AM' and
        b.wait_class = 'User I/O')
order by 6 desc;
 
SESS_ID USERNAME PROGRAM    WAIT_EVENT                SESS_TIME PCT_TIME_WAITED
------- -------- ---------- ------------------------- ---------- -------------
    242 SYS      exp@RHAT9K db file scattered read       3502978         33.49
    242 SYS      oracle@RHA db file sequential read      2368153         22.64
    242 SYS      oracle@RHA db file scattered read       1113896         10.65
    243 SYS      oracle@RHA db file sequential read       992168          9.49

The Oracle Database 10g V$ACTIVE_SESSION_HISTORY view comes into play here to provide an insightful look back in time at session experiences for a given time period. This view gives you a lot of excellent information without the need for laborious tracing functions. We'll see more use of it in the next section, which deals with analyzing the response times of SQL statements.

SQL Response-Time Analysis

Examining the response time of SQL statements became easier in Oracle9i, and with Oracle Database 10g, DBAs have many tools at their disposal to help them track inefficient database code.

Historically the applicable V$ view here has been V$SQLAREA. Starting with Oracle9i, Oracle added the ELAPSED_TIME and CPU_TIME columns, which have been a huge help in determining the actual end user experience of a SQL statement execution (at least, when dividing them by the EXECUTIONS column, which produces the average amount of time per execution).

In Oracle Database 10g, six new wait-related and timing columns have been added to V$SQLAREA:
  • APPLICATION_WAIT_TIME
  • CONCURRENCY_WAIT_TIME
  • CLUSTER_WAIT_TIME
  • USER_IO_WAIT_TIME
  • PLSQL_EXEC_TIME
  • JAVA_EXEC_TIME

The new columns are helpful in determining, for example, the amount of time that a procedure spends in PL/SQL code vs. standard SQL execution, and if a SQL statement has experienced any particular user I/O waits. For example, a query you could use to find the top five SQL statements with the highest user I/O waits would be:
 
select *
from
(select sql_text,
        sql_id,
        elapsed_time,
        cpu_time,
        user_io_wait_time
from    sys.v_$sqlarea
order by 5 desc)
where rownum < 6;
 
SQL_TEXT                  SQL_ID       ELAPSED_TIME CPU_TIME  USER_IO_WAIT_TIME
------------------------- ------------ ------------ ---------- ---------------
select /*+ rule */ bucket db78fxqxwxt7     47815369   19000939            3423
SELECT :"SYS_B_0" FROM SY agdpzr94rf6v     36182205   10170226            2649
select obj#,type#,ctime,m 04xtrk7uyhkn     28815527   16768040            1345
select grantee#,privilege 2q93zsrvbdw4     28565755   19619114             803
select /*+ rule */ bucket 96g93hntrzjt      9411028    3754542             606

Of course, getting the SQL statements with the highest elapsed time or wait time is good, but you need more detail to get to the heart of the matter—which is where the V$ACTIVE_SESSION_HISTORY view again comes into play. With this view, you can find out what actual wait events delayed the SQL statement along with the actual files, objects, and object blocks that caused the waits (where applicable).

For example, let's say you've found a particular SQL statement that appears to be extremely deficient in terms of user I/O wait time. You can issue the following query to get the individual wait events associated with the query along with the corresponding wait times, files, and objects that were the source of those waits:
 
select event,
        time_waited,
        owner,
        object_name,
        current_file#,
        current_block# 
from    sys.v_$active_session_history a,
        sys.dba_objects b 
where   sql_id = '6gvch1xu9ca3g' and
        a.current_obj# = b.object_id and
        time_waited <> 0;
 
EVENT                     TIME_WAITED OWNER  OBJECT_NAME           file  block
------------------------- ----------- ------ --------------------- ---- ------
db file sequential read         27665 SYSMAN MGMT_METRICS_1HOUR_PK    3  29438
db file sequential read          3985 SYSMAN SEVERITY_PRIMARY_KEY     3  52877

Of course, you can use V$ACTIVE_SESSION_HISTORY in a historical fashion to narrow down unoptimized SQL statements for a particular time period. The point is that Oracle Database 10g makes it a lot easier to conduct response-time analysis on SQL statements with simplified data dictionary views, as opposed to the time-consuming trace-and-digest method.

Conclusion

DBAs and performance analysts who manage the performance of Oracle Database 10g will find many of the response-time metrics they've yearned for over the years now at their fingertips in the latest release of Oracle's flagship database. Such statistics will help accelerate the process of finding the proverbial needle in the haystack of large and complex database performance situations.

REFERENCES


Response-Time Analysis Made Easy in Oracle Database 10g by Robin Schumacher

No comments:

Post a Comment