Skip to content

Commit b23790d

Browse files
raydiveraydive
authored
Merge pull request #10 from nulab/fix/post-processor-span-before-factory
fix: start post_processor span before the factory call
2 parents 6c7c362 + eaf6675 commit b23790d

4 files changed

Lines changed: 156 additions & 19 deletions

File tree

‎flexmark-core-test/pom.xml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,5 +38,10 @@
3838
<artifactId>jmh-generator-annprocess</artifactId>
3939
<scope>test</scope>
4040
</dependency>
41+
<dependency>
42+
<groupId>io.opentelemetry</groupId>
43+
<artifactId>opentelemetry-sdk-testing</artifactId>
44+
<scope>test</scope>
45+
</dependency>
4146
</dependencies>
4247
</project>

‎flexmark-core-test/src/test/java/com/vladsch/flexmark/core/test/util/parser/PostProcessorManagerSpanTest.java‎

Lines changed: 118 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,118 @@
1+
package com.vladsch.flexmark.core.test.util.parser;
2+
3+
import com.vladsch.flexmark.ast.Text;
4+
import com.vladsch.flexmark.parser.Parser;
5+
import com.vladsch.flexmark.parser.block.DocumentPostProcessor;
6+
import com.vladsch.flexmark.parser.block.DocumentPostProcessorFactory;
7+
import com.vladsch.flexmark.parser.block.NodePostProcessor;
8+
import com.vladsch.flexmark.parser.block.NodePostProcessorFactory;
9+
import com.vladsch.flexmark.util.ast.Document;
10+
import com.vladsch.flexmark.util.ast.Node;
11+
import com.vladsch.flexmark.util.ast.NodeTracker;
12+
import io.opentelemetry.api.GlobalOpenTelemetry;
13+
import io.opentelemetry.api.common.AttributeKey;
14+
import io.opentelemetry.api.trace.Span;
15+
import io.opentelemetry.sdk.testing.junit4.OpenTelemetryRule;
16+
import io.opentelemetry.sdk.trace.data.SpanData;
17+
import org.jetbrains.annotations.NotNull;
18+
import org.junit.After;
19+
import org.junit.Before;
20+
import org.junit.Rule;
21+
import org.junit.Test;
22+
23+
import java.util.List;
24+
25+
import static org.junit.Assert.assertEquals;
26+
import static org.junit.Assert.assertNotNull;
27+
import static org.junit.Assert.assertTrue;
28+
29+
/**
30+
* Verifies that the per-processor span wraps {@code PostProcessorFactory.apply(...)}, so time spent
31+
* constructing a post processor is attributed to that processor's span.
32+
*/
33+
final public class PostProcessorManagerSpanTest {
34+
private static final AttributeKey<String> CLASS_ATTRIBUTE = AttributeKey.stringKey("markdown.post_processor.class");
35+
36+
@Rule
37+
public final OpenTelemetryRule openTelemetry = OpenTelemetryRule.create();
38+
39+
@Before
40+
public void installAsGlobal() {
41+
// PostProcessorManager obtains its tracer from GlobalOpenTelemetry, which the rule does not register.
42+
GlobalOpenTelemetry.resetForTest();
43+
GlobalOpenTelemetry.set(openTelemetry.getOpenTelemetry());
44+
}
45+
46+
@After
47+
public void resetGlobal() {
48+
GlobalOpenTelemetry.resetForTest();
49+
}
50+
51+
@Test
52+
public void nodePostProcessorFactoryIsAppliedInsideItsSpan() {
53+
RecordingNodePostProcessorFactory factory = new RecordingNodePostProcessorFactory();
54+
Parser.builder().postProcessorFactory(factory).build().parse("some text");
55+
56+
assertFactoryAppliedInsideSpan(factory.spanCurrentDuringApply, RecordingNodePostProcessor.class);
57+
}
58+
59+
@Test
60+
public void documentPostProcessorFactoryIsAppliedInsideItsSpan() {
61+
RecordingDocumentPostProcessorFactory factory = new RecordingDocumentPostProcessorFactory();
62+
Parser.builder().postProcessorFactory(factory).build().parse("some text");
63+
64+
assertFactoryAppliedInsideSpan(factory.spanCurrentDuringApply, RecordingDocumentPostProcessor.class);
65+
}
66+
67+
private void assertFactoryAppliedInsideSpan(Span spanCurrentDuringApply, Class<?> expectedProcessorClass) {
68+
assertNotNull("factory was not applied", spanCurrentDuringApply);
69+
List<SpanData> spans = openTelemetry.getSpans();
70+
assertEquals(1, spans.size());
71+
SpanData span = spans.get(0);
72+
assertEquals("markdown.parse.post_processor", span.getName());
73+
assertEquals("factory was applied outside the post_processor span", span.getSpanId(), spanCurrentDuringApply.getSpanContext().getSpanId());
74+
assertEquals(expectedProcessorClass.getName(), span.getAttributes().get(CLASS_ATTRIBUTE));
75+
assertTrue(span.hasEnded());
76+
}
77+
78+
static class RecordingNodePostProcessorFactory extends NodePostProcessorFactory {
79+
Span spanCurrentDuringApply;
80+
81+
RecordingNodePostProcessorFactory() {
82+
super(false);
83+
addNodes(Text.class);
84+
}
85+
86+
@NotNull
87+
@Override
88+
public NodePostProcessor apply(@NotNull Document document) {
89+
spanCurrentDuringApply = Span.current();
90+
return new RecordingNodePostProcessor();
91+
}
92+
}
93+
94+
static class RecordingNodePostProcessor extends NodePostProcessor {
95+
@Override
96+
public void process(@NotNull NodeTracker state, @NotNull Node node) {
97+
}
98+
}
99+
100+
static class RecordingDocumentPostProcessorFactory extends DocumentPostProcessorFactory {
101+
Span spanCurrentDuringApply;
102+
103+
@NotNull
104+
@Override
105+
public DocumentPostProcessor apply(@NotNull Document document) {
106+
spanCurrentDuringApply = Span.current();
107+
return new RecordingDocumentPostProcessor();
108+
}
109+
}
110+
111+
static class RecordingDocumentPostProcessor extends DocumentPostProcessor {
112+
@NotNull
113+
@Override
114+
public Document processDocument(@NotNull Document document) {
115+
return document;
116+
}
117+
}
118+
}

