Expensive formatting calls in two Debug Logs

[raidancampbell]

calls to the Gorep helper function are expensive (as noted in its comment). While profiling some performance tests, I found two culprits which called it very often, accounting for roughly 9 seconds of CPU time in a 120 second profile. These numbers will vary quite a bit based on the rules that are executed.

Would you consider the following two debug lines eligible for change or deletion?

• logging all the bindings in RunJavascript accounted for 7 seconds
• logging the output of RunJavascript accounted for an additional 2 seconds

The problem isn't in the logging, unfortunately it's in the call to Gorep that's passed to the logger. So omitting the call to Gorep would make it cheaper. Internally I simply deleted the log lines as we don't consume debug-level messages.

[jsccast]

I'll not give in to the urge to lament the lack of Go macros for these situations.

Is there a clever, effective optimization for Gorep? (It got its own function out of optimism for such a possibility.) Alternately -- and perhaps preferably -- perhaps Log needs a better implementation. Something that defers more computation until after the "should I log anything" check? Alternatively, maybe doing an explicit conditional ("Are we debugging?") before the Log call in these sensitive locations?

[raidancampbell]

What's the desired functionality of Gorep? The current implementation is "if it's a string, use the string. otherwise print the fully type-annotated representation". It's used exclusively in logging, so I'm tempted to believe that changes away from "print the fully type-annotated representation" are okay.

I can see a few options here:

• wrap any log statement using Gorep with a log level check. Ugly and lazy, but a viable fallback
• drop the type data, e.g. %#v -> %+v. I have no idea what the performance impact of this is and will need to do some benchmarks. EDIT: no noticeable performance improvement in benchmark testing here between %#v, %+v, and %v.
• add a check to see if the interface given to Gorep implements the fmt.Stringer interface, and potentially use that. I'll also need to do some digging to see what the interface{} types are under the hood at runtime, I don't have any intuition for what the binding types actually are. EDIT: from a test run, Gorep receives either string or map[string]interface{}. So stringers unfortunately won't help here.

After going back and testing some stuff as noted in the "EDIT" sections, I think the most feasible option is to wrap the log call in the "Are we debugging?" conditional.

[jsccast]

What's the desired functionality of Gorep?

Historically it was used to do logging in a way that could be processed (by Rulio!) relatively easily while being flexible and robust. At least that was its aspiration -- at great cost. That said, I don't know of any real dependency today on the structure of the log messages.

The "Are we debugging" conditional sounds like an expedient solution. Maybe overhaul logging itself later?

[raidancampbell]

The "Are we debugging" conditional sounds like an expedient solution. Maybe overhaul logging itself later?

Agreed. I'll have a tiny PR within a couple hours.