Handle full queue in RemoteReporter #180

mabn · 2017-05-13T16:41:19Z

This PR:

Fixes RemoteReporter throws exception when commandQueue is full #178 (RemoteReporter throws exception when commandQueue is full)
Fixes Error handing missing for RemoteReporter TimerTask #116 (Error handing missing for RemoteReporter TimerTask)

Currently when RemoteReporter's queue is full all 3 operations (append, close, flush) throw the exception:

java.lang.IllegalStateException: Queue full
at java.util.AbstractQueue.add(AbstractQueue.java:98)
at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312)

I've changed all 3 to use offer instead which does not block/throw. It's a clearly good choice for appendand flush, but I'm not sure if in case of close this is the best approach. I made close wait for a short time (100ms) and then just ignore the QueueProcessor thread, but maybe it should throw to indicate that it failed? Or block indefinitely?

There's one more issue I just spotted - updating "reporterQueueLength" metric happens inside FlushCommand - but when the queue is full this command is almost never queued. E.g. when it has compete for a flow with 99 AppendCommands then it will run only once in 100 attempts.
This would explain the weird plot I have when max size was set to 100

To fix that I moved reporterQueueLength update to the flush() method triggered by the TimerTask

The check “commandQueue.size() == maxQueueSize” is not thread safe, this lead to: java.lang.IllegalStateException: Queue full It’s better to .offer() and check the returned value

When the command queue is full it’s not possible to queue control commands - FlushCommand or CloseCommand. They were throwing exceptions. This change replaces BLockingQueue.add with BlockingQueue.offer to handle this situation. I’ve modified test InMemorySender to allow it to block. This makes it possible to easily fill the RemoteReporter’s command queue in tests.

mabn · 2017-05-13T16:42:04Z

jaeger-core/src/test/java/com/uber/jaeger/reporters/RemoteReporterTest.java

