A long while back, we had faced a weird situation with configurator and desperately needed to trace it to find out what was happening behind the scenes.

After consulting many a metalink notes, however hard I tried, the tracing would simply not happen. The right sequence of character and options is quite tricky and not very well documented. (Not surprising, as Configurator is an acquired product)

After many attempts, the tracing did work and this article is more as a reminder to myself and any other people out there who want to trace the confiurator servlet. Be reminded though, that this tracing is more like FRD log tracing (for Oracle Forms) and is NOT sql tracing.

Having said so, here are the magical options that you need to add to $IAS_ORACLE_HOME/Apache/Jserv/etc/zone.properties file:

zone.properties
==========
....
....
servlets.default.initArgs=cz.activemodel=|/tl=@$TRACEDIR/ciotracesupport.lce| /gt=$TRACEDIR/ciotracesupport.java|/nolp|/nodp|/noatp|
....

....

where, $TRACEDIR is the directory where the trace (.lce) file will be produced. Also, please note that the /gt= option was just wrapped around to the below line for reading purposes. In reality, it needs to be in the same line as the /tl= option.

If anyone of you reading this article has a better idea than this, please let me know through the comment mechanism.

What got triggered as a human mistake in a cloned instance at a customer environment, caused a new discovery by the onsite senior DBA, Brian Fane

Someone from the customer released a sysadmin custom job that caused the configurator servlet JVMs in Production to get bounced! This was an unexpected situation and while the users sat twiddling their thumbs while the configurator models were pre-loading, Brian started digging into the current executing sql of the DB sessions doing the preloading.

To give an idea of the patch levels, the CZ patchset installed was  11i.CZ.I(2690432) and the FND & ATG patchsets were 11i.FND.H(3262159) and 11i.ATG_PF.H.5(5473858) respectively.

He happened to note that the maximum time seemed to be taken by the following sql:

SELECT  cz_lce_load_specs.lce_header_id,
        cz_lce_texts.lce_text,
        cz_lce_headers.component_id
    FROM apps.cz_lce_load_specs,
         apps.cz_lce_headers,
         apps.cz_lce_texts
   WHERE cz_lce_load_specs.attachment_comp_id = :1
     AND cz_lce_load_specs.net_type = :2
     AND cz_lce_texts.lce_header_id = cz_lce_load_specs.lce_header_id
     AND cz_lce_texts.lce_header_id = cz_lce_headers.lce_header_id
     AND cz_lce_headers.deleted_flag = :3
     AND cz_lce_load_specs.deleted_flag = :4
ORDER BY cz_lce_texts.seq_nbr;

When he ran it a BCV copy of the PROD (which was a replica of PROD as of that morning - daily process), it did ~37,400 gets/execution, and almost all of them were physical reads. Most of this comes from a full table scan on CZ_LCE_LOAD_SPECS, which right around 37,150 blocks. Query time was between 1 and 2 seconds (TOAD doesn't get any more precise when dealing with values > 1 second).

His Solution...

So well, he thought, why not add an index to cz_lce_load_specs that may speed up the query:

CREATE INDEX cz.blf_test ON cz.cz_lce_load_specs
       (attachment_comp_id, net_type, deleted_flag)
       COMPUTE STATISTICS;

This reduced the gets from 37,400 to 20. Execution dropped to ~10 ms.

Some more data points...

Let's try some testing in DEV and see how this index performs in the wild :)

DECLARE
   CURSOR c_driver IS
      SELECT attachment_comp_id, net_type
        FROM apps.cz_lce_load_specs
       WHERE deleted_flag = '0'
         AND ROWNUM < 100;

   counter NUMBER := 0;
   v4 varchar2(10) := '0';
   v1 number;
   v2 varchar2(2000);
   v3 number;
BEGIN
   FOR r_driver IN c_driver LOOP
      BEGIN
          SELECT   cz_lce_load_specs.lce_header_id,
                   cz_lce_texts.lce_text,
                   cz_lce_headers.component_id
            INTO v1, v2, v3
            FROM apps.cz_lce_load_specs,
                 apps.cz_lce_headers,
                 apps.cz_lce_texts
           WHERE cz_lce_load_specs.attachment_comp_id = r_driver.attachment_comp_id
             AND cz_lce_load_specs.net_type = r_driver.net_type
             AND cz_lce_texts.lce_header_id = cz_lce_load_specs.lce_header_id
             AND cz_lce_texts.lce_header_id = cz_lce_headers.lce_header_id
             AND cz_lce_headers.deleted_flag = v4
             AND cz_lce_load_specs.deleted_flag = v4
           ORDER BY cz_lce_texts.seq_nbr;
           EXCEPTION
             WHEN others THEN NULL;
      END;
   END LOOP;
END;
/

Observation data for without the index creation on cz_lce_load_specs:

1) First passive configurator model loading (preloading):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
2:14.6	2,403,145	35,551	68	110.45	35,340
2:02.0	2,367,735	0	67	94.66	35,340
2:03.3	2,367,735	0	68	94.7	35,340

