Clojurians Log v2

Hi. Im evaluating potentially using Clara for one of our use cases. Can you imagine a sensible way to be able to determine the start-time and end-time of a given rule execution? Say I have a rule that has some expensive operation… I’d like to be able to record when it started and ended, ideally without adding the required code to the rule itself and adding the values to the emitted fact (as it would be great if all rules exposed this information implicitly). I’ve started looked into: • The inspect + trace tools dont seem to provide it • Creating a new Listener, but this may be a bad idea given it would no longer be immutable if its calling out for the current time? • Creating a macro and extend the parsing logic to wrap the rule execution somehow Any thoughts / suggestions appreciated. Many thanks

@mbragg I don’t think it’s as straightforward as perhaps it seems. Rules aren’t the same as something like a fn body that you can time

The rules are structures that are used to create a rete based data flow tree (forest really)

Some examples of the complexity: (1) In some cases LHS conditions from separate rules may end up being shared as one common node in this tree. (2) rule conditions are nodes on the tree. They have varying degrees of eager vs lazy behavior. In most cases, the engine tries to batch facts up prior to evaluation of conditions

(3) before fire-rules happens a certain degree of evaluation takes place. Once fire-rules happens more work is done but always oriented towards batched fact propagation.

The inspection/trace stuff can be useful to get a sense of how many times a condition is being evaluated/matched. This tends to just give a relative “count” to compare and often find the outliers.

But overall. The rules are more like “sql query structures” where they are then compiled to a network, like the “db eval plan”

So the concerns tend to be things like how many times is this “join condition” being evaluated given some facts.

With profiling you can find actually hot spot functions which sometimes end up being a fn used in a condition that is being evaluated a large number of times:

[MyFact (my-fn ...)]

Thanks @mikerod for the explanation, makes sense. I guess I was specifically meaning everything in the RHS do block for a given rule. But I can see it may not be that straight forward... especially if there’s batching involved.

@mbragg the RHS is easier to time at least

I mean you can wrap that fairly easily - but still the time it takes to do the insert! sort of functions is where the batching happens

so you if you’re RHS is:

(insert! (->Something ?x))

that same RHS may end up being activated N times - so it evaluates N times, and you have N insert! calls all batched, so no fact is actually inserted right away until a later cycle

the batching is very useful from a perf standpoint too - but does complicate timing things

@mikerod ok understood. It think I’m going to suggest that this “rule timing” requirement is something we drop if we go with Clara, as it sounds like it doesn’t really make sense... in the way they are imagining rules being executed anyway. Thanks for all your help

In a defrule RHS, when making a record to insert, is there a way to access the rule name (the symbol associated with the rule that is firing) to store as a field in the inserted fact?

@matthew.pettis I suppose you want this instead of being repetitive?

(defrule my-rule
=>
(insert! (->MyFact `my-rule))

Yeah, right now I'm copying the name as the rule as a string in the creation of MyFact , so if there is a way to resolve the name of the rule in which the insert is operating that's what I'm looking for (so, as you said, I'm not repetitive in the sense of mis-copypasting the rule name into the string...)

Thinking of something like this, so I can use the same insert statement and not have to copy in the rulename somehow...

@matthew.pettis have to look to think if anything is directly available

however, you can always opt to make your own macro

defrule itself is just a macro and rules and queries in Clara are all modeled in a data-oriented data structure underneath that alternative DSL’s can be written to produce (via macros typically)

OK. A macro implementation might be in line for me too.

or you can have a macro that expands to defrule for your case

I think I may follow the custom macro expansion to defrule, thanks. Was just wondering if it was a common need and something was built in that I was missing...

an old (and probably no longer able to run examples) post, that did give a good overview of alterantive DSL’s http://www.toomuchcode.org/blog/2015/11/14/insta-declarative-dsls/ just for reference if that concept is something you find further interest in - you don’t really need it for this small case

I don’t see anything built-in as of now

I have came across a similar use-case in the past. I think I just repeated the name basically - I believe I used keywordized version instead though

but can be error-prone indeed

I’ve also done alternative DSLs that compile to underlying rule structures though in some cases where there was more to it

I like the macro wrapper for the cases where I want to insert a fact tracking what rule was fired. And, yeah, in my use case, I was thinking of using rule firing to track all of the rules that were fired on a given fact. This is like using rules as a way to track all of the ways a fact can violate rules without making a big conditional statement that checks all conditions and logs that observation.

Yeah that makes sense

In case a concrete demonstration helps for clarity, the rule RHS calls like insert! add things to a cache that will be processed later (the details of that probably aren’t super important here), the default implementation of which is in this file: https://github.com/cerner/clara-rules/blob/master/src/main/clojure/clara/rules/update_cache/core.cljc It’s certainly possible to have a poorly-performing function called in a rule, for which profiling with something like VisualVM can be useful, but a simple timer isn’t necessarily much help with diagnosing poorly performing rules networks as Mike has elaborated on.