Current SQL runtime tracking mechanism

InfoSphere® Master Data Management Collaboration Server - Collaborative Edition provides an option through the log4j mechanism to track its generated SQLs and runtime in separate log files. There are two distinct configuration settings which influence the logging behaviour.

  • Logging level in the $TOP/etc/default/log4j2.xml directory.
    The priority value for appender DB defines at what detail level executed SQLs and their run-times get tracked in db.log files in each InfoSphere Master Data Management Collaboration Server - Collaborative Edition services log directory.
    • use debug mode, to track all SQLs
    • use lower logging levels like information or warning, to track "delayed queries" only
    Excerpt from $TOP/etc/default/log4j2.xml:
    <category name="com.ibm.ccd.common.db" additivity="false">
<priority value="debug" />
<appender-ref ref="DB" />
</category>
Replace above content with- 

<Logger name="com.ibm.ccd.common.db" level="debug" additivity="false">
<AppenderRef ref="DB" />
</Logger>
    This setting can be changed at any time and will be picked up by InfoSphere Master Data Management Collaboration Server - Collaborative Edition without having to restart.
    Note: Setting the DB appender priority value to debug might impact the overall performance due to overhead of logging but should be less than 5%.
    The common.properties parameter profiling_query_delay_threshold.

    It defines a runtime threshold, at which queries are marked as "delayed queries".

    profiling_query_delay_threshold= <milliseconds>
    Only SQLs with run-times larger than the defined threshold, will be marked and tracked as delayed queries.

Two different types of queries can be distinguished within the db.log files.
Static queries
This type of query are identified by the keyword Static Query along with a name and therefore can be uniquely distinguished, for example: Static Query [name: GET_DOC_STORE_REAL_FILES_WITH_ATTRIBUTE]
Dynamic queries
This type of query are built dynamically and the number of arguments and parameter list will vary. They are identified by the keyword Dynamic Query, but can be distinguished only by the SQL body itself. Nevertheless, some rough grouping of Dynamic queries is possible by using the first n characters as differentiators. This mechanism is used in Sumall utility ($JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall)when using the leng option.
The following sample db.log file output illustrates this. It shows:
  • one Static query GEN_SEC_CMP_COMPANY_GETBYID with a runtime of 1 millisecond
  • one Dynamic query with a runtime of 1146 milliseconds.
2011-04-06 08:15:03,916 [Thread-36] DEBUG com.ibm.ccd.common.db.Query - Time: (1 ms)
Static Query [name: GEN_SEC_CMP_COMPANY_GETBYID]
[id: 934]
SELECT *
FROM tsec_cmp_company
WHERE cmp_company_id = 1

2011-04-06 08:49:10,818 [jsp_82: invoker.jsp] DEBUG com.ibm.ccd.common.db.Query - Time: (1146 ms)
Dynamic Query [
SELECT itm_id,
        itm_primary_key,
        itm_version_id,
        itm_next_version_id,
        itm_status,
        itm_collab_info
   FROM tctg_itm_item
  WHERE (itm_id in (2818133))
    AND itm_version_id <= 999999999
    AND itm_next_version_id >= 999999999
    AND itm_container_id = 12002
    AND itm_company_id = 60001]

2011-04-06 08:49:10,818 [jsp_82: invoker.jsp] WARN  com.ibm.ccd.common.db.Query - CWPCM0018W:The query is delayed: ( 1,146 ms)\n Dynamic Query [
SELECT itm_id,
        itm_primary_key,
        itm_version_id,
        itm_next_version_id,
        itm_status,
        itm_collab_info
   FROM tctg_itm_item
  WHERE (itm_id in (2818133))
    AND itm_version_id <= 999999999
    AND itm_next_version_id >= 999999999
    AND itm_container_id = 12002
    AND itm_company_id = 60001]
Attention:
  • When using debug mode for appender DB, consider to set profiling_query_delay_threshold to a very high value to avoid duplicate logging of slow queries.
  • profiling_query_delay_threshold is an ambiguous setting. It will be applied for all queries, but while 50 milliseconds can be already quite slow for a highly utilized simple query, it would flag complex query as slow, for which it is normal to run for seconds.
  • Run times tracked in the db.log files do not represent the time needed by the database itself to complete the SQL, but instead measures the time-span between when the query was issued within InfoSphere Master Data Management Collaboration Server - Collaborative Edition code and InfoSphere Master Data Management Collaboration Server - Collaborative Edition was able to pick up the result.

    Therefore, under specific situations where InfoSphere Master Data Management Collaboration Server - Collaborative Edition services can not pick up returned SQL results fast enough (for example, JVM thread hangs, delayed network traffic between InfoSphere Master Data Management Collaboration Server - Collaborative Edition service and DB server), the reported run times might be much higher than the actual runtime on database.

When looking at logged runtimes, keep the following guidelines in mind:
  • single and few slow queries might not be significant, rely more on a statistical approach (Sumall utility ($JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall)
  • keep an eye out for variations of the run-time over time for a single query (Sumall utility ($JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall)
  • when in doubt, run some of the identified slow running queries outside InfoSphere Master Data Management Collaboration Server - Collaborative Edition jdbc connection, for example, run it by using the DB2® command line processor respectively sqlplus and perform the test on both servers, where InfoSphere Master Data Management Collaboration Server - Collaborative Edition is installed and directly on the database server.