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:
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. 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.
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. 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 (((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 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.
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 gat some
really nice reports. In figure x 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.
Additional information on Oracle response time components is
available
HERE.
APPENDIX
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.
and include the URL for the page.
