See How Long it Takes for Your Extension to Finish

Your order management extension might result in taking a long time to save or submit a sales order.

For example, a complex extension might integrate with a service that has a slow response. To troubleshoot this problem, you can use this code in your extension and measure how much time it takes to finish running:

logger = context.getLogger();
def startTime = context.getCurrentTime();
try {
  /*your custom code*/
}finally {
  logDuration(startTime);
}
/*your custom functions*/
void logDuration(java.sql.Timestamp startTime) {
  def endTime = context.getCurrentTime();
  long diff = endTime.getTime() - startTime.getTime();
  logger.logSevere( "ExtensionDurationCheck;" +
context.getExtensionName() + " " + header.getAttribute("OrderNumber") + ";" + diff.toString());
}

If it exceeds a time threshold, then you can end the extension, or least examine your logs to identify which extension is taking a long time to finish, for which sales order, then take corrective action.

Consider this code.

OALOMExtensionDurationCheck;extension_name;extension_runtime_duration.

where

Order Management replaces extension_name with the name of your extension.
Order Management replaces extension_runtime_duration with the time in hour, minutes and seconds.

This code makes sure that Order Management creates a log for your extension even when you set it at a SEVERE level.

Assume the code adds these details to your log.

'OALOMExtensionDurationCheck;CopyOrderFields for Return Orders;122'

It means an extension named CopyOrderFields for Return Orders took 122 milliseconds to finish.

Examine Your Log

As an alternative, you can examine your log. Consider an example extension that runs on the On End of Submission Request extension point.

Set the logging profile to FINER.
Create and submit a sales order.

Open the log for your extension and examine the results.

Finished invoking extensions for event ON_END_SUBMIT in 5ms

Here's an example log. Search it for the text in 5ms.

