Skip to content

DBAzine.com

Sections
Personal tools
You are here: Home » Oracle » Oracle Articles Archive » Creating a Response Time Monitor for Oracle Forms
Seeking new owner for this high-traffic DBAzine.com site.
Tap into the potential of this DBA community to expand your business! Interested? Contact us today.
Who Are You?
I am a:
Mainframe True Believer
Distributed Fast-tracker

[ Results | Polls ]
Votes : 3548
 

Creating a Response Time Monitor for Oracle Forms

by John Garmany

Introduction

Oracle Forms Server 6i introduced an exciting new feature to collect performance data. The Performance Collector allows the application developer to quickly locate sub-optimal code. Using the Performance Collector, a developer can determine exactly which form, event within a form, and tier (client, form server or database server), is affecting the application performance. Oracle Forms provides the developer with a capable, flexible structure for building complex applications. Being able to place code and PL/SQL procedures/functions in both the form and the database helps produce efficient, modular code. However, this flexibility also adds a level of complexity when the developer is trying to identify sub-optimal routines. Performance tuning is always difficult once the application is in use. However, the Performance Collector can produce data while the application is in use that will help the developer focus his optimization efforts. The Forms 6i Performance Collector records to a log file, the application time spent in each of the three tiers (refer to Figure 1) used by Oracle Forms;

      • The client tier is time spent executing the client code, processing input, displaying forms, and interacting with the user interface. It includes time spent on the physical network connecting the client program to the Forms Server and could include user-input time.
      • The forms server tier is time spent in the Forms Server. This includes processing requests, executing functions and procedures located on the Forms Server.
      • The database tier is time spent requesting information from the database. This includes both the time spent in the database servicing the request and the time spent on the physical network connecting the database and Forms Server.

Each client that uses the Forms Server will generate a Performance Log file. This log begins when the user logs onto the Forms Server, and stores timing data until the user logs off the Forms Server. The log follows the user as they progress through the system to include the opening of forms. The basic structure for the performance log starts with the user executing an event. The event (to include the form name) is logged followed by timing marks as the event moves in and out of the Forms Server. This continues until the next event is encountered.

The Performance log captures two important pieces of information critical to the developer’s performance tuning of the application: time spent in each tier and the number of database calls required to satisfy an event. Because of modular construction, complicated user interface forms can require 20–30 separate database queries to retrieve and populate the form. This has a significant impact on the application’s performance and adds unnecessary overhead on the database. The timing information depicts the applications transition between the three tiers (Figure 1.). In fact, the timing marks represent the applications transition into and out of the Form Server. By analyzing these logs, the developer can determine the exact areas affecting the system’s performance.

Figure 1: Three tiers in Performance Collector.

The timestamp indicates a time that the forms application entered or exited the Form Server tier. For example, TSE DB_START indicates a request was sent from the Forms Server to the database. TSE DB_END indicates the database has responded and the application has re-entered the Forms Server. The difference in the timing marks from TSE DB_START and TSE DB_END is the time spent in the database to execute the request. The Performance Collector divides the timings into four categories:

      • A — Database
      • B — Forms Server
      • C — Network
      • D – Client

The Network and Client categories represent the elapsed time spent in the Client tier. Time spent in the Client tier processing information but not interacting with the user is logged in the Network category. Time spent in the Client tier that involved interaction with the user is placed in the Client category. Hence, the total time spent in the Client tier is the sum of the Network and Client categories. Both the Client and Network categories include time spent on the physical network connecting the Form Server to the Client.

To analyze the performance log, Oracle provides a Perl script called f60parse.pl, which can produce either a comma-delineated text file or an html report. The comma-delineated text file can be loaded into a spreadsheet for analyses. The html report can be loaded into a browser and provides detailed performance information in an easy to read form. This script is very effective and informative during testing to analyze a single performance log.

The downside:

      • Too many files — However, once your forms server application is in production, Oracle Forms produces a separate file for each user, which quickly overwhelms the capability of the Perl script. For example, one server that I currently support generates hundreds of log files a day ranging from a few Kbytes to more than 100M each.
      • Long time to run — Using the Perl script to analyze 30 days of performance logs required more than 8 hours to generate the comma-delineated file, which was then split up and loaded into MS Excel for analysis. This was a three- to four-day job.

The solution:

Load the data into the Oracle Database — I needed a more efficient method to process and analyze the performance logs. My methodology was to create a simple Java program to process the daily performance logs and load the results into the Oracle database. This would allow me to use the power of the Oracle database to analyze the performance data as needed. The purpose of this article is to explain a great method to parse the Performance Log, load the data into the database and analyze the performance of the overall system. Let’s start with the performance log.

