Logging Execution Traces

Logging Execution Traces

A logging utility, based on the SLF4J Simple Logging Facade, for indenting logging output (on a per-thread basis) that is useful for viewing a coarse execution trace of a program coupled with high level profiling information. The intended usage is to create a static class that creates a LogX instance internally and that provides simple wrapper methods around this instance for outputting a particular type of trace.

As an example, if you are developing a suite of interconnected algorithms based on pseudo-code, it may be useful to add a PseudoCodeTrace class so that its easier to follow how the described algorithms are implemented. This could be implemented as follows:

...
public class PseudoCodeTrace {
    private static final LogX _defaultPseudoCodeTrace;
    static {
        _defaultPseudoCodeTrace= LogXFactory.getLogX(
                        getDefaultLoggerName(), PseudoCodeTrace.class.getName());
                
        _defaultPseudoCodeTrace.setIndentIndentationContent(true);
    }
    ...
    public static LogX getDefaultLogX() {
        return _defaultPseudoCodeTrace;
    }
    ... 
    public static String getDefaultLoggerName() {
        return PseudoCodeTrace.class.getName();
    }
    ... 
    public static void in(String msg, Object... args) {
        in(null, msg, args);
    }
    ...
    public static void in(Marker marker, String msg, Object... args) {
        getDefaultLogX().indent(marker, msg, args);
    }
    ...
    public static void out(String msg, Object... args) {
        out(null, msg, args);
    }
    ...
    public static void out(Marker marker, String msg, Object... args) {
        getDefaultLogX().outdent(marker, msg, args);
    }
    ...
    public static void log(String msg, Object... args) {
        log(null, msg, args);
    }
    ...
    public static void log(Marker marker, String msg, Object... args) {
        getDefaultLogX().trace(marker, msg, args);
    }
}

and use in an actual implementation in the following way:

...
public class AnAlgorithm {
    ... 
    public Object execute(Object arg1, Object arg2) {
        PseudoCodeTrace.in("+AnAlgorithm.execute({}, {})", arg1, arg2);

        PseudoCodeTrace.log("Step 1 - initialize variables");

        ...
        Object subRoutineResult = subRoutine(arg1);
        ...
        Object result = ...;
        
        PseudoCodeTrace.out("-AnAlgorithm.execute={}", result);
        return result;
    }
    ...
    public Object subRoutine(Object arg1) {
        PseudoCodeTrace.in("+AnAlgorithm.subRoutine({})", arg1);
 
        ...
        
        PseudoCodeTrace.out("-AnAlgorithm.subRoutine={}", result);

        return result;
    }
}

An example of actual LogX trace output:

|+lbp.R_DifferenceOfExtensionalAndIntensionalSet(( \({ a }, { ( on X ) X | X = a }), 0 )) - under context variables = [], constrained by true
|    { Alpha' | C' }_I' <- standardize { Alpha | C }_I apart from {a1,...,an}
|    condition <- R_formula_simplification(there exists I' : C' and a_i = Alpha')
|        +lbp.R_formula_simplification(there exists X : X = a and a = X) - under context variables = [], constrained by true
|                +lbp.R_simplify(there exists X : X = a and a = X) - under context variables = [], constrained by true
|                                    Rewriting whole expression:
|                                       ----> (Greater than,  0 ms, #1, 15 rewriter selections (246 since start))
|                                    true
|                    Rewriting whole expression:
|                       ----> (Quantifier elimination wrapper,  47 ms, #1, 32 rewriter selections (32 since start))
|                    true
|                -lbp.R_simplify=true[56ms.]
|        -lbp.R_formula_simplification=true[58ms.]
|    // condition=true, a_i=a
|    R_simplify(
|        if condition
|            then R_DifferenceOfExtensionalAndIntensionalSet({a_1,...,a_i-1,a_i+1,...,a_n}, { Alpha' | C' }_I', i)
|            else R_DifferenceOfExtensionalAndIntensionalSet({a_1,...,a_n}, { Alpha' | C' }_I', i+1))
|        +lbp.R_DifferenceOfExtensionalAndIntensionalSet(( \({ }, { ( on X ) X | X = a }), 0 )) - under context variables = [], constrained by true
|            if i > n
|                return {a1,...,an}
|        -lbp.R_DifferenceOfExtensionalAndIntensionalSet={ }[1ms.]
|        +lbp.R_simplify({ }) - under context variables = [], constrained by true
|        -lbp.R_simplify={ }[3ms.]
|-lbp.R_DifferenceOfExtensionalAndIntensionalSet={ }[90ms.]

To support output of this trace format a custom conversion specifier, which leverages the logback native implementation of the SLF4J API is provided. This can be included in a logback XML configuration file as follows:

...
<configuration>
    <conversionRule conversionWord="logxtracemsg" 
                  converterClass="com.sri.ai.util.log.LogXTraceConverter" />
    ...
    <appender name="logx.console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.sri.ai.grinder.helper.RewriterLoggingNamedRewriterFilter" />
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>|%logxtracemsg%n</Pattern>
        </encoder>
    </appender>
    ...