Only drop elements exported by BatchSpanProcessor #1567

huntc · 2020-08-20T09:06:01Z

This PR takes an approach where only the actual elements passed onto an exporter is removed from the internal buffer of spans within a BatchSpanProcessor. Any pressure on the buffer becoming full will result in the BatchSpanProcessor dropping elements as per its original design.

Prior to this PR, spans could be dropped by the BatchSpanProcessor without being reported.

Along the way, it occurred to me that the worker thread can be replaced by using the timer thread that we have to have. I've now affected code changes there too, which I think simplifies the BatchSpanProcessor.

Fixes #1566

cc @anuraaga

This commit takes an approach where only the actual elements passed onto an exporter are removed from the internal buffer of spans within a BatchSpanProcessor. Any pressure on the buffer becoming full will result in the BatchSpanProcessor dropping elements as per its original design. Prior to this commit, spans could be dropped by the BatchSpanProcessor without being reported.

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

huntc · 2020-08-20T10:20:15Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

      } else {
-        logger.log(Level.FINE, "Exporter busy. Dropping spans.");
+        return 0;


Returning zero is key - this is what'll cause the internal buffer to mount up and for the existing span-drop functionality of logging to kick in.

anuraaga

Because of

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

anuraaga · 2020-08-20T14:04:09Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

        }
        // Execute the batch export outside the synchronized to not block all producers.
-        exportBatches(spansCopy);
+        int taken = onBatchExport(spansCopy);


I might be missing it, but I think this will cause multiple batches to be sent concurrently? If so, I think it's not respecting the spirit of maxExportBatchSize. To be honest, I don't know exactly what the spirit of maxExportBatchSize is but I think it's one of 1) send batches sequentially or 2) wait scheduledDelayMillis between each chunk of maxExportBatchSize no matter what. #1565 aims for 1), neither of our PRs aim for 2) :( But I guess if we're sending concurrently that's not good for BSP, that's the SSP's role. Let me know if I'm confused though.

It isn’t sending an export concurrently. Only one export is permitted at a time within the onExportBatch function.

Exporting “no matter what” on schedule is what things look like before this PR. ;-)

Ah I see how the return 0 works. Isn't this effectively a spinlock because we'll keep on looping, find the queue is larger than batch size, try to export, find it's not available, and continue until it's available again? I wouldn't expect to see spinning to wait for I/O, is it better than parking?

Good point. It would indeed spin until the number of buffer elements drops below the max buffer size. I think we should move the condition on the wait also... that way it wouldn't spin. The batch would then just wake up on its timer no matter what and then try another export. This would ultimately represent the park that you suggested.

I will push another commit now along with some other small changes to improve comprehension.

anuraaga · 2020-08-20T14:06:56Z

Because of #1567 (comment) my current recommendation is to merge #1565 since we do need a quick fix for BSP dropping spans that shouldn't be and it seems the simplest. All of the related PRs have made me believe we need to prioritize #1560 #729 before doing a deep dive here

huntc · 2020-08-20T19:37:34Z

Because of #1567 (comment) my current recommendation is to merge #1565 since we do need a quick fix for BSP dropping spans that shouldn't be and it seems the simplest. All of the related PRs have made me believe we need to prioritize #1560 #729 before doing a deep dive here

I see this PR as being much simpler than 1565. The BSP’s contract acknowledges that spans can be dropped, so we’ve not violated that contract. Let’s get this right rather than look for a quick fix.

Renamed the onBatchExport to tryExport as this more correctly conveys intent. Also introduced a dropSpans function that should be more performant over what I had.

We should avoid spinning if the buffer is not full. The change here keeps things simple where the batch processor only wakes up on its schedule, tries to export, retains elements that it can't export, and then sleeps again.

huntc · 2020-08-20T23:28:21Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