The Performance Log

      • The performance log is stored as a simple text file. This file contains timing markers as the system moves between the three tiers. It starts by:
          1. Identifying the form
          2. An event
          3. From 1 to n timing marks (refer to Example 1)

This data is collected every time the application passes into and out of the Form Server (Figure 1). Example 1 is a segment of a performance log. It captures the opening of the form and the events executed in the form. Each timing mark 'TSE' identifies a transition to or from one of the three tiers. All of the time is captured including time spent logging onto or off the database. Let's walk through the segment of the performance log in.

Example 1:

It identifies that the user opened the form F_sys_maint.fmx. Each event in the performance log is assigned a number beginning with #1. The log segment in Example 1 addresses event #23 through the start of event #24. The user clicks the F_AVN_MAINT BUTTONS CLAIM#_BTN with a timing mark of 31035531, starting event #23. The Form Server starts, performs three interactions with the database and sends the information back to the client. The Form Server again starts and ends (this time without interacting with the database) by sending data back to the client. The client executes a new event, #24. Total time to execute event #23 is:

Forms Server            = 00000015
Database                = 00000000
Client                  = 00003422
Network                 = 00000000

Also note that event #23 executed three consecutive interactions with the database.

Opened file: d:\forms\F_avn_maint.fmx

# 23 - F_AVN_MAINT:BILLS_BLOCK.CLIENT_BILL_IDENTIFIER.31035531
CLICK F_AVN_MAINT BUTTONS CLAIM#_BTN 1 MOUSE
TSE FSERVER_START -1 20 31035531
TSE DB_START 0 0 31035531
TSE DB_END 0 0 31035531
TSE DB_START 0 0 31035531
TSE DB_END 0 0 31035531
TSE DB_START 0 0 31035531
TSE DB_END 0 0 31035531
TSE FSERVER_END -1 0 31035546
##### CTIME STARTS HERE
##### CTIME STARTS HERE
TSE FSERVER_START -1 170 31035734
TSE FSERVER_END -1 0 31035734
##### CTIME STARTS HERE
# 24 - F_AVN_MAINT:BILLS_BLOCK.CLIENT_BILL_IDENTIFIER.31038968
TAB F_AVN_MAINT TAB_CANVAS BUDGET

Example 1: Fragment of a performance log.

By comparing a timestamp with the previous timestamp, you can determine in which of the four categories the application is spending the most time. Some are obvious. DB_START à DB_END is time spent in the database. FSERVER_START à DB_START is time in the Forms Servers. Figure 2 shows the timestamp relationships:

FSERVER_START      à any other timestamp = Forms Server
DB_START           à DB_END               = Database
DBLOGON_START      à DBLOGON_END          = Database
DBLOGOFF_START     à DBLOGOFF_END              = Database
DB_END             à any other timestamp  = Forms Server
DBLOGON_END        à any other timestamp  = Forms Server
DBLOGOFF_END       à any other timestamp  = Forms Server
FSERVER_END        à FSERVER_START        = Network

Figure 2: Timestamp relationships.

