FarragoTracing

From Eigenpedia

Contents 1 Configuration 2 Trace Levels 3 JNI Handle Tracing 4 Trace Configuration Caching

Configuration

Tracing based on the standard java.util.logging facility is controlled by the file farrago/trace/FarragoTrace.properties, which is generated when the catalog is created. You can make modifications to this file; they won't be overwritten during regeneration. However, comments cannot be preserved during regeneration, so don't bother. Normally, trace output is written to farrago/trace/FarragoTrace.log.

Here is an example of the default FarragoTrace.properties generated for a developer build:

         #Developer tracing configuration (do not add comments)
         #Sat Dec 10 00:28:54 PST 2005
         .level=CONFIG
         handlers=java.util.logging.FileHandler
         java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter
         java.util.logging.FileHandler.pattern=/home/jvs/open/farrago/trace/FarragoTrace.log
         net.sf.farrago.jdbc.level=FINER
         java.util.logging.FileHandler.append=true

NOTE: it is very easy to forget to append the ".level" part of the specification when enabling a new trace. If something isn't tracing and you think it should be, this is the first thing to check.

The timestamp of the trace configuration file is checked once per second; whenever it changes, the new configuration is applied automatically (and dumped to FarragoTrace.log), so there's no need to restart the JVM. This can be very useful in the middle of a debugging session. (TODO: make this behavior configurable, since that's not always desirable for all usages.)

When Fennel is run inside of Farrago, Fennel trace output is automatically intercepted and appended to Farrago's trace log, so all tracing from Java and native code is unified.

---

Trace Levels

Most Farrago classes use the standard logger naming scheme (logger name matches fully-qualified class name). However, Fennel doesn't use the java.util.logging API directly, so it has a custom logger naming scheme. You never need to include the class name unless you require fine-grained discrimination.

Some common trace settings you might need:

• add net.sf.farrago.jdbc.level=FINER to trace exceptions which are returned via the JDBC driver (this is very useful since it traces underlying exceptions as well; these may not be visible in a front end such as sqlline); this is added automatically for developer builds
• add net.sf.farrago.db.level=FINE to see all SQL statements as they are prepared and executed (use FINER to see dynamic parameter values as well)
• add net.sf.farrago.query.streamgraph.level=FINE to trace Fennel execution stream graphs
• add net.sf.farrago.fennel.level=FINE to trace just the commands sent to the Fennel API (not their implementation)
• add net.sf.fennel.xo.level=FINER to trace tuples produced by execution streams and enable ExecStreamGraphVisualization
• add org.eigenbase.relopt.level=FINE to trace query optimization
• add net.sf.farrago.query.plandump.level=FINE to dump optimizer plans for all statements prepared
• add net.sf.farrago.dynamic.level=FINE to cause generated Java source files to be saved in the file system for debugging (as described in FarragoCodeGenDebugging)

The table below lists all known tracers except for ones which have been added recently. The table isn't in any particular order. For Java code, these tracers are declared in classes FarragoTrace and EigenbaseTrace.

Functional Area	Name	Description	Levels
JDBC Driver	net.sf.farrago.jdbc.engine.FarragoJdbcEngineDriver	Traces JDBC driver errors.	FINER enables trace of JDBC errors.
	net.sf.farrago.runtime.FarragoIteratorResultSet	Traces JDBC result sets	FINE enables trace of cursor open/fetch/close.
Database	net.sf.farrago.db.FarragoDatabase	Traces database events.	CONFIG traces database configuration parameters; INFO traces database open/close and session connect/disconnect; FINE traces miscellaneous state changes.
Session	net.sf.farrago.db.FarragoDbSession	Traces session events.	INFO traces transaction begin/end and SQL statement preparation.
	net.sf.farrago.db.FarragoDbStmtContext	Traces statement execution.	FINE traces statement execution and update counts; FINER includes dynamic parameter values for each execution.
	org.eigenbase.sql.timing	Traces timing of various stages of query processing.	FINE emits a high-resolution timer record for each stage.
Catalog	net.sf.farrago.catalog.FarragoRepos	Traces catalog and repository events.	INFO traces catalog open/close; FINE traces repository transaction begin/end.
	net.sf.farrago.mdr	Traces Farrago's use of MDR.	EXCEPTION traces errors; WARNING traces warnings; INFO traces messages intended for users; FINE traces what MDR calls informational messages; and FINER traces anything else.
Optimizer	org.eigenbase.relopt.RelOptPlanner	Traces the query optimization process.	FINE prints rules as they fire; FINER prints and validates the whole expression pool and rule queue as each rule fires; FINEST prints finer details like rule importance. See also HepTracing.
	net.sf.farrago.query.rule	Traces rules which have enough complexity to require tracing.	FINER traces rule details.
	net.sf.farrago.query.plandump	Dumps plans generated by sql2rel conversion and the optimizer.	FINE dumps plan before UDT flattening, after UDT flattening, and after optimization.
	net.sf.farrago.plannerviz	Controls JGraph visualization of planner activity; see FarragoPlannerVisualization for details.	FINE renders only logical equivalence classes; FINER renders only physical equivalence classes; FINEST renders both.
