Tracking Errors with dmstool Oracle Application Server Tips by Burleson Consulting

The dmstool utility is also useful for tracking important internal errors within OHS.  In the example below we use dmstool with the ohs_responses argument to see detailed error information.

#!/bin/ksh

PATH=$PATH:/home/oracle/oraportal904/bin
export PATH

dmstool -table ohs_responses > resp.lst

Here is wee a listing of all OHS errors, reported in 10-minute intervals (Listing 10.11).

Mon Jul 14 14:56:22 MDT 2003

-------------
ohs_responses
-------------

CltErr_Authorization_Required_401.count:        0       ops
CltErr_BadRange_416.count:                      0       ops
CltErr_Bad_Request_400.count:                   0       ops
CltErr_Conflict_409.count:                      0       ops
CltErr_ExpectFailed_417.count:                  0       ops
CltErr_Failed_Dependency_424.count:             0       ops
CltErr_Forbidden_403.count:                     0       ops
CltErr_Gone_410.count:                          0       ops
CltErr_LengthRequired_411.count:                0       ops
CltErr_Locked_423.count:                        0       ops
CltErr_Method_Not_Allowed_405.count:            0       ops
CltErr_Not_Acceptable_406.count:                0       ops
CltErr_Not_Found_404.count:                    14       ops
CltErr_Payment_Required_402.count:              0       ops
CltErr_PreCondFail_412.count:                   0       ops
CltErr_ProxyAuthReq_407.count:                  0       ops
CltErr_ReqEntityTooLarge_413.count:             0       ops
CltErr_Timeout_408.count:                       0       ops
CltErr_URITooLarge_414.count:                   0       ops
CltErr_Unprocessable_Entity_422.count:          0       ops
CltErr_UnsuppMediaType_415.count:               0       ops
Info_Continue_100.count:                        0       ops
Info_Processing_102.count:                      0       ops
Info_ProtoSwitch_101.count:                     0       ops
Redirect_Found_302.count:                       1046    ops
Redirect_Moved_301.count:                       0       ops
Redirect_MultiChoice_300.count:                 0       ops
Redirect_NotModified_304.count:                 0       ops
Redirect_SeeOther_303.count:                    0       ops
Redirect_Temporary_307.count:                   0       ops
Redirect_UseProxy_305.count:                    0       ops
Success_Accepted_202.count:                     0       ops
Success_Created_201.count:                      0       ops
Success_Multi-Status_207.count:                 0       ops
Success_NoContent_204.count:                    0       ops
Success_NonAuthInfo_203.count:                  0       ops
Success_OK_200.count:                           173910  ops
Success_PartialContent_206.count:               0       ops
Success_ResetContent_205.count:                 0       ops
SvrErr_BadGateway_502.count:                    0       ops
SvrErr_GtwyTimeout_504.count:                   0       ops
SvrErr_Insufficient_Storage_507.count:          0       ops
SvrErr_InternalError_500.count:                 155     ops
SvrErr_NotImplemented_501.count:                0       ops
SvrErr_Not_Extended_510.count:                  0       ops
SvrErr_SvcUnavail_503.count:                    0       ops
SvrErr_Variant_Also_Negotiates_506.count:       0       ops
SvrErr_VersionNotSupp_505.count:                0       ops
Host:   appsvr
Name:   Responses
Parent: /Apache
Process:        Apache:2534:6004
ohs_server:     Apache

Listing 10.11: dmstool error report for OHS

This listing shows all possible errors in the OHS server.  The most common is the ?404 Not Found? message when an invalid URL is encountered.  Most Oracle9iAS administrators write automated scripts to review these logs and report on the important internal errors such as the SvrErr_InternalError_500.count error line.

#!/bin/ksh

PATH=$PATH:/home/oracle/oraportal904/bin
export PATH

dmstool -table ohs_responses|grep SvrErr_InternalError_500.count|cut ?d? ? ?f1 

Here we can get the numerical lists of the internal errors at 10 minute intervals.  When we see a large number of internal errors we will want to check the OHS error_log file to see the URL that is causing the internal error.  This output can be easily charted and graphed for time-series analysis (Listing 10.12).

34
1
1
5
61
77
12
3

Listing 10.12: OHS internal errors in 10-minute intervals

Capturing detailed module performance data in OHS