2) The models are already preloaded now and they are being launched:

Web response time	Buffer  gets	Disk reads	Executions
0:05.6	0	0	0
0:06.4	0	0	0
0:05.5	0	0	0

3) Launch a configurator model, change an attribute of a selection for an item or sub-item and save the configuration (do not submit an order yet):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0:30.1	600,259	3	17	23.76	35,309
0:05.9	0	0	0
0:04.3	0	0	0

Observation data for WITH the index creation on cz_lce_load_specs:

1) First passive load of the configurator model (preloading):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0:22.7	3,240	3	67	0.03	48
0:23.1	3,141	0	67	0.04	47
0:26.1	3,141	0	67	0.02	47

2) First WebUI launch, after the preloading with the index:

Web response time	Buffer  gets	Disk reads	Executions
0.04.3	0	0	0
0.04.4	0	0	0
0.04.8	0	0	0

3) Launch a configurator model, change an attribute of a selection for an item or sub-item and save the configuration (do not submit an order yet):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0.05.1	209	0	17	0.01	12
0.04.8	0	0	0
0.04.0	0	0	0

Real time benefits..

To illustrate this point better after putting it in production, here is a quick comparision of the preload timings of a some configurator models that were grouped in 2 configurator servlets JVMs:

Before the index:

GROUP29	Max preloading time was 857 secs taken by M91R  Min preloading time was 852 secs taken by M91  Avg preloading time was 0:14:13 ( 853 seconds ) secs/model over a total of 6 models
GROUP30	Max preloading time was 1684 secs taken by TDXSR-CG Min preloading time was 1302 secs taken by TDXSCSEAT Avg preloading time was 0:25:56 ( 1556 seconds ) secs/model over a total of 13 models

After the index:

GROUP29	Max preloading time was 54 secs taken by M91R Min preloading time was 53 secs taken by M91-C Avg preloading time was 0:0:53 ( 53 seconds ) secs/model over a total of 6 models
GROUP30	Max preloading time was 96 secs taken by TDXSC2-CG Min preloading time was 82 secs taken by TDXSR-HD Avg preloading time was 0:1:30 ( 90 seconds ) secs/model over a total of 14 models

Conclusion

Although this index could have been provided by Oracle, it was a lucky discovery to speeden up the preloading time for configurator models. With the new index, it is now possible for the client to bounce anytime and have 10-20 most popular models preloaded in within 2-3 mins, as compared to 10-15 mins before, which is really something.

Interestingly, the same columns got indexes in the 11.5.10 release as seen from http://etrm.oracle.com:



Note: This article is being produced with the explicit permission of Brian Fane, and is aimed at sharing tips in the Oracle world for other people who might be in the same situation.

While I have written a previous article on XML parsing error for Online iPayment transactions in Oracle Applications 11i, For the want of XML parsing, iPayment was lost; for the want of not being able to take payment, business was lost., the customer had always suffered another issue with the batch close processing carried out by the IBYSCHEDULER module: iPayment Scheduler program.

Unknown to me, there was another person from the customer's production support who was working diligently with Oracle Support and development to have this addressed. This is the story of Patrick Baker, , who gets the credit for having this resolved, over a period of one long year. Interestingly, the solution was to use another copy of the xmlparserv2 archive file on the concurrent manager tier.

The version of the Oracle Applications was 11.5.10.2 (as per FND & ATG) and 11.5.9 for some other products.

The problem and error message

Almost every night, the customer would get this error in the BATCH CLOSE processing program (the details of the servers and domain name have been blurred out to protect the data integrity of the customer):

