Logging with BIRT (JDK or log4j)

Hi, 
 
I found some docs regarding logging with JDK and log4j in BIRT, but I somehow did not find some summarizing documentation about it and still did'nt get it to work as I need it to. 
Maybe this thread can summarize some issues about the logging for further reference as well. 
 
 
S) First I like to state my situation which may be very common amongst BIRT developers: 
My report with many queries and nested tables takes a very long time, but all I can see is this in the logs (using the cmdline BIRT API - genRep.sh ; the birt output starts after " - birt call: " ... this is due to a nested call ANT->Java->exec(...)): 
 
<pre class='_prettyXprint _lang-auto _linenums:0'>
[exec] 2010-09-03 13:10:19,092 WARN Streams:139 - birt call: Sep 3, 2010 1:10:18 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,093 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,094 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,094 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,094 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,095 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,095 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,096 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,096 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,097 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,097 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,097 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,098 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,098 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,099 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,099 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,100 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,100 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,100 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,101 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,101 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,102 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,102 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,102 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,103 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,103 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,104 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,104 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,105 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,105 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,105 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,106 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,106 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,107 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,107 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,108 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:19,108 WARN Streams:139 - birt call: Sep 3, 2010 1:10:19 PM org.eclipse.birt.report.data.adapter.impl.ModelAdapter adaptDataSet
[exec] 2010-09-03 13:10:19,108 WARN Streams:139 - birt call: WARNING: handle type: org.eclipse.birt.report.model.api.OdaDataSetHandle
[exec] 2010-09-03 13:10:21,811 WARN Streams:139 - birt call: Sep 3, 2010 1:10:21 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:21,812 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:10:22,017 WARN Streams:139 - birt call: Sep 3, 2010 1:10:21 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:22,017 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:10:22,017 WARN Streams:139 - birt call: Sep 3, 2010 1:10:21 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:22,017 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:10:22,120 WARN Streams:139 - birt call: Sep 3, 2010 1:10:22 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:22,120 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:10:22,120 WARN Streams:139 - birt call: Sep 3, 2010 1:10:22 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:22,120 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:10:41,723 WARN Streams:139 - birt call: Sep 3, 2010 1:10:41 PM org.eclipse.birt.report.engine.ir.DimensionType parserUnit
[exec] 2010-09-03 13:10:41,724 WARN Streams:139 - birt call: SEVERE: The value "auto" is invalid with the type "dimension".
[exec] 2010-09-03 13:11:47,239 WARN Streams:139 - birt call: Sep 3, 2010 1:11:47 PM org.eclipse.birt.chart.internal.datafeed.ResultSetWrapper initializeMeta
[exec] 2010-09-03 13:11:47,239 WARN Streams:139 - birt call: WARNING: Unable to determine data types from resultset
</pre>
 
Now I would like to know (from the logs) 
 
S.a ) which report items (e.g. names of tables) are processed and when => thus one could see how long a query runs 
 
S.b ) or even have a look at the SQL that is actually run against the database 
(e.g. I still don't know how BIRT internally works regarding the various query filters you can set: 1. on the SQL itself through scripting; 2. on the DataSet; 3. on the report items; ...) 
(or how it calculates row counts - extra query towards the database or retrieving and counting all dataset rows or ...?) 
 
 
K) These are known sources to me for configuring the logging, but it does not give me the big picture: 
 
 
K.1) Now here's something general about how to configure the JDK logging with "-Djava.util.logging.config.file=<logger.properties path>" and a sample logger.properties file: 
<a class='bbc_url' href='http://www.javapractices.com/topic/TopicAction.do?Id=143'>http://www.javapractices.com/topic/TopicAction.do?Id=143</a> 
- this did not help so much to produce more output (I could saw some uninteresting loglines, but that was it) 
- I guess a lot of the settings below are overwritten by BIRT (XMLOutputter or levels are basically ignored) 
 
<pre class='_prettyXprint _lang-auto _linenums:0'>
# Specify the handlers to create in the root logger
# (all loggers are children of the root logger)
# The following creates two handlers
handlers=java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# Set the default logging level for the root logger
.level=FINEST

# Set the default logging level for new ConsoleHandler instances
java.util.logging.ConsoleHandler.level=FINEST
#java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.ConsoleHandler.formatter=java.util.logging.XMLFormatter

# Set the default logging level for new FileHandler instances
java.util.logging.FileHandler.level=FINEST
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

# Set the default formatter for new ConsoleHandler instances

