NIFI-3229 When a queue contains only Penalized FlowFile's the next pr…

[patricker]

…ocessor Tasks/Time statistics becomes extremely large

For all changes:

• Is there a JIRA ticket associated with this PR? Is it referenced
  in the commit message?

• Does your PR title start with NIFI-XXXX where XXXX is the JIRA number you are trying to resolve? Pay particular attention to the hyphen "-" character.

• Has your PR been rebased against the latest commit within the target branch (typically master)?

• Is your initial contribution a single, squashed commit?

For code changes:

• Have you ensured that the full suite of tests is executed via mvn -Pcontrib-check clean install at the root nifi folder?
• Have you written or updated unit tests to verify your changes?
• If adding new dependencies to the code, are these dependencies licensed in a way that is compatible for inclusion under ASF 2.0?
• If applicable, have you updated the LICENSE file, including the main LICENSE file under nifi-assembly?
• If applicable, have you updated the NOTICE file, including the main NOTICE file found under nifi-assembly?
• If adding new Properties, have you added .displayName in addition to .name (programmatic access) for each of the new properties?

For documentation related changes:

• Have you ensured that format looks appropriate for the output in which it is rendered?

Note:

Please ensure that once the PR is submitted, you check travis-ci for build issues and submit an update to your PR as soon as possible.

[markap14]