‎flexmark/src/main/java/com/vladsch/flexmark/parser/internal/PostProcessorManager.java‎

Lines changed: 26 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -76,9 +76,10 @@ public Document postProcess(Document document) {
7676
boolean hadGlobal = false;
7777
for (PostProcessorFactory dependent : stage.dependents) {
7878
if (dependent.affectsGlobalScope()) {
79-
PostProcessor postProcessor = dependent.apply(document);
80-
Span span = startPostProcessorSpan(postProcessor);
79+
Span span = startPostProcessorSpan();
8180
try (Scope ignored = span.makeCurrent()) {
81+
PostProcessor postProcessor = dependent.apply(document);
82+
span.setAttribute(POST_PROCESSOR_CLASS_ATTRIBUTE, postProcessor.getClass().getName());
8283
document = postProcessor.processDocument(document);
8384
} catch (Throwable t) {
8485
span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
@@ -98,17 +99,18 @@ public Document postProcess(Document document) {
9899
}
99100

100101
Map<Class<?>, Set<Class<?>>> dependentNodeTypes = dependent.getNodeTypes();
101-
PostProcessor postProcessor = dependent.apply(document);
102-
BitSet exclusionSet = new BitSet();
103-
if (dependentNodeTypes != null) {
104-
for (Set<Class<?>> excluded : dependentNodeTypes.values()) {
105-
BitSet mapped = classifyingNodeTracker.getExclusionSet().indexBitSet(excluded);
106-
exclusionSet.or(mapped);
107-
}
102+
Span span = startPostProcessorSpan();
103+
try (Scope ignored = span.makeCurrent()) {
104+
PostProcessor postProcessor = dependent.apply(document);
105+
span.setAttribute(POST_PROCESSOR_CLASS_ATTRIBUTE, postProcessor.getClass().getName());
106+
BitSet exclusionSet = new BitSet();
107+
if (dependentNodeTypes != null) {
108+
for (Set<Class<?>> excluded : dependentNodeTypes.values()) {
109+
BitSet mapped = classifyingNodeTracker.getExclusionSet().indexBitSet(excluded);
110+
exclusionSet.or(mapped);
111+
}
108112

109-
ReversibleIterable<Node> nodes = classifyingNodeTracker.getCategoryItems(Node.class, dependentNodeTypes.keySet());
110-
Span span = startPostProcessorSpan(postProcessor);
111-
try (Scope ignored = span.makeCurrent()) {
113+
ReversibleIterable<Node> nodes = classifyingNodeTracker.getCategoryItems(Node.class, dependentNodeTypes.keySet());
112114
for (Node node : nodes) {
113115
if (node.getParent() == null) continue; // was already removed
114116
// now we need to get the bitset for the excluded ancestors of the node, then intersect it with the actual ancestors of this factory
@@ -132,12 +134,12 @@ public Document postProcess(Document document) {
132134
}
133135
postProcessor.process(classifyingNodeTracker, node);
134136
}
135-
} catch (Throwable t) {
136-
span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
137-
throw t;
138-
} finally {
139-
span.end();
140137
}
138+
} catch (Throwable t) {
139+
span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
140+
throw t;
141+
} finally {
142+
span.end();
141143
}
142144
}
143145
}
@@ -146,11 +148,16 @@ public Document postProcess(Document document) {
146148
return document;
147149
}
148150

149-
private static Span startPostProcessorSpan(PostProcessor postProcessor) {
151+
private static final String POST_PROCESSOR_CLASS_ATTRIBUTE = "markdown.post_processor.class";
152+
153+
// Started before PostProcessorFactory.apply(...) so that work done while constructing the processor
154+
// (which may be expensive, e.g. loading data to build matching patterns) is attributed to this span
155+
// instead of showing up only as unexplained time in the enclosing post_process span. The processor
156+
// class is therefore added as an attribute by the caller once the instance exists.
157+
private static Span startPostProcessorSpan() {
150158
// no-op span unless a Java agent (or the application) has wired GlobalOpenTelemetry
151159
return GlobalOpenTelemetry.getTracer("com.vladsch.flexmark")
152160
.spanBuilder("markdown.parse.post_processor")
153-
.setAttribute("markdown.post_processor.class", postProcessor.getClass().getName())
154161
.startSpan();
155162
}
156163

‎pom.xml‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -546,6 +546,13 @@
546546
<artifactId>opentelemetry-instrumentation-annotations</artifactId>
547547
<version>2.16.0</version>
548548
</dependency>
549+
<!-- Test-only: in-memory span exporter for asserting on spans. Keep in step with the
550+
opentelemetry-api version pulled in transitively by the annotations artifact. -->
551+
<dependency>
552+
<groupId>io.opentelemetry</groupId>
553+
<artifactId>opentelemetry-sdk-testing</artifactId>
554+
<version>1.50.0</version>
555+
</dependency>
549556

550557
<!-- Common test dependencies -->
551558
<dependency>

0 commit comments

Comments
 (0)