Event API for structured logging?

[holgerbrandl]

Hi,

I guess as everyone here, we sometimes increase the log level to see what's really happing during construction and search. However, the sheer volume of log data emitted by the engine is often not easy to process. Having multiple data scientists in our team, we could in theory parse the log to study why the solver does not yet perform as intended. We're thinking here about statistics and timelines from various perspectives and angles which are all in the log but not visible by eye/without aggregation.

However, as the log is quite dense and diverse I wonder if these events could also be exposed as structured log? So instead of

timefold-solver/core/core-impl/src/main/java/ai/timefold/solver/core/impl/localsearch/decider/LocalSearchDecider.java

Lines 126 to 129 in 4415f4d

	logger.trace("{} Move index ({}), score ({}), accepted ({}), move ({}).",
	logIndentation,
	moveScope.getMoveIndex(), moveScope.getScore(), moveScope.getAccepted(),
	moveScope.getMove());

it could do something like

data class MoveLogEvent(val index:Int, val score: Score, val accepted: Boolean, val move: Move)

sturcturedLogListerners.forEach{ 
  it.logMove(MoveLogEvent(moveScope.getMoveIndex(), moveScope.getScore(), moveScope.getAccepted(), moveScope.getMove()) 
}

with this structured logging in place, it would be very easy to collect these and write them into csv for analysis. And thus develop solvers with timefold faster and more efficiently.

How do you feel about such an idea? Are there alternatives to collect details move properties and timelines as currently displayed in the unstructured log?

Thanks & Kind regards.

[triceo]

Hello @holgerbrandl.

I see your point and I like the idea. It would also come some way towards solving another pain point, #399.

I think there's currently no reliable other way to get at this data from code. We'll have to think about this a bit more, consider any downsides and impacts on other parts of the codebase, but at the moment I think that this should be relatively easy to do.

[ge0ffrey]

the sheer volume of log data emitted by the engine is often not easy to process

Good point. I wonder if the move info alone is enough. Probably the event needs to have the working solution too:

1. If the working solution doesn't get cloned, this probably shouldn't be a public api. The working solution can't get changed and can't be send to another thread. But an non-official internal API would already a step forward.

2. If the working solution does get cloned, it's going to unusable slow.

And it probably needs step events too.

But what do you do with this data?
To add new custom moves?

I have a gut feeling that if we implement move streams (huge RFE), the needs for this will change.

[holgerbrandl]

I wonder if the move info alone is enough.

Indeed @ge0ffrey , the event from above was just an example. Currently, we separate the log into different event-streams, build parsers to ingest the various string representations (moves, planning entities, scores), and bring it all back together in R/python to better understand/visualize the solver-process. Having dedicated events would help to streamline this process significantly.

We have not thought about any technical implications, it's just an idea we wanted to share/discuss.

[holgerbrandl]

We use these data, in particular, to study why moves are not successful during the terminal search
expressed via UnimprovedSecondsSpentLimit. We want to understand what moves are explored in terms of planning value and entity distributions without improving the solution. That's because we have observed that sometimes we feel that there are seemingly obvious improvements for the final solution which are unexplored by the solver.

By improving this understanding, we hope to come up with better entity and value selector policies to guide search.

[ge0ffrey]

Interesting, thanks for sharing.

Proposal B)
Maybe we should consider micrometer to expose the selected moves?
Basically add it to this list:
https://timefold.ai/docs/timefold-solver/latest/configuration/configuration#_additional_metrics
Not sure if telemetry(micrometer) is the right tool for the job though to record change moves, etc as we probably want the values of each change move etc.

[ge0ffrey]

In my experience, adding a useful custom move can do a lot more than tweaking move selection. But writing custom moves is too much boilerplate, especially to write them well (JIT, etc), and a bit unpowered (no access to supply-demand system). We're aware of that and intend to improve that.

[terbrack]

Hi Geoffrey,
the described feature (structured logging of moves etc. and associated analysis) is very interesting.
Are there any updates on this?
Thanks and kind regards
Hajo

[triceo]

Hello @terbrack - there hasn't been any movement on this, and it is not on the short-term roadmap.