If there is a client time flag (##### CTIME STARTS HERE) such as in Example 1 between FSERVER_END and FSERVER_START, then that time is added to the Client category rather than the Network category. Again, time in the Client and Network category includes time on the physical network connecting the client application to the Forms Server. Time in the Database tier includes time in the database and time on the physical network connecting the database to the Form Server. Now that we know the workings of the performance log, let’s look at how we get the information loaded in the database.

Capturing the Performance Data

The first step in capturing the performance data is to process each performance log, developing a data set that captures the time spent in each tier for each event. We also want to capture the number of database interactions required to execute each event. This information will allow the developer to identify those events/forms that require performance tuning.

I chose to implement the parsing program in Java. The program can run on any computer with an Oracle Client loaded and thus does not have to run on the Forms or Database Server. The same Java program used to parse the performance logs can then insert the data into the database using a JDBC connection. From that point a simple query can extract from the database the time spent in each tier, the form and the event within the form, which is using the most time. This can assist in focusing optimization efforts. Since I normally use STATSPACK in tuning and monitoring my databases, I placed my Forms performance data in the STATSPACK schema perfstat. Example 2 is the DDL used to build the performance data table.

   create table 
   FormStats (
      FORM_ID     VARCHAR2(120),
      EVENT       VARCHAR2(120),
      FSERVER     NUMBER,
      DBASE       NUMBER,
      NWORK       NUMBER,
      CLIENT      NUMBER,
      DATE        DATE) ;

Example 2: The performance table.

By adding the performance log file date I am able to focus my analysis. I can run monthly, weekly or daily reports. I can also delete or archive old data. I also specify PCTFREE 0 since the data is never updated. This will minimize the table's storage requirements. The Java program cycles through the Performance Log, producing a single record for each event containing the Form Name, the starting event, the ending event, the time spent in each tier, the number of database interactions and the performance log file date.

Java's extensive string-handling capability easily parses the performance log, extracting the important information. Code Snippet 1 demonstrates how easy it is to parse the log. Let's walk through the Java code to see how it extracts the performance data. Note that some code has been removed to reduce the size and add clarity. For example, all CATCH clauses have been removed. The code begins with a string that starts with "TSE" indicating that it is a timing mark. The timestamp name and time are extracted and the time is converted from a string to a LONG datatype. The Java's LONG datatype can be loaded into Oracle's NUMBER datatype. Next the program falls through a series of IF…ELSE statements.

When the IF clause identifies the timestamp name, the program adds the difference in the second and first times to the correct category. The program continues to cycle through this code, adding time to specific categories, until a new event is encountered. When the program finds a new event, the current category values, along with the form name, event name and the log file date are loaded into the database using the JDBC. The program then updates the form name, event name, resets the category values and continues to process the performance log.

while (((str = in.readLine()) != null)

    if (str.startsWith("TSE"))
    {
        Add time to appropriate tier;
    } 
    if (str.startsWith("# "))       
    {
        1  —  Extract Event and Form Name;
        2  —  Load record into database;
        3  —  Clear times;
     }
}

While the Java JDBC is beyond the scope of this article, Example 3 is an example of the INSERT statement that is built by the program and then sent to the database over the JDBC connection.

INSERT INTO stats$forms_perf  VALUES 

(‘d:\forms\F_avn_maint.fmx’,
‘CLICK F_AVN_MAINT BUTTONS CLAIM#_BTN 1 MOUSE’,
‘TAB F_AVN_MAINT TAB_CANVAS BUDGET’,
15,0,3422,0,3,TO_DATE('2002-03-22','YYYY-MM-DD')
);

Example 3: Sample INSERT statement.

In Example 3, the form “F_avn_maint.fmx” was being used and the start event was the CLICK F_AVN_MAINT BUTTONS CLAIM#_BTN 1 MOUSE. The event ended with the user executed the event TAB F_AVN_MAINT TAB_CANVAS BUDGET. The time spent in the Forms Server was 15ms and in the client tier was 3422ms. Once we have the data loaded, we can user the power of the Oracle database to quickly extract the information we need. Once the table is created and loaded, queries are easy:

Select Number of Form Events with Database Access Time < 4 seconds

SELECT  
   COUNT(*)
FROM
   FormStat
WHERE
   (DBASE)/1000) > 4
AND DATE >= SYSDATE-1
AND DATE <= SYSDATE;

Select the Form with the greatest time spent in the Forms Server:

SELECT Form_ID, FSERVER
FROM FormStat
Where FSERVER = (SELECT MAX(FSERVER) FROM FormStat);

Analyzing the Data

Once the performance data is loaded in the database, accessing it is as easy as querying the database. The DBA will normally focus on time spent in the database while the developers focus on overall performance. The data represents the total time spent in each tier in executing one event. A database time of 3 secs could indicate a long-running PL/SQL procedure or it could indicate 20 database queries used to load data for a large and complicated form. A database time of more than 3 seconds probably indicates that the DBA should get with the developer and attempt to develop a more efficient access methodology.

Likewise, multiple interactions with the database can be restructured into one PL/SQL procedure/function to reduce the overhead of the separate queries. Although the developer must work to make the entire system as efficient as possible, the Client tier can present him with additional problems. Time in the Client tier has a number of external factors impacting performance. The capability of the client’s system and what the client is executing on the system in addition to the Application will effect the processing time. Some user input time is also captured.

The key is to identify the forms/events that are using the most resources in specific tiers for optimization. A simple SELECT COUNT(*) query can be used to produce a general view of the systems performance.