scm.doo.common.extensions.model.applicationModule.DooCommonExtensionsAMImpl] [SRC_CLASS: oracle.apps.fnd.applcore.log.AppsODLHandler] [SRC_METHOD: publish] Invoking ON_END_SUBMIT Extensions for headerId: 300100185658909
[2020-03-27T20:24:14.877+00:00] [UIServer_2] [TRACE:16] [] [oracle.apps.appslogger] [tid: 130] [userId: ORDER_ENTRY_SPEC] [ecid: 005cTjY2YVbDg^O5Ijo2yf00055I0001Ye,0:4] [APP: ORA_FSCM_UIAPP#V2.0.n-TV_j4ycNhG-GhU36AdAA] [APPS_USER_NAME: ORDER_ENTRY_SPEC] [APPS_SESSION_ID: A1D8F6426C73FA3CE0530503F40A6116] [APPS_THREAD_NAME: [ACTIVE].ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'] [APPS_TERRITORY: US] [APPS_AUTO_LOG: false] [APPS_USER_ID: 27E079FDC4D0AE55B8F4F424AD9940EA] [APPS_DB_CONNECTION_URL: jdbc:oracle:thin:@FA_DEFAULT] [APPS_SOURCE: scm.doo.orchInfra.protectedModel.extensionsFwk.applicationModule.ExtensionsRuntimeAMImpl] [SRC_CLASS: oracle.apps.fnd.applcore.log.AppsODLHandler] [SRC_METHOD: publish] Entering invokeExtensions - eventCode: ON_END_SUBMIT
[2020-03-27T20:24:14.881+00:00] [UIServer_2] [TRACE] [] [oracle.apps.appslogger] [tid: 130] [userId: ORDER_ENTRY_SPEC] [ecid: 005cTjY2YVbDg^O5Ijo2yf00055I0001Ye,0:4] [APP: ORA_FSCM_UIAPP#V2.0.n-TV_j4ycNhG-GhU36AdAA] [APPS_USER_NAME: ORDER_ENTRY_SPEC] [APPS_SESSION_ID: A1D8F6426C73FA3CE0530503F40A6116] [APPS_THREAD_NAME: [ACTIVE].ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'] [APPS_TERRITORY: US] [APPS_AUTO_LOG: false] [APPS_USER_ID: 27E079FDC4D0AE55B8F4F424AD9940EA] [APPS_DB_CONNECTION_URL: jdbc:oracle:thin:@FA_DEFAULT] [APPS_SOURCE: scm.doo.orchInfra.protectedModel.extensionsFwk.applicationModule.ExtensionsRuntimeAMImpl] [SRC_CLASS: oracle.apps.fnd.applcore.log.AppsODLHandler] [SRC_METHOD: publish] Finished invoking extension Default EFF in 0ms
[2020-03-27T20:24:14.882+00:00] [UIServer_2] [TRACE] [] [oracle.apps.appslogger] [tid: 130] [userId: ORDER_ENTRY_SPEC] [ecid: 005cTjY2YVbDg^O5Ijo2yf00055I0001Ye,0:4] [APP: ORA_FSCM_UIAPP#V2.0.n-TV_j4ycNhG-GhU36AdAA] [APPS_USER_NAME: ORDER_ENTRY_SPEC] [APPS_SESSION_ID: A1D8F6426C73FA3CE0530503F40A6116] [APPS_THREAD_NAME: [ACTIVE].ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'] [APPS_TERRITORY: US] [APPS_AUTO_LOG: false] [APPS_USER_ID: 27E079FDC4D0AE55B8F4F424AD9940EA] [APPS_DB_CONNECTION_URL: jdbc:oracle:thin:@FA_DEFAULT] [APPS_SOURCE: scm.doo.orchInfra.protectedModel.extensionsFwk.applicationModule.ExtensionsRuntimeAMImpl] [SRC_CLASS: oracle.apps.fnd.applcore.log.AppsODLHandler] [SRC_METHOD: publish] Finished invoking extensions for event ON_END_SUBMIT in 5ms
[2020-03-27T20:24:14.882+00:00] [UIServer_2] [TRACE:16] [] [oracle.apps.appslogger] [tid: 130] [userId: ORDER_ENTRY_SPEC] [ecid: 005cTjY2YVbDg^O5Ijo2yf00055I0001Ye,0:4] [APP: ORA_FSCM_UIAPP#V2.0.n-TV_j4ycNhG-GhU36AdAA] [APPS_USER_NAME: ORDER_ENTRY_SPEC] [APPS_SESSION_ID: A1D8F6426C73FA3CE0530503F40A6116] [APPS_THREAD_NAME: [ACTIVE].ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'] [APPS_TERRITORY: US] [APPS_AUTO_LOG: false] [APPS_USER_ID: 27E079FDC4D0AE55B8F4F424AD9940EA] [APPS_DB_CONNECTION_URL: jdbc:oracle:thin:@FA_DEFAULT] [APPS_SOURCE: scm.doo.common.extensions.model.applicationModule.DooCommonExtensionsAMImpl] [SRC_CLASS: oracle.apps.fnd.applcore.log.AppsODLHandler] [SRC_METHOD: publish] Exiting invokeExtensions

Use a Warning Message

As another alternative you can use a warning message.

Here's an example extension that measures the time that the extension runs, then uses the messaging framework to display it in an Oracle warning message.

import oracle.apps.scm.doo.common.extensions.ValidationException;
import oracle.apps.scm.doo.common.extensions.Message;
import oracle.apps.scm.doo.common.extensions.Message;
List<Message> messages = new ArrayList<Message>();
 def starttime = context.getCurrentTime();  //get current time
 
//assume you want to get the order lines that are in the sales order
def lines = header.getAttribute("Lines");                                                 
while( lines.hasNext() ) {                                                                         
  def line = lines.next(); 
  
  // do whatever processing you need                                                                   
}
 
def endtime = context.getCurrentTime(); // assuming that this is the end of your macro, register the time
 
 // this example code creates a warning message named TEST_LOGGING_MESSAGE. It uses 3 tokens: start time, end time, and extension name.
 
def tokens = [START_TIME: starttime.toString(), END_TIME: endtime.toString(), EXTENSION_NAME: context.getExtensionName()]; //create
 
Message logMessage =  new Message(Message.MessageType.WARNING, "ORA_MANAGE_EXTENSIONS", "TEST_LOGGING_MESSAGE",tokens);
messages.add(logMessage);
ValidationException ex = new ValidationException(messages);
 
 // if you want to print only the time, do this:
 
 //def printstring = "Start time : " + starttime.toString() +  "\n" + "End time : " + endtime.toString();
//ValidationException ex = new ValidationException(printstring);
//ValidationException ex = new ValidationException("ORA_MANAGE_EXTENSIONS", "TEST_LOGGING_MESSAGE", tokens);
 
throw ex;