Mining useful monitoring/troubleshooting information from Oracle Configurator (CZ) logs


                                 mining uneful information from config log files.JPG:

Preface


Configurator is fairly new product and there arent as many published monitoring/troubleshooting  scripts out there to really find out if a particular model was preloaded properly or what was the response time of a model launch from the log files.

Im a strong believer in open source and in this article, some scripts are pur forward for mining the information in the Configurator logs which are created in $IAS_ORACLE_HOME/Apache/Jserv/logs.

These are just some scripts which were made to dig deeper into escalated configurator issues at one of the large implementors of Oracle Configurator module in North americas.

But before that...

These scripts are simply a starting point. They are provided "as is". The user would be responsible extending them as per the environment specific to different installations.

Having said so, the scripts are fairly simple and should be easy enough to extend.

PS: If you do happen to have the time to extend them more, please let me know at gaurav.verma@oracle.com.

I wish there were something ...

...which could tell me if a model preloading actually worked or not and if it was loaded into the JVM heap on the startup of configurator servlet?

...which could tell me how long it took for a model to preload?

...which could tell me accurately how long did it take for a user to actually launch a configurator model on the browser. The user claims that it took a long time for it to actually launch. How can I verify it?

... which could tell me why a user is getting a wierd error while launching configurator model? How can I find the root cause?

The list goes on. Well, we can certainly get answers for most of the above questions.

You would know, if you looked...

There is a goldmine of information available at $IAS_ORACLE_HOME/Apache/Jserv/logs. Essentially, there are at least three kinds of files:

Error log files for failed configurator launch sessions:

config_machine:web_prod> ls cz*.log
cz_exc_Applet18_20Apr07_0135PM_37068.log  cz_exc_DHTML172_20Apr07_0246PM_25823.log 
cz_exc_DHTML17_20Apr07_0110PM_35240.log   cz_exc_DHTML5_20Apr07_0107PM_34927.log
....
....


Log files for each session:

config_machine:web_prod>  ls cz-session-DHTML*.txt
cz-session-DHTML101_20Apr07_0209PM_50243.txt  cz-session-DHTML24_20Apr07_0140PM_31102.txt
cz-session-DHTML10_20Apr07_0108PM_28629.txt   cz-session-DHTML25_20Apr07_0115PM_03127.txt
....
....

The master configurator servlet log file:

This file keeps information about each session or model launch. Its like a double entry system.

usellx27:web_prod27a> ls *serv*.txt
cz-servlet_20Apr07_0105PM_55204.txt  cz-servlet_20Apr07_0105PM_55221.txt


Each file has a timestamp in its name when the servlet was started. In this case, we see that the 9iAS home was configured to start two instances of the CZ servlet. The following command tells us the way AutoConfig has been setup on the configurator tier:


config_machine:web_test> grep "s_oacore_nprocs"  $CONTEXT_FILE
         <oacore_nprocs oa_var="s_oacore_nprocs">2</oacore_nprocs>
config_machine:web_test>

Controlling runtime caching of models..

Know that, by default, configurator servlet caches models at runtime if they have been launched once. The following setting in $IAS_ORACLE_HOME/Apache/Jserv/etc/jserv.properties file controls it:

config_machine:web_test> grep dio_share jserv.properties
# wrapper.bin.parameters=-Dcz.uiservlet.dio_share=false
config_machine:web_test>

In this case, runtime caching of models has been enabled by default. Un-commenting the above setting would cause
caching of models to be disabled.

How does preloading happen and finding if a model has been preloaded..

Sometimes, due to missing directives, preloading may not work as expected. This kind of a situation is covered in Note 404719.1.

It is assumed here that the preloading file is $IAS_ORACLE_HOME/Apache/Jserv/etc/preload.txt.

To find if a model is been preloaded or not, the following script
getpreloadtimings.sh may be used. This script assumes that there is a read only database account called ivci. This may of course, be modified as per the new installation.

Here is a sample run of this script:

output of getpreloadtimings.sh.jpg:

The script also pre-assumes that an auxiliary script timediff.sh be present in the same directory. timediff.sh tells the difference between two timestamps.:


config_machine:web_test> more timediff.sh
#!/bin/ksh

( [ -z $1 ] || [ -z $2 ] ) && exit 1

time=$1
h1=$(expr "$time" : "\(..\):..:..")
m1=$(expr "$time" : "..:\(..\):..")
s1=$(expr "$time" : "..:..:\(..\)")

time=$2
h2=$(expr "$time" : "\(..\):..:..")
m2=$(expr "$time" : "..:\(..\):..")
s2=$(expr "$time" : "..:..:\(..\)")

#echo "from=$h1:$m1:$s1 to=$h2:$m2:$s2"

seconds=$(echo "$h2*3600+$m2*60+$s2-($h1*3600+$m1*60+$s1)" | bc)

if [ "$seconds" -lt 0 ] ; then
((seconds=seconds+86400))
fi

hh=$(expr $seconds / 3600)
mm=$(expr ( $seconds - $hh * 3600 ) / 60)
ss=$(expr $seconds - $hh * 3600 - $mm * 60)
echo "elapsed: $hh:$mm:$ss ($seconds seconds)"

Extending this concept, a summary script getpreloadtimings_summary.sh can also be created to give min and max preloading timings across different models in a group. Here is a sample run of getpreloadtimings_summary.sh :


config_machine:web_test> ./getpreloadtimings_summary.sh
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
 Preloading Min Max Statistics:
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
 Max preloading time was 794 secs taken by TDX3SE
 Min preloading time was 642 secs taken by TRSX50FB
 The following models could not be preloaded so far: ALL models were preloaded
 Avg preloading time was 0:12:19 ( 739 seconds ) secs/model over a total of 42 models
config_machine:web_test>

Is that not useful information? Well, that depending on how escalated your user is, it pretty much can be. Its amazing what simple observation and some unix pattern matching skills can fetch you, if the concepts are applied properly.

Verifying time taken to launch a model....

calculate_response_time_for_model_launch.sh is a model script which can written to find out what DHTML session launched a model at what time and whether it ended or not. Here is a sample run of the the script:

calculate_response_time_for_model_launch.sh_output.JPG:

What happened to my model launch??

Lets say a DHTML session did not end (end time undefined), there would be a very good
probability that it either was not pre-loaded and timed out OR there
was a corresponding log file created for that DHTML session. The DHTML
logfile with the session number will have extended error messages which
will point you in the correct direction.

Here you see an example of 4 different error log files and different kind of error messages, ranging from ora-01000 (maximum open cursors exceeded) to Configurator developer model rule contradiction to other runtime exceptions. This is just a starting point for troubleshooting model launch failures.

example of configurator error log files.JPG:

The Good stuff: source code of the scripts


Listing of timediff.sh  - Auxiliary script used for all other scripts

Listing of getpreloadtimings.sh

Listing of getpreloadtimings_summary.sh


Listing of calculate_response_time_for_model_launch.sh



Comments:

Post a Comment:
  • HTML Syntax: NOT allowed
About

bocadmin_ww

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today