# Set the default logging level for the logger named com.mycompany
org.eclipse.birt.report.model.api.level = FINEST
</pre>
 
 
K.2) now looking at the content of the BIRT distribution I could find some .option files that looked a bit more promising, but I was not able to produce some result with my modifications here (basically setting the default "false" values to "true" or "FINEST": 
 
- e.g. looking at birt-runtime-2_5_2/ReportEngine/plugins/eclipse-birt-core_2.5.2....jar!/.options 
<pre class='_prettyXprint _lang-auto _linenums:0'>org.eclipse.birt.core/debug=true</pre>
 
- or e.g. modifying birt-runtime-2_5_2/ReportEngine/plugins/org.eclipse.report.data.oda.jdbc_2.5.2.../.options 
<pre class='_prettyXprint _lang-auto _linenums:0'>
org.eclipse.birt.report.data.oda.jdbc/debug = true
org.eclipse.birt.report.data.oda.jdbc/traceLogging/logLevel = FINEST
org.eclipse.birt.report.data.oda.jdbc/traceLogging/logFormatterClass = java.util.logging.SimpleFormatter
org.eclipse.birt.report.data.oda.jdbc/traceLogging/logFileNamePrefix = org.eclipse.birt.report.data.oda.jdbc-log
org.eclipse.birt.report.data.oda.jdbc/traceLogging/logDirectory = .
org.eclipse.birt.report.data.oda.jdbc/JDBCDriverManager=true
org.eclipse.birt.report.data.oda.jdbc/OdaJdbcDriver=true
org.eclipse.birt.report.data.oda.jdbc/Connection=true
org.eclipse.birt.report.data.oda.jdbc/Statement=true
</pre>
 
 
K.3) this is an interesting source if you are wondering why JDK logging (SimpleFormatter) uses two lines per log record, no class path ... and how to resolve it (it's only possible using this provided class or write an own pattern-based one): 
<a class='bbc_url' href='http://mytechrantings.blogspot.com/2007/04/pattern-formatter-for-javautillogging.html'>http://mytechrantings.blogspot.com/2007/04/pattern-formatter-for-javautillogging.html</a> 
 
 
K.4) Here is some hint how one could use log4j for logging by writing a JDK-logging handler for it: 
<a class='bbc_url' href='http://wiki.eclipse.org/BIRT/FAQ/Deployment#Q:_Can_I_use_Log4j_with_BIRT.3F'>http://wiki.eclipse.org/BIRT/FAQ/Deployment#Q:_Can_I_use_Log4j_with_BIRT.3F</a> 
 
- I did not try it out, but will it solve the problem I have? (I only use log4j for now and know it well, but would be glad if I e.g. just had to supply a logging.properties file (JDK logging)) 
 
 
Thanks for any help on the issues 
Andreas :-)

Find more posts tagged with

Comments

andreas2

There's a book I just bought and that's really helpful (not on the kind of logging I described above, but in general regarding BIRT):
http://www.lebirtexpert.com/

... My source problem was that my report ran slow although I tried to applied the table filters so that the (in my understanding) implicitly added " WHERE ..." clause should speed up everything. The book clearly points out that table filters are applied in memory only. (I guess since you can use any datasource in BIRT it cannot rely on the fact that the datasource "understands" the added " WHERE ..." string)

Anyways it would be helpful to have some feedback to the logging from above here.

johnw

<a class='bbc_url' href='http://birtworld.blogspot.com/2010/01/quick-and-dirty-logging.html'>http://birtworld.blogspot.com/2010/01/quick-and-dirty-logging.html</a> 
 
<a class='bbc_url' href='http://birtworld.blogspot.com/2009/03/raising-errors-in-event-handlers.html'>http://birtworld.blogspot.com/2009/03/raising-errors-in-event-handlers.html</a> 
 
Anything more than that is going to require either some scripting, where you set it up in the initialize event, or your going to have to set up the logging with the API. We have done similar things to monitor performance in the past, and it summarizes runs in each phase for each section of the report. 
 
John 
 
<blockquote class='ipsBlockquote' data-author="'andreas2'" data-cid="68156" data-time="1283842914" data-date="07 September 2010 - 12:01 AM">
There's a book I just bought and that's really helpful (not on the kind of logging I described above, but in general regarding BIRT): 
<a class='bbc_url' href='http://www.lebirtexpert.com/'>http://www.lebirtexpert.com/</a> 
 
... My source problem was that my report ran slow although I tried to applied the table filters so that the (in my understanding) implicitly added " WHERE ..." clause should speed up everything. The book clearly points out that table filters are applied in memory only. (I guess since you can use any datasource in BIRT it cannot rely on the fact that the datasource "understands" the added " WHERE ..." string) 
 
Anyways it would be helpful to have some feedback to the logging from above here. </blockquote>

andreas2

Hi John,

thanks for the links (I knew the first one already).

Anyways it would be sad if you can't just enable some logging (via some *.properties or *.xml file) and BIRT would already give you some good clues what it does. (It has all the GUI object names, SQLs, Datasource names, ... already)
I don't like to do so much manual work where everything could be done on the BIRT side. (Maybe I have to anyways)

But maybe the logging in the BIRT framework is not useful at all at its current state. (Maybe all I saw in my logs is actually what is beeing logged. And there may not be more coming from the BIRT side)

So if somebody can provide some feedback to the quality of the activatable BIRT log statements (via API or other) regarding my thoughts above - this would already be helpful. (More precise: Can you follow what BIRT is doing from a user perspective and can it give you a good clue what is going on when and how long does it take? (e.g. generating report items, printing your table names in the logs, SQL beeing executed, ...)

Kind regards
Andreas