+---------------------------------------------------------------------------+
iPayment: Version : 11.5.0 - Development

Copyright (c) 1979, 1999, Oracle Corporation. All rights reserved.

IBYSCHEDULER module: iPayment Scheduler
+---------------------------------------------------------------------------+

Current system time is 28-MAR-2007 00:16:23

+---------------------------------------------------------------------------+


Processing BATCH CLOSE operations ..

empty batch for account (payee id=087295,account id=XXXXXXX Corp:087295:944599:XXXXXX:944599:CORPORAT,batch id=3343)
exception occured for (payee id=087295,account id=XXXXXXXX Corp:087295:944599:XXXXXXX:944599:CORPORAT,batch id=3344) External XML parse error.  Document passed to iPayment by external application http://ipayment.xxxxxxxx.com:8000/servlet/oramipp_ptk generated XML parse error Start of root element expected. .

The Stack Trace is -
oracle.apps.iby.exception.PSException: External XML parse error.  Document passed to iPayment by external application http://payment.xxxxxxxx.com:8000/servlet/oramipp_ptk generated XML parse error Start of root element expected. .
    at oracle.apps.iby.util.bpsUtil.raiseException(bpsUtil.java:159)
    at oracle.apps.iby.net.XMLMessenger.deliverDoc(XMLMessenger.java:138)
    at oracle.apps.iby.payment.proc.BatchCCPayment.closeBatch(BatchCCPayment.java:1147)
    at oracle.apps.iby.scheduler.SchedBatchClose.schedPmt(SchedBatchClose.java:124)
    at oracle.apps.iby.scheduler.Scheduler.doProcess(Scheduler.java:260)
    at oracle.apps.iby.scheduler.Scheduler.init(Scheduler.java:297)
    at oracle.apps.iby.scheduler.SchedInitiator.runProgram(SchedInitiator.java:200)
    at oracle.apps.fnd.cp.request.Run.main(Run.java:161)


Finished processing BATCH CLOSE
+---------------------------------------------------------------------------+
Start of log messages from FND_FILE
+---------------------------------------------------------------------------+
+---------------------------------------------------------------------------+
End of log messages from FND_FILE
+---------------------------------------------------------------------------+
Successfully resubmitted concurrent program IBYSCHEDULER with request ID 32185967 to start at 29-MAR-2007 00:15:56 (ROUTINE=AFPSRS)

+---------------------------------------------------------------------------+
Executing request completion options...

Finished executing request completion options.

+---------------------------------------------------------------------------+
Concurrent request completed
Current system time is 28-MAR-2007 00:22:09

+---------------------------------------------------------------------------+

Lets think a bit..

OK, lets try to make some sense out of it. Since this error was being received in the output of a concurrent manager, obviously, the xmlparser class file was on the concurrent manager tier and NOT on the iPayment tier (which was used by the online transactions).

A different solution..

On the dedicated iPayment tier, the same error message was resolved by using $JAVA_TOP/xmlparserv2.zip file in the $IAS_ORACLE_HOME/Apache/Jserv/etc/jserv.properties, but in this case, the solution was to the use $IAS_ORACLE_HOME/xdk/lib/xmlparserv2.jar instead in different files:

To implement the solution, open the file $APPL_TOP/admin/adovars.env on the concurrent manager tier, 
and in the values of CLASSPATH  and AF_CLASSPATH variable, add $IAS_ORACLE_HOME/xdk/lib/xmlparserv2.jar: 
before $JAVA_TOP/appsborg2.zip: 

Note: this must be done in both: CLASSPATH and AF_CLASSPATH

To prevent the entries in $APPL_TOP/admin/adovars.env  to be over-written, you can either add this at the "end of the file" 
in the # BEGIN Customizations and # END Customizations tags or you can create your own 
custom autoconfig template file for adovars.env with the changes. 

E.g.

# Begin customizations
....
CLASSPATH=......:$IAS_ORACLE_HOME/xdk/lib/xmlparserv2.jar:$JAVA_TOP/appsborg2.zip:....
....
....
AF_CLASSPATH=......:$IAS_ORACLE_HOME/xdk/lib/xmlparserv2.jar:$JAVA_TOP/appsborg2.zip:....
....
# End customizations

Note: Make sure the content for CLASSPATH and AF_CLASSPATH is included in 1 line if you do a cut and paste. The entire value SHOULD BE 1 SINGLE LINE, otherwise the value will get corrupted.