SELECT COUNT(*) FROM stat$forms_perf
WHERE ((FSERVER + DBASE)/1000) < 1
AND FRMDATE >= TO_DATE(‘2002-03-01','YYYY-MM-DD')
AND FRMDATE <= TO_DATE('2002-03-31’,'YYYY-MM-DD')";

The above query will tell you how many events had a Form Server + Database time of less than 1 second. Again using Java it is relatively simple to build standard reports such as the one in Figure 3. The Java code in Code Snippet 2 demonstrates how easy it is to extract the data from the Oracle database and produce a standard report.

The code begins by defining an ARRAY of LONG datatypes, then cycling through the select statement with different time setting and loading the result into the array. This is part of the code used to produce the report in Figure 3. The information in Figure 3 can be used to compare performance over time or over an application upgrade. It displays the number of events and the percent of total events that meet the time criteria. It calculates these values for total time (time spent in all four categories) and time spent just in the Forms Server and Database.

 
               Form,Dbase,          
              Network,Client       Form,Dbase
Seconds       Events    %          Events    %
 < 01         44958  44.16%         99313  97.54%
 < 02         61950  60.85%        101143  99.34%
 < 03         72769  71.47%        101443  99.63%
 < 04         79238  77.82%        101571  99.76%
 < 05         83241  81.76%        101634  99.82%
 < 06         86089  84.55%        101667  99.85%
 < 07         88186  86.61%        101689  99.88%
 < 08         89755  88.15%        101719  99.90%
 < 09         91055  89.43%        101734  99.92%
 < 10         92099  90.46%        101758  99.94%
 < 15         94879  93.19%        101780  99.96%
 < 25         97080  95.35%        101796  99.98%
 < 30         97602  95.86%        101798  99.98%
 < 60         99108  97.34%        101804  99.99%
Total Events: 101816               101816

Figure 3. Performance analysis.

You can also easily plot this data using an MS-Excel spreadsheet:

The code simply loops to retrieve the data and prints out a text file. A start date and an end date limit the result set. This is an effective management report in a development environment as this type of report can show performance over time, the effects of adding new features or upgraded equipment. The DBA and the developer, on the other hand, are looking for inefficiencies (Forms, procedures, functions, queries). Using the query in Example 4, a list can be produced to focus optimization efforts.

 SELECT
  form_id,
  startevent,
  adb,
  cdb
FROM
  (SELECT /*+ index(stat$forms_perf,idx_stat$forms_date) */
       form_id,
       startevent,
       (avg(dbase)/1000) adb,
       count(*) cdb
     FROM
       stat$forms_perf
     WHERE
       frmdate >= to_date('2002-02-15','YYYY-MM-DD')
     AND
       frmdate <= to_date('2002-02-20','YYYY-MM-DD')
     GROUP BY
       form_id, startevent
     ORDER BY
       cdb desc)
WHERE
  cdb > 20
AND
  adb > 1;

Example 4: FormsList.sql.

The query in Example 4 uses the sub query to obtain a list of forms, events, average database time in seconds, and number of times this form/event executes within two dates. It then filters the result to be those form/events with executions over 20 and average database time greater than 1 sec. The results after a little cleanup looks like Figure 4. In the same manner a query can be developed that shows which events/forms are executed the most, the least or a combination such as the longest running queries that execute over 200 times a day. Using this information, the DBA and developer can create a prioritized list of high impact events that will most benefit from optimization.

FORM_ID
STARTEVENT
   ADB       CDB
 
c:\forms\F_AVN.fmx
SCROLL F_AVN AVN_TAB_ALLOUT UP ONE
2.002094972        179
 
c:\forms\F_AVN.fmx
SCROLL F_AVN AVN_TAB_ALLOUT DOWN ONE
2.314           177
 
c:\forms\F_END_USER_PARTS_PRODUCTION.fmx
SCROLL F_AVN AVN_TAB_ALLOUT UP ONE
1.672              34
 
c:\forms\F_END_USER_PARTS_PRODUCTION.fmx
CLICK F_AVN_MAINT DATE_CONTROL_BLOCK MONTH_PLUS1 1 MOUSE
2.0098            31
4 rows selected.

Figure 4: FormsPerf.lst.

Visual Display

Once you have captured and loaded the data you can get some really nice reports. In Figure 5 we break out the response time according to each component.

Total  
 Response Time
 
 Response         # of
 Time       Trans
 =======    ======
 <01  secs 177,013
 1-2  secs  48,851
 2-3  secs  34,033
 3-4  secs  21,974
 4-5  secs  15,894
 5-6  secs  10,084
 6-7  secs   7,608
 7-8  secs   5,366
 8-9  secs   4,087
 9-10 secs   3,160
 Database  
 Response Time

 Response        # of
 Time       Trans
 =======    ======
 <01  secs 346,528
 1-2  secs   2,037
 2-3  secs   3,853
 3-4  secs   2,982
 4-5  secs     486
 5-6  secs     366
 6-7  secs     321
 7-8  secs     234
 8-9  secs     160
 9-10 secs     163

 FormServer  
 Response Time 

 Response       # of
 Time       Trans

 =======    ======

 <01  secs 345,934
 1-2  secs   8,116
 2-3  secs   2,857
 3-4  secs     648
 4-5  secs     240
 5-6  secs     133
 6-7  secs      50
 7-8  secs      39
 8-9  secs      30
 9-10 secs       2

Figure 5: Response time breakdown.

We can also see the 98-percent threshold for transactions, showing transaction levels above our threshold value.

Form,Database,        Form,Dbase,
              Network,Client        Network              Form,Dbase

Seconds       Events    %           Events    %          Events    %

 < 01         63,318  56.68%        91,088  81.54%       109,580  98.09%
 < 02         79,244  70.93%        99,264  88.85%       110,798  99.18%
 < 03         88,512  79.23%       103,028  92.22%       111,364  99.68%
 < 04         93,640  83.82%       104,994  93.98%       111,556  99.86%
 < 05         96,900  86.74%       106,184  95.05%       111,630  99.92%
 < 06         99,036  88.65%       106,950  95.73%       111,660  99.95%
 < 07        100,740  90.18%       107,484  96.21%       111,676  99.96%
 < 08        101,954  91.26%       107,902  96.59%       111,682  99.97%
 < 09        103,016  92.21%       108,240  96.89%       111,690  99.98%
 < 10        103,778  92.89%       108,490  97.11%       111,698  99.98%
 < 15        106,074  94.95%       109,226  97.77%       111,708  99.99%
 < 20        107,216  95.97%       109,604  98.11%       111,708  99.99%
 < 30        108,432  97.06%       110,000  98.46%       111,708  99.99%
 < 60        109,834  98.32%       110,552  98.96%       111,710  99.99%

Total Events: 111,716 111,716 111,716

Figure 6: Seeing the 98-percent threshold.

In figure 7 we see the most important report of all, the top offending Forms. This allows us to quickly work on the most important response time problem.

Top 10 Forms and Events that use the most Average Form Server Time
with a minimum of 10 executions and greater than 2 seconds for execution.

1. Form: d:\prod\forms\F_END_USER_GENERATED_LETTERS.fmx
Event: CLICK F_END_USER_GENERATED_LETTERS BUTTONS SAVE_BTN 1 MOUSE
Avg Tm: 5.00 Seconds. Number of Executions: 62

2. Form: d:\prod\forms\F_PC_PICK_RETURNS.fmx
Event: CLICK F_PC_PICK_RETURNS BUTTONS PROCESS 1 MOUSE
Avg Tm: 4.00 Seconds. Number of Executions: 13

Top 10 Forms and Events that use the most Average Database Time
with a minimum of 2 executions and greater than 5 seconds for execution.

1. Form: d:\prod\forms\f_pc_case_maint.fmx
Event: CLICK F_DIARY DIARY_TAB_ALLOUT DATE_OF_INCIDENT 9
Avg Tm: 472.00 Seconds. Number of Executions: 2

Figure 7: Top 10 poor response time forms.

Conclusion

The Performance Collector is a great addition to Oracle Forms. It contains a great deal of data, but requires some work to use. Monitoring Forms performance in a production system can be problematic. Analyzing the amount of data produced by the Performance Collector can consume a considerable amount of time and effort. Using the methodology presented here, you can easily parse and load the performance data and use the power of the Oracle Database to quickly analyze the results.

Appendix
(click here to see two code snippets from John Garmany)

--

John Garmany is a senior DBA with Burleson Consulting. John is a graduate of West Point, an Airborne Ranger and a retired Lt. Colonel with 20+ years of IT experience. John is an OCP Certified Oracle DBA with a Master's Degree in Information Systems, a Graduate Certificate in Software Engineering, and a BS degree (Electrical Engineering) from West Point. A respected Oracle expert and author, John serves as a writer for Oracle Internals, DBAzine, and Builder.com. John is the author of Logical Database Design — Principles & Practices, CRC Press; the Oracle Database 10g Application Server Administration Handbook, Oracle Press; Oracle Replication — Snapshot, Multi-master & Materialized Views Scripts and Oracle SQL*Plus Reports — Fast reporting with SQL and SQL*Plus, Rampant TechPress. John can be reached at john.garmany@dba-oracle.com.


Contributors : John Garmany
Last modified 2005-06-22 12:47 AM
Transaction Management
Reduce downtime and increase repeat sales by improving end-user experience.
Free White Paper
Database Recovery
Feeling the increased demands on data protection and storage requirements?
Download Free Report!
 
 

Powered by Plone