@@ -62,7 +68,7 @@ public void setUp() throws Exception {
  public void testRemoteReporterReport() throws Exception {
    Span span = (Span) tracer.buildSpan("raza").start();
    reporter.report(span);
-    Thread.sleep(5);
+    Thread.sleep(50);


I increased it because it was failing every time on my laptop. There's already a PR to make it right: #177

codecov-io · 2017-05-13T17:02:08Z

Codecov Report

Merging #180 into master will increase coverage by 0.6%.
The diff coverage is 100%.

@@             Coverage Diff             @@
##             master     #180     +/-   ##
===========================================
+ Coverage     80.85%   81.45%   +0.6%     
- Complexity      459      463      +4     
===========================================
  Files            77       77             
  Lines          1786     1790      +4     
  Branches        208      210      +2     
===========================================
+ Hits           1444     1458     +14     
+ Misses          252      244      -8     
+ Partials         90       88      -2

Impacted Files	Coverage Δ	Complexity Δ
...java/com/uber/jaeger/reporters/RemoteReporter.java	`89.55% <100%> (+8.59%)`	`8 <5> (+3)`	⬆️
.../uber/jaeger/samplers/RemoteControlledSampler.java	`92.95% <0%> (+1.4%)`	`19% <0%> (+1%)`	⬆️
...jaeger/reporters/protocols/ThriftUdpTransport.java	`86.44% <0%> (+3.38%)`	`16% <0%> (ø)`	⬇️
...c/main/java/com/uber/jaeger/senders/UdpSender.java	`74.54% <0%> (+3.63%)`	`11% <0%> (ø)`	⬇️

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 797ef4f...e3653d1. Read the comment docs.

yurishkuro · 2017-05-13T17:13:46Z

jaeger-core/src/test/java/com/uber/jaeger/reporters/InMemorySender.java


+/**
+ * InMemorySender "appends" span only earlier "append" was permitted. Appending is a blocking


did you mean "only if earlier"?

Actually I'd rather change it to:

Sender which stores spans in memory. Appending a new span is a blocking operation unless "permitted". By default Integer.MAX_VALUE "appends" are permitted.

yurishkuro · 2017-05-13T17:14:52Z

jaeger-core/src/main/java/com/uber/jaeger/reporters/RemoteReporter.java

+    try {
+      // best-effort: if we can't add CloseCommand in this time then it probably will never happen
+      closeCommandAdded = commandQueue
+          .offer(new CloseCommand(), CLOSE_ENQUEUE_TIMEOUT_MILLIS, TimeUnit.MILLISECONDS);


makes sense. Only I would increase the timeout to 1sec.

yurishkuro · 2017-05-13T17:16:16Z

jaeger-core/src/test/java/com/uber/jaeger/reporters/InMemorySender.java

+
+  /**
+   * InMemorySender "appends" span only if the "append" was permitted. Otherwise append blocks
+   * until it it permitted.


this comment not needed here

yurishkuro · 2017-05-13T17:21:21Z

jaeger-core/src/test/java/com/uber/jaeger/reporters/RemoteReporterTest.java

+    }
+
+    // When: at this point the queue is full or there is one slot empty (if the worker thread has
+    // already picked up some command). We add two spans to make sure that we overfill the queue


if the workers are still reading from the queue, then it looks like you have a race condition and no guarantee that the next two commands would actually cause a queue overflow

That's why I changed InMemorySender to become blocking:

// change sender to blocking mode sender.permitAppend(0);

Thanks to this nothing is processing the queue - QueueProcessor picks only 1 AppendCommand and blocks on the append call.
So this test:

adds maxQueueSize spans to the queue

QueueProcessor takes 1 commands and blocks

adds additional span to make the queue full

adds one more span and it is dropped without throwing exception

Point 2 sometimes might not happen (due to scheduling) - then both span from points 3) and 4) are dropped.

I tried to come with some simple way of testing various cases without possibility of race conditions - adding that semaphore/permits to InMemorySender was the simplest solution I could find.

When the command queue is full further FlushCommands are not enqueued and queue length metric does not update. I moved it outside the command - now it updates whenever scheduled flush() executes.

yurishkuro · 2017-05-14T21:03:18Z

jaeger-core/src/main/java/com/uber/jaeger/reporters/RemoteReporter.java

  }

  @Override
  public void close() {
-    commandQueue.add(new CloseCommand());
+    boolean closeCommandAdded = false;
+    try {


was just having a second look - why do we need a separate try/catch? Seems like you can just call offer in L102

You're right - removed

yurishkuro · 2017-05-14T23:04:48Z

Thanks, @mabn

Marcin Biegan added 2 commits May 13, 2017 17:39

Fix RemoteReport race condition when queue is full

8242beb

The check “commandQueue.size() == maxQueueSize” is not thread safe, this lead to: java.lang.IllegalStateException: Queue full It’s better to .offer() and check the returned value

mabn commented May 13, 2017

View reviewed changes

code style & spelling

4952d49

yurishkuro reviewed May 13, 2017

View reviewed changes

Apply improvements suggested in the PR comments

e34f389

yurishkuro mentioned this pull request May 14, 2017

RemoteReporter throws exception when commandQueue is full #178

Closed

RemoteReporter’s queue length update when queue full

569807c

When the command queue is full further FlushCommands are not enqueued and queue length metric does not update. I moved it outside the command - now it updates whenever scheduled flush() executes.

yurishkuro reviewed May 14, 2017

View reviewed changes

Marcin Biegan and others added 2 commits May 15, 2017 00:11

Remove unnecessary try-catch

9257c14

Merge branch 'master' into full_remote_reporter

e3653d1

yurishkuro approved these changes May 14, 2017

View reviewed changes

yurishkuro merged commit 4c06ea6 into jaegertracing:master May 14, 2017

jkandasa mentioned this pull request May 17, 2017

[jaeger-core:test] testRemoteReporterReport failing randomly #177

Merged

pavolloffay mentioned this pull request May 10, 2019

Automatically generate changelog #629

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Handle full queue in RemoteReporter #180

Handle full queue in RemoteReporter #180

mabn commented May 13, 2017 •

edited by yurishkuro

Loading

mabn May 13, 2017

codecov-io commented May 13, 2017 •

edited

Loading

yurishkuro May 13, 2017

mabn May 13, 2017

yurishkuro May 13, 2017

mabn May 14, 2017

yurishkuro May 13, 2017

yurishkuro May 13, 2017

mabn May 13, 2017

yurishkuro May 14, 2017

mabn May 14, 2017

yurishkuro commented May 14, 2017


		/**
		* InMemorySender "appends" span only earlier "append" was permitted. Appending is a blocking

Handle full queue in RemoteReporter #180

Handle full queue in RemoteReporter #180

Conversation

mabn commented May 13, 2017 • edited by yurishkuro Loading

Choose a reason for hiding this comment

codecov-io commented May 13, 2017 • edited Loading

Codecov Report

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

yurishkuro commented May 14, 2017

mabn commented May 13, 2017 •

edited by yurishkuro

Loading

codecov-io commented May 13, 2017 •

edited

Loading