After this, the concurrent managers do need to be bounced and then the IBYSCHEDULER module: iPayment Scheduler program gives expected results.

A new learning..

From this experience, It now seems that it is possible to make $IAS_ORACLE_HOME/xdk/lib/xmlparserv2.jar 
work for the parsing needs on the dedicated iPayment tier for servicing online transactions too.

For that, you need to put the following entry in $IAS_ORACLE_HOME/Apache/Jserv/etc/jserv.properties:

Put this entry in the # BEGIN customizations and # END customizations (should be done at the END of the file):

# BEGIN customizations
...
...
wrapper.classpath=/ORACLE/qa/9iAS/xdk/lib/xmlparserv2.jar
...
...
# END customizations

And I had no answer for him. I couldn't blame him. CIOs want to know this kind of information. Better still, he would have liked a pie chart depicting it like this:

I wish..

Well, for once, it would have been nice if Oracle 9i or 10g kept the historical startup or shutdown information in the v$ or some dba_* tables. A simple query off the table would have got me the answer.

Anyways, it set me thinking. There are always other ways to get the same information. Statspack or AWR was one possibility, but I was not sure if it really gathers the details information about when the instance was shutdown or started up (historically) -- they sure are aware if there was an instance restart between two snaps.

An Aha moment..

But wait, the database alert log has information about each startup and shutdown! So if we could mine the alert log for the right regular expressions, and then find the time difference between time stamps, it could be done.

This method would not give you the overall downtime for the production instance, including the downtime for the middle tiers or Apache web server, but the same idea could probably be extended for the other services, but in this article, the scope is just the database. There is an auxiliary script (get_epoch.sh) supplied here that would be useful in this quest.

Auxiliary script: get_epoch.sh

Also available for download here.

#!/usr/bin/perl
#
# The format of input date is:  Thu Jun  5 21:15:48 2008
#
# NOTE: The format of `date` command is:  Thu Jun  5 21:15:48 EDT 2008
# -- it has the timezone in the output as well
# BUT this script does not assume that since the timestamps in
# alert log dont have the timezone in it
#
# This script heavily uses this function to convert a UTC timestamp
# into seconds after 1 jan 1970:
# timelocal($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst);

use Time::Local;

my $wday = $ARGV[0];

my $month = $ARGV[1];
# convert the month shortname into 0-11 number
if ( $month eq "Jan" ) { $mon = 0 }
elsif ( $month eq "Feb" ) { $mon = 1 }
elsif ( $month eq "Mar" ) { $mon = 2 }
elsif ( $month eq "Apr" ) { $mon = 3 }
elsif ( $month eq "May" ) { $mon = 4 }
elsif ( $month eq "Jun" ) { $mon = 5 }
elsif ( $month eq "Jul" ) { $mon = 6 }
elsif ( $month eq "Aug" ) { $mon = 7 }
elsif ( $month eq "Sep" ) { $mon = 8 }
elsif ( $month eq "Oct" ) { $mon = 9 }
elsif ( $month eq "Nov" ) { $mon = 10 }
elsif ( $month eq "Dec" ) { $mon = 11 };

my $mday = $ARGV[2];

# initialize time varialble and split hours (24 hr format), minutes, seconds into an array
my $time = $ARGV[3];
@time = split /:/, $time;

# if the timezone is left out of the input, the position of year becomes 5th in ARGV
my $year = $ARGV[4];

#######################################################################################
# I found that by excluding $wday, the seconds results (EPOCH) is more
# accurate, so $wday parameter has been omitted from the call to
# timelocal() function.
#######################################################################################
$epoch= timelocal($time[2], $time[1], $time[0], $mday, $mon, $year);
print "$epoch\n";

The main script..

Due to formatting issues, the main script is available for download here.

Sample Usage and output..

I realized that it would probably make more sense to have an optional cutoff date to calculate the downtime from, so that was added to the version 2 of the script. The version 1 which calculates the downtime from the first database startup time is uploaded here.

sandbox:sandbox> ./calculate_downtime.sh                             
Correct Usage: calculate_downtime.sh alertlogfilepath [cutoff_date in format Sat Jun 7 08:49:34 2008]

