Friday, May 28, 2010

Framework Logging Performance

I have been working with my eScript logging framework for a couple of months now and it has been extremely helpful with debugging complicated script procedures. What keeps it from being truly useful in a production environment though is it is too damn slow. In an ideal world, I could leave logging on at all times, or at least for long periods of times for users or groups I want to keep track of. In order to do this, I need to make sure they do not notice a significant degradation in their work day.

The way the logging object functions work in the framework is basically to send one line at a time to the step function which then opens a file, writes the content along with a timestamp, and closes the file. It is these file operations that take the great majority of performance time. A given complicated script takes about 7 seconds with logging turned up to 5 which outputs a 63kb log file on my thick client. While I could expect server performance to be a bit faster, just turning logging off, reduces the performance time to under 2 seconds. What to do...

Buffer the output. It strikes me that I will do the exact same thing Siebel does with its own log files. Ever notice that the SQL Spool file or server log files are not always completely up to date with what you are executing in the GUI? This is because the application keeps a buffer of output and only writes the buffer when it is full. So I will do the same thing. I will store a new system parameter called 'Log Buffer' which will equal the number of lines to buffer. I will then create some new global variables to keep a running line count and one to buffer the output.


var giLogBuffer = Frame.GetSysPref("Log Buffer");
var giLogLines = 0;
var giLogCache = "";


All I have to do is modify my step function to leverage these values. Here is my step function again from the framework Log object with my mods:


step : function ( text, Lvl ) {
if (((Lvl == null)||(TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl))&&
(giLogLines >= giLogBuffer)) {
var fp = Clib.fopen(OutPutFileName, "a");
Clib.fputs(giLogCache, fp);
Clib.fputs(Frame.GetLocalTime()+" "+gsIndent + text + "\n", fp);
Clib.fclose(fp);
giLogLines = 0;
giLogCache = "";
}
else {
giLogLines++;
giLogCache += Frame.GetLocalTime()+" "+gsIndent + text + "\n"
}
}


After setting the new buffer parameter to 20, performance improved drastically. My old 7 second run went down to 2 seconds. Could not even notice that logging was ramped up. My only concern is that things I really want to see don't appear in the log right away, like errors. So I need to modify the RaiseError function to artificially fill the buffer and force a log dump. Here is the new line I inserted (followed by the existing line):


giLogLines = giLogBuffer; //insure errors gets written to log file
Log.step("---End Function "+sFunction+"\n");

I would probably need to do something similar on the Application Close event. Not sure if user's hitting windows X will trigger this though. Something to think about.

Wednesday, May 26, 2010

eScript Framework - Query return Array

In my post introducing my eScript Framework, I glossed over the functional content of the functions I included so let me go into some more detail before proceeding. The last function in the declaration was called QueryExprArrayReturn. This function will execute a query against the business component whose string name is passed to the function using a complete expression also passed. The last parameter is an array of fields whose values will be returned, via an associative array.

