OWA Replacement Cartridge, Detailed Timings

Quick Answers

Is there overhead
What setup do I need to do?
What reports are available?

While developing this cartridge, we thought it would be nice to have a means to capture very detailed statistics about how long code was executing and where. Normally, we would have used the system profiler (prof on unix) to gather this information. Unfortunately, we couldn't get prof to work with our shared object code (.so) files. Therefore, we injected some timings into the code directly. We found these to be so useful, we left them in for everyone.

Basically, the code uses the sys.v_$timer table to get hundredth's of seconds. It does this before and after critical sections of code (see the list below for what you can time). It also inserts these values into a database table. You can then run queries against this table to see how long things are taking to execute (something you just can't get from the svXXXX.log file). Very useful for performance tuning. Now you can see what takes a long time and what doesn't.

You enable tracing in the svXXXX.app file by setting some values in the [DBAUTH] section. For example:

	[DBAUTH]
	....

	timingsTable	    = ows2.timings
	timingsModules     = all

Would enable tracing into the ows2.timings table for ALL modules. timingsModules may either contain the word 'all' to capture all statistics or it may contain a space-separated list consisting of certain keywords. All keywords are defined in a list below, the following table explains the above variables.

Variable	Mandatory	Meaning
timingsTable	NO	Our web agent has the ability to collect detailed timing stats down to the hundreds of a second for all web operations. These stats go into a table named 'timings' and owned by someone. The definition of the timings table is in owarepl.sql found in the owarepl/sql subdirectory. If you install this table and want timings, you will set the timingsTable variable equal to the owner.tablename. For example, my timings table is owned by ows2 and is called timings.
timingsModules	NO	This allows you to filter the level at which you want to collect timings. If you set this to all, all timings will be collected. You may also set a specific set of timings to capture. For example, if you timingsModules = TOTAL EXEC-BLOCK You will collect stats for the TOTAL execution time (from the time the user connects until they get the whole page) and the time spent executing just the PL/SQL code for the web agent. The difference between these two times is the overhead my code and the web imposed. Some of the things that take time are parsing the cgi-environment, loading large files that are uploaded, describing invalid procedures, and so on. A complete list of modules is in the example directory in the svdbauth.app file. Their meanings are listed below this table.

Variable

Mandatory

Meaning

timingsTable

Our web agent has the ability to collect detailed timing stats down to the hundreds of a second for all web operations. These stats go into a table named 'timings' and owned by someone. The definition of the timings table is in owarepl.sql found in the owarepl/sql subdirectory. If you install this table and want timings, you will set the timingsTable variable equal to the owner.tablename. For example, my timings table is owned by ows2 and is called timings.

timingsModules

This allows you to filter the level at which you want to collect timings. If you set this to all, all timings will be collected. You may also set a specific set of timings to capture. For example, if you

	timingsModules = TOTAL EXEC-BLOCK

You will collect stats for the TOTAL execution time (from the time the user connects until they get the whole page) and the time spent executing just the PL/SQL code for the web agent. The difference between these two times is the overhead my code and the web imposed. Some of the things that take time are parsing the cgi-environment, loading large files that are uploaded, describing invalid procedures, and so on.

A complete list of modules is in the example directory in the svdbauth.app file. Their meanings are listed below this table.

The following is a list of values that may be used with "timingsModules =" to get timing statistics:

CGI-ENV
How long it took to call owa.init_cgi_env in the database. This is overhead we have to go through to get the CGI ENV passed to the web agent. This should be very fast/short.
RETURN-PAGE
How long it took to invoke owa.get_page and WRBWriteClient to return the page after it was generated. This may take a long time for large pages.
EXEC-BLOCK
How long your pl/sql code ran for. This is just your code executing, no overhead introduced into this number.
DESCRIBE
How long it took for us to describe your procedure. If your procedure gets invalid a lot, this will take a long time. Remember, long is a relative term. We are talking about 10/100 of a second or so.
GET-IMAGE
How long did it take to piecewise fetch and then WRBClientWrite an image from the database. The bigger the image, the longer the time.
BUILD-ARGLIST
How long did it take to process the GET or POST information. If using file upload, this includes the time to insert into the database or write the information to the file system.
TOTAL
The total time from logon to logoff of all activities. If you trace EXEC-BLOCK and TOTAL you can see the difference between how long your pl/sql code took to execute and the total time to get the answer back. That will tell you how much time you are spending in the Cartridge code as opposed to doing database work.
GET-IMAGE-FILE
How long did it take to read an image file from disk and return it using WRBClientWrite. Used by the server side include processing.
PROCESS-SSI
How long did it take to read an SSI file (using <ORACLE> tags) and process it.
DO-SSI-BLOCK
How long did each individual block within an SSI file take to execute.

Is there overhead

If the variable timingsTable is not set (eg: the dbauth section does not contain it or it is commented out using a ';' in column 1) there is no overhead involved. All C calls to get_hsecs and log_timings return immediately.

If the variable timingsTable is set but timingsModules is not, then the routine get_hsecs() will perform a select on the sys.v_$timer table every time it is called. This overhead is minimal.

If the variable timingsTable is set and the timingModules is set to either all or some list of values, then an insert into the timings table will take place for the specified modules. If you leave the timings table un-indexed (recommended), the overhead is not significant.

Again, by commenting out or removing the timingsTable variable in the [DBAUTH] section, you will remove all tracing overhead.

What setup do I need to do?

You need to

create the timings table
'grant all' on it to public
make sure that access to sys.v_$timer is available. For example, I suggest you log in as SYS and grant select on v_$timer to public. At a minimum, all user accounts logging into the database over the web will need access to this table.

The timings table (create statement to be found in ./owarepl/sql/owarepl.sql along with grants) has the following structure:


	create table timings
	(  	sessionid		number default userenv('sessionid'),
		url             varchar2(80),
		msg             varchar2(20),
		start_hsecs     number,
		stop_hsecs      number,
		time_stamp      date default sysdate,
		userid          varchar2(50),
		remote_addr     varchar2(30),
		http_user_agent varchar2(80)
	)
	/
	grant all on timings to public
	/

Where

Column	Meaning
Sessionid	The sessionid for the connected session. This, coupled with start_hsecs, consistute a 'primary key' for this table. If you select * from timings where sessionid = 55, you will get all relevant records for a given session
URL	The url that was submitted to the cartridge.
Msg	The section of code the timing is for. For example, this will have values 'TOTAL', 'EXEC-BLOCK' and so on.
Start_Hsecs
Stop_Hsecs	You will take stop_hsecs-start_hsecs to get elapsed times
Time_Stamp	SYSDATE of when the timing finished. NOTE: Timestamp will vary within a given sessionid if the request > 1 second to process
Userid	Who is logged in. If using database authentication, this will be the name of the person logged in. If not using database authentication, this will be the DCD usename
Remote_Addr	IP address of client
Http_User_Agent	Browser being used by client

What reports are available?

None yet, haven't gotten to that yet. Using SQL*Plus it is very easy to come up with some standard queries.