Skip to content

Commit 1b42c42

Browse files
committed
implemented performance logging
1 parent 9c113e6 commit 1b42c42

File tree

10 files changed

+158
-15
lines changed

10 files changed

+158
-15
lines changed

sliceworkz-eventmodeling-api/src/main/java/org/sliceworkz/eventmodeling/commands/AbstractCommand.java

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,10 @@
1919

2020
public sealed interface AbstractCommand<CONSUMED_EVENT_TYPE, PRODUCED_EVENT_TYPE> permits Command, OutboundCommand {
2121

22+
default String commandName ( ) {
23+
return this.getClass().getSimpleName();
24+
}
25+
2226
CommandResult<CONSUMED_EVENT_TYPE, PRODUCED_EVENT_TYPE> execute ( CommandContext<CONSUMED_EVENT_TYPE, PRODUCED_EVENT_TYPE> context );
2327

2428
}

sliceworkz-eventmodeling-api/src/main/java/org/sliceworkz/eventmodeling/commands/Command.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,5 +18,5 @@
1818
package org.sliceworkz.eventmodeling.commands;
1919

2020
public non-sealed interface Command<DOMAIN_EVENT_TYPE> extends AbstractCommand<DOMAIN_EVENT_TYPE,DOMAIN_EVENT_TYPE> {
21-
21+
2222
}

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/boundedcontext/BoundedContextBuilderImpl.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -265,7 +265,7 @@ public <T extends BoundedContext<DOMAIN_EVENT_TYPE, INBOUND_EVENT_TYPE, OUTBOUND
265265
AutomationModule<DOMAIN_EVENT_TYPE> am = new AutomationModule<>(name, domainEventStream, automations, instance);
266266

267267
ReadModelModule<DOMAIN_EVENT_TYPE> rmm = new ReadModelModule<DOMAIN_EVENT_TYPE>(name, domainEventStream, readAllInStoreEventStream, liveModelClasses, consistentReadModels, eventuallyConsistentSharedReadModels, eventuallyConsistentLocalReadModels, eventuallyConsistentEphemeralReadModels, instance, meterRegistry);
268-
DCBModule<DOMAIN_EVENT_TYPE, OUTBOUND_EVENT_TYPE> dcb = new DCBModule<DOMAIN_EVENT_TYPE, OUTBOUND_EVENT_TYPE>(name, rmm, domainEventStream, outboundEventStream, false, meterRegistry);
268+
DCBModule<DOMAIN_EVENT_TYPE, OUTBOUND_EVENT_TYPE> dcb = new DCBModule<DOMAIN_EVENT_TYPE, OUTBOUND_EVENT_TYPE>(name, instance, rmm, domainEventStream, outboundEventStream, false, meterRegistry);
269269

