Add progress logging for CompositeStage and SimplePipeline
Description
Environment
Activity
Done, commit 00cddc22fc7a1904935c98892f5b4357bb879ac8.
SimplePipeline is an empty subclass of CompositeStage, now, so there’s no work required there; everything is in CompositeStage.
As well as a per-instance property enabling this behaviour, the class enables it for all instances if the system property net.shibboleth.metadata.loggingAllProgress is set to true.
Scott suggested another route to controlling this more global enabling would be to include something like this in the parent bean:
p:logProgress="${mda.logAllProgress:false}"I think this ends up addressing slightly different use cases, and also depends on people using the (new in this release) standard bean definition resource. There’s also the issue of whether placeholders get replaced correctly in all environments (the above would not, for example, work correctly in the IdP environment, where the placeholders need to be %{...} instead of ${...}. All considered, I’m going to leave that in the back of my mind as a possible future addition if it looks like it’s needed later.
This is what I’ve tried; needs to be converted to a property:
for (final Stage<T> stage : getStages()) {
if (log.isInfoEnabled()) {
final var stageStart = Instant.now();
log.info("{} >>> {}, count={}", getId(), stage.getId(), items.size());
stage.execute(items);
final var stageEnd = Instant.now();
final var stageTime = Duration.between(stageStart, stageEnd);
log.info("{} <<< {}, count={}, duration={}", getId(), stage.getId(),
items.size(), stageTime);
} else {
stage.execute(items);
}
}
When performing performance analysis of MDA deployments, what you really want is “how much time is spent in operation X” so that you can decide, for example, to reimplement some costly XSLT operation in Java.
The existing
ComponentInfosystem is worthless for this use case, so I’m going to remove it in 0.10, see MDA-281: Remove ComponentInfo systemClosed. I’d like to add useful functionality while doing that, though, in the form of new progress logging when a sequence of stages is executed.I have an initial implementation of this which is controlled by the log level set on
CompositeStageandSimplePipelinewhich logs time spent in each stage at INFO level. This seems too broad, though, so it’s probably better to use a boolean property on the individual components so that you can get more targeted logging restricted to specific instances.Some variant of this should be added for 0.10.0.