Java codegen	org.eigenbase.oj.stmt.OJPreparingStmt	Dumps Java classes generated to implement SQL expressions.	FINE enables dump.
	org.eigenbase.oj.util.OJClassMap	Reports when synthetic classes are generated to represent SQL types.	FINE enables trace.
	org.eigenbase.oj.rel.JavaRelImplementor	Reports when the outputs of relational expressions are bound to Java variables.	FINE enables trace.
	net.sf.farrago.dynamic	See FarragoCodeGenDebugging	FINE results in preservation of generated sources.
Calc codegen	net.sf.farrago.fennel.calc.CalcProgramBuilder	Dumps calc programs once they are constructed.	FINE enables dump.
Java executor	org.eigenbase.runtime.CompoundIterator, CompoundParallelIterator	Traces Java UNION implementation	FINE traces transitions to the next iterator; FINER traces every element
DDL	org.eigenbase.jmi.JmiChangeSet	Traces repository update processing.	FINE enables trace.
	net.sf.farrago.ddl.DdlValidator	Traces generic DDL processing.	FINE enables trace.
Parser	org.eigenbase.sql.parser	Traces parse events.	FINE enables trace.
Fennel JNI Layer (Java half)	net.sf.farrago.fennel.FennelDbHandle	Traces commands sent to Fennel.	FINE traces commands rendered as XMI.
	net.sf.farrago.fennel.FennelStreamGraph	Traces stream graph calls.	FINE traces open/close/abort/deallocate; FINER traces fetch.
	net.sf.farrago.query.streamgraph	Traces ExecStreamGraph definitions.	FINE traces graphs as they are prepared.
	net.sf.farrago.runtime.FennelPipeIterator	Traces class FennelPipeIterator	FINE enables trace.
	net.sf.farrago.runtime.JavaPushTupleStream	Traces class JavaPushTupleStream	FINE enables trace.
Fennel native code	net.sf.fennel.xo.[streamname]	Traces Fennel execution streams	FINE traces result of each scheduled stream execution; FINER traces buffer states before and after, including tuple contents after; FINEST traces buffer contents before execution as well.
	net.sf.fennel.xo.scheduler	Traces Fennel execution stream scheduler	FINE traces start/stop/abort/enter/leave, and enables ExecStreamGraphVisualization
	net.sf.fennel.xo.resourceGovernor	Traces Fennel execution stream resource governor	FINE traces resource setting changes and allocation requests and returns at the stream graph level; FINER traces allocation assignments to each individual stream in the graph.
	net.sf.fennel.segment	Traces storage access.	FINE traces segment open/close and page allocation/deallocation; FINER traces page updates; FINEST traces page map/unmap (this is very verbose!)
	net.sf.fennel.Database	Traces database events.	INFO traces open/close/recovery.
	net.sf.fennel.calc	Traces calculator execution.	FINE traces programs when they are assembled; FINER traces instruction execution.
	net.sf.fennel.[testname]	Traces specific tests.	Depends on test.
Test	net.sf.farrago.test.FarragoTestCase	Traces test events.	INFO traces test begin/end; FINE traces memory usage also.
Utilities	org.eigenbase.util.property.Property	Traces property lookup infrastructure.	WARNING traces warnings about property settings.
	net.sf.farrago.util.FarragoFileAllocation	Traces auto-deletion of files from Java.	WARNING traces warnings if files cannot be deleted.
	net.sf.farrago.util.FarragoFileLockAllocation	Traces files locked from Java.	FINE enables trace of lock/unlock.
	net.sf.farrago.util.FarragoObjectCache	Traces object definitions cached in Java.	FINE enables trace of object cache pin/unpin.

To add a new Java tracer, edit the tracer class corresponding to your component (e.g. net.sf.farrago.trace.FarragoTrace), add and document a new member variable there, and refer to it from the class into which you are inserting trace calls. Also, remember to update the table above!

For a good example of an existing class which uses tracing, see the source code for net.sf.farrago.db.FarragoDbSession.

TODO: use annotations to generate the above table automatically from Tracer classes.

---

JNI Handle Tracing

There is a special facility for tracing JNI handle usage; see FennelJniHandleTracing.

---

Trace Configuration Caching

Some components (especially inside Fennel) cache trace settings for performance. Cached trace settings are typically associated with an object lifetime. For example, when an ExecStreamGraph is first prepared, extra tracers are instrumented into the graph if the corresponding trace setting is set. These continue to trace for the lifetime of the graph. Conversely, if the graph was prepared when trace was off, no extra tracers are created, and the graph's execution will never be traced even if the trace settings change in the middle. This is intentional, but when combined with object caching, it can make debugging mysterious. If you want to be absolutely sure of getting something traced, start a new VM after changing trace settings.