Skip to content

Commit d47df8e

Browse files
lassewesthlassewesth
committed
add (correlated) logging around algorithm processing
1 parent 0535577 commit d47df8e

File tree

5 files changed

+215
-28
lines changed

5 files changed

+215
-28
lines changed

‎applications/algorithms/machinery/src/main/java/org/neo4j/gds/applications/algorithms/machinery/DefaultAlgorithmProcessingTemplate.java‎

Lines changed: 32 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -36,16 +36,20 @@
3636
import java.util.function.Supplier;
3737
import java.util.stream.Stream;
3838

39+
@SuppressWarnings("ClassCanBeRecord")
3940
public class DefaultAlgorithmProcessingTemplate implements AlgorithmProcessingTemplate {
41+
private final Log log;
4042
private final GraphStoreCatalogService graphStoreCatalogService;
4143
private final RequestScopedDependencies requestScopedDependencies;
4244
private final ComputationService computationService;
4345

4446
DefaultAlgorithmProcessingTemplate(
47+
Log log,
4548
GraphStoreCatalogService graphStoreCatalogService,
4649
RequestScopedDependencies requestScopedDependencies,
4750
ComputationService computationService
4851
) {
52+
this.log = log;
4953
this.graphStoreCatalogService = graphStoreCatalogService;
5054
this.requestScopedDependencies = requestScopedDependencies;
5155
this.computationService = computationService;
@@ -68,6 +72,7 @@ public static DefaultAlgorithmProcessingTemplate create(
6872
);
6973

7074
return new DefaultAlgorithmProcessingTemplate(
75+
log,
7176
graphStoreCatalogService,
7277
requestScopedDependencies,
7378
algorithmComputer
@@ -220,31 +225,37 @@ public <CONFIGURATION extends AlgoBaseConfig, RESULT_TO_CALLER, RESULT_FROM_ALGO
220225
Optional<SideEffect<RESULT_FROM_ALGORITHM, SIDE_EFFECT_METADATA>> sideEffect,
221226
ResultRenderer<RESULT_FROM_ALGORITHM, RESULT_TO_CALLER, SIDE_EFFECT_METADATA> resultRenderer
222227
) {
223-
// as we progress through the steps we gather timings
224-
var timingsBuilder = new AlgorithmProcessingTimingsBuilder();
228+
try (RequestScopedLog log = RequestScopedLog.create(this.log, configuration.jobId())) {
229+
// as we progress through the steps we gather timings
230+
var timingsBuilder = new AlgorithmProcessingTimingsBuilder();
225231

226-
var graphResources = loadAndValidateGraph(
227-
timingsBuilder,
228-
relationshipWeightOverride,
229-
graphName,
230-
configuration,
231-
postGraphStoreLoadValidationHooks,
232-
postGraphStoreLoadETLHooks
233-
);
232+
log.onLoadingGraph();
233+
var graphResources = loadAndValidateGraph(
234+
timingsBuilder,
235+
relationshipWeightOverride,
236+
graphName,
237+
configuration,
238+
postGraphStoreLoadValidationHooks,
239+
postGraphStoreLoadETLHooks
240+
);
234241

235-
var result = runComputation(
236-
configuration,
237-
graphResources,
238-
label,
239-
estimationSupplier,
240-
computation,
241-
timingsBuilder,
242-
dimensionTransformer
243-
);
242+
log.onComputing();
243+
var result = runComputation(
244+
configuration,
245+
graphResources,
246+
label,
247+
estimationSupplier,
248+
computation,
249+
timingsBuilder,
250+
dimensionTransformer
251+
);
244252

245-
var metadata = processSideEffect(timingsBuilder, graphResources, result, sideEffect);
253+
log.onProcessingResult();
254+
var metadata = processSideEffect(timingsBuilder, graphResources, result, sideEffect);
246255

247-
return resultRenderer.render(graphResources, result, timingsBuilder.build(), metadata);
256+
log.onRenderingOutput();
257+
return resultRenderer.render(graphResources, result, timingsBuilder.build(), metadata);
258+
}
248259
}
249260

250261
/**

‎applications/algorithms/machinery/src/main/java/org/neo4j/gds/applications/algorithms/machinery/RequestScopedLog.java‎

Lines changed: 76 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,76 @@
1+
/*
2+
* Copyright (c) "Neo4j"
3+
* Neo4j Sweden AB [http://neo4j.com]
4+
*
5+
* This file is part of Neo4j.
6+
*
7+
* Neo4j is free software: you can redistribute it and/or modify
8+
* it under the terms of the GNU General Public License as published by
9+
* the Free Software Foundation, either version 3 of the License, or
10+
* (at your option) any later version.
11+
*
12+
* This program is distributed in the hope that it will be useful,
13+
* but WITHOUT ANY WARRANTY; without even the implied warranty of
14+
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
15+
* GNU General Public License for more details.
16+
*
17+
* You should have received a copy of the GNU General Public License
18+
* along with this program. If not, see <http://www.gnu.org/licenses/>.
19+
*/
20+
package org.neo4j.gds.applications.algorithms.machinery;
21+
22+
import org.neo4j.gds.core.utils.progress.JobId;
23+
import org.neo4j.gds.logging.Log;
24+
import org.neo4j.gds.utils.StringFormatting;
25+
26+
/**
27+
* Logging enhanced with correlation id.
28+
* So that we may know when an algorithm began, ended, and what it did in between.
29+
* Use this in a try-with-resources for that nice finalizer.
30+
*/
31+
@SuppressWarnings("ClassCanBeRecord")
32+
final class RequestScopedLog implements AutoCloseable {
33+
private final Log log;
34+
private final JobId jobId;
35+
36+
private RequestScopedLog(Log log, JobId jobId) {
37+
this.log = log;
38+
this.jobId = jobId;
39+
}
40+
41+
static RequestScopedLog create(Log log, JobId jobId) {
42+
log(log, "[%s] Algorithm processing commencing", jobId);
43+
44+
return new RequestScopedLog(log, jobId);
45+
}
46+
47+
void onLoadingGraph() {
48+
log(log, "[%s] Loading graph", jobId);
49+
}
50+
51+
void onComputing() {
52+
log(log, "[%s] Computing algorithm", jobId);
53+
}
54+
55+
void onProcessingResult() {
56+
log(log, "[%s] Processing algorithm result", jobId);
57+
}
58+
59+
void onRenderingOutput() {
60+
log(log, "[%s] Rendering output", jobId);
61+
}
62+
63+
/**
64+
* We get a hook where we can tell when stuff finished
65+
*/
66+
@Override
67+
public void close() {
68+
log(log, "[%s] Algorithm processing complete", jobId);
69+
}
70+
71+
private static void log(Log log, String template, JobId jobId) {
72+
@SuppressWarnings("PatternValidation") var logMessage = StringFormatting.formatWithLocale(template, jobId.asString());
73+
74+
log.info(logMessage);
75+
}
76+
}

‎applications/algorithms/machinery/src/test/java/org/neo4j/gds/applications/algorithms/machinery/DefaultAlgorithmProcessingTemplateTest.java‎

Lines changed: 93 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -24,11 +24,17 @@
2424
import org.neo4j.gds.api.GraphName;
2525
import org.neo4j.gds.core.loading.GraphResources;
2626
import org.neo4j.gds.core.loading.GraphStoreCatalogService;
27+
import org.neo4j.gds.core.utils.progress.JobId;
28+
import org.neo4j.gds.logging.Log;
2729

2830
import java.util.Optional;
2931

3032
import static org.assertj.core.api.Assertions.assertThat;
33+
import static org.assertj.core.api.Assertions.fail;
34+
import static org.junit.jupiter.api.Assertions.assertEquals;
3135
import static org.mockito.Mockito.mock;
36+
import static org.mockito.Mockito.never;
37+
import static org.mockito.Mockito.verify;
3238
import static org.mockito.Mockito.when;
3339

3440
/**
@@ -39,16 +45,18 @@
3945
class DefaultAlgorithmProcessingTemplateTest {
4046
@Test
4147
void shouldDoFourStepProcess() {
48+
var log = mock(Log.class);
4249
var graphStoreCatalogService = mock(GraphStoreCatalogService.class);
4350
var requestScopedDependencies = RequestScopedDependencies.builder().build();
4451
var algorithmComputer = mock(ComputationService.class);
4552
var template = new DefaultAlgorithmProcessingTemplate(
53+
log,
4654
graphStoreCatalogService,
4755
requestScopedDependencies,
4856
algorithmComputer
4957
);
5058

51-
var configuration = new ExampleConfiguration();
59+
var configuration = new ExampleConfiguration(new JobId("my little job id"));
5260
var graphResources = new GraphResources(null, mock(Graph.class), null);
5361
when(graphStoreCatalogService.getGraphResources(
5462
GraphName.parse("some graph"),
@@ -90,20 +98,28 @@ void shouldDoFourStepProcess() {
9098
);
9199

92100
assertThat(renderedResult).isEqualTo("some rendered result");
101+
102+
verify(log).info("[my little job id] Algorithm processing commencing");
103+
verify(log).info("[my little job id] Computing algorithm");
104+
verify(log).info("[my little job id] Processing algorithm result");
105+
verify(log).info("[my little job id] Rendering output");
106+
verify(log).info("[my little job id] Algorithm processing complete");
93107
}
94108

95109
@Test
96110
void shouldSkipSideEffect() {
111+
var log = mock(Log.class);
97112
var graphStoreCatalogService = mock(GraphStoreCatalogService.class);
98113
var requestScopedDependencies = RequestScopedDependencies.builder().build();
99114
var algorithmComputer = mock(ComputationService.class);
100115
var template = new DefaultAlgorithmProcessingTemplate(
116+
log,
101117
graphStoreCatalogService,
102118
requestScopedDependencies,
103119
algorithmComputer
104120
);
105121

106-
var configuration = new ExampleConfiguration();
122+
var configuration = new ExampleConfiguration(new JobId("job's a good 'un"));
107123
var graphResources = new GraphResources(null, mock(Graph.class), null);
108124
when(graphStoreCatalogService.getGraphResources(
109125
GraphName.parse("some other graph"),
@@ -145,5 +161,80 @@ void shouldSkipSideEffect() {
145161
);
146162

147163
assertThat(renderedResult).isEqualTo("some other rendered result");
164+
165+
verify(log).info("[job's a good 'un] Algorithm processing commencing");
166+
verify(log).info("[job's a good 'un] Computing algorithm");
167+
verify(log).info("[job's a good 'un] Processing algorithm result");
168+
verify(log).info("[job's a good 'un] Rendering output");
169+
verify(log).info("[job's a good 'un] Algorithm processing complete");
170+
}
171+
172+
@Test
173+
void shouldLogProcessingEvenWhenErrorsHappen() {
174+
var log = mock(Log.class);
175+
var graphStoreCatalogService = mock(GraphStoreCatalogService.class);
176+
var requestScopedDependencies = RequestScopedDependencies.builder().build();
177+
var algorithmComputer = mock(ComputationService.class);
178+
var template = new DefaultAlgorithmProcessingTemplate(
179+
log,
180+
graphStoreCatalogService,
181+
requestScopedDependencies,
182+
algorithmComputer
183+
);
184+
185+
var configuration = new ExampleConfiguration(new JobId("opaque job ids ftw"));
186+
var graphResources = new GraphResources(null, mock(Graph.class), null);
187+
when(graphStoreCatalogService.getGraphResources(
188+
GraphName.parse("some other graph"),
189+
configuration,
190+
Optional.empty(),
191+
Optional.empty(),
192+
Optional.empty(),
193+
requestScopedDependencies.user(),
194+
requestScopedDependencies.databaseId()
195+
)).thenReturn(graphResources);
196+
when(algorithmComputer.computeAlgorithm(
197+
configuration,
198+
graphResources,
199+
new StandardLabel("some other compute job"),
200+
null,
201+
null,
202+
DimensionTransformer.DISABLED
203+
)).thenReturn("some other result");
204+
205+
try {
206+
template.processAlgorithmAndAnySideEffects(
207+
Optional.empty(),
208+
GraphName.parse("some other graph"),
209+
configuration,
210+
Optional.empty(),
211+
Optional.empty(),
212+
new StandardLabel("some other compute job"),
213+
DimensionTransformer.DISABLED,
214+
null,
215+
null,
216+
Optional.of((__, ___) -> {
217+
try {
218+
throw new RuntimeException("Fly, you fools!");
219+
} finally {
220+
log.info("[opaque job ids ftw] Error: wouldn't it be nice if it behaved like this");
221+
}
222+
}),
223+
null
224+
);
225+
226+
fail();
227+
} catch (RuntimeException e) {
228+
assertEquals("Fly, you fools!", e.getMessage());
229+
}
230+
231+
verify(log).info("[opaque job ids ftw] Algorithm processing commencing");
232+
verify(log).info("[opaque job ids ftw] Computing algorithm");
233+
verify(log).info("[opaque job ids ftw] Processing algorithm result");
234+
verify(log).info("[opaque job ids ftw] Error: wouldn't it be nice if it behaved like this");
235+
// it would be nice, actually, but this is just logging, so bits of our code can opt in,
236+
// but we cannot mandate nor guarantee
237+
verify(log, never()).info("[opaque job ids ftw] Rendering output"); // because exception happened
238+
verify(log).info("[opaque job ids ftw] Algorithm processing complete"); // but you get the finaliser
148239
}
149240
}

‎applications/algorithms/machinery/src/test/java/org/neo4j/gds/applications/algorithms/machinery/ExampleConfiguration.java‎

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -22,20 +22,24 @@
2222
import org.neo4j.gds.config.AlgoBaseConfig;
2323
import org.neo4j.gds.config.RelationshipWeightConfig;
2424
import org.neo4j.gds.core.concurrency.Concurrency;
25+
import org.neo4j.gds.core.utils.progress.JobId;
2526

2627
import java.util.Optional;
2728

2829
/**
2930
* A fake configuration that we can slowly build out
3031
*/
32+
@SuppressWarnings("ClassCanBeRecord")
3133
class ExampleConfiguration implements AlgoBaseConfig, RelationshipWeightConfig {
34+
private final JobId jobId;
3235
private final boolean sudo;
3336

34-
ExampleConfiguration() {
35-
this(false);
37+
ExampleConfiguration(JobId jobId) {
38+
this(jobId, false);
3639
}
3740

38-
ExampleConfiguration(boolean sudo) {
41+
private ExampleConfiguration(JobId jobId, boolean sudo) {
42+
this.jobId = jobId;
3943
this.sudo = sudo;
4044
}
4145

@@ -44,6 +48,11 @@ public Concurrency concurrency() {
4448
return new Concurrency(7);
4549
}
4650

51+
@Override
52+
public JobId jobId() {
53+
return jobId;
54+
}
55+
4756
@Override
4857
public Optional<String> relationshipWeightProperty() {
4958
return Optional.empty();
@@ -56,6 +65,6 @@ public boolean sudo() {
5665

5766
@Override
5867
public Optional<String> usernameOverride() {
59-
throw new UnsupportedOperationException("TODO");
68+
return Optional.empty();
6069
}
6170
}

‎core/src/main/java/org/neo4j/gds/core/loading/GraphStoreCatalogService.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -114,7 +114,7 @@ protected void validateAlgorithmRequirements(
114114
/**
115115
* Load GraphStore and graph, with copious validation.
116116
*/
117-
private GraphResources getGraphResources(
117+
public GraphResources getGraphResources(
118118
GraphName graphName,
119119
Collection<NodeLabel> nodeLabelsFilter,
120120
Collection<RelationshipType> relationshipTypesFilter,

0 commit comments

Comments
 (0)