sandbox:sandbox> ./calculate_downtime.sh $DATA_DIR/admin/bdump/alert*.log Fri Mar 28 15:20:59 2008

Cutoff date is : Fri Mar 28 15:20:59 2008

Shutdown times:

Timestamp              --  epoch (seconds)

Wed Jan 9 17:53:08 2008 - 1199919188
Wed Jan 16 12:05:09 2008 - 1200503109
Fri Jan 18 11:19:42 2008 - 1200673182
Thu Jan 24 17:34:15 2008 - 1201214055
Fri Feb 15 09:00:44 2008 - 1203084044
Wed Feb 20 16:50:14 2008 - 1203544214
Wed Mar 12 12:43:26 2008 - 1205340206
Fri Mar 28 15:21:59 2008 - 1206732119
Thu Apr 3 11:03:52 2008 - 1207235032
Thu Apr 3 11:10:20 2008 - 1207235420
Thu Apr 3 11:15:44 2008 - 1207235744
Thu Apr 3 11:22:38 2008 - 1207236158
Thu Apr 3 11:27:36 2008 - 1207236456
Thu Apr 3 11:34:35 2008 - 1207236875
Thu Apr 3 11:41:36 2008 - 1207237296
Mon May 12 14:17:13 2008 - 1210616233
Thu Jun 5 10:36:58 2008 - 1212676618
shutdown_counter=17

Startup times:

Timestamp              --  epoch (seconds)

Wed Jan 9 17:50:42 2008 -- 1199919042
Thu Jan 10 09:43:18 2008 -- 1199976198
Thu Jan 17 12:00:03 2008 -- 1200589203
Fri Jan 18 11:26:13 2008 -- 1200673573
Wed Jan 30 12:19:21 2008 -- 1201713561
Tue Feb 19 22:57:38 2008 -- 1203479858
Wed Mar 12 12:39:03 2008 -- 1205339943
Mon Mar 24 13:44:20 2008 -- 1206380660
Thu Apr 3 11:00:33 2008 -- 1207234833
Thu Apr 3 11:07:12 2008 -- 1207235232
Thu Apr 3 11:14:01 2008 -- 1207235641
Thu Apr 3 11:20:54 2008 -- 1207236054
Thu Apr 3 11:25:25 2008 -- 1207236325
Thu Apr 3 11:31:53 2008 -- 1207236713
Thu Apr 3 11:40:18 2008 -- 1207237218
Tue Apr 29 16:50:49 2008 -- 1209502249
Mon Jun 2 14:20:38 2008 -- 1212430838
Thu Jun 5 10:38:39 2008 -- 1212676719
startup_counter=18
 As per the alert log, The instance is currently up


Here are the downtime windows ...

Wed Jan 9 17:50:42 2008 -- Wed Jan 9 17:53:08 2008
Thu Jan 10 09:43:18 2008 -- Wed Jan 16 12:05:09 2008
Thu Jan 17 12:00:03 2008 -- Fri Jan 18 11:19:42 2008
Fri Jan 18 11:26:13 2008 -- Thu Jan 24 17:34:15 2008
Wed Jan 30 12:19:21 2008 -- Fri Feb 15 09:00:44 2008
Tue Feb 19 22:57:38 2008 -- Wed Feb 20 16:50:14 2008
Wed Mar 12 12:39:03 2008 -- Wed Mar 12 12:43:26 2008
Mon Mar 24 13:44:20 2008 -- Fri Mar 28 15:21:59 2008
Thu Apr 3 11:00:33 2008 -- Thu Apr 3 11:03:52 2008
Thu Apr 3 11:07:12 2008 -- Thu Apr 3 11:10:20 2008
Thu Apr 3 11:14:01 2008 -- Thu Apr 3 11:15:44 2008
Thu Apr 3 11:20:54 2008 -- Thu Apr 3 11:22:38 2008
Thu Apr 3 11:25:25 2008 -- Thu Apr 3 11:27:36 2008
Thu Apr 3 11:31:53 2008 -- Thu Apr 3 11:34:35 2008
Thu Apr 3 11:40:18 2008 -- Thu Apr 3 11:41:36 2008
Tue Apr 29 16:50:49 2008 -- Mon May 12 14:17:13 2008
Mon Jun 2 14:20:38 2008 -- Thu Jun 5 10:36:58 2008
Thu Jun 5 10:38:39 2008 --