The dmstool interface also allows us to gather drill-down details for all modules with OHS.  The default OHS installation includes these modules (Table 10.2), and you can get detailed performance values on each of these components:

http_core.c
mod_access.c
mod_actions.c
mod_alias.c
mod_asis.c
mod_auth.c
mod_auth_anon.c
mod_auth_dbm.c
mod_autoindex.c
mod_cern_meta.c
mod_cgi.c
mod_dav.c
mod_define.c
mod_digest.c
mod_dir.c
mod_dms.c
mod_env.c
mod_example.c
mod_expires.c
mod_fastcgi.c
mod_headers.c
mod_imap.c
mod_include.c
mod_info.c
mod_log_agent.c
mod_log_config.c
mod_log_referer.c
mod_mime.c
mod_mime_magic.c
mod_mmap_static.c
mod_negotiation.c
mod_oc4j.c
mod_onsint.c
mod_ossl.c
mod_osso.c
mod_perl.c
mod_plsql.c
mod_proxy.c
mod_rewrite.c
mod_setenvif.c
mod_so.c
mod_speling.c
mod_status.c
mod_unique_id.c
mod_userdir.c
mod_usertrack.c
mod_vhost_alias.c
mod_wchandshake.c

Table 10.2: All default modules within the OHS server

While each of these modules server important functions, there are some that are especially noteworthy, namely the http_core.c and mod_oc4j.c modules.  We will take a close look at these in just a minute.

Here is a small script to generate the performance details for each module.

#!/bin/ksh

PATH=$PATH:/home/oracle/oraportal904/bin
export PATH

dmstool -table ohs_module -c 1

Here we get a huge listing showing a verbose record of detailed performance metrics for all OHS processes (Listing 10.13).  Here we see the details for the http_core.c and the mod_oc4j.c OHS process.

Name:   mod_oc4j.c     
Parent: /Apache/Modules
Process:        Apache:2534:6004
ohs_server:     Apache 

decline.count:  13487   ops
handle.active:  0       threads
handle.avg:     3       usecs
handle.completed:       13487   ops
handle.maxTime: 8       usecs
handle.minTime: 2       usecs
handle.time:    43710   usecs
Host:   appsvr
Name:   http_core.c
Parent: /Apache/Modules
Process:        Apache:2534:6004
ohs_server:     Apache

decline.count:  0       ops
handle.active:  0       threads
handle.avg:     0       usecs
handle.completed:       0       ops
handle.maxTime: 0       usecs
handle.minTime: 0       usecs
handle.time:    0       usecs
 . . .

Listing 10.13: ohs_response listing for OHS modules

The above listing we see execution time details for the mod_oc4j.c and http_core.c modules, including the number of executions (handle.completed), the max time, min time and average time for execution in milliseconds.  The most important metric is the handle.avg statistic because it shows the average time for execution.  Let?s see why these are important modules:

• http_core.c ? This module handles every request for static pages in OHS and warrants special attention. Monitoring http_core.c is critical because the Web Cache layer should be preventing static pages from reaching the OHS server.  Hence, processing values for http_core.c usually indicate a problem at the Web Cache level.  In Listing 10.13 we see that http_core.c has very little activity, indicating a properly configured Web Cache.

• mod_oc4j.c ? This module processes all J2EE requests (OC4J), and will be one of the most important modules in OHS.  This value will give you a good idea about the number of transactions that have been forwarded to OC4J.

Now let?s take a close look at this data and see how to compute the real response time for an OHS module.

Computing real response time for OHS Modules

One of the problems with the OHS statistics is that the one-time operations will skew the overall averages in the ohs_response listings.  To remove these factors, Oracle recommends computing the real response time as follows:

                  (time ? min ? max)
real_average = ------------------------
                    (completed ? 2)

Using the data from the above mod_oc4j.c listing, we can compute the real response time:

                  (43,710 ? 2 ? 8)
real_average = ------------------------
                    (13,487 ? 2)

                    (43,700)
real_average = ------------------ = 3.24 milliseconds
                    (13,485)

Now that we understand dmstool and OHS performance, let?s take a quick look at the aggrespy online interface.  The aggrespy utility provides a quick summary of important performance information.

Monitoring Oracle9iAS with aggrespy

