After a recent Upgrade
Users cannot work with the forms application anymore; it has been a few weeks since an upgrade to Forms 12c.
The usual suspects have been investigated.
- The database is not waiting on forms transactions
- The application server is not in any distress, and yes, we have fluctuations in server CPU usage, but well within limits
- The user PCs (running the forms in a Browser) are not seeing any issues like CPU/memory limitations
- The forms are very slow in navigation and at odd times during the day they “freeze”
Re-visit the Basics
The forms application started life as “thick client” that would connect directly to the database. Today, it is a very different implementation (OHS, Weblogic, Listener Servlets, frmweb processes, Applets).
When a form is written, it is likely to use “triggers” and “program-units” to carry out application logic and displays rows of data in data blocks that are tied to a query involving one or more database tables. These triggers may be “fired” when the user navigates from one item to another, when the forms instance starts, when a new row of data is inserted, or in countless other ways. In a well-designed form, triggers would typically call program units. Users can also use shortcut keys to add new rows, delete rows, commit or rollback data.
If you have used a forms application, you will understand its simplicity and complexity. You (usually) do not scroll up or down the page like when viewing a spreadsheet, but you view a subset of the rows of data and the rows move up or down in response to keystrokes.
In Forms 12c, there is now a stand-alone client that can be used to start the applet.
The forms applet is able to display the screen, capture the users’ keystrokes, show the form icons, status bar menus, and is a fixed view. It is able to respond to basic OS events and relies on its much smarter companion the frmweb process that lives on the forms server to actually talk with the database and process the logic of the form. So the forms applet sends small chunks of info every few milliseconds and receives responses from the frmweb process. They chatter a lot!
A colleague of mine was incredulous when he looked at the network traffic ( the application with about 50 users logged in pings the forms server 200 times in a second !)
So why is it slow?
In essence, if the application is not responding quickly we have these classical areas to review
- The applet is slow to respond to the user input
- The frmweb process is slow to respond to the events received from the Applet
- The frmweb process is waiting on the database to provide it data
- Other unknown reasons
Instead of us guessing our way through this, let’s get some data. Oracle provides an easy way to trace the forms sessions as they are running.
The trace files are written on the Forms server and are labelled with the frmweb process ID.
The trace location in Forms 12c is
[oracle@oraserver1 karun]$ ls -ltr $DOMAIN_HOME/system_components/FORMS/forms1/trace | tail -3 ... -rw-r----- 1 oracle dba 5882480 May 6 10:50 forms_26737.trc -rw-r----- 1 oracle dba 759326 May 6 18:00 forms_17824.trc -rw-r----- 1 oracle dba 1209818 May 6 18:15 forms_16979.trc [oracle@oraserver1 karun]$
The easy way to start a trace
Use the Enterprise Manager Control:
Select a session and click on Enable Tracing
Choose the tracegroup (I usually choose to run with debug as this has all the details).
After a few minutes of tracing you can click on Disable Tracing button.
And EM can also show you the trace file contents.
The other easy way to start a trace
This is what we can also do when the EM is not accessible ( or you do not really like the pointy-clicky stuff)
Start the form on the client PC with this URL:
Work for a few minutes and close the application.
Having generated trace files, we now have to read them on the forms application server after we translate them to text.
$JAVA_HOME/bin/java -classpath $ORACLE_HOME/jlib/frmxlate.jar oracle.forms.diagnostics.Xlate datafile=$DOMAIN_HOME/system_components/FORMS/forms1/trace/forms_17824.trc outputfile=trace_my_session_20180506.txt outputclass=WriteOutTEXT
I can also use different options if I want to translate the trace file to HTML or XML with
What can traces tell us
A typical trace file is an engineer’s delight. To give you an idea, this is a snippet
9615 [BUILTIN.END,3] Timestamp=53160, StartEvent=9614, Duration=0 9616 [BUILTIN.START,3] Timestamp=53160, EndEvent=9617, Name=SET_ITEM_INSTANCE_PROPERTY [Arguments] Type=In Position=1 DataType=INTEGER Value=131081 Type=In Position=2 DataType=NUMBER Value=0 Type=In Position=3 DataType=NUMBER Value=1526 Type=In Position=4 DataType=STRING Value=BACKGROUND Type=In Position=5 DataType=STRING Value=NULL 9617 [BUILTIN.END,3] Timestamp=53160, StartEvent=9616, Duration=0 9618 [Local_PU.END,2] Timestamp=53160, StartEvent=9613, Duration=0 9619 [TRIGGER.END,1] Timestamp=53160, StartEvent=9612, Duration=0 9620 [NETWORK.WRITE] Timestamp=53160, StartEvent=9601, Duration=0, Packets=1, Bytes=742 9621 [NETWORK.READ] Timestamp=53220, EndEvent=9625, Duration=0, Packets=1, Bytes=270 9622 [ECID] Timestamp=53220, Value=XXXXXXXXXX #9623 [Key] Timestamp=53220, FormName=XXX__YYY(3), KeyPressed=Up 9624 [ERROR] Timestamp=53220, Msg= Error Message: FRM-40100: At first record. 9625 [NETWORK.WRITE] Timestamp=53220, StartEvent=9621, Duration=0, Packets=1, Bytes=94
Fun with traces
- I extracted the NETWORK events timestamps.
[oracle@oraserver1 karun]$ grep "NETWORK" trace_my_session_20180506.txt | tail -200
13378 [NETWORK.READ] Timestamp=185260, EndEvent=13397, Duration=0, Packets=1, Bytes=312 13397 [NETWORK.WRITE] Timestamp=185260, StartEvent=13378, Duration=0, Packets=1, Bytes=650 13398 [NETWORK.READ] Timestamp=185390, EndEvent=13417, Duration=0, Packets=1, Bytes=315 13417 [NETWORK.WRITE] Timestamp=185390, StartEvent=13398, Duration=0, Packets=1, Bytes=704 13418 [NETWORK.READ] Timestamp=185520, EndEvent=13437, Duration=0, Packets=1, Bytes=318 ... ...
- I graphed the timestamp data. I am interested in the timestamp intervals.
I am showing the timestamp in the X-axis and (Timestamp Next – Timestamp previous) on the Y-axis.
Notice the typical network timestamp interval is definitely above 100ms with spikes. In my head, this is telling us that the frmweb process on the server is idle for ~100ms while the next payload from the applet is yet to reach it!
Yes, it correlates with reality — the users are really complaining about the application being unresponsive to the keyboard input when they use this machine. It “freezes” too!
As a comparison, we ran the same form and gathered a trace from another machine in a different part of the network.
Here the network timestamp interval is around 50ms and it does spike a few times to be around 75ms.
On this machine the Users are able to work, but they do see a bit of freezing off and on. We are getting somewhere!
The traces point to yet another (previously overlooked) contributor to the slow response.
After some more digging, we found that the “slow” machines (running the applet) are in the network segments with really high latency.
TL&DR: Forms 12c traces are a valuable source of information, easy to gather!
Instead of guessing why your form applications are slow and applying arbitrary fixes, please consider using the trace data next time.
Call us at Pythian anytime you need us to help with slow Forms 12c applications.
My apologies to the folks using windows as their forms server — I am sure you get the idea. The windows commands and file locations are very similar.
ps: In case you are wondering what is an acceptable network timestamp interval?
I would welcome your actual test results in your responses and if I hear more we could build another blog post.
For the people interested in keyboard latency numbers, I could find this.
Open question: Is the keyboard + ~10ms is the lowest possible network timestamp interval?
Interested in working with Karun? Schedule a tech call.