Purpose of Document
The purpose of this document is to provide guidance on enabling the advance logging settings for Dynamic Cubes and how to interpret the log messages which will help to diagnose various issues such as cube start problems, unexpected or wrong metadata, unexpected or wrong query results and poor query performance. This document will cover an introduction to event log groups, followed by detail about the log message format, and will continue with a description of the Dynamic Cubes default logging capabilities and an explanation about how to interpret the corresponding log messages. The document outlines the information that can be collected when enabling the advanced Dynamic Cubes logging event groups, the different log trace levels, and how to interpret the corresponding log messages.
The techniques and settings described in this document apply to,
- IBM Cognos Business Intelligence 10.2
In addition, later versions may have added or removed Dynamic Cubes logging event groups or changed specific logging messages. For further assistance or clarification please contact IBM Cognos Support for assistance. Also the user must have access to each server the IBM Cognos BI Dispatcher is installed on, as well as having the ability to stop and restart either the Query Service or the IBM BI Cognos Dispatcher.
Dynamic Cubes Logging Capabilities
Dynamic Cubes exists within the Dynamic Query Mode (DQM) server, therefore Dynamic Cubes leverage the same logging mechanism as the DQM server. Dynamic Cubes uses the concept of event groups to distinguish between the different areas of the Dynamic Cubes which can be logged. Furthermore, an event group can support five different logging levels.
|none||Nothing will be logged for this event group|
|error||Log messages about unrecoverable errors will be logged for this event group. Note that these error log messages are usually logged regardless if the event group has been enabled.|
|warn||Log messages about recoverable errors will be logged for this event group|
|info||Log messages about various kinds of information will be logged for this event group|
|trace||All possible log messages for this event group will be logged. This log level is usually used for diagnostic purposes and should not be enabled in a normally operating production environment.|
The event groups are set via a configuration file called xqe.diagnosticlogging.xml under the
<Cognos Home Dir>\configuration directory. Unless a log appender is specified in the configuration file, the log entries are found in the
<Cognos Home Dir>\logs\XQE directory in a file named xqelog-YYMMDD-xxxxxxxxxx, where xxxxxxxxxx is the difference between the time the log was created and Universal Time (UTC) in milliseconds.
To enable a specific event group find the
<component name="XQE"> tag in the xqe.diagnosticlogging.xml file and add a new child tag with the following format:
<eventGroup name="Name of the Event Group" level="Logging Level"/>
Restart the IBM Cognos BI service or just the QueryService specifically for the DQM server to pick up the newly added event group.
The log file contains a timestamp since each time the QueryService is started/restarted in IBM Cognos Administration (and also if the IBM Cognos BI service is restarted) a new xqelog-YYMMDD-xxxxxxxxxx file is created. The timestamp allows the user to cross reference which log file is corresponds to which instance the QueryService was restarted. By default XQE log files rollover once the log file is over 10MB.
DQM and Dynamic Cubes will never delete existing XQE log files. It is up to the user to manage and delete old log files from the
Cognos Home Dir>\logs\XQE directory when they are no longer required.
How to Read a Dynamic Cube Log Entry
This section will discuss some of the attributes of a Dynamic Cube log entry and their meaning. Consider the following sample log entry,
<event component="XQE" group="ROLAPCubes.Loader" level="ERROR" thread="1" timestamp="2013-03-28 01:13:30.892" contextId="17028" requestId="requestIDForValidation" rolapCube="Sales1_MUN_DB2" sessionId="f8b90254-4efc-4f33-98bb-181a0d168280"> <![CDATA[XQE-ROL-0095 The definition for the calculated member 'Product_Calc_MemberSet' is not valid. It has been removed from the hierarchy [Product].[Product (Sales1997)]…</event>
When reading a Dynamic Cube log entry there are some important things to note in order to diagnose problems and speed up time to resolution. First, note the value of the group attribute for the log entry. The value for this attribute will give you an indication of which area the log message relates to. In the sample above, the value is “ROLAPCubes.Loader” which indicates that the log message is related to cube loading.
Next, note the value of the level attribute for the log entry. The value for this attribute will give you an indication of the severity of the log message. In this case the value is “ERROR” which indicates that an unrecoverable error has occurred.
Next note the value of the rolapCube attribute. The value of this attribute tells you the specific Dynamic Cube the message pertains to. In this case the value indicates that the error occurred when loading the Dynamic Cube named ‘Sales1 MUN DB2’.
At this point note that the text between the
</event> tags contains the detailed log message. In this log message the error is about an invalid calculated member definition for the calculated member named “Product_Calc_MemberSet”. Furthermore, the log message states that the calculated member has been removed from the hierarchy and will not appear in the cube. The solution for this issue would be to reopen the model for the Dynamic Cube named Sales1 MUN DB2 and correct the calculated member expression for the calculated member Product_Calc_MemberSet.
Other interesting attributes are timestamp and sessionId. Sometimes it is helpful to check the value of the timestamp to make sure the log entries are not too old or irrelevant and to check the value of the sessionId in order to cross reference all the other log messages that are related to that particular session.
Dynamic Cube Default Logging Capabilities
Error level log messages for specific Dynamic Cubes event groups are always enabled by default. The only non-error level Dynamic Cubes event group that is enabled by default is the ROLAPCubes.Info event group which has the logging level set to info.
The ROLAPCubes.Info event group enabled at the info log level will log various information about when a cube has been added, updated, loaded, enabled/disabled, or deleted from a Cognos BI server. Other types of log messages that apply to a specific cube include validation messages for the cube’s aggregate slices, signaling when the cube’s in-memory aggregates have begun loading, and signaling when the cube’s cache (member/data/security) has been successfully updated.
Dynamic Cube Advanced Logging Capabilities
Dynamic Cubes has 14 specific event groups that can enabled at the trace level for more detailed log messages.
Table 2 - Dynamic Cube Advanced Log Groups
The ROLAPCubes event group enabled at the trace log level will log the total number of members in the member cache for a specific cube. This information is helpful when estimating how much JVM memory is needed for a cube and is an early indicator if the cube has been modeled correctly, since an incorrectly modeled cube would have a total number of cached members that is either more or less then what is expected.
The ROLAPCubes.Loader event group logs messages related to the loading of a cube. By default, if errors are encountered when loading a calculated member or measure, a ROLAPCubes.Loader event group message is logged explaining why the calculated member or measures was invalid and discarded. By default a ROLAPCubes.Loader event group message is also logged if there is an error when attempting to assign a default member to a hierarchy. If the ROLAPCubes.Loader event group is enabled at the info log level, it will log various information including the relative time current period expressions, which hierarchies and levels have padding members, when a specific hierarchy is being loaded, what type of hierarchy is being loaded (level versus parent-child), the total number of members loaded for a specific hierarchy, and the time it takes to load a specific hierarchy.
The ROLAPCubes.Loader event group log messages are very helpful in diagnosing why a specific cube takes so long to load and why the members of a hierarchy appear the way they do in the metadata, especially if used in conjunction with the QueryService.SQL event group found in the same xqelog-YYMMDD-xxxxxxxxxx log file set at trace level. By looking at the log entries about when the member query has started and stopped loading a specific hierarchy, the user can determine how long it takes for a that hierarchy to fully load. Enabling the QueryService.SQL event group set at trace level will log the SQL queries that are being run to create the members for a hierarchy. Looking at the SQL will allow the user to determine if the hierarchy has been modeled correctly with the correct level keys and attributes.
Finally validating that the total number of members loaded for a specific hierarchy with the number of unique level keys in the dimension table is a good way to determine if the cube has been modeled correctly. In summary, it is helpful to enable the ROLAPCubes.Loader event group during the process of modeling, deploying, and publishing a cube and to then disable the event group once the cube has been validated as modeled and running correctly. The ROLAPCubes.Loader event group enabled at the trace log level will log more detailed information, including messages marking the start and end of the process to load a specific hierarchy and the time it takes to query the relational database for the members.
The ROLAPCubes.Info event group is set to the info level by default and there is no need to change the logging level unless the user wishes to disable the event group by removing the log group entry from the xqe.diagnosticlogging.xml file or setting the logging level to none.
The ROLAPCubes.Management event group logs messages related to the management of the cube. By default, if an error is encountered with setting one or more of the cube’s configuration parameters a ROLAPCubes.Management event message will be logged. The ROLAPCubes.Managerment event group enabled at the info level will log various information such as when a specific version of a data cache, member cache, or security cache is created, when a cube startup trigger starts and finishes, and other esoteric cube management information including Cognos BI inter-communication related to Dynamic Cubes.
Since most of the ROLAPCubes.Management event group log messages are esoteric, the only time this event group needs to be enabled is if a user is asked to do so by your local IBM Cognos Support group in order to diagnose a specific problem.
The ROLAPCubes.Reservation event group logs messages related to cube reservations. There exists a class of cube operations that when run concurrently require that they are run in a thread-safe manner. Locks/reservations are used to ensure thread safety. Since the ROLAPCubes.Reservation event group log messages are very esoteric, the only time this event group needs to be enabled is if a user is asked to do so by your local IBM Cognos Support group in order to diagnose a specific problem related to unexpected behavior during concurrent actions.
The ROLAPCubes.Security event group logs messages related to Dynamic Cubes security. When the ROLAPCubes.Security event group is enabled at a level of info, it will log details about the security views during startup of the cube. This includes if the cube has been granted all member access or all member denied and the total the number of members granted/denied. There will also be log messages with details about what expressions were run for the security views, how many members the individual views allowed and how many security views are loaded for the cube. This type of information can be helpful in determining how the different security views for a specific cube are interacting in combination and a quick way to check if the expected number of members have been granted or denied.
When the ROLAPCubes.Security event group is enabled at trace level it will log the names of the individual users who log on to the cube and the user’s role and views. There will also be log messages about the user’s specific security view combination and if the user can see all, some, or none of the hierarchy. This type of information can be helpful in determining why a specific user is seeing the wrong members in the cube due to an incorrect security combination.
The ROLAPCubes.FMAPI event groups logs messages related to Cube Designer and the member browser of the cube. By default, if an error is encountered while handling the member browser requests from Cube Designer this event group will log a detailed error message in the log about the error. If a user encounters issues with the Cube Designer member browser functionality, this event group will help diagnose the problem.
The ROLAPQuery event group logs messages related to when a query is executed against a Dynamic Cube. When the ROLAPQuery event group enabled at the trace level it will log details about the query such as the specific query that is about to be executed, details about measure pre-fetching, details about member predicate optimization, and if there are no results returned after executing the query. Unless you are only looking for specific information such as the V5 query, it is recommended that the ROLAPQuery.Performance event group and the ROLAPQuery event group be enabled at the trace level in order to debug Dynamic Cube query issues effectively.
The ROLAPQuery.Performance event group logs messages related to query performance for Dynamic Cubes queries. The ROLAPQuery.Performance log entry introduces the
duration attributes. The
op attribute value is either START or END, allowing the user to see when a specific query action starts and ends in the log. The
duration attribute value is the difference in time in milliseconds between the start and end of a specific query action.
When the ROLAPQuery.Performance event group is enabled at trace level it will log details about the query and the duration of time spent in specific areas of query execution. This kind of information is invaluable in debugging the performance of cube. By looking at the log entries and the execution times a user can determine the time spent in the areas of query planning/generation, the retrieval of values from the data cache, the retrieval of value from the aggregate cache, the execution of the SQL query, retrieval of data from the underlying RDBMS, and the storage of values into the data cache. The total query time is also helpful when compared against the time it takes for a report to display on the screen. This allows a user to determine if query performance issues are in the query engine layer or in the result transport and report rendering layers.
It is sometimes helpful to note what kind of log messages are logged or are unexpectedly missing between the START and END log messages for a specific query action. For example, if a user sees log messages pertaining to the execution of a SQL query and retrieval of data from the underlying RDBMS for a report that should be using the warm cache, this would be an indication that something is being stored incorrectly in the warm cache or that the user’s assumption that the report is leveraging the warm cache is incorrect. Pay special attention to the ROLAPQuery.Performance log message which logs the finished execution of QueryStrategy for a specific report like the one below,
<event component="XQE" group="ROLAPQuery.Performance" level="INFO" thread="78" timestamp="2013-04-08 12:41:44.347" op="END" duration="32" contextId="4" requestId="requestIDForValidation" rolapCube="GoSalesSample" sessionId="3af370b5:13dea8508b9:-7fd3"> <![CDATA[Finished execution of Query Strategy for report Measures_Measures Requested 100 tuples Found 50 tuples in data cache Found 0 tuples in aggregate cubes Fetched 50 tuples from database 0 of the tuples were from pushdown queries Created 0 tuples from the aggregate cache Total time processing aggregates : 0 (ms) using 0 tasks 0 aggregate cells rolled up into 0 separate locations ]]></event>
This log message includes a breakdown of the categories where the result tuples came from and how many tuples were returned per category.
Table 3 - Dynamic Cube Query Categories for Tuple Results
|Data Cache||Tuple values from the in-memory data cache. The values are read from the in-memory data cache which is populated from previously run queries. This is considered data from a warm cache.|
|Aggregate Cube||Tuple values from the in-database aggregates. The values returned come from running a SQL query against the aggregate/summary tables found in the underlying RDBMS database.|
|Database||Tuple values from running a SQL query against the underlying RDBMS database. This is considered data from a cold cache.|
|Pushdown Query||A subset of tuples values from running a JDBC query against the underlying RDBMS database in which the query is pushdown to the database. Pushdown queries are only supported in queries with FILTER, TOPCOUNT, or TOPSUM function calls.|
|Aggregate Cache||Tuple values from the in-memory aggregates. The values are read from the in-memory aggregate cache.|
By looking at the breakdown of the different categories for a specific query, the user can determine if the query is being handled by the appropriate caches or database and in the right ratios.
The ROLAPQuery.AggregateStrategy event group enabled at trace level logs detail analysis about aggregates for a specific report. This information includes a log message about whether aggregates are not present for use by the report, which aggregates were considered for the report, which aggregates were used and finally which aggregates were rejected and the reason for the rejection.
If a specific report or query has poor performance because it is not using the expected aggregates, use the ROLAPQuery.AggregateStrategy event group enabled at a trace level.
The ROLAPCubes.AggregateCache event group logs numerous messages related to the different aspects of how the aggregate cache works. By default, the ROLAPCubes.AggregateCache event group is enabled at the error level and logs issues with reading the aggregate cache or if a specific aggregate does not completely solve an entire query. The ROLAPCubes.AggregateCache event group will also log a warning message when loading of an in-memory aggregate has been skipped because the max aggregate cache size is zero. This is a useful message to look for when in-memory aggregates are not being loaded for an unexpected reason.
When the ROLAPCubes.AggregateCache event group is enabled at an info level it will log different aspects pertaining to the loading of the aggregate cache. The messages are usually a two part message with a message marking the start of the aggregate loading and whether the loading was successful or unsuccessful. For example, when enabled at the info level the log could contain a message saying “beginning loading aggregate definition xyz” and then followed by a success message saying “loaded aggregate definition xyz with # of cells and # of bytes”.
It could also log messages about how many threads/tasks are being used to load the aggregate cache, total number of aggregate cells accessed, total aggregate storage size, if no aggregates are selected for a query, and the query set levels. This type of information is invaluable when debugging issues about reducing the time to load the aggregates, how much memory is needed for the aggregates, if reports are actually using aggregates, and if a specific query contains the members at the correct level for an aggregate to match.
When enabled at trace level, the ROLAPCubes.AggregateCache event group logs the result set returned from the aggregate cache and more detail information why specific aggregates were rejected. This information is very important in helping to craft better aggregates or to modify the reports so they will match the existing aggregates.
The ROLAPCubes.AggregateCache event group enabled at info or trace level will cause a lot of information to be logged. If the event group is enabled in conjunction with using an appender (see Appendix A), the main log file will be less cluttered. It is recommended that this event group only be used when required to investigate issues with the aggregate cache.
The ROLAPAggregateAdvisor event group logs messages about how the aggregate advisor works and the errors that the advisor may encounter while attempting to recommend aggregates.
When the ROLAPAggregateAdvisor event group is enabled at an info level it will log information about the workflow that the advisor took to come up with its aggregate recommendations. This information is important when investigating why a specific aggregate advisor run is returning the wrong set of aggregates. For example, the event group would log messages like “aggregate xyz was rejected because it is too large compared to the fact table”. Such a message would mean that the cardinality of the aggregate needs to be reduced, perhaps by removing a dimension for the aggregate to be recommended.
The ROLAP.AggregateWorkload event group enabled at info level or higher will enable workload logging for Dynamic Cubes queries. The workload logs are used by the Aggregate Advisor when determining aggregates. For more information about how the Aggregate Advisor uses workload logging see Optimize dynamic cube performance with Aggregate Advisor.
Another way to enable workload logging is to set the workload enabled property on the cube. The ROLAP.AggregateWorkload event group enabled at trace level will also log messages if issues are encountered with deleting workload log files.
The ROLAPCubes.Virtual event group logs various information about virtual cubes including how a virtual cube is initialized, how a virtual cube will merge its source cubes, what source objects are hidden (if any), and what queries are sent to the source cube. By default, the ROLAPCubes.Virtual event group will log warning messages such as when invalid source dimension, hierarchy, level, or members are detected during the creation of a virtual cube. It will also log the dead cube warning when a virtual hierarchy is created which does not have an ALL member and does not merge hierarchies from all the source cubes. This will result in a “dead” source cube since no queries will be routed to the cubes corresponding to the missing source hierarchies.
To help diagnose issues where a virtual cube is merging incorrectly or returning unexpected results like only returning data from one source cube, enable the ROLAPCubes.Virtual event group with the trace log level.
The event group will log detailed messages about how the source objects are being merged. If a dimension, hierarchy, level, or member is not merging properly the resulting virtual tuple log message could explain why queries are returning only the data from one source cube. Also look for log messages where one or more dimensions from a source cube are not merged, if a hierarchy is hidden and not defaulted, or a hierarchy is not hidden and defaulted. These cases could also cause a query not be run against a source cube.
The DQM logging mechanism has a log appender feature that allows users to redirect a specific event group log messages to a specific file rather than the standard xqelog-YYMMDD-xxxxxxxxxx file. In certain cases this is helpful because the standard xqelog-YYMMDD-xxxxxxxxxx file can become hard to parse if too many event groups are enabled and too many log messages are logged in the standard log file. By placing a specific event group log messages in a specific file the log messages are easier to parse. The drawback is separate log files make it harder to cross reference log messages when a user needs to see different event group log messages relative to one another.
To enable a log appender, add the attribute
appender whose value is the name of the appender to the event group entry in the xqe.diagnosticlogging.xml file. For example,
<eventGroup name="ROLAPCubes.Info" appender=”DesiredAppenderName” level="info"/>
Next setup an appender in the xqe.diagnosticlogging.xml as follows, making sure the name attribute is exactly the same as the value specified above.
<appender name="DesiredAppenderName" class="com.cognos.xqe.trace.appender.XQEFileAppender"> <param name="myAppender.log" value="DesiredAppenderFileName"/> <param name="includeTimestamp" value="true"/> <param name="includeTimestampInFileName" value="true" /> </appender>
This will write log messages for the event group ROLAPCubes.Info to the file myAppender.log.