@@ -177,7 +177,7 @@ public void forceFlush() {
    private final AtomicBoolean exportAvailable = new AtomicBoolean(true);

    @GuardedBy("monitor")
-    private final List<ReadableSpan> spansList;
+    private final ArrayList<ReadableSpan> spansList;


Exposing an array list here as the operations we perform on it assumes an array in terms of bulk copying and therefore, o(1) element access.

Just realised that the worker thread can now be eliminated

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

anuraaga · 2020-08-20T23:44:29Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

+            // In the case of a spurious wakeup we export only if we have at least one span in
+            // the batch. It is acceptable because batching is a best effort mechanism here.
+            try {
+              monitor.wait(scheduleDelayMillis);


I think this causes the wait to happen between each export batch, rather than between each "processing of the queue". It effectively means the queue size parameter is not having much effect if I'm not mistaken.

FWIW, I am interested in flushing in an async manner :) I think the way to do it is to have a separate Flusher. What I'm expecting is for it to look like something like

ExecutorService executor; init() executor.schedule(wakeup); wakeup { if (spans.empty) executor.schedule(wakeup) drained = spans.drain new Flusher(drained).flush(); Flusher { pending Flusher(spans) pending = spans flush() { if (pending.isEmpty()) { executor.schedule(wakeup) return } taken = pending.take(batchSize) result = exporter.export(taken) result.whenComplete(this::flush) }

I think this has the properties that we want - run through entire queue when exporting, export a batch at a time, and delay between each queue processing (not between every batch as in the right side here, nor potentially no delay ever like left side here). And consecutive flushes without blocking.

So my plan is #1565, then #729, then add AsyncFlusher. @jkwatson has wanted us to migrate to an ExecutorService for a long time and I agree :) I think it will make our lives simpler when actually addressing the asyncronous export. Does this plan make sense?

@anuraaga I need to absorb your comments above more and will do so now. However, #1565 does not make sense to me as it introduces additional complexity that is avoidable. Back soon.

So, if I've got this right... you're making a distinction here between the time interval in terms of processing the queue vs the time interval between exporting to an exporter. You're also favouring the former.

You want to see exporting happen continually if there are more elements in the queue.

Correct?

Yeah - at least that's my understanding of the spec / goal of the class, but I could be wrong in my reading of course :)

https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/sdk.md#batching-processor

A second reading makes me think actually this PR may have the right semantics since it says scheduledDelayMillis = delay between export, and maxExportBatchSize = maximum size of an export. I'm having trouble invisioning how I would actually set maxExportBatchSize different from queueSize but this PR seems ok to me too now. Interested in hearing what others think the BSP is "supposed to do" though :)

OK, I've just pushed another commit.

The worker thread has been removed and we now instead use the timer for scheduling work, thus saving us a thread. In addition, if there remains work to be done once the export has completed then we queue it for running immediately.

A test has changed slightly in that it was previously relying on the worker thread becoming blocked; which it now no longer does.

The worker thread has been removed and we now instead use the timer for scheduling work, thus saving us a thread. In addition, if there remains work to be done once the export has completed then we queue it for running immediately. A test has changed slightly in that it was previously relying on the worker thread becoming blocked; which it now no longer does.

huntc · 2020-08-21T01:52:53Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

+      System.arraycopy(spansList.toArray(), count, retainedSpanList, 0, remaining);
+      spansList.clear();
+      spansList.addAll(Arrays.asList(retainedSpanList));
+    }


There has to be a better way of dropping elements from an array... Given that clear traverses the array and nulls elements, we've effectively got three traverses of the array. Now in practical terms, retainedSpanList should be empty most times, or at least only a few elements. So the array copying at L308 and L310 is going to be negligible.

huntc · 2020-08-21T01:53:19Z

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java

+                    if (!spansList.isEmpty()) {
+                      timer.schedule(new WorkerTask(), 0);
+                    }
+                  }


We now steal more work if there's some more available.

huntc · 2020-08-21T01:58:19Z

stressTest_withBatchSpanProcessor is failing - I shall look at that next

Adjusted the stress test as it can only guarantee that the buffer size is sent to the exporter now. I'm noticing that several thousand get exported, but some do (and should) get lost. Also, the test did highlight one area of neglect where I should be waking up the timer when the buffer is half full and there's no export in progress.

huntc · 2020-08-21T02:31:36Z

sdk/tracing/src/test/java/io/opentelemetry/sdk/trace/TracerSdkTest.java

    stressTestBuilder.build().run();
-    assertThat(countingSpanExporter.numberOfSpansExported.get()).isEqualTo(8_000);
+    assertThat(countingSpanExporter.numberOfSpansExported.get())
+        .isGreaterThanOrEqualTo(defaultMaxQueueSize);


This needed to change given that we are now fully async. We can't guarantee that all spans get through. This is ok though as it is in line with the BatchSpanProcessor's contract.

In reality, this test does see several thousand get through.

codecov · 2020-08-21T02:40:26Z

Codecov Report

Merging #1567 into master will increase coverage by 0.11%.
The diff coverage is 93.54%.

@@             Coverage Diff              @@
##             master    #1567      +/-   ##
============================================
+ Coverage     91.49%   91.61%   +0.11%     
  Complexity      976      976              
============================================
  Files           116      116              
  Lines          3517     3518       +1     
  Branches        304      303       -1     
============================================
+ Hits           3218     3223       +5     
+ Misses          206      203       -3     
+ Partials         93       92       -1

Impacted Files	Coverage Δ	Complexity Δ
...telemetry/sdk/trace/export/BatchSpanProcessor.java	`96.00% <93.54%> (+1.36%)`	`8.00 <0.00> (ø)`
...y/sdk/metrics/aggregator/DoubleMinMaxSumCount.java	`100.00% <0.00%> (+3.92%)`	`6.00% <0.00%> (ø%)`

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 ad9f7d4...223d052. Read the comment docs.

Let's not overwhelm the exporter...

…uffer This class should now behave fully in accordance with the spec

anuraaga · 2020-08-21T04:58:45Z

@huntc Chatted with @jkwatson today about this and we decided that because the current behavior is only in snapshot, not released, we don't have to rush a fix in. So going to close my #1565 :-) He also think we really should go ahead and clean up the processor before (or perhaps while) fixing it rather than continuing work with the current monitor / worker pattern. I'm working on a PR for that. @huntc does that sound OK to you? I'm keeping this PR in mind instead of adding any blocking - I think the code will be dramatically simplified and hope it helps us with future possible improvements.

huntc · 2020-08-24T05:27:26Z

Closing given the work of #1571

huntc mentioned this pull request Aug 20, 2020

Fix to export entire batch sequentially instead of dropping spans. #1565

Closed

huntc commented Aug 20, 2020

View reviewed changes

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java Outdated Show resolved Hide resolved

huntc commented Aug 20, 2020

View reviewed changes

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java Outdated Show resolved Hide resolved

huntc commented Aug 20, 2020

View reviewed changes

huntc changed the title ~~Only drop elements exported in BatchSpanProcessor~~ Only drop elements exported by BatchSpanProcessor Aug 20, 2020

anuraaga reviewed Aug 20, 2020

View reviewed changes

huntc added 2 commits August 21, 2020 09:19

PR feedback

1087a69

Renamed the onBatchExport to tryExport as this more correctly conveys intent. Also introduced a dropSpans function that should be more performant over what I had.

Avoid spinning

afdf0f1

We should avoid spinning if the buffer is not full. The change here keeps things simple where the batch processor only wakes up on its schedule, tries to export, retains elements that it can't export, and then sleeps again.

huntc marked this pull request as ready for review August 20, 2020 23:23

huntc requested review from arminru, bogdandrutu, carlosalberto, jkwatson, pavolloffay, thisthat and tylerbenson as code owners August 20, 2020 23:23

huntc commented Aug 20, 2020

View reviewed changes

Added a fixme and removed a comment

e1903d5

Just realised that the worker thread can now be eliminated

huntc commented Aug 20, 2020

View reviewed changes

sdk/tracing/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java Outdated Show resolved Hide resolved

anuraaga reviewed Aug 20, 2020

View reviewed changes

huntc commented Aug 21, 2020

View reviewed changes

Comment removal

c9fd046

huntc commented Aug 21, 2020

View reviewed changes

huntc added 3 commits August 21, 2020 13:59

Resorted to pre-commit behaviour

88cff89

Let's not overwhelm the exporter...

Corrected check - push out another batch if we have adequate in our b…

abcdebc

…uffer This class should now behave fully in accordance with the spec

Removed a comment that I'd previously added

223d052

huntc closed this Aug 24, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Only drop elements exported by BatchSpanProcessor #1567

Only drop elements exported by BatchSpanProcessor #1567

huntc commented Aug 20, 2020 •

edited

Loading

huntc Aug 20, 2020

anuraaga left a comment

anuraaga Aug 20, 2020

huntc Aug 20, 2020

huntc Aug 20, 2020

anuraaga Aug 20, 2020

huntc Aug 20, 2020

anuraaga commented Aug 20, 2020

huntc commented Aug 20, 2020

huntc Aug 20, 2020

anuraaga Aug 20, 2020

huntc Aug 20, 2020

huntc Aug 20, 2020

anuraaga Aug 21, 2020

huntc Aug 21, 2020

huntc Aug 21, 2020

huntc Aug 21, 2020

huntc commented Aug 21, 2020

huntc Aug 21, 2020

codecov bot commented Aug 21, 2020 •

edited

Loading

anuraaga commented Aug 21, 2020

huntc commented Aug 24, 2020

Only drop elements exported by BatchSpanProcessor #1567

Only drop elements exported by BatchSpanProcessor #1567

Conversation

huntc commented Aug 20, 2020 • edited Loading

Choose a reason for hiding this comment

anuraaga 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

anuraaga commented Aug 20, 2020

huntc commented Aug 20, 2020

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

huntc commented Aug 21, 2020

Choose a reason for hiding this comment

codecov bot commented Aug 21, 2020 • edited Loading

Codecov Report

anuraaga commented Aug 21, 2020

huntc commented Aug 24, 2020

huntc commented Aug 20, 2020 •

edited

Loading

codecov bot commented Aug 21, 2020 •

edited

Loading