The Oracle9iAS aggrespy utility is a Java servlet that is used with standalone OC4J instances.  The aggrespy utility can be used to display metrics for many Oracle9iAS processes including:

• HTTP Server processes

• OC4J processes

• OPMN processes

Unlike the dmstool utility which provides statistics in time intervals, the aggrespy web pages only provide a real-time summary of overall performance.

Note: Many beginners misinterpret the aggrespy output, attempting to use it to diagnose a current performance problem.  Remember, aggrespy contains roll-up information since startup time, and is NOT useful for spotting current performance bottlenecks.  For acute performance troubleshooting, you should use the dmstool utility to get time-slice summaries. 

You can access Aggrespy by invoking this URL: http://myhost:myport/dmsoc4j/AggreSpy.   In our system, we invoke http://appsvr.localdomain.com:7778/dmsoc4j/AggreSpy and we see the following aggrespy main screen (Figure 10.11).

Figure 10.11: The Aggrespy main screen

The main window of this screen allows you to drill-down into increasing levels of detail.  For example, clicking the ohs_module link from the right-hand pane, shows the same details as the dmstool -table ohs_module -c 1 command (Figure 10.12).

Figure 10.12: Performance details for the OHS modules using aggrespy

In Figure 10.12 we can quickly see that the http_core.c module has processed 57,972 requests with an average response time of 247 milliseconds.

The aggrespy utility is a fast way to examine specific real-time performance metrics within your Oracle9iAS architecture, but for time-series analysis most Oracle9iAS administrators will use the dmstool utility to capture time-based data for trend analysis.

Now that we have covered OHS monitoring and tuning, let?s take a quick look at tuning the iasdb and back-end Oracle database.  For in-depth details on Oracle database tuning, see Oracle9i High-Performance Tuning with STATSPACK by Oracle Press.

Monitoring the Oracle database instances

Because the Infrastructure and Oracle back-end database are critical Oracle9iAS components, special care should be taken to ensure their optimal performance.

The concept of instance tuning is one of the most misunderstood areas of Oracle tuning. In practice, an overstressed Oracle SGA can cause serious performance problems, but once tuned, the Oracle SGA really needs little attention from the Oracle9iAS professional.

The tuning of the Oracle instance involves checking all of the initialization parameters for the Oracle database. As most Oracle professionals know, the Oracle init.ora parameters are getting more complex as the Oracle database becomes more sophisticated. While there are hundreds of initialization parameters, there are a handful of Oracle9i parameters that are very important for Oracle tuning:

• buffer_pool_keep - This data buffer pool is used to store small tables that perform full table scans.

• buffer_pool_recycle - This pool is reserved for table blocks from very large tables that perform full table scans.

• db_cache_size - This parameter determines the number of database block buffers in the Oracle SGA and represents the single most important parameter to Oracle memory.

• db_block_size - The size of the database blocks can make a huge improvement in performance. While the default value may be as small as 2,048 bytes, data warehouses and applications that have large tables with full table scans will see a tremendous improvement in performance by increasing db_block_size to a larger value. As a general rule, the larger the block size, the less physical I/O, and the faster the overall performance.

• db_file_multiblock_read_count - This parameter is used for multiblock reads when performing full table scans or large range scans.

• large_pool_size - This is a special area of the shared pool that is reserved for SGA usage when using the multithreaded server. The large pool is also used for parallel query and RMAN processing.

• log_buffer - This parameter determines the amount of memory to allocate for Oracle's redo log buffers. If there is a high amount of update activity, the log_buffer should be allocated more space.

• shared_pool_size - This parameter defines the pool that is shared by all users in the system, including SQL areas and data dictionary caching. As we will learn later in this chapter, a large shared_pool_size is not always better than a smaller shared pool. If your application contains nonreusable SQL, you may get better performance with a smaller shared pool.

• pga_aggregate_target - This parameter determines the memory region that is allocated for in-memory sorting. When the stats$sysstat value sorts (disk) becomes excessive, you may want to allocate additional memory.

Of course, Oracle database tuning is a huge topic and far beyond the scope of this text.  For more details on effective Oracle database monitoring and tuning see Oracle9i High Performance Tuning with STATSPACK by Oracle Press.

This is an excerpt from "Oracle 10g Application Server Administration Handbook" by Don Burleson and John Garmany.