Part 1 - Introduction and basic settings
Part 2 - Modules and Components
Part 3 - API call timings
Part 4 - Query logging
Part 5 - Log Formatting
Part 6 - Assertions, Unix and 64 bit Windows
Part 7 - Choosing the correct settings and example defaults

Full article also available in SDN's Article section here.

API Call Timings

One of the pieces of information logged by the OLAP Data Access logging is the time it took for calls to the OLAP Data Access component API to complete. There are additional logging settings that can be utilized to control the logging of API call timings that make it easier, for example, to identify long running API calls which might point to potential bottlenecks.

The exact nature of the logging and the facilities to control it vary slightly between versions of the OLAP Data Access component.

MDA API Call Timing Behavior

Here is a list of points describing the behavior of API call timing logging in the MDA version of the OLAP Data Access component.

• API call timings are logged as part of the APIMODULE.
• They are logged at either a verbosity of 5 or 10.
• Logging at a verbosity of 5 eliminates all API calls that complete in less than 0.0001 seconds.
• The API call timings are also logged to a specific component called TIMER so a log file could be configured to contain just the API call timings.
• Only times over a certain threshold are logged
• By default the threshold is set to 0.000
• The threshold can be set by creating a DWROD called Timer Threshold in the APIMODULE folder and entering a value for the number of milliseconds. For example a value of 1000 will only log times that take over one second.

Note: In practice there is no difference to the amount of API calls logged out at verbosity 5 or 10. If the threshold it at its default setting of zero then times that are less than 0.0001 seconds tend to get rounded off to a value of zero so are not logged.

An example of what API call timing log statements look like is given here:

Tue Dec 01 16:40:42.698: APIMODULE: TIMER: Call to CubeViewImpl::query took 0.701 seconds

Tue Dec 01 16:42:07.675: APIMODULE: TIMER: Call to AxisResultSetImpl::getCount took 1.411 seconds

Tue Dec 01 16:42:09.090: APIMODULE: TIMER: Call to CellResultSetImpl::getCursor(UInt, UInt) took 1.382 seconds

MDA Example registry settings

Here is an example for configuring the registry for capturing just API call timings for MDA 12.

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\MDA\Log\Modules\APIMODULE]

"Verbosity"=dword:00000000

"Timer Threshold"=dword:000001f4

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\MDA\Log\Modules\APIMODULE\Components]

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\MDA\Log\Modules\APIMODULE\Components\TIMER]

"Verbosity"=dword:00000005

This turns of all logging for APIMODULE at the module level. It set the timer threshold to 500 milliseconds (500 is 1f4 in hexadecimal). It finally sets the TIMER component to log at verbosity 5.

If there are no other verbosity settings for other modules or components in the registry, this setting would log only OLAP Data Access API calls that took over half a second.

SOFA API Call Timing Behavior

Here is a list of points describing the behavior of API call timing logging in the SOFA version of the OLAP Data Access component.

• API call timings are logged as part of either the COMWRAP or the COUTILITIES modules
• They are logged at either a verbosity of 5 or 10
• Logging at a verbosity of 5 eliminates all API calls that complete in less than 0.0001 seconds.
• Logging at verbosity 10 logs the API entry point as well as the exit point.
• The API call timings are also logged to a specific component called Timer so a log file could be configured to contain just the API call timings.
• There is no threshold setting for SOFA API call times unlike MDA API calls

Note Unlike the MDA version of the API timer logging, logging at verbosity 5 or 10 does make a difference. Logging at verbosity 10 will log two lines for every API call regardless of how long the API call took to complete. The first line logged will indicate the beginning of the API call. For example:

Thu Dec 03 14:18:03.659: COMWRAP: Timer: Calling Level::CLevel::get_Caption ...

The second log line will indicate the completion of an API call. For example:

Thu Dec 03 14:18:03.675: COMWRAP: Timer: Call to Level::CLevel::get_Caption took 0.000 seconds

SOFA Example registry settings

Here is an example for configuring the registry for capturing just API call timings for SOFA 12.

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COMWRAP]

"Verbosity"=dword:00000000

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COMWRAP\Components]

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COMWRAP\Components\Timer]

"Verbosity"=dword:00000005

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COUTILITIES]

"Verbosity"=dword:00000000

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COUTILITIES\Components]

[HKEY_LOCAL_MACHINE\SOFTWARE\Business Objects\Suite 12.0\OLAP Intelligence\OCCA(o)\Log\Modules\COUTILITIES\Components\Timer]

"Verbosity"=dword:0000000a

This turns off all logging for both the COMWRAP and COUTILITIES modules, but turns on logging for the Timer component for both those modules at a verbosity of 5 for COMWRAP and 10 for COUTILITIES. This will mean that there will be a single line logged for any COMWRAP API calls that take an amount of measurable time and two lines (start and end) will be logged for all COUTILITIES API calls.