270270
BoundedContextImpl<DOMAIN_EVENT_TYPE, INBOUND_EVENT_TYPE, OUTBOUND_EVENT_TYPE> bc =
271271
new BoundedContextImpl<DOMAIN_EVENT_TYPE, INBOUND_EVENT_TYPE, OUTBOUND_EVENT_TYPE>(name, deployedFeatureSlices, undeployedFeatureSlices, domainEventStream, inboundEventStream, outboundEventStream, observabilityEventStream, dcb, rmm, am, im, om, instance, meterRegistry);

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/boundedcontext/BoundedContextImpl.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -81,7 +81,7 @@ public BoundedContextImpl ( String name, List<? extends FeatureSliceConfiguratio
8181
this.dcbDomainModule = dcbModule;
8282
this.automationModule = automationModule;
8383

84-
this.dcbKernelModule = new DCBModule<KernelEvent,KernelEvent>(name, null, kernelLoggingEventStream, kernelLoggingEventStream, true, meterRegistry);
84+
this.dcbKernelModule = new DCBModule<KernelEvent,KernelEvent>(name, instance, null, kernelLoggingEventStream, kernelLoggingEventStream, true, meterRegistry);
8585

8686
// pass reference to self
8787
this.readmodelModule.kernelFunctions(this);
Lines changed: 113 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,113 @@
1+
/*
2+
* Sliceworkz Event Modeling - an opinionated Event Modeling framework in Java
3+
* Copyright © 2025 Sliceworkz / XTi (info@sliceworkz.org)
4+
*
5+
* This program is free software: you can redistribute it and/or modify
6+
* it under the terms of the GNU Lesser General Public License as published by
7+
* the Free Software Foundation, either version 3 of the License, or
8+
* (at your option) any later version.
9+
*
10+
* This program is distributed in the hope that it will be useful,
11+
* but WITHOUT ANY WARRANTY; without even the implied warranty of
12+
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13+
* GNU Lesser General Public License for more details.
14+
*
15+
* You should have received a copy of the GNU Lesser General Public License
16+
* along with this program. If not, see <http://www.gnu.org/licenses/>.
17+
*/
18+
package org.sliceworkz.eventmodeling.module.boundedcontext;
19+
20+
import java.util.HashMap;
21+
import java.util.Map;
22+
23+
import org.slf4j.Logger;
24+
import org.slf4j.LoggerFactory;
25+
import org.sliceworkz.eventmodeling.events.Instance;
26+
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent.Metrics;
27+
28+
public class PerformanceLogger {
29+
30+
public static final Logger LOGGER = LoggerFactory.getLogger("PERFORMANCE");
31+
32+
private Map<String,String> keyValues = new HashMap<>();
33+
34+
public PerformanceLogger context ( String value ) {
35+
add("context", value);
36+
return this;
37+
}
38+
39+
public PerformanceLogger type ( String value ) {
40+
add("type", value);
41+
return this;
42+
}
43+
44+
public PerformanceLogger readmodel ( String value ) {
45+
add("readmodel", value);
46+
return this;
47+
}
48+
49+
public PerformanceLogger command ( String value ) {
50+
add("command", value);
51+
return this;
52+
}
53+
54+
public PerformanceLogger processor ( String value ) {
55+
add("processor", value);
56+
return this;
57+
}
58+
59+
public PerformanceLogger instance ( Instance instance ) {
60+
add("instance.logical", instance.logical());
61+
add("instance.physical", instance.physical());
62+
add("instance.process", instance.process());
63+
return this;
64+
}
65+
66+
public PerformanceLogger metrics ( Metrics metrics ) {
67+
add("duration", metrics.durationMs());
68+
add("queriesDone", metrics.queriesDone());
69+
add("eventsStreamed", metrics.eventStreamed());
70+
add("eventsHandled", metrics.eventsHandled());
71+
if ( metrics.until() != null ) {
72+
add("until.id", metrics.until().id().value());
73+
add("until.pos", metrics.until().position());
74+
}
75+
return this;
76+
}
77+
78+
public String log ( ) {
79+
return log(null);
80+
}
81+
82+
public String log ( String message ) {
83+
StringBuilder sb = new StringBuilder("log=performance "); // with space at the end to separate
84+
if ( message != null ) {
85+
sb.append(message);
86+
sb.append(" : ");
87+
}
88+
for ( var e: keyValues.entrySet() ) {
89+
sb.append(e.getKey());
90+
sb.append("=");
91+
sb.append(e.getValue());
92+
sb.append(" ");
93+
}
94+
String result = sb.toString();
95+
LOGGER.info(result);
96+
return result;
97+
}
98+
99+
public static PerformanceLogger entry ( ) {
100+
return new PerformanceLogger();
101+
}
102+
103+
private void add ( String key, String value ) {
104+
keyValues.put(key, value);
105+
}
106+
private void add ( String key, int value ) {
107+
keyValues.put(key, Integer.toString(value));
108+
}
109+
private void add ( String key, long value ) {
110+
keyValues.put(key, Long.toString(value));
111+
}
112+
113+
}

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/dcb/DCBModule.java

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
import org.sliceworkz.eventmodeling.commands.Command;
2727
import org.sliceworkz.eventmodeling.commands.CommandContext;
2828
import org.sliceworkz.eventmodeling.commands.OutboundCommand;
29+
import org.sliceworkz.eventmodeling.events.Instance;
2930
import org.sliceworkz.eventmodeling.events.Tracing;
3031
import org.sliceworkz.eventmodeling.module.boundedcontext.BoundedContextFunctions;
3132
import org.sliceworkz.eventmodeling.module.readmodels.ReadModelModule;
@@ -43,6 +44,8 @@ public class DCBModule<DOMAIN_EVENT_TYPE,OUTBOUND_EVENT_TYPE> implements Lifecyc
4344
private static final Logger LOGGER = LoggerFactory.getLogger(DCBModule.class);
4445

4546
private String boundedContext;
47+
private Instance instance;
48+
4649
private ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule;
4750
private EventStream<DOMAIN_EVENT_TYPE> domainEventStream;
4851
private EventStream<OUTBOUND_EVENT_TYPE> outboundEventStream;
@@ -53,8 +56,9 @@ public class DCBModule<DOMAIN_EVENT_TYPE,OUTBOUND_EVENT_TYPE> implements Lifecyc
5356
private Counter meterCommand;
5457
private Timer timerCommand;
5558

56-
public DCBModule ( String boundedContext, ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule, EventStream<DOMAIN_EVENT_TYPE> domainEventStream, EventStream<OUTBOUND_EVENT_TYPE> outboundEventStream, boolean kernelMode, MeterRegistry meterRegistry ) {
59+
public DCBModule ( String boundedContext, Instance instance, ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule, EventStream<DOMAIN_EVENT_TYPE> domainEventStream, EventStream<OUTBOUND_EVENT_TYPE> outboundEventStream, boolean kernelMode, MeterRegistry meterRegistry ) {
5760
this.boundedContext = boundedContext;
61+
this.instance = instance;
5862
this.readModelModule = readModelModule;
5963
this.domainEventStream = domainEventStream;
6064
this.outboundEventStream = outboundEventStream;
@@ -107,7 +111,7 @@ private <PRODUCED_EVENT_TYPE> Optional<EventReference> executeInternal ( Abstrac
107111
return timerCommand.record(()->{
108112

109113
@SuppressWarnings({ "unchecked", "rawtypes" })
110-
ExecuteCommandCommand<DOMAIN_EVENT_TYPE,OUTBOUND_EVENT_TYPE> cmd = new ExecuteCommandCommand(boundedContext, readModelModule, domainEventStream, targetEventStream, command);
114+
ExecuteCommandCommand<DOMAIN_EVENT_TYPE,OUTBOUND_EVENT_TYPE> cmd = new ExecuteCommandCommand(boundedContext, instance, readModelModule, domainEventStream, targetEventStream, command);
111115
kernelFunctions.executeKernelCommand(cmd, tracing);
112116

113117
// return the last application event reference rather than the observability event

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/dcb/ExecuteCommandCommand.java

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,8 +23,10 @@
2323
import org.sliceworkz.eventmodeling.commands.Command;
2424
import org.sliceworkz.eventmodeling.commands.CommandContext;
2525
import org.sliceworkz.eventmodeling.commands.CommandResult;
26+
import org.sliceworkz.eventmodeling.events.Instance;
2627
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent;
2728
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent.Metrics;
29+
import org.sliceworkz.eventmodeling.module.boundedcontext.PerformanceLogger;
2830
import org.sliceworkz.eventmodeling.module.readmodels.ReadModelModule;
2931
import org.sliceworkz.eventmodeling.readmodels.ReadModel;
3032
import org.sliceworkz.eventstore.events.Event;
@@ -36,6 +38,7 @@
3638
public class ExecuteCommandCommand<DOMAIN_EVENT_TYPE, PRODUCED_EVENT_TYPE> implements Command<KernelEvent> {
3739

3840
private String boundedContext;
41+
private Instance instance;
3942
private ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule;
4043
private AbstractCommand<DOMAIN_EVENT_TYPE,PRODUCED_EVENT_TYPE> command;
4144
private EventStream<DOMAIN_EVENT_TYPE> queryEventStream;
@@ -45,8 +48,9 @@ public class ExecuteCommandCommand<DOMAIN_EVENT_TYPE, PRODUCED_EVENT_TYPE> imple
4548

4649
private ReadModel<DOMAIN_EVENT_TYPE> readModel;
4750

48-
public ExecuteCommandCommand ( String boundedContext, ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule, EventStream<DOMAIN_EVENT_TYPE> queryEventStream, EventStream<PRODUCED_EVENT_TYPE> targetEventStream, AbstractCommand<DOMAIN_EVENT_TYPE,PRODUCED_EVENT_TYPE> command ) {
51+
public ExecuteCommandCommand ( String boundedContext, Instance instance, ReadModelModule<DOMAIN_EVENT_TYPE> readModelModule, EventStream<DOMAIN_EVENT_TYPE> queryEventStream, EventStream<PRODUCED_EVENT_TYPE> targetEventStream, AbstractCommand<DOMAIN_EVENT_TYPE,PRODUCED_EVENT_TYPE> command ) {
4952
this.boundedContext = boundedContext;
53+
this.instance = instance;
5054
this.readModelModule = readModelModule;
5155
this.queryEventStream = queryEventStream;
5256
this.targetEventStream = targetEventStream;
@@ -75,8 +79,10 @@ public CommandResult<KernelEvent,KernelEvent> execute(CommandContext<KernelEvent
7579

7680
long finish = System.currentTimeMillis();
7781
long duration = finish - start;
78-
ProjectorMetrics metrics = commandContext.projectorMetrics();
79-
return kernelCommandResult.raiseEvent(new KernelEvent.CommandExecuted(command.getClass(), new Metrics(duration, metrics.queriesDone(), metrics.eventsStreamed(), metrics.eventsHandled(), metrics.lastEventReference()), commandContext.projector().eventQuery()), Tags.none());
82+
ProjectorMetrics projectorMetrics = commandContext.projectorMetrics();
83+
Metrics metrics = new Metrics(duration, projectorMetrics.queriesDone(), projectorMetrics.eventsStreamed(), projectorMetrics.eventsHandled(), projectorMetrics.lastEventReference());
84+
PerformanceLogger.entry().context(boundedContext).instance(instance).metrics(metrics).type("command.execute").command(command.commandName()).log();
85+
return kernelCommandResult.raiseEvent(new KernelEvent.CommandExecuted(command.getClass(), new Metrics(duration, projectorMetrics.queriesDone(), projectorMetrics.eventsStreamed(), projectorMetrics.eventsHandled(), projectorMetrics.lastEventReference()), commandContext.projector().eventQuery()), Tags.none());
8086
}
8187

8288
public Optional<EventReference> getLastAppendedEventReference ( ) {

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/readmodels/ProjectLiveModelCommand.java

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -25,8 +25,10 @@
2525
import org.sliceworkz.eventmodeling.commands.Command;
2626
import org.sliceworkz.eventmodeling.commands.CommandContext;
2727
import org.sliceworkz.eventmodeling.commands.CommandResult;
28+
import org.sliceworkz.eventmodeling.events.Instance;
2829
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent;
2930
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent.Metrics;
31+
import org.sliceworkz.eventmodeling.module.boundedcontext.PerformanceLogger;
3032
import org.sliceworkz.eventmodeling.readmodels.ReadModel;
3133
import org.sliceworkz.eventmodeling.readmodels.ReadModelWithMetaData;
3234
import org.sliceworkz.eventstore.events.Tags;
@@ -41,10 +43,14 @@ class ProjectLiveModelCommand<DOMAIN_EVENT_TYPE> implements Command<KernelEvent>
4143
private Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass;
4244
private Object[] constructorParams;
4345
private EventSource<DOMAIN_EVENT_TYPE> eventSource;
46+
private String boundedContext;
47+
private Instance instance;
4448

4549
private ReadModelWithMetaData<DOMAIN_EVENT_TYPE> readModel;
4650

47-
public ProjectLiveModelCommand ( EventSource<DOMAIN_EVENT_TYPE> eventSource, Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass, Object... constructorParams ) {
51+
public ProjectLiveModelCommand ( String boundedContext, Instance instance, EventSource<DOMAIN_EVENT_TYPE> eventSource, Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass, Object... constructorParams ) {
52+
this.boundedContext = boundedContext;
53+
this.instance = instance;
4854
this.eventSource = eventSource;
4955
this.readModelClass = readModelClass;
5056
this.constructorParams = constructorParams;
@@ -65,7 +71,9 @@ public CommandResult<KernelEvent,KernelEvent> execute(CommandContext<KernelEvent
6571
ProjectorMetrics projectorMetrics = projector.run();
6672
long finish = System.currentTimeMillis();
6773
long duration = finish - start;
68-
return result.raiseEvent(new KernelEvent.LiveModelProjected(readModelClass, map(duration, projectorMetrics), projector.eventQuery()), Tags.none());
74+
Metrics metrics = map(duration, projectorMetrics);
75+
PerformanceLogger.entry().context(boundedContext).instance(instance).metrics(metrics).type("readmodel.live").readmodel(readModel.readmodelName()).log();
76+
return result.raiseEvent(new KernelEvent.LiveModelProjected(readModelClass, metrics, projector.eventQuery()), Tags.none());
6977
} catch (InstantiationException | IllegalAccessException | InvocationTargetException e) {
7078
LOGGER.error(e.getMessage(), e);
7179
throw new RuntimeException(e);

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/readmodels/ProjectLiveModelUnboundedCommand.java

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -22,8 +22,10 @@
2222
import org.sliceworkz.eventmodeling.commands.Command;
2323
import org.sliceworkz.eventmodeling.commands.CommandContext;
2424
import org.sliceworkz.eventmodeling.commands.CommandResult;
25+
import org.sliceworkz.eventmodeling.events.Instance;
2526
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent;
2627
import org.sliceworkz.eventmodeling.module.boundedcontext.KernelEvent.Metrics;
28+
import org.sliceworkz.eventmodeling.module.boundedcontext.PerformanceLogger;
2729
import org.sliceworkz.eventmodeling.readmodels.ReadModel;
2830
import org.sliceworkz.eventmodeling.readmodels.ReadModelWithMetaData;
2931
import org.sliceworkz.eventstore.events.Tags;
@@ -36,10 +38,14 @@ public class ProjectLiveModelUnboundedCommand <DOMAIN_EVENT_TYPE> implements Com
3638
private Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass;
3739
private Object[] constructorParams;
3840
private EventSource<DOMAIN_EVENT_TYPE> eventSource;
41+
private String boundedContext;
42+
private Instance instance;
3943

4044
private ReadModelWithMetaData<DOMAIN_EVENT_TYPE> readModel;
4145

42-
public ProjectLiveModelUnboundedCommand ( EventSource<DOMAIN_EVENT_TYPE> eventSource, Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass, Object... constructorParams ) {
46+
public ProjectLiveModelUnboundedCommand ( String boundedContext, Instance instance, EventSource<DOMAIN_EVENT_TYPE> eventSource, Class<? extends ReadModel<? extends DOMAIN_EVENT_TYPE>> readModelClass, Object... constructorParams ) {
47+
this.boundedContext = boundedContext;
48+
this.instance = instance;
4349
this.eventSource = eventSource;
4450
this.readModelClass = readModelClass;
4551
this.constructorParams = constructorParams;
@@ -57,10 +63,12 @@ public CommandResult<KernelEvent,KernelEvent> execute(CommandContext<KernelEvent
5763
try {
5864
readModel = (ReadModelWithMetaData<DOMAIN_EVENT_TYPE>) readModelClass.getDeclaredConstructors()[0].newInstance(constructorParams);
5965
Projector<DOMAIN_EVENT_TYPE> projector = Projector.from(eventSource).towards(readModel).build();
60-
ProjectorMetrics metrics = projector.run();
66+
ProjectorMetrics projectorMetrics = projector.run();
6167
long finish = System.currentTimeMillis();
6268
long duration = finish - start;
63-
return result.raiseEvent(new KernelEvent.LiveModelProjected(readModelClass, new Metrics(duration, metrics.queriesDone(), metrics.eventsStreamed(), metrics.eventsHandled(), metrics.lastEventReference()), projector.eventQuery()), Tags.none());
69+
Metrics metrics = new Metrics(duration, projectorMetrics.queriesDone(), projectorMetrics.eventsStreamed(), projectorMetrics.eventsHandled(), projectorMetrics.lastEventReference());
70+
PerformanceLogger.entry().context(boundedContext).instance(instance).metrics(metrics).type("readmodel.live").readmodel(readModel.readmodelName()).log();
71+
return result.raiseEvent(new KernelEvent.LiveModelProjected(readModelClass, metrics, projector.eventQuery()), Tags.none());
6472
} catch (InstantiationException | IllegalAccessException | InvocationTargetException e) {
6573
throw new RuntimeException(e);
6674
}

sliceworkz-eventmodeling-impl/src/main/java/org/sliceworkz/eventmodeling/module/readmodels/ReadModelModule.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -133,7 +133,7 @@ public <T> T liveModel ( Class<? extends ReadModelWithMetaData<? extends DOMAIN_
133133
meterLiveModel.increment();
134134

135135
return timerLiveModel.record(()->{
136-
ProjectLiveModelCommand cmd = new ProjectLiveModelCommand(domainEventStream, readModelClass, constructorParams);
136+
ProjectLiveModelCommand cmd = new ProjectLiveModelCommand(boundedContext, instance, domainEventStream, readModelClass, constructorParams);
137137
kernelFunctions.executeKernelCommand(cmd, tx);
138138
return (T) cmd.readModel();
139139
});
@@ -149,7 +149,7 @@ public <T> T liveModelUnbounded ( Class<? extends ReadModelWithMetaData<? extend
149149
meterLiveModel.increment();
150150

151151
return timerLiveModel.record(()->{
152-
ProjectLiveModelUnboundedCommand cmd = new ProjectLiveModelUnboundedCommand(allInStorageEventStream, readModelClass, constructorParams);
152+
ProjectLiveModelUnboundedCommand cmd = new ProjectLiveModelUnboundedCommand(boundedContext, instance, allInStorageEventStream, readModelClass, constructorParams);
153153
kernelFunctions.executeKernelCommand(cmd, tracing);
154154
return (T) cmd.readModel();
155155
});

0 commit comments

Comments
 (0)