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 (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 request, 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 over 100M each.
-
Long time to run - Using the Perl script to analyze 30 days of
performance logs required over 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 in to 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:
-
Identifying the form
-
An
event
-
From 1
to n timing marks (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. Lets 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.
Example 1. Fragment of a
Performance Log.
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
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:
Figure 2. 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
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.
Example 2. The Performance Table
CREATE TABLE stats$forms_perf
(form_id VARCHAR2(120), // the
form name and
procedure
startevent VARCHAR2(120), // the
starting event
endevent VARCHAR2(120), // the
ending event
fserver NUMBER, // Forms
Server time
dbase NUMBER, //
Database time
nwork NUMBER, //
Client time
client NUMBER, //
Network time
dbcount NUMBER, //
Number of DB interactions
frmdate DATE) // Log
File Date
PCTFREE 0
;
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. Lets 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 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.
Example 3.
Sample INSERT Statement.
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')
);
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.
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 over 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.
Figure 3.
Performance Analysis
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
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.
Example 4.
FormsList.sql
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;
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.
Figure 4.
FormsPerf.lst
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.
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.
Code Snippet 1
Parsing the Performance Log
// object s2 is
previous timing mark
// object s is
the later timing mark
// object.set
method adds the time to the named category.
if (s.startsWith("TSE")) //
timing event
// parse the
event name and time
{ sx =
s.substring(4,s.indexOf(" ",6));
d.setEndEvent(sx.trim());
ctime2 =
s.substring(s.lastIndexOf(" ") + 1);
ctimet =
ctime2.trim();
try
{ // change
string to LONG
time2 =
Long.parseLong(ctimet);
}
// if..else to
add time
if
(s2.equals("FSERVER_START"))
{
d.setFormServerTime(time2 - time1);
}
else if
(s2.equals("DBLOGON_START"))
{
d.setDatabaseTime(time2 - time1);
}
else if
(s2.equals("DB_START"))
{
d.setDatabaseTime(time2 - time1);
}
else if
(s2.equals("DBLOGOFF_START"))
{
d.setDatabaseTime(time2 - time1);
}
else if
(s2.equals("DBLOGON_END"))
{
d.setFormServerTime(time2 - time1);
}
else if
(s2.equals("DB_END"))
{
d.setFormServerTime(time2 - time1);
}
else if
(s2.equals("DBLOGOFF_END"))
{
d.setFormServerTime(time2 - time1);
}
else if
(s2.equals("FSERVER_END"))
{ if
(client) // Add to Client
not Network
{
d.setClientTime(time2 - time1);
client
= false; // clear the
flag
}
else // Add to
Network
{
d.setNetworkTime(time2 - time1);
}
}
} // end start TSE
if (s.startsWith("#####"))
{ // Begin Client
time
client =
true; // set the flag
}
.
.
.
End Code Snippet
1.
Code Snippet 2
Filling an array with Performance Data
int x = 0;
// define the
array to hold the results
long[] dataAr =
new long[15];
for (int i = 0;
i < 15; i++)
{ if (i < 10) x
= i + 1; // set sec = 1
thru 10
else
{ if (i ==
10) x = 15; // set seconds =
15
if (i ==
11) x = 25; // set seconds =
25
if (i ==
12) x = 30; // set seconds =
30
if (i ==
13) x = 60; // set seconds =
60
if (i ==
14) x = 1000; // Count all
events
}
if (i < 14)
query =
"SELECT
COUNT(*) " +
"FROM
stats$forms_perf"
+
" WHERE ((FSERVER
+ DBASE)/1000) < " + x +
" AND
FRMDATE >= " +
"TO_DATE('"
+ startdate + "','YYYY-MM-DD')" +
" AND
FRMDATE <= " +
"TO_DATE('"
+ enddate + "','YYYY-MM-DD')";
else query =
"SELECT
COUNT(*) " +
"FROM
stats$forms_perf"
+
" WHERE
FRMDATE >= " +
"TO_DATE('"
+ startdate + "','YYYY-MM-DD')" +
" AND
FRMDATE <= " +
"TO_DATE('"
+ enddate + "','YYYY-MM-DD')";
try
{ // execute the
query
rs =
stmt.executeQuery(query);
rs.next();
// load the
results into the array
dataAr[i] =
rs.getLong(1);
}
.
.
.
End Code Snippet
2.
Author Biography
John Garmany is a
graduate of the US Military Academy at West Point and a retired Lt.
Colonel with 20+ years of IT experience. John is an OCP Certified Oracle
DBA with a Master Degree in Information Systems, a Graduate Certificate in
Software Engineering, and a BS degree in electrical engineering from West
Point. John can be reached at
john.garmany@dba-oracle.com
|