QueryExprArrayReturn : function( sBO, sBC, sExpr, aFields) {
// Use : Frame.QueryExprArrayReturn (sBO : string nsme of Business
Object,
// sBC : string nsme of Business Component,
// sExpr : search expression to be applied,
// aFields : array of fields to be returned)
// Returns : string replacing fields and parameters from the lookup BC and/or property set
var aFnd, bFound, iRecord, sField;
var aValues = new Array();
var rePattern = /(?<=\[)[^[]*(?=\])/g;
with (TheApp.GetBusObject(sBO).GetBusComp(sBC)) {
while ((aFnd = rePattern.exec(sExpr)) != null) ActivateField(aFnd[0]);
for (var c=0; c < aFields.length; c++) ActivateField(aFields[c]);
ClearToQuery();
SetViewMode(AllView);
SetSearchExpr(sExpr);
ExecuteQuery(ForwardOnly);
if (FirstRecord()) {
iRecord = 0;
for (var i=0; i < aFields.length; i++) {
aValues[aFields[i]] = new Array();
aValues[aFields[i]][iRecord] = GetFieldValue(aFields[i]);
}
while (NextRecord()) {
iRecord++;
for (var i=0; i < aFields.length; i++) {
aValues[aFields[i]][iRecord] = GetFieldValue(aFields[i]);
}
}
}
return(aValues)
}


What is occurring here is pretty straightforward:
  1. Instantiate a BC using the passed BO/BC strings
  2. Activate any fields used in the Search Expression
  3. Activate the fields needing to be returned
  4. Query using the passed search expression
  5. If at least one record is found, create an associtive array of field values where the first index is the field name and the second index is the record number
  6. Continue populating this array for each record found

Probably the most interesting aspect of this query is the use of a regular expression search of the passed in expression to activate and BC fields present there by identifying them in enclosing square brackets [].

Monday, May 24, 2010

eScript Framework - Logging

The ABS Framework apparently has a logging module that Jason describes. This is interesting because I have been building my own logging technique over the past couple of years that largely parallels what I believe the framework does. Understanding object prototyping redirected my thoughts a bit and helped me centralize the effort. My previous post introduced the Frame and TheApp objects. This post will introduce a new object: Log. The following script will also be added to the Application declarations section.


Object.prototype.Log = function() {
return {
step : function ( text, Lvl ) {
if ((Lvl == null)(TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl)) {
var fp = Clib.fopen(OutPutFileName, "a");
Clib.fputs(Frame.GetLocalTime()+" "+gsIndent + text + "\n", fp);
Clib.fclose(fp);
}
},
RaiseError : function ( e ) {
if(!defined(e.errText)) e.errText = e.toString();
var sFunction = gaFunctionStack.pop();

Log.step("".rPad(100, "*"));
Log.step("*** - ERROR - "+sFunction+" - "+e.errCode);
Log.step("*** "+e.errText.replace(/\n/g, "\n"+gsIndent+"".rPad(20," ")+"*** "));
Log.step("".rPad(100, "*")+"\n");
Log.step("---End Function "+sFunction+"\n");

var sLength = gaFunctionStack.length;
gsIndent = "".rPad(giIndent*sLength, ' ');

if (sLength>0) Log.step("<<-Returning to Function "+gaFunctionStack[sLength-1]+"\n"); throw(e); }, StartStack : function ( sType, sName, sMethod, Lvl ) { gaFunctionStack.push(sName+"."+sMethod); gsIndent = "".rPad(giIndent*gaFunctionStack.length, ' '); if (TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl) {
Log.step(" ");
Log.step("".rPad(100, "-"));
Log.step("".rPad(100, "-"));
Log.step(sType+": "+sName);
Log.step("Method: "+sMethod+"\n");
}
},
Stack : function ( sFunction, Lvl ) {
gaFunctionStack.push(sFunction);
gsIndent = "".rPad(giIndent*gaFunctionStack.length, ' ');

if (TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl) {
Log.step(" ");
Log.step(">".rPad(100, "-"));
Log.step("Function: "+sFunction+"\n");
}
},
Unstack : function ( sReturn, Lvl ) {
var sFunction = gaFunctionStack.pop();
if (TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl) {
var sString = "";
if (sReturn != "") sString = " - Return: "+sReturn;
Log.step("---End Function "+sFunction+sString+"\n");
}
var sLength = gaFunctionStack.length;
gsIndent = "".rPad(giIndent*sLength, ' ');

if ((TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl)&&(sLength>0))
Log.step("<<-Returning to Function "+gaFunctionStack[sLength-1]+"\n"); }, PropSet : function (Inputs, Lvl) { // Print out the contents of a property set. if (TheApp.GetProfileAttr("CurrentLogLevel") >= Lvl) {
PSDepth++; // Dive down a level
var InpChildCount, inprop, inpropval, inpropcnt;
var BlankLine = ' ';
var Indent = "".lPad(giIndent*PSDepth, " ") + ToString(PSDepth).lPad(2, "0") + ' ';

Log.step(BlankLine);
Log.step(Indent + '---- Starting a new property set ----');
InpChildCount = Inputs.GetChildCount();
Log.step(Indent + 'Value is ........ : "' + Inputs.GetValue() + '"');
Log.step(Indent + 'Type is ........ : "' + Inputs.GetType() + '"');
Log.step(Indent + 'Child count ..... : ' + ToString(InpChildCount));

var PropCounter = 0;
inprop = Inputs.GetFirstProperty();
while (inprop != "") { // Dump the properties of this property set
PropCounter++;
inpropval = Inputs.GetProperty(inprop);
Log.step(BlankLine);

var PropCountStr = ToString(PropCounter).lPad(2, "0");
Log.step(Indent+'Property '+PropCountStr+' name : <'+inprop + '>');
Log.step(Indent+'Property '+PropCountStr+' value : <'+inpropval + '>');
inprop = Inputs.GetNextProperty();
}

// Dump the children of this PropertySet
if (InpChildCount != 0) {
for (var ChildNumber = 0; ChildNumber < InpChildCount; ChildNumber++) {
Log.step(BlankLine);
Log.step(Indent + 'Child Property Set ' + ToNumber(ChildNumber + 1) + ' of ' + ToNumber(InpChildCount) + ' follows below.');
Log.step(Indent + 'This child is on level ' + ToNumber(PSDepth));

// Recursive call for children, grandchildren, etc.
Log.PropSet(Inputs.GetChild(ChildNumber), Lvl);
}
}
PSDepth--; // Pop up a level
}
}
}
}();
var OutPutFileName;
//Indent child prop sets this many spaces to the right for each level down.
var giIndent = 2;
var PSDepth = 0; // How deep in the property set tree, what level
var CurrentLogLevel = 2;
//used in debugStack function so store called functions
var gaFunctionStack = new Array();
var giStackIndex = 0; //Where in the function stack the current function resides
var gsIndent = ''; //used in debug methods to identify stack indents


In addition, I added the following to the Application Start event. The prerequisite for this is the new profile attribute I created in this post, and the creation of a new system parameter, 'Framework Log Path':


var sPath = Frame.GetSysPref("Framework Log Path");
sPath = sPath.replace(/\\$/, ""); //Remove trailing backslash if used
OutPutFileName = sPath+"\\Trace-"+
TheApp.LoginName()+"-"+
Frame.GetLocalTime("%02d%02d%d%02d%02d%02d")+".txt";
try {
Log.step("Log Application Start Event", 1);
}
catch(e) {
//default to OOTB Log File Location:
OutPutFileName = "Trace-"+TheApp.LoginName()+"-"+
Frame.GetLocalTime("%02d%02d%d%02d%02d%02d")+".txt";
Log.step("Invalid Preference - Framework Log Path: "+sPath, 0);
}
//Get the System Preference Log Level. Get the Log Level set for this user (if provided) and
//then set the log level for this session
var sLogLevel = Frame.GetSysPref("CurrentLogLevel");
if (TheApp.GetProfileAttr("User Log Level") != "")
TheApp.SetProfileAttr("CurrentLogLevel", TheApp.GetProfileAttr("User Log Level"));
else TheApp.SetProfileAttr("CurrentLogLevel", sLogLevel);
Log.step("Session Logging Level: "+TheApp.GetProfileAttr("CurrentLogLevel"), 1);


Here is an example of these functions in use in a PreInvokeMethod event of a BC:


function BusComp_PreInvokeMethod (MethodName) {
try {
Log.StartStack("Business Component", this.Name(), MethodName, 1);
var bReturn;
var sVar1 = "TEST"
switch(MethodName) {
case "TestMethod":
Log.step("Variable 1: "+sVar1 ,1);
TestMethod(sVar1 );
bReturn = CancelOperation;
break;
}

Log.Unstack(bReturn,0);
return(bReturn);
}
catch(e) {
Log.RaiseError(e);
}
}


And this is how it would be used in a method:


function TestMethod (sVar1) {
try {
Log.Stack("TestMethod", 1);
Log.step("sVar1: ".lPad(30,".")+sVar1+"\n", 2);
sVar1 += sVar1 + sVar1;
Log.Unstack("N", 2);
}
catch(e) {
Log.RaiseError(e);
}
}


The result of this provides an individual log file placed in the directory specified by the system parameter. Each method call is indented 2 spaces.

UPDATE: I am no HTML wizard but am learning. I updated tags to make code easier to read

The Framework

It has been a while but I want to return to the eScript Framework. I have already put up a couple of posts about some potential functions the Framework should include. So lets put a wrapper around this based on Jason's post. My thinking is that this code will all be placed in the Application declarations sections. I am still working on understanding the Object prototypes for modifying BCs which I hope will add significantly more functionality. Here is the script so far:


Object.prototype.TheApp = this;
Object.prototype.Frame = function() {
return {
AddToDate : function ( srcDate, iDays, iHrs, iMin, iSec, nSign ) {
//Use : Frame.AddToDate ( srcDate : Date Object
// iDays, iHrs, iMin, iSec : Integer Numbers
// nSign : 1 or -1 {1 to ADD to the srcDate
// -1 to SUBTRACT from the srcDate } )
//Returns : date object, after adding/subtracting iDays, iHrs, iMin and iSec to the srcDate
var retDate = srcDate;
retDate.setDate(retDate.getDate()+nSign*iDays);
retDate.setHours(retDate.getHours()+nSign*iHrs);
retDate.setMinutes(retDate.getMinutes()+nSign*iMin);
retDate.setSeconds(retDate.getSeconds()+nSign*iSec);
return(retDate);
},
DateToString : function (dDate) {
//Use: Frame.DateToString ( dDate : Date Object )
//Returns: A string with the format "mm/dd/yyyy" or "mm/dd/yyyy hh:mi:ss"
var sMon = ToString(dDate.getMonth()+1);
if (sMon.length==1) sMon = "0" + sMon;
var sDay = ToString(dDate.getDate());
if (sDay.length==1) sDay = "0" + sDay;
var sHrs = ToString(dDate.getHours());
if (sHrs.length==1) sHrs = "0" + sHrs;
var sMin = ToString(dDate.getMinutes());
if (sMin.length==1) sMin = "0" + sMin;
var sSec = ToString(dDate.getSeconds());
if (sSec.length==1) sSec = "0" + sSec;
if (sHrs == "00" && sMin == "00" && sSec == "00")
return(sMon+"/"+sDay+"/"+dDate.getFullYear());
else return(sMon+"/"+sDay+"/"+dDate.getFullYear()+" "+sHrs+":"+sMin+":"+sSec);
},
StringToDate : function ( sDate ) {
//Use: Frame.StringToDate(sDate: A string with format "mm/dd/yyyy" or "mm/dd/yyyy hh:mi:ss"
//Returns: a Date Object
var aDateTime = sDate.split(" ");
var sDate = aDateTime[0];
var aDate = sDate.split("/");
if (aDateTime.length==1)
return (new Date(ToNumber(aDate[2]),
ToNumber(aDate[0])-1,
ToNumber(aDate[1])));
else {
var ArTime = aDateTime[1];
var aTime = ArTime.split(":");
if (aTime[0]=="00" && aTime[1]=="00" && aTime[2]=="00")
return (new Date(ToNumber(aDate[2]),
ToNumber(aDate[0])-1,
ToNumber(aDate[1])));
else {
return (new Date(ToNumber(aDate[2]),
ToNumber(aDate[0])-1,
ToNumber(aDate[1]),
ToNumber(aTime[0]),
ToNumber(aTime[1]),
ToNumber(aTime[2])));
}
}
},
GetSysPref : function ( sPreference ) {
//Use: Frame.GetSysPref( sPreference: the preference name in the system preference view )
//Returns: the value in the system preference view for this preference name
var boPref = TheApp.GetBusObject("System Preferences");
var bcPref = boPref.GetBusComp("System Preferences");
with (bcPref) {
ClearToQuery();
SetSearchSpec("Name", sPreference);
ActivateField("Value");
ExecuteQuery(ForwardOnly);
if (FirstRecord()) return(GetFieldValue("Value"));
else return("");
}
},
SetSysPref : function ( sPreference, sValue ) {
//Use: Frame.SetSysPref( sPreference: the preference name in the system preference view,
// sValue: the value of the preference )
var boPref = TheApp.GetBusObject("System Preferences");
var bcPref = boPref.GetBusComp("System PreferencesUpd");

with (bcPref) {
ClearToQuery();
ActivateField("Value");
SetSearchSpec("Name", sPreference);
ExecuteQuery(ForwardOnly);

if (FirstRecord()) SetFieldValue("Value", sValue);
else {
NewRecord(NewBefore);
SetFieldValue("Name", sPreference);
SetFieldValue("Value", sValue);
WriteRecord();
}
}
},
DiffDays : function (date1, date2) {
// Use : Frame.DiffDays ( date1 : Starting Date object, date2 : Another Date object )
// Returns : Number of days between date1 and date2
return ((date2.getTime()-date1.getTime())/(1000*60*60*24));
},
GetLocalTime : function (sFormat) {
// Use : Frame.GetLocalTime ()
// Returns : string of the current timestamp
var dNow = new Date();
var sNow;
if (sFormat != null)
Clib.sprintf(sNow, sFormat, dNow.getMonth()+1, dNow.getDate(),
dNow.getFullYear(), dNow.getHours(), dNow.getMinutes(), dNow.getSeconds());
else Clib.sprintf(sNow, "%02d/%02d/%d %02d:%02d:%02d", dNow.getMonth()+1,
dNow.getDate(), dNow.getFullYear(), dNow.getHours(), dNow.getMinutes(),
dNow.getSeconds());
return (sNow);
},
QueryExprArrayReturn : function( sBO, sBC, sExpr, aFields) {
// Use : Frame.QueryExprArrayReturn (sBO : string nsme of Business Object,
// sBC : string nsme of Business Component,
// sExpr : search expression to be applied,
// aFields : array of fields to be returned)
// Returns : string replacing fields and parameters from the lookup BC and/or property set
var aFnd, bFound, iRecord, sField;
var aValues = new Array();
var rePattern = /(?<=\[)[^[]*(?=\])/g;
with (TheApp.GetBusObject(sBO).GetBusComp(sBC)) {
while ((aFnd = rePattern.exec(sExpr)) != null) ActivateField(aFnd[0]);
for (var c=0; c < aFields.length; c++) ActivateField(aFields[c]);
ClearToQuery();
SetViewMode(AllView);
SetSearchExpr(sExpr);
ExecuteQuery(ForwardOnly);

if (FirstRecord()) {
iRecord = 0;
for (var i=0; i %lt; afields.length; i++) {
aValues[aFields[i]] = new Array();
aValues[aFields[i]][iRecord] = GetFieldValue(aFields[i]);
}
while (NextRecord()) {
iRecord++;
for (var i=0; i < afields.length; i++)
aValues[aFields[i]][iRecord] = GetFieldValue(aFields[i]);
}
}
}
return(aValues)
}
}
}();


This is in addition to the string prototype modifications discussed in earlier posts.

Tuesday, May 4, 2010

Making an MVF Required

If you were to do a google search for this requirement you would probably find a lot of posts returned so I do not want to claim I am doing anything new. In fact, My Oracle Support even has a post about doing this declaratively and they claim this has been added to bookshelf for 8.x as the documentation defect is shown to be fixed but I cannot find the relevant page. (Search for Document ID ID 476071.1). Anyway I just wanted to put all this information in one place for my own reference and for anyone else that finds this useful.

First, the configuration:

The key thing here is that since the calculated field name has the same name as the MVF with just a space added, the message displayed to the user will be the same as well. Next, the appearance:

To make the red asterisk appear, add the following text to the Applet Control Caption - String Override whereever in the string you need the asterisk:

<img src="images/icon_req.gif" alt="Code Validated field" border="0" space="0" hspace="0">

Keep in mind Siebel automatically adds the colon (:) after the field label so that in Siebel 8.x, the red asterisk will appear before the colon while other required fields will have the asterisk appear after the colon. If you wish to be even more precise, and don't we all, you can remove the field label Siebel creates for you all together and create your own so you can place the colon where you wish. This is described in Document 852952.1 on My Oracle Support in a pretty superfluosly wordy way, so here is the excerpted nickel version:

  1. First remove the existing Field Label of HTML type Text.
  2. Drag a drop a Control of Type Label in the Grid Layout Applet web template
  3. Set the Caption for this Label Control. To show for example,

Last Name: *

Enter the following in the Caption - String Override:

Last Name:<img src="images/icon_req.gif" alt="Code Validated field" border="0" space="0" hspace="0">

Set the property HTML Type = Label


As for making the asterisk conditionally appear (for instance to support the BC level functionality enforced by the calculated field in the Required Field User Property), there is not really a way to do that, but a close approximation if you only have one is to use toggle applets which toggle on the same conditional value that the fields user property is based on.