@patricker thanks for the PR! I had gone down this path before but I backed out the changes. The changes in this PR will result in obtaining a Write Lock on the queue of every incoming connection for every running processor in the graph. This can become quite expensive for a complex flow that is made up of thousands (or even 10's of thousands) of processors) and result in overall system performance suffering. This is why we are so care in the FlowFile Queue's implementation to ensure that isActiveQueueEmpty() never obtains a lock but instead only references AtomicReference variables.

We should be able to do better, though. For example, when we pull a FlowFile from the queue, we check if it's penalized. If so, we throw it back on. Since the queue is ordered, we could do some smart things like looking at the FlowFile expiration date, then keeping track of the fact that we know all FlowFiles are penalized until that time is reached - or until a non-penalized FlowFile is added to the queue.

[patricker]

@markap14 I was worried about the same thing, which is why the if statement is structured as it is. First, we do the standard check on isActiveQueueEmpty. This happens in the code now as you mentioned, and right now if this passes we create a writelock, migrateSwapToActive(), and call the processor.

All my change does is add one additional check, but only if isActiveQueueEmpty is already passing. So as far as I can tell, I'm locking one extra time for a queue that is already going to get locked, but not locking any queues that would not already get locked. Also, because I'm calling migrateSwapToActive() during my check, when the processor does get called the lock for the second run of this method should not last as long as it would otherwise, as there is less work to do. So overall lock time should be affected only minimally. Thoughts?

[markap14]

@patricker you're right - it may perform just fine. However, the concern is not that we are holding a lock longer but rather that we are obtaining it twice as often now when there's data queued. The acquisition of the lock itself can be expensive. So all I am suggesting is that we don't want to make such a change without knowing how it's going to affect things. We'd want to gather some performance numbers before and after this changeset is applied.

Specifically, I'd want to setup a test suite that calculates things like:
How long does it take to check if there are FlowFiles queued 10 million times when there are no FlowFiles queued?
How long does it take to check if there are FlowFiles queued 10 million times when there are FlowFiles queued?
How do these numbers change when you have 1 thread vs. 2 threads vs. 12 threads vs. 25 threads?

I'd want to run these tests 10-20 times in a row to ensure that the numbers are steady, and then get these numbers before and after the changeset is applied.
If the worst-case differs by say 5% then it's probably fine. If the worse case differs by say 50% then it probably makes sense to look for a different solution.

[patricker]

@markap14 Sounds reasonable, I'll work on it.

[patricker]

@markap14 I built unit tests, but I'm having trouble running them at scale. I temporarily checked back in the original method so I could run side-by-side speed comparisons on the same Connectable. But if I exceed about 100k tests my unit tests seem to go out to lunch, even if I increase heap so they don't run out.

These are checked in right now to run 1 million iterations, but that has not succeeded for me... This is true of the unmodified method if run by itself also (at least on my poor little computer).

[markap14]

Hey @patricker sorry for the delay in getting back to this. I looked into the unit tests, and did some quick profiling. It looks like the reason that it seemed to "go out to lunch" as you say was because of Mockito objects being used. They are super useful but don't provide great performance. I updated the test so that instead of using Mockito it just created simple objects like Funnels or implemented interfaces directly without much of anything happening. That resulted in much better performance.

I updated the test about to run in multiple threads, as well, because this is where we are going to see the heavy contention and therefore the performance concerns. When I run with a single thread, we see pretty comparable results between the existing implementation and the new implementation that checks for penalization:

1M checks for FlowFiles, non-empty queue: 57 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 101 millis

1M checks for FlowFiles, non-empty queue: 47 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 67 millis

1M checks for FlowFiles, non-empty queue: 60 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 77 millis

1M checks for FlowFiles, non-empty queue: 38 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 66 millis

1M checks for FlowFiles, non-empty queue: 34 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 54 millis

1M checks for FlowFiles, non-empty queue: 28 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 91 millis

1M checks for FlowFiles, non-empty queue: 67 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 96 millis

1M checks for FlowFiles, non-empty queue: 35 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 59 millis

1M checks for FlowFiles, non-empty queue: 29 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 55 millis

1M checks for FlowFiles, non-empty queue: 36 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 50 millis

The difference is measurable but not necessarily concerning.
At 2 threads, the performance is more concerning but still not necessarily a deal breaker:

1M checks for FlowFiles, non-empty queue: 314 millis
1M checks for FlowFiles, non-empty queue: 315 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 410 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 412 millis

1M checks for FlowFiles, non-empty queue: 240 millis
1M checks for FlowFiles, non-empty queue: 240 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 166 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 167 millis

1M checks for FlowFiles, non-empty queue: 235 millis
1M checks for FlowFiles, non-empty queue: 236 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 510 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 510 millis

1M checks for FlowFiles, non-empty queue: 225 millis
1M checks for FlowFiles, non-empty queue: 227 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 3 seconds, 994 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 3 seconds, 995 millis

1M checks for FlowFiles, non-empty queue: 239 millis
1M checks for FlowFiles, non-empty queue: 239 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 102 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 102 millis

1M checks for FlowFiles, non-empty queue: 229 millis
1M checks for FlowFiles, non-empty queue: 231 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 634 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 634 millis

1M checks for FlowFiles, non-empty queue: 234 millis
1M checks for FlowFiles, non-empty queue: 235 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 3 seconds, 732 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 3 seconds, 732 millis

1M checks for FlowFiles, non-empty queue: 231 millis
1M checks for FlowFiles, non-empty queue: 233 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 252 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 253 millis

1M checks for FlowFiles, non-empty queue: 231 millis
1M checks for FlowFiles, non-empty queue: 231 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 195 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 195 millis

1M checks for FlowFiles, non-empty queue: 235 millis
1M checks for FlowFiles, non-empty queue: 237 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 89 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 4 seconds, 89 millis

However, when we update the test to use 12 threads, we see some results that are more concerning:

1M checks for FlowFiles, non-empty queue: 4 seconds, 430 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 463 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 486 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 331 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 316 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 484 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 517 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 357 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 357 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 349 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 478 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 372 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 435 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 31 seconds, 434 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 142 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 422 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 444 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 513 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 520 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 567 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 572 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 579 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 587 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 586 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 582 millis
1M checks for FlowFiles, non-empty queue: 4 seconds, 594 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 21 seconds, 787 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 755 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 772 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 777 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 780 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 794 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 804 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 813 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 819 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 819 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 807 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 810 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 802 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 8 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 9 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 16 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 16 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 15 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 10 seconds, 16 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 469 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 481 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 479 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 521 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 544 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 553 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 575 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 566 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 581 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 582 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 583 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 572 millis

1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 926 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 960 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-penalized method, non-empty queue: 1 minutes, 19 seconds, 965 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 724 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 745 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 761 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 764 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 776 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 774 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 800 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 800 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 802 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 803 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 805 millis
1M checks for FlowFiles, non-empty queue: 2 seconds, 795 millis

So with 12 threads, each checking 1 million times, the difference in performance/latency goes from 2-3 seconds to 70-90 seconds.

We can also see what happens to the CPU utilization as it switches between the version that checks penalization and the one that doesn't:

So at one thread, I'm not concerned about the performance difference. But if you start adding several threads to a processor, the performance concern is definitely more significant and I think is concerning.