Timing breakdown #588

felixbarny · 2019-04-16T08:51:18Z

closes #556
depends on #587, elastic/apm-server#2086

TODO

guard against concurrent reads (report metrics to APM Server) and writes (tracking of metrics)
Javadoc
~~Report self_time on transactions/spans?~~
Feature flag
Limit timers to 1000
Thread-safe publication for Labels#immutableCopy

Open questions

resetting timers ~~vs monotonically increment~~ Timer counters
decide on a final format for top-level metric tags (Top-level tags/labels for metrics apm-server#2086)

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/Labels.java

codecov-io · 2019-04-17T11:45:45Z

Codecov Report

Merging #588 into master will increase coverage by <.01%.
The diff coverage is 79.25%.

@@             Coverage Diff              @@
##             master     #588      +/-   ##
============================================
+ Coverage     63.82%   63.83%   +<.01%     
  Complexity       68       68              
============================================
  Files           205      207       +2     
  Lines          8254     8496     +242     
  Branches       1056     1062       +6     
============================================
+ Hits           5268     5423     +155     
- Misses         2673     2741      +68     
- Partials        313      332      +19

Impacted Files	Coverage Δ	Complexity Δ
...lastic/apm/agent/report/ReporterConfiguration.java	`100% <ø> (ø)`	`0 <0> (ø)`	⬇️
.../apm/agent/concurrent/ExecutorInstrumentation.java	`46.93% <ø> (ø)`	`0 <0> (ø)`	⬇️
...m/agent/impl/async/SpanInScopeRunnableWrapper.java	`100% <ø> (ø)`	`0 <0> (ø)`	⬇️
...m/agent/impl/async/SpanInScopeCallableWrapper.java	`100% <ø> (ø)`	`0 <0> (ø)`	⬇️
...va/co/elastic/apm/agent/impl/transaction/Span.java	`78.02% <100%> (+3.02%)`	`0 <0> (ø)`	⬇️
...ic/apm/agent/metrics/builtin/JvmMemoryMetrics.java	`100% <100%> (ø)`	`0 <0> (ø)`	⬇️
...va/co/elastic/apm/agent/impl/ElasticApmTracer.java	`74.05% <100%> (ø)`	`0 <0> (ø)`	⬇️
...astic/apm/agent/impl/transaction/AbstractSpan.java	`83.63% <100%> (+7.01%)`	`0 <0> (ø)`	⬇️
...lastic/apm/agent/metrics/builtin/JvmGcMetrics.java	`92.85% <100%> (ø)`	`0 <0> (ø)`	⬇️
...astic/apm/agent/metrics/builtin/ThreadMetrics.java	`100% <100%> (ø)`	`0 <0> (ø)`	⬇️
... and 16 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 8aaaf6a...f84852a. Read the comment docs.

felixbarny · 2019-06-04T13:17:48Z

@bmorelli25 the last commit contains documentation for the metrics. I'd love to get some feedback from you 🙂

docs/metrics.asciidoc

bmorelli25

These docs look almost as good as your balcony in the summer ☀️

Co-Authored-By: Brandon Morelli <[email protected]>

eyalkoren

This PR is very big and complicated.
So I did my best to follow and provide initial feedback.
We can continue the review together, adding notes here as necessary.

NOTICE

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/AbstractSpan.java

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java

eyalkoren · 2019-06-17T07:04:28Z

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

+        timer.update(duration);
+        if (finished) {
+            // in case end()->trackMetrics() has been called concurrently
+            // don't leak timers


Still not thread safe:

Thread A: AbstractSpan#end() -> Transaction#doEnd -> trackMetrics() // all timers are reset, finished == false Thread B: AbstractSpan#end() -> Span#doEnd // creates an put a Timer, doesn't clean because finished == false Thread A: AbstractSpan#end() -> Transaction#doEnd (continue) AbstractSpan#end() -> sets finished = true

will set finished = true earlier

should be fixed now

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/MetricRegistry.java

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/MetricSet.java

eyalkoren · 2019-06-17T07:47:27Z

apm-agent-core/src/main/java/co/elastic/apm/agent/util/KeyListConcurrentHashMap.java

+     * Returns a mutable {@link List}, roughly equal to the {@link #keySet()}.
+     * <p>
+     * Note that in concurrent scenarios, the key list may be a subset of the values of the respective {@link #keySet()}.
+     * Entries added via the {@code compute*} family of methods are not reflected in the list.


What are the compute methods?
I think this list in general may not reflect the underlying keySet() as it is not thread-safe with regard to the underlying map, right?

For example java.util.concurrent.ConcurrentHashMap#computeIfAbsent

Synchronizing on add and remove operations should also make it thread-safe, right? That would make the map more applicable for other use-cases where modifying the list does not happen under contention.

eyalkoren · 2019-06-17T09:23:39Z

apm-agent-core/src/main/java/co/elastic/apm/agent/util/KeyListConcurrentHashMap.java

+ * It can be used to iterate over the map's keys without allocating an {@link java.util.Iterator}
+ */
+public class KeyListConcurrentHashMap<K, V> extends ConcurrentHashMap<K, V> {
+    private final List<K> keyList = Collections.synchronizedList(new ArrayList<K>());


Make sure the map can only grow in size- throw unsupported operation exceptions from remove and clear

see #588 (comment)

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

eyalkoren

Didn't go thoroughly through tests, but mostly through everything else.

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/MetricRegistry.java

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

eyalkoren · 2019-06-18T09:31:43Z

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/Timer.java

+        update(durationUs, 1);
+    }
+
+    public void update(long durationUs, long count) {


Add a comment that must be used within code that guarantees atomicity, or make atomic, so that can't be queried while updated

eyalkoren · 2019-06-18T09:41:46Z

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

+                    final Timer timer = spanTimings.get(spanType);
+                    if (timer.getCount() > 0) {
+                        labels.spanType(spanType.getSpanType()).spanSubType(spanType.getSpanSubType());
+                        metricRegistry.updateTimer("span.self_time", labels, timer.getTotalTimeUs(), timer.getCount());


In addition, Timer update is not atomic, so reading here is not guaranteed to get fully updated Timer state (ie updated halfway by incrementTimer)

should now be fixed

eyalkoren · 2019-06-18T09:53:35Z

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/Timer.java

+    }
+
+    @Override
+    public void resetState() {


Same- not atomic and may occur concurrently with reads or other writes

eyalkoren · 2019-06-18T09:54:51Z

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

+                    if (timer.getCount() > 0) {
+                        labels.spanType(spanType.getSpanType()).spanSubType(spanType.getSpanSubType());
+                        metricRegistry.updateTimer("span.self_time", labels, timer.getTotalTimeUs(), timer.getCount());
+                        timer.resetState();


Same- may be executed concurrently with updates

should now be fixed

eyalkoren · 2019-06-18T10:02:03Z

...agent-core/src/main/java/co/elastic/apm/agent/report/serialize/MetricRegistrySerializer.java

+        serializeValue(key, ".count", timer.getCount(), jw);
+        jw.writeByte(JsonWriter.COMMA);
+        serializeValue(key, ".sum", timer.getTotalTimeMs(), jw);
+        timer.resetState();


All these resets seem awkward here, much better fit in metricSet.onAfterReport(). Is this done here in order to prevent additional iteration?

Yes, that the idea was to prevent another iteration. But it's probably better to trade off in favor of readability here.

...agent-core/src/main/java/co/elastic/apm/agent/report/serialize/MetricRegistrySerializer.java

eyalkoren

A really epic PR! 👏 👏

I think this change should come with a visible warning that high cardinality of span types and subtypes is highly discouraged as it will make this feature useless. It will also result with increased resource consumption (memory, cpu and bandwidth) but not sure how significant that would be.

eyalkoren · 2019-07-18T12:37:00Z

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

@@ -48,6 +60,9 @@
     */
    private final TransactionContext context = new TransactionContext();
    private final SpanCount spanCount = new SpanCount();
+    // type: subtype: timer
+    private final KeyListConcurrentHashMap<String, KeyListConcurrentHashMap<String, Timer>> spanTimings = new KeyListConcurrentHashMap<>();


Add a comment that this map does not get recycled and instead accumulates all span types and subtypes.
Maybe an additional ALL-CAPITALS comment about that in the resetState method, so to not let anyone fall for this one.

eyalkoren · 2019-07-18T14:14:10Z

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/AbstractSpan.java

    protected AtomicInteger references = new AtomicInteger();
    protected volatile boolean finished = true;

    public int getReferenceCount() {
        return references.get();
    }

+    private static class ReentrantTimer implements Recyclable {
+
+        private AtomicInteger nestingLevel = new AtomicInteger();


I find this name confusing. I thought it is about nested children, but it is more about counting concurrent-updaters of only first level (ie direct children) spans.

Recycle via reference counting

953c909

felixbarny self-assigned this Apr 16, 2019

felixbarny added the [zube]: In Progress label Apr 16, 2019

felixbarny added 3 commits April 16, 2019 11:26

Revert unrelated changes

847aecd

Introduce Labels

8bc8dd1

Add breakdown

d0e5d51

felixbarny force-pushed the timing-breakdown branch from 8d5c32c to d0e5d51 Compare April 16, 2019 09:28

felixbarny commented Apr 16, 2019

View reviewed changes

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/Labels.java Outdated Show resolved Hide resolved

felixbarny commented Apr 16, 2019

View reviewed changes

apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/Labels.java Outdated Show resolved Hide resolved

felixbarny added 2 commits April 23, 2019 09:49

Make tracking breakdown metrics garbage free

dffbba0

Merge remote-tracking branch 'origin/master' into timing-breakdown

576f2da

felixbarny force-pushed the timing-breakdown branch from f6cc3ff to 576f2da Compare May 3, 2019 13:43

felixbarny added 6 commits May 3, 2019 16:37

Update to new metric names

790f2e2

Merge remote-tracking branch 'origin/master' into timing-breakdown

2c8d6d2

Thread safe publication of immutable labels

33bfcae

Add span.subtype to breakdown metrics

b5395a1

Disable all breakdown code paths when disable_metrics=span.self_time

a609d71

Document metrics

dc701f7

felixbarny requested review from bmorelli25 and eyalkoren June 4, 2019 13:17

bmorelli25 reviewed Jun 4, 2019

View reviewed changes

docs/metrics.asciidoc Outdated Show resolved Hide resolved

bmorelli25 reviewed Jun 4, 2019

View reviewed changes

docs/metrics.asciidoc Outdated Show resolved Hide resolved

bmorelli25 approved these changes Jun 4, 2019

View reviewed changes

felixbarny and others added 5 commits June 5, 2019 08:28

Clarify docs

280f663

Co-Authored-By: Brandon Morelli <[email protected]>

Another docs clarification

a336827

Co-Authored-By: Brandon Morelli <[email protected]>

Fix tests

833bbe1

Guard agains concurrent reads/writes

5639197

Limit number of metricsets

a0d167d

felixbarny added 2 commits June 5, 2019 17:22

Add some Javadocs

9aca16f

Eliminate allocations

253ad87

felixbarny marked this pull request as ready for review June 11, 2019 11:50

eyalkoren reviewed Jun 17, 2019

View reviewed changes

felixbarny added [zube]: In Review and removed [zube]: In Progress labels Jun 17, 2019

eyalkoren reviewed Jun 17, 2019

View reviewed changes

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java Outdated Show resolved Hide resolved

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java Show resolved Hide resolved

eyalkoren reviewed Jun 18, 2019

View reviewed changes

felixbarny added 6 commits June 21, 2019 15:35

Addressed some comments

dbf5884

Merge remote-tracking branch 'origin/master' into timing-breakdown

6549546

Report timers in microseconds and use .us suffix

d8394c3

Merge remote-tracking branch 'origin/master' into timing-breakdown

308f519

Merge remote-tracking branch 'origin/master' into timing-breakdown

580bf1d

Fix race condition between trackMetrics and incrementTimer

bf6c221

felixbarny requested a review from eyalkoren July 18, 2019 09:27

eyalkoren approved these changes Jul 18, 2019

View reviewed changes

Renaming and add comments

f84852a

felixbarny merged commit d383730 into elastic:master Jul 19, 2019

zube bot added [zube]: Done and removed [zube]: In Review labels Jul 19, 2019

felixbarny deleted the timing-breakdown branch July 19, 2019 13:17

felixbarny removed the [zube]: Done label Jul 22, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timing breakdown #588

Timing breakdown #588

felixbarny commented Apr 16, 2019 •

edited

Loading

codecov-io commented Apr 17, 2019 •

edited

Loading

felixbarny commented Jun 4, 2019

bmorelli25 left a comment

eyalkoren left a comment

eyalkoren Jun 17, 2019

felixbarny Jun 18, 2019

felixbarny Jul 18, 2019

eyalkoren Jun 17, 2019

felixbarny Jun 18, 2019

felixbarny Jun 21, 2019

eyalkoren Jun 17, 2019

felixbarny Jul 17, 2019

eyalkoren left a comment

eyalkoren Jun 18, 2019

eyalkoren Jun 18, 2019

felixbarny Jul 18, 2019

eyalkoren Jun 18, 2019

eyalkoren Jun 18, 2019

felixbarny Jul 18, 2019

eyalkoren Jun 18, 2019

felixbarny Jun 21, 2019

eyalkoren left a comment

eyalkoren Jul 18, 2019

eyalkoren Jul 18, 2019

Timing breakdown #588

Timing breakdown #588

Conversation

felixbarny commented Apr 16, 2019 • edited Loading

codecov-io commented Apr 17, 2019 • edited Loading

Codecov Report

felixbarny commented Jun 4, 2019

bmorelli25 left a comment

Choose a reason for hiding this comment

eyalkoren left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eyalkoren left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eyalkoren left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

felixbarny commented Apr 16, 2019 •

edited

Loading

codecov-io commented Apr 17, 2019 •

edited

Loading