Downtime 1 : Wed Jan  9 17:53:08 2008 (1199919188)            --> Thu Jan 10 09:43:18 2008 (1199976198) = 57010 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Wed Jan  9 17:53:08 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 2 : Wed Jan 16 12:05:09 2008 (1200503109)            --> Thu Jan 17 12:00:03 2008 (1200589203) = 86094 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Wed Jan 16 12:05:09 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 3 : Fri Jan 18 11:19:42 2008 (1200673182)            --> Fri Jan 18 11:26:13 2008 (1200673573) = 391 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Fri Jan 18 11:19:42 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 4 : Thu Jan 24 17:34:15 2008 (1201214055)            --> Wed Jan 30 12:19:21 2008 (1201713561) = 499506 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Thu Jan 24 17:34:15 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 5 : Fri Feb 15 09:00:44 2008 (1203084044)            --> Tue Feb 19 22:57:38 2008 (1203479858) = 395814 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Fri Feb 15 09:00:44 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 6 : Wed Feb 20 16:50:14 2008 (1203544214)            --> Wed Mar 12 12:39:03 2008 (1205339943) = 1795729 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Wed Feb 20 16:50:14 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 7 : Wed Mar 12 12:43:26 2008 (1205340206)            --> Mon Mar 24 13:44:20 2008 (1206380660) = 1040454 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is < than shutdown time Wed Mar 12 12:43:26 2008 - so not accruing
Running Cumulative downtime = 0 seconds

Downtime 8 : Fri Mar 28 15:21:59 2008 (1206732119)            --> Thu Apr  3 11:00:33 2008 (1207234833) = 502714 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Fri Mar 28 15:21:59 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 502714 seconds

Downtime 9 : Thu Apr  3 11:03:52 2008 (1207235032)            --> Thu Apr  3 11:07:12 2008 (1207235232) = 200 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:03:52 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 502914 seconds

Downtime 10 : Thu Apr  3 11:10:20 2008 (1207235420)            --> Thu Apr  3 11:14:01 2008 (1207235641) = 221 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:10:20 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 503135 seconds

Downtime 11 : Thu Apr  3 11:15:44 2008 (1207235744)            --> Thu Apr  3 11:20:54 2008 (1207236054) = 310 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:15:44 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 503445 seconds

Downtime 12 : Thu Apr  3 11:22:38 2008 (1207236158)            --> Thu Apr  3 11:25:25 2008 (1207236325) = 167 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:22:38 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 503612 seconds

Downtime 13 : Thu Apr  3 11:27:36 2008 (1207236456)            --> Thu Apr  3 11:31:53 2008 (1207236713) = 257 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:27:36 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 503869 seconds

Downtime 14 : Thu Apr  3 11:34:35 2008 (1207236875)            --> Thu Apr  3 11:40:18 2008 (1207237218) = 343 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:34:35 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 504212 seconds

Downtime 15 : Thu Apr  3 11:41:36 2008 (1207237296)            --> Tue Apr 29 16:50:49 2008 (1209502249) = 2264953 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Apr  3 11:41:36 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 2769165 seconds

Downtime 16 : Mon May 12 14:17:13 2008 (1210616233)            --> Mon Jun  2 14:20:38 2008 (1212430838) = 1814605 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Mon May 12 14:17:13 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 4583770 seconds

Downtime 17 : Thu Jun  5 10:36:58 2008 (1212676618)            --> Thu Jun  5 10:38:39 2008 (1212676719) = 101 seconds
the cutoff date Fri Mar 28 15:20:59 2008 is > shutdown time Thu Jun  5 10:36:58 2008 - greater than cutoff, so accruing
Running Cumulative downtime = 4583871 seconds


Calculating lifetime of instance as per criteria specified..

Starting time being used = Fri Mar 28 15:20:59 2008 -- 1206732059
Ending time epoch = Sat Jun 7 11:49:49 2008 -- 1212853789
Total lifetime in seconds = 6121730

   Beginning Fri Mar 28 15:20:59 2008, The instance was down 74 % of the time

Application of this data..

Now, this data could be put in some kind of dashboard for CIO meetings. This would give them an approximate idea of how long do their databases and (the dependent middle tier or admin tier services) remain down due to maintenance. Sure, this method cannot distinguish between unplanned and planned maintenance, but its probably a good start.