[rules-dev] Rule Engine Detailed Trace Mode

For those that don’t know, the new algorithm supports a detailed trace mode. Create a logback.xml and set the level to trace. <logger name="org.drools" level="trace"/> You’ll then get outputs like the following, which shows you what rules fired and when, and with what amounts of data for each node. It also shows you when rules are linked and unlinked. 2014-02-25 05:00:16,023 [main] DEBUG Starting Engine in PHREAK mode 2014-02-25 05:00:16,084 [main] TRACE Adding Rule R1 2014-02-25 05:00:16,088 [main] TRACE Adding Rule R2 2014-02-25 05:00:16,134 [main] TRACE Insert [fact 0:1:1708041420:1708041420:1:DEFAULT:NON_TRAIT:org.drools.compiler.integrationtests.Misc2Test$Foo@65cea4cc] 2014-02-25 05:00:16,142 [main] TRACE LinkNode notify=false nmask=1 smask=1 spos=0 rules= 2014-02-25 05:00:16,142 [main] TRACE LinkSegment smask=2 rmask=2 name=R2 2014-02-25 05:00:16,146 [main] TRACE LinkNode notify=true nmask=1 smask=1 spos=0 rules=[RuleMem R1], [RuleMem R2] 2014-02-25 05:00:16,147 [main] TRACE Insert [fact 0:2:281271144:281271144:2:DEFAULT:NON_TRAIT:org.drools.compiler.integrationtests.Misc2Test$Foo2@10c3db68] 2014-02-25 05:00:16,148 [main] TRACE BetaNode insert=1 stagedInsertWasEmpty=true 2014-02-25 05:00:16,148 [main] TRACE LinkNode notify=true nmask=2 smask=3 spos=0 rules=[RuleMem R1], [RuleMem R2] 2014-02-25 05:00:16,148 [main] TRACE LinkSegment smask=1 rmask=1 name=R1 2014-02-25 05:00:16,149 [main] TRACE LinkSegment smask=1 rmask=3 name=R2 2014-02-25 05:00:16,149 [main] TRACE LinkRule name=R2 2014-02-25 05:00:16,161 [main] TRACE Queue RuleAgendaItem [Activation rule=R2, act#=0, salience=0, tuple=null] 2014-02-25 05:00:16,161 [main] TRACE Queue Added 1 [Activation rule=R2, act#=0, salience=0, tuple=null] 2014-02-25 05:00:16,161 [main] TRACE Added R2 to eager evaluation list. 2014-02-25 05:00:16,162 [main] TRACE Rule[name=R2] segments=2 TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,162 [main] TRACE 1 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,163 [main] TRACE Segment 0 2014-02-25 05:00:16,163 [main] TRACE 1 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,167 [main] TRACE rightTuples TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,168 [main] TRACE Segment 1 2014-02-25 05:00:16,168 [main] TRACE 2 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,169 [main] TRACE Segment 1 2014-02-25 05:00:16,169 [main] TRACE 2 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,169 [main] TRACE rightTuples TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,171 [main] TRACE 3 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,171 [main] TRACE Segment 1 2014-02-25 05:00:16,171 [main] TRACE 3 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,172 [main] TRACE Fire "R2" [[ R2 active=false ] [ null [fact 0:2:281271144:281271144:2:DEFAULT:NON_TRAIT:org.drools.compiler.integrationtests.Misc2Test$Foo2@10c3db68] [fact 0:1:1708041420:1708041420:1:DEFAULT:NON_TRAIT:org.drools.compiler.integrationtests.Misc2Test$Foo@65cea4cc] ] ] 2014-02-25 05:00:16,177 [main] TRACE Update [fact 0:2:281271144:281271144:3:DEFAULT:NON_TRAIT:org.drools.compiler.integrationtests.Misc2Test$Foo2@10c3db68] 2014-02-25 05:00:16,178 [main] TRACE LinkSegment smask=1 rmask=1 name=R1 2014-02-25 05:00:16,178 [main] TRACE LinkSegment smask=1 rmask=3 name=R2 2014-02-25 05:00:16,178 [main] TRACE LinkRule name=R2 2014-02-25 05:00:16,178 [main] TRACE Added R2 to eager evaluation list. 2014-02-25 05:00:16,179 [main] TRACE Insert [fact 0:3:1226345699:-62068830:4:DEFAULT:LEGACY_TRAITABLE:[Person name='null age='0' likes='null']] 2014-02-25 05:00:16,179 [main] TRACE BetaNode insert=1 stagedInsertWasEmpty=true 2014-02-25 05:00:16,179 [main] TRACE LinkNode notify=true nmask=1 smask=1 spos=1 rules=[RuleMem R1] 2014-02-25 05:00:16,180 [main] TRACE LinkSegment smask=2 rmask=3 name=R1 2014-02-25 05:00:16,180 [main] TRACE LinkRule name=R1 2014-02-25 05:00:16,180 [main] TRACE Queue RuleAgendaItem [Activation rule=R1, act#=2, salience=0, tuple=null] 2014-02-25 05:00:16,180 [main] TRACE Queue Added 1 [Activation rule=R1, act#=2, salience=0, tuple=null] 2014-02-25 05:00:16,181 [main] TRACE LinkNode notify=true nmask=1 smask=1 spos=1 rules=[RuleMem R2] 2014-02-25 05:00:16,181 [main] TRACE LinkSegment smask=2 rmask=3 name=R2 2014-02-25 05:00:16,181 [main] TRACE LinkRule name=R2 2014-02-25 05:00:16,181 [main] TRACE Added R2 to eager evaluation list. 2014-02-25 05:00:16,181 [main] TRACE Rule[name=R2] segments=2 TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,182 [main] TRACE 4 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,182 [main] TRACE Segment 0 2014-02-25 05:00:16,182 [main] TRACE 4 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,183 [main] TRACE rightTuples TupleSets[insertSize=0, deleteSize=0, updateSize=1] 2014-02-25 05:00:16,183 [main] TRACE Segment 1 2014-02-25 05:00:16,183 [main] TRACE 5 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=0, deleteSize=0, updateSize=1] 2014-02-25 05:00:16,184 [main] TRACE Segment 1 2014-02-25 05:00:16,184 [main] TRACE 5 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=0, deleteSize=0, updateSize=1] 2014-02-25 05:00:16,184 [main] TRACE rightTuples TupleSets[insertSize=1, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,184 [main] TRACE UnlinkNode notify=true nmask=1 smask=0 spos=1 rules=[RuleMem R2] 2014-02-25 05:00:16,185 [main] TRACE UnlinkSegment smask=2 rmask=1 name=[RuleMem R2] 2014-02-25 05:00:16,185 [main] TRACE UnlinkRule name=R2 2014-02-25 05:00:16,185 [main] TRACE Added R2 to eager evaluation list. 2014-02-25 05:00:16,185 [main] TRACE 6 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=1, updateSize=0] 2014-02-25 05:00:16,186 [main] TRACE Segment 1 2014-02-25 05:00:16,186 [main] TRACE 6 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=1, updateSize=0] 2014-02-25 05:00:16,187 [main] TRACE Rule[name=R2] segments=2 TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,187 [main] TRACE 7 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,188 [main] TRACE Skip Segment 0 2014-02-25 05:00:16,188 [main] TRACE Segment 1 2014-02-25 05:00:16,188 [main] TRACE 7 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,188 [main] TRACE rightTuples TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,188 [main] TRACE 8 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,189 [main] TRACE Segment 1 2014-02-25 05:00:16,189 [main] TRACE 8 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,189 [main] TRACE Rule[name=R2] segments=2 TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,189 [main] TRACE 9 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,190 [main] TRACE Skip Segment 0 2014-02-25 05:00:16,190 [main] TRACE Segment 1 2014-02-25 05:00:16,190 [main] TRACE 9 [NotNode(9) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,191 [main] TRACE rightTuples TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,191 [main] TRACE 10 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,191 [main] TRACE Segment 1 2014-02-25 05:00:16,191 [main] TRACE 10 [RuleTerminalNode(10): rule=R2] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,192 [main] TRACE Rule[name=R1] segments=2 TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,192 [main] TRACE 11 [JoinNode(5) - [ClassObjectType class=org.drools.compiler.integrationtests.Misc2Test$Foo2]] TupleSets[insertSize=0, deleteSize=0, updateSize=0] 2014-02-25 05:00:16,192 [main] TRACE Skip Segment 0 2014-02-25 05:00:16,192 [main] TRACE Segment 1 2014-02-25 05:00:16,192 [main] TRACE 11 [JoinNode(7) - [ClassObjectType class=org.drools.compiler.Person]] TupleSets[insertSize=0, deleteSize=0, updateSize=1] 2014-02-25 05:00:16,193 [main] TRACE rightTuples TupleSets[insertSize=1, deleteSize=0, updateSize=0] java.lang.NullPointerException at org.drools.core.util.index.LeftTupleIndexHashTable.remove(LeftTupleIndexHashTable.java:386) at org.drools.core.phreak.RuleNetworkEvaluator.doUpdatesReorderLeftMemory(RuleNetworkEvaluator.java:799)