Strange FJP behavior (bug?)

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Strange FJP behavior (bug?)

JSR166 Concurrency mailing list
Experts,

We've observed, and isolated, a strange behavior with ForkJoinPool in relation to capped ForkJoinThreadWorkerFactories and ManagedBlocker code followed by unmanaged blocking.

Expected behavior:
Pool scales up to the limit of workers as given by the pool, as a result of the managed blocking, then either terminates those extra threads or uses them to help out processing the work.

Observed behavior:
Threads are created during the managed blocking, but then get stuck in this stack frame:

sun.misc.Unsafe.park(Native Method)
java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

And only a single thread continues to process the rest of the workload, one item at a time!



Reproducer code (Foo.java) just compile with javac and then run with java, no parameters needed:

package test;

import java.time.Instant;
import java.util.function.Function;
import java.util.stream.Stream;
import java.util.concurrent.ForkJoinPool;
import java.util.concurrent.ForkJoinWorkerThread;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;

public final class Foo {

  public final static int MAX_THREADS = 128;
  public final static int MAX_BLOCKERS = 256;
  public final static int CORES = Runtime.getRuntime().availableProcessors();

  public static final class FJWTF extends AtomicInteger implements ForkJoinPool.ForkJoinWorkerThreadFactory {
    private final boolean allocate() {
       for(;;) {
         final int current = get();
         if (current == MAX_THREADS || current == Integer.MAX_VALUE) return false;
         else if (compareAndSet(current, current + 1)) return true;
       }
    }

    private final boolean deallocate() {
      for(;;) {
         final int current = get();
         if (current == 0) return false;
         else if (compareAndSet(current, current - 1)) return true;
       }
    }

    public ForkJoinWorkerThread newThread(final ForkJoinPool fjp) {
      if (allocate()) {
        final ForkJoinWorkerThread worker = new ForkJoinWorkerThread(fjp) {
          @Override public void onTermination(final Throwable cause) {
            try {
              deallocate();
            } finally {
              super.onTermination(cause);
            }
          }
        };
        return worker;
      } else return null;
    }
  };

  static String printAndGetTime(final String prefix, String name) {
    try {
    final String t = Thread.currentThread().toString();
    System.out.println(t + " started " + prefix + " " + name);
    final Instant now = Instant.now();
    Thread.sleep(1000);
    final String res = t + " finished " + prefix + " " + name + " : " + now;
    System.out.println(res);
    return res;
    } catch (final InterruptedException ie) {
      Thread.currentThread().interrupt();
      return "interrupted";
    }
  }

  static CompletableFuture<Void> generate(final int n, Function<String, CompletableFuture<String>> f) {
    return CompletableFuture.allOf(Stream.iterate(0, i -> i + 1).limit(n).map(String::valueOf).map(f).toArray(CompletableFuture[]::new));
  }

  static CompletableFuture<Void> managedBlockers(final int n, final ForkJoinPool fjp) {
    return generate(n, (String name) -> {
        return CompletableFuture.completedFuture("").thenApplyAsync(unused ->
            {
              try {
                ForkJoinPool.managedBlock(new ForkJoinPool.ManagedBlocker() {
                  @Override public boolean block() {
                    printAndGetTime("managed", name);
                    return true;
                  }
                  @Override public boolean isReleasable() { return false; }
                });
              } catch (final InterruptedException ie) {
                Thread.currentThread().interrupt();
              }
            return name;
          }, fjp);
      });
  }

  static CompletableFuture<Void> unmanagedBlockers(final int n, final ForkJoinPool fjp) {
    return generate(n, (String name) -> CompletableFuture.completedFuture("").thenApplyAsync(unused -> printAndGetTime("unmanaged", name), fjp));
  }

  public static void main(final String[] args) throws Exception {
    final ForkJoinPool fjp = new ForkJoinPool(CORES, new FJWTF(), (t, c) -> c.printStackTrace(System.err),true);
    final int n = CORES + MAX_BLOCKERS;

    CompletableFuture.completedFuture("").
      thenComposeAsync(unused -> managedBlockers(n,fjp), fjp).
      thenComposeAsync(unused -> unmanagedBlockers(n, fjp), fjp).
      get(100, TimeUnit.SECONDS);

    fjp.shutdownNow();
  }
 
}

Sample output:

Thread[ForkJoinPool-1-worker-0,5,main] started managed 2
Thread[ForkJoinPool-1-worker-3,5,main] started managed 1
Thread[ForkJoinPool-1-worker-2,5,main] started managed 0
Thread[ForkJoinPool-1-worker-1,5,main] started managed 3
Thread[ForkJoinPool-1-worker-4,5,main] started managed 4
Thread[ForkJoinPool-1-worker-6,5,main] started managed 5
Thread[ForkJoinPool-1-worker-7,5,main] started managed 6
Thread[ForkJoinPool-1-worker-5,5,main] started managed 7
Thread[ForkJoinPool-1-worker-11,5,main] started managed 8
Thread[ForkJoinPool-1-worker-10,5,main] started managed 9
Thread[ForkJoinPool-1-worker-12,5,main] started managed 10
Thread[ForkJoinPool-1-worker-14,5,main] started managed 11
Thread[ForkJoinPool-1-worker-9,5,main] started managed 12
Thread[ForkJoinPool-1-worker-13,5,main] started managed 13
Thread[ForkJoinPool-1-worker-15,5,main] started managed 14
Thread[ForkJoinPool-1-worker-8,5,main] started managed 15
Thread[ForkJoinPool-1-worker-18,5,main] started managed 16
Thread[ForkJoinPool-1-worker-19,5,main] started managed 17
Thread[ForkJoinPool-1-worker-27,5,main] started managed 18
Thread[ForkJoinPool-1-worker-20,5,main] started managed 19
Thread[ForkJoinPool-1-worker-30,5,main] started managed 20
Thread[ForkJoinPool-1-worker-23,5,main] started managed 21
Thread[ForkJoinPool-1-worker-31,5,main] started managed 22
Thread[ForkJoinPool-1-worker-24,5,main] started managed 23
Thread[ForkJoinPool-1-worker-17,5,main] started managed 24
Thread[ForkJoinPool-1-worker-29,5,main] started managed 25
Thread[ForkJoinPool-1-worker-22,5,main] started managed 26
Thread[ForkJoinPool-1-worker-28,5,main] started managed 27
Thread[ForkJoinPool-1-worker-21,5,main] started managed 28
Thread[ForkJoinPool-1-worker-16,5,main] started managed 29
Thread[ForkJoinPool-1-worker-26,5,main] started managed 30
Thread[ForkJoinPool-1-worker-25,5,main] started managed 31
Thread[ForkJoinPool-1-worker-42,5,main] started managed 32
Thread[ForkJoinPool-1-worker-51,5,main] started managed 33
Thread[ForkJoinPool-1-worker-44,5,main] started managed 34
Thread[ForkJoinPool-1-worker-37,5,main] started managed 35
Thread[ForkJoinPool-1-worker-61,5,main] started managed 36
Thread[ForkJoinPool-1-worker-54,5,main] started managed 37
Thread[ForkJoinPool-1-worker-47,5,main] started managed 38
Thread[ForkJoinPool-1-worker-40,5,main] started managed 39
Thread[ForkJoinPool-1-worker-33,5,main] started managed 40
Thread[ForkJoinPool-1-worker-59,5,main] started managed 41
Thread[ForkJoinPool-1-worker-52,5,main] started managed 42
Thread[ForkJoinPool-1-worker-45,5,main] started managed 43
Thread[ForkJoinPool-1-worker-38,5,main] started managed 44
Thread[ForkJoinPool-1-worker-62,5,main] started managed 45
Thread[ForkJoinPool-1-worker-55,5,main] started managed 46
Thread[ForkJoinPool-1-worker-48,5,main] started managed 47
Thread[ForkJoinPool-1-worker-41,5,main] started managed 48
Thread[ForkJoinPool-1-worker-34,5,main] started managed 49
Thread[ForkJoinPool-1-worker-60,5,main] started managed 50
Thread[ForkJoinPool-1-worker-53,5,main] started managed 51
Thread[ForkJoinPool-1-worker-46,5,main] started managed 52
Thread[ForkJoinPool-1-worker-39,5,main] started managed 53
Thread[ForkJoinPool-1-worker-63,5,main] started managed 54
Thread[ForkJoinPool-1-worker-56,5,main] started managed 55
Thread[ForkJoinPool-1-worker-49,5,main] started managed 56
Thread[ForkJoinPool-1-worker-50,5,main] started managed 57
Thread[ForkJoinPool-1-worker-35,5,main] started managed 58
Thread[ForkJoinPool-1-worker-32,5,main] started managed 59
Thread[ForkJoinPool-1-worker-58,5,main] started managed 60
Thread[ForkJoinPool-1-worker-57,5,main] started managed 61
Thread[ForkJoinPool-1-worker-43,5,main] started managed 62
Thread[ForkJoinPool-1-worker-36,5,main] started managed 63
Thread[ForkJoinPool-1-worker-90,5,main] started managed 64
Thread[ForkJoinPool-1-worker-115,5,main] started managed 65
Thread[ForkJoinPool-1-worker-107,5,main] started managed 66
Thread[ForkJoinPool-1-worker-71,5,main] started managed 126
Thread[ForkJoinPool-1-worker-86,5,main] started managed 125
Thread[ForkJoinPool-1-worker-85,5,main] started managed 124
Thread[ForkJoinPool-1-worker-72,5,main] started managed 123
Thread[ForkJoinPool-1-worker-99,5,main] started managed 122
Thread[ForkJoinPool-1-worker-64,5,main] started managed 121
Thread[ForkJoinPool-1-worker-113,5,main] started managed 120
Thread[ForkJoinPool-1-worker-121,5,main] started managed 119
Thread[ForkJoinPool-1-worker-127,5,main] started managed 118
Thread[ForkJoinPool-1-worker-70,5,main] started managed 117
Thread[ForkJoinPool-1-worker-78,5,main] started managed 116
Thread[ForkJoinPool-1-worker-84,5,main] started managed 115
Thread[ForkJoinPool-1-worker-100,5,main] started managed 114
Thread[ForkJoinPool-1-worker-98,5,main] started managed 113
Thread[ForkJoinPool-1-worker-106,5,main] started managed 112
Thread[ForkJoinPool-1-worker-112,5,main] started managed 111
Thread[ForkJoinPool-1-worker-120,5,main] started managed 110
Thread[ForkJoinPool-1-worker-126,5,main] started managed 109
Thread[ForkJoinPool-1-worker-69,5,main] started managed 108
Thread[ForkJoinPool-1-worker-77,5,main] started managed 107
Thread[ForkJoinPool-1-worker-83,5,main] started managed 106
Thread[ForkJoinPool-1-worker-91,5,main] started managed 105
Thread[ForkJoinPool-1-worker-97,5,main] started managed 104
Thread[ForkJoinPool-1-worker-105,5,main] started managed 103
Thread[ForkJoinPool-1-worker-111,5,main] started managed 102
Thread[ForkJoinPool-1-worker-119,5,main] started managed 101
Thread[ForkJoinPool-1-worker-125,5,main] started managed 100
Thread[ForkJoinPool-1-worker-68,5,main] started managed 99
Thread[ForkJoinPool-1-worker-76,5,main] started managed 98
Thread[ForkJoinPool-1-worker-82,5,main] started managed 97
Thread[ForkJoinPool-1-worker-92,5,main] started managed 96
Thread[ForkJoinPool-1-worker-96,5,main] started managed 95
Thread[ForkJoinPool-1-worker-104,5,main] started managed 94
Thread[ForkJoinPool-1-worker-110,5,main] started managed 93
Thread[ForkJoinPool-1-worker-118,5,main] started managed 92
Thread[ForkJoinPool-1-worker-124,5,main] started managed 91
Thread[ForkJoinPool-1-worker-67,5,main] started managed 90
Thread[ForkJoinPool-1-worker-75,5,main] started managed 89
Thread[ForkJoinPool-1-worker-81,5,main] started managed 88
Thread[ForkJoinPool-1-worker-89,5,main] started managed 87
Thread[ForkJoinPool-1-worker-95,5,main] started managed 86
Thread[ForkJoinPool-1-worker-103,5,main] started managed 85
Thread[ForkJoinPool-1-worker-109,5,main] started managed 84
Thread[ForkJoinPool-1-worker-117,5,main] started managed 83
Thread[ForkJoinPool-1-worker-123,5,main] started managed 82
Thread[ForkJoinPool-1-worker-66,5,main] started managed 81
Thread[ForkJoinPool-1-worker-74,5,main] started managed 80
Thread[ForkJoinPool-1-worker-80,5,main] started managed 79
Thread[ForkJoinPool-1-worker-88,5,main] started managed 78
Thread[ForkJoinPool-1-worker-94,5,main] started managed 77
Thread[ForkJoinPool-1-worker-102,5,main] started managed 76
Thread[ForkJoinPool-1-worker-108,5,main] started managed 75
Thread[ForkJoinPool-1-worker-116,5,main] started managed 74
Thread[ForkJoinPool-1-worker-122,5,main] started managed 73
Thread[ForkJoinPool-1-worker-65,5,main] started managed 72
Thread[ForkJoinPool-1-worker-73,5,main] started managed 71
Thread[ForkJoinPool-1-worker-79,5,main] started managed 70
Thread[ForkJoinPool-1-worker-87,5,main] started managed 69
Thread[ForkJoinPool-1-worker-93,5,main] started managed 68
Thread[ForkJoinPool-1-worker-101,5,main] started managed 67
Thread[ForkJoinPool-1-worker-114,5,main] started managed 127
Thread[ForkJoinPool-1-worker-115,5,main] finished managed 65 : 2018-04-10T12:21:37.324Z
Thread[ForkJoinPool-1-worker-3,5,main] finished managed 1 : 2018-04-10T12:21:37.301Z
Thread[ForkJoinPool-1-worker-48,5,main] finished managed 47 : 2018-04-10T12:21:37.319Z
Thread[ForkJoinPool-1-worker-115,5,main] started managed 128
Thread[ForkJoinPool-1-worker-48,5,main] started managed 129
Thread[ForkJoinPool-1-worker-3,5,main] started managed 130
Thread[ForkJoinPool-1-worker-5,5,main] finished managed 7 : 2018-04-10T12:21:37.303Z
Thread[ForkJoinPool-1-worker-1,5,main] finished managed 3 : 2018-04-10T12:21:37.302Z
Thread[ForkJoinPool-1-worker-1,5,main] started managed 132
Thread[ForkJoinPool-1-worker-6,5,main] finished managed 5 : 2018-04-10T12:21:37.303Z
Thread[ForkJoinPool-1-worker-6,5,main] started managed 133
Thread[ForkJoinPool-1-worker-4,5,main] finished managed 4 : 2018-04-10T12:21:37.302Z
Thread[ForkJoinPool-1-worker-35,5,main] finished managed 58 : 2018-04-10T12:21:37.322Z
Thread[ForkJoinPool-1-worker-11,5,main] finished managed 8 : 2018-04-10T12:21:37.304Z
Thread[ForkJoinPool-1-worker-35,5,main] started managed 135
Thread[ForkJoinPool-1-worker-40,5,main] finished managed 39 : 2018-04-10T12:21:37.313Z
Thread[ForkJoinPool-1-worker-12,5,main] finished managed 10 : 2018-04-10T12:21:37.304Z
Thread[ForkJoinPool-1-worker-10,5,main] finished managed 9 : 2018-04-10T12:21:37.304Z
Thread[ForkJoinPool-1-worker-33,5,main] finished managed 40 : 2018-04-10T12:21:37.313Z
Thread[ForkJoinPool-1-worker-36,5,main] finished managed 63 : 2018-04-10T12:21:37.324Z
Thread[ForkJoinPool-1-worker-7,5,main] finished managed 6 : 2018-04-10T12:21:37.303Z
Thread[ForkJoinPool-1-worker-36,5,main] started managed 141
Thread[ForkJoinPool-1-worker-7,5,main] started managed 142
Thread[ForkJoinPool-1-worker-59,5,main] finished managed 41 : 2018-04-10T12:21:37.313Z
Thread[ForkJoinPool-1-worker-41,5,main] finished managed 48 : 2018-04-10T12:21:37.319Z
Thread[ForkJoinPool-1-worker-61,5,main] finished managed 36 : 2018-04-10T12:21:37.312Z
Thread[ForkJoinPool-1-worker-8,5,main] finished managed 15 : 2018-04-10T12:21:37.306Z
Thread[ForkJoinPool-1-worker-9,5,main] finished managed 12 : 2018-04-10T12:21:37.305Z
Thread[ForkJoinPool-1-worker-8,5,main] started managed 146
Thread[ForkJoinPool-1-worker-33,5,main] started managed 140
Thread[ForkJoinPool-1-worker-18,5,main] finished managed 16 : 2018-04-10T12:21:37.306Z
Thread[ForkJoinPool-1-worker-18,5,main] started managed 148
Thread[ForkJoinPool-1-worker-10,5,main] started managed 139
Thread[ForkJoinPool-1-worker-62,5,main] finished managed 45 : 2018-04-10T12:21:37.318Z
Thread[ForkJoinPool-1-worker-62,5,main] started managed 149
Thread[ForkJoinPool-1-worker-14,5,main] finished managed 11 : 2018-04-10T12:21:37.304Z
Thread[ForkJoinPool-1-worker-14,5,main] started managed 150
Thread[ForkJoinPool-1-worker-19,5,main] finished managed 17 : 2018-04-10T12:21:37.306Z
Thread[ForkJoinPool-1-worker-19,5,main] started managed 151
Thread[ForkJoinPool-1-worker-12,5,main] started managed 138
Thread[ForkJoinPool-1-worker-40,5,main] started managed 137
Thread[ForkJoinPool-1-worker-44,5,main] finished managed 34 : 2018-04-10T12:21:37.311Z
Thread[ForkJoinPool-1-worker-44,5,main] started managed 152
Thread[ForkJoinPool-1-worker-57,5,main] finished managed 61 : 2018-04-10T12:21:37.323Z
Thread[ForkJoinPool-1-worker-23,5,main] finished managed 21 : 2018-04-10T12:21:37.307Z
Thread[ForkJoinPool-1-worker-90,5,main] finished managed 64 : 2018-04-10T12:21:37.324Z
Thread[ForkJoinPool-1-worker-11,5,main] started managed 136
Thread[ForkJoinPool-1-worker-54,5,main] finished managed 37 : 2018-04-10T12:21:37.312Z
Thread[ForkJoinPool-1-worker-31,5,main] finished managed 22 : 2018-04-10T12:21:37.308Z
Thread[ForkJoinPool-1-worker-54,5,main] started managed 156
Thread[ForkJoinPool-1-worker-90,5,main] started managed 155
Thread[ForkJoinPool-1-worker-4,5,main] started managed 134
Thread[ForkJoinPool-1-worker-34,5,main] finished managed 49 : 2018-04-10T12:21:37.319Z
Thread[ForkJoinPool-1-worker-53,5,main] finished managed 51 : 2018-04-10T12:21:37.320Z
Thread[ForkJoinPool-1-worker-53,5,main] started managed 159
Thread[ForkJoinPool-1-worker-2,5,main] finished managed 0 : 2018-04-10T12:21:37.301Z
Thread[ForkJoinPool-1-worker-42,5,main] finished managed 32 : 2018-04-10T12:21:37.311Z
Thread[ForkJoinPool-1-worker-42,5,main] started managed 161
Thread[ForkJoinPool-1-worker-47,5,main] finished managed 38 : 2018-04-10T12:21:37.312Z
Thread[ForkJoinPool-1-worker-49,5,main] finished managed 56 : 2018-04-10T12:21:37.321Z
Thread[ForkJoinPool-1-worker-47,5,main] started managed 162
Thread[ForkJoinPool-1-worker-5,5,main] started managed 131
Thread[ForkJoinPool-1-worker-56,5,main] finished managed 55 : 2018-04-10T12:21:37.321Z
Thread[ForkJoinPool-1-worker-56,5,main] started managed 164
Thread[ForkJoinPool-1-worker-16,5,main] finished managed 29 : 2018-04-10T12:21:37.310Z
Thread[ForkJoinPool-1-worker-58,5,main] finished managed 60 : 2018-04-10T12:21:37.323Z
Thread[ForkJoinPool-1-worker-58,5,main] started managed 166
Thread[ForkJoinPool-1-worker-50,5,main] finished managed 57 : 2018-04-10T12:21:37.322Z
Thread[ForkJoinPool-1-worker-50,5,main] started managed 167
Thread[ForkJoinPool-1-worker-52,5,main] finished managed 42 : 2018-04-10T12:21:37.314Z
Thread[ForkJoinPool-1-worker-21,5,main] finished managed 28 : 2018-04-10T12:21:37.309Z
Thread[ForkJoinPool-1-worker-21,5,main] started managed 169
Thread[ForkJoinPool-1-worker-28,5,main] finished managed 27 : 2018-04-10T12:21:37.309Z
Thread[ForkJoinPool-1-worker-28,5,main] started managed 170
Thread[ForkJoinPool-1-worker-49,5,main] started managed 163
Thread[ForkJoinPool-1-worker-43,5,main] finished managed 62 : 2018-04-10T12:21:37.323Z
Thread[ForkJoinPool-1-worker-43,5,main] started managed 171
Thread[ForkJoinPool-1-worker-22,5,main] finished managed 26 : 2018-04-10T12:21:37.309Z
Thread[ForkJoinPool-1-worker-22,5,main] started managed 172
Thread[ForkJoinPool-1-worker-51,5,main] finished managed 33 : 2018-04-10T12:21:37.311Z
Thread[ForkJoinPool-1-worker-0,5,main] finished managed 2 : 2018-04-10T12:21:37.301Z
Thread[ForkJoinPool-1-worker-0,5,main] started managed 174
Thread[ForkJoinPool-1-worker-2,5,main] started managed 160
Thread[ForkJoinPool-1-worker-29,5,main] finished managed 25 : 2018-04-10T12:21:37.308Z
Thread[ForkJoinPool-1-worker-29,5,main] started managed 175
Thread[ForkJoinPool-1-worker-37,5,main] finished managed 35 : 2018-04-10T12:21:37.311Z
Thread[ForkJoinPool-1-worker-34,5,main] started managed 158
Thread[ForkJoinPool-1-worker-17,5,main] finished managed 24 : 2018-04-10T12:21:37.308Z
Thread[ForkJoinPool-1-worker-39,5,main] finished managed 53 : 2018-04-10T12:21:37.320Z
Thread[ForkJoinPool-1-worker-24,5,main] finished managed 23 : 2018-04-10T12:21:37.308Z
Thread[ForkJoinPool-1-worker-24,5,main] started managed 179
Thread[ForkJoinPool-1-worker-32,5,main] finished managed 59 : 2018-04-10T12:21:37.322Z
Thread[ForkJoinPool-1-worker-31,5,main] started managed 157
Thread[ForkJoinPool-1-worker-23,5,main] started managed 154
Thread[ForkJoinPool-1-worker-57,5,main] started managed 153
Thread[ForkJoinPool-1-worker-30,5,main] finished managed 20 : 2018-04-10T12:21:37.307Z
Thread[ForkJoinPool-1-worker-20,5,main] finished managed 19 : 2018-04-10T12:21:37.307Z
Thread[ForkJoinPool-1-worker-30,5,main] started managed 181
Thread[ForkJoinPool-1-worker-27,5,main] finished managed 18 : 2018-04-10T12:21:37.306Z
Thread[ForkJoinPool-1-worker-55,5,main] finished managed 46 : 2018-04-10T12:21:37.318Z
Thread[ForkJoinPool-1-worker-60,5,main] finished managed 50 : 2018-04-10T12:21:37.319Z
Thread[ForkJoinPool-1-worker-9,5,main] started managed 147
Thread[ForkJoinPool-1-worker-61,5,main] started managed 145
Thread[ForkJoinPool-1-worker-41,5,main] started managed 144
Thread[ForkJoinPool-1-worker-59,5,main] started managed 143
Thread[ForkJoinPool-1-worker-15,5,main] finished managed 14 : 2018-04-10T12:21:37.305Z
Thread[ForkJoinPool-1-worker-13,5,main] finished managed 13 : 2018-04-10T12:21:37.305Z
Thread[ForkJoinPool-1-worker-38,5,main] finished managed 44 : 2018-04-10T12:21:37.318Z
Thread[ForkJoinPool-1-worker-13,5,main] started managed 187
Thread[ForkJoinPool-1-worker-15,5,main] started managed 186
Thread[ForkJoinPool-1-worker-60,5,main] started managed 185
Thread[ForkJoinPool-1-worker-55,5,main] started managed 184
Thread[ForkJoinPool-1-worker-27,5,main] started managed 183
Thread[ForkJoinPool-1-worker-20,5,main] started managed 182
Thread[ForkJoinPool-1-worker-32,5,main] started managed 180
Thread[ForkJoinPool-1-worker-39,5,main] started managed 178
Thread[ForkJoinPool-1-worker-17,5,main] started managed 177
Thread[ForkJoinPool-1-worker-37,5,main] started managed 176
Thread[ForkJoinPool-1-worker-51,5,main] started managed 173
Thread[ForkJoinPool-1-worker-45,5,main] finished managed 43 : 2018-04-10T12:21:37.314Z
Thread[ForkJoinPool-1-worker-26,5,main] finished managed 30 : 2018-04-10T12:21:37.310Z
Thread[ForkJoinPool-1-worker-25,5,main] finished managed 31 : 2018-04-10T12:21:37.310Z
Thread[ForkJoinPool-1-worker-52,5,main] started managed 168
Thread[ForkJoinPool-1-worker-63,5,main] finished managed 54 : 2018-04-10T12:21:37.321Z
Thread[ForkJoinPool-1-worker-16,5,main] started managed 165
Thread[ForkJoinPool-1-worker-46,5,main] finished managed 52 : 2018-04-10T12:21:37.320Z
Thread[ForkJoinPool-1-worker-63,5,main] started managed 192
Thread[ForkJoinPool-1-worker-46,5,main] started managed 193
Thread[ForkJoinPool-1-worker-26,5,main] started managed 190
Thread[ForkJoinPool-1-worker-25,5,main] started managed 191
Thread[ForkJoinPool-1-worker-45,5,main] started managed 189
Thread[ForkJoinPool-1-worker-38,5,main] started managed 188
Thread[ForkJoinPool-1-worker-86,5,main] finished managed 125 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-85,5,main] finished managed 124 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-72,5,main] finished managed 123 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-72,5,main] started managed 196
Thread[ForkJoinPool-1-worker-64,5,main] finished managed 121 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-121,5,main] finished managed 119 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-127,5,main] finished managed 118 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-70,5,main] finished managed 117 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-78,5,main] finished managed 116 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-78,5,main] started managed 201
Thread[ForkJoinPool-1-worker-100,5,main] finished managed 114 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-100,5,main] started managed 202
Thread[ForkJoinPool-1-worker-112,5,main] finished managed 111 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-112,5,main] started managed 203
Thread[ForkJoinPool-1-worker-77,5,main] finished managed 107 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-77,5,main] started managed 204
Thread[ForkJoinPool-1-worker-91,5,main] finished managed 105 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-91,5,main] started managed 205
Thread[ForkJoinPool-1-worker-125,5,main] finished managed 100 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-76,5,main] finished managed 98 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-125,5,main] started managed 206
Thread[ForkJoinPool-1-worker-107,5,main] finished managed 66 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-127,5,main] started managed 199
Thread[ForkJoinPool-1-worker-107,5,main] started managed 208
Thread[ForkJoinPool-1-worker-71,5,main] finished managed 126 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-71,5,main] started managed 209
Thread[ForkJoinPool-1-worker-92,5,main] finished managed 96 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-92,5,main] started managed 210
Thread[ForkJoinPool-1-worker-76,5,main] started managed 207
Thread[ForkJoinPool-1-worker-82,5,main] finished managed 97 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-82,5,main] started managed 211
Thread[ForkJoinPool-1-worker-68,5,main] finished managed 99 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-111,5,main] finished managed 102 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-111,5,main] started managed 213
Thread[ForkJoinPool-1-worker-68,5,main] started managed 212
Thread[ForkJoinPool-1-worker-119,5,main] finished managed 101 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-105,5,main] finished managed 103 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-105,5,main] started managed 215
Thread[ForkJoinPool-1-worker-119,5,main] started managed 214
Thread[ForkJoinPool-1-worker-97,5,main] finished managed 104 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-97,5,main] started managed 216
Thread[ForkJoinPool-1-worker-83,5,main] finished managed 106 : 2018-04-10T12:21:37.357Z
Thread[ForkJoinPool-1-worker-69,5,main] finished managed 108 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-126,5,main] finished managed 109 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-120,5,main] finished managed 110 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-106,5,main] finished managed 112 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-98,5,main] finished managed 113 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-84,5,main] finished managed 115 : 2018-04-10T12:21:37.356Z
Thread[ForkJoinPool-1-worker-70,5,main] started managed 200
Thread[ForkJoinPool-1-worker-121,5,main] started managed 198
Thread[ForkJoinPool-1-worker-64,5,main] started managed 197
Thread[ForkJoinPool-1-worker-113,5,main] finished managed 120 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-99,5,main] finished managed 122 : 2018-04-10T12:21:37.355Z
Thread[ForkJoinPool-1-worker-113,5,main] started managed 224
Thread[ForkJoinPool-1-worker-99,5,main] started managed 225
Thread[ForkJoinPool-1-worker-85,5,main] started managed 195
Thread[ForkJoinPool-1-worker-86,5,main] started managed 194
Thread[ForkJoinPool-1-worker-84,5,main] started managed 223
Thread[ForkJoinPool-1-worker-98,5,main] started managed 222
Thread[ForkJoinPool-1-worker-106,5,main] started managed 221
Thread[ForkJoinPool-1-worker-120,5,main] started managed 220
Thread[ForkJoinPool-1-worker-126,5,main] started managed 219
Thread[ForkJoinPool-1-worker-69,5,main] started managed 218
Thread[ForkJoinPool-1-worker-83,5,main] started managed 217
Thread[ForkJoinPool-1-worker-114,5,main] finished managed 127 : 2018-04-10T12:21:37.395Z
Thread[ForkJoinPool-1-worker-114,5,main] started managed 226
Thread[ForkJoinPool-1-worker-101,5,main] finished managed 67 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-93,5,main] finished managed 68 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-93,5,main] started managed 228
Thread[ForkJoinPool-1-worker-87,5,main] finished managed 69 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-79,5,main] finished managed 70 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-87,5,main] started managed 229
Thread[ForkJoinPool-1-worker-73,5,main] finished managed 71 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-65,5,main] finished managed 72 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-122,5,main] finished managed 73 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-108,5,main] finished managed 75 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-108,5,main] started managed 234
Thread[ForkJoinPool-1-worker-116,5,main] finished managed 74 : 2018-04-10T12:21:37.360Z
Thread[ForkJoinPool-1-worker-116,5,main] started managed 235
Thread[ForkJoinPool-1-worker-94,5,main] finished managed 77 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-94,5,main] started managed 236
Thread[ForkJoinPool-1-worker-102,5,main] finished managed 76 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-88,5,main] finished managed 78 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-80,5,main] finished managed 79 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-74,5,main] finished managed 80 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-74,5,main] started managed 239
Thread[ForkJoinPool-1-worker-66,5,main] finished managed 81 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-66,5,main] started managed 240
Thread[ForkJoinPool-1-worker-123,5,main] finished managed 82 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-123,5,main] started managed 242
Thread[ForkJoinPool-1-worker-117,5,main] finished managed 83 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-109,5,main] finished managed 84 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-103,5,main] finished managed 85 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-95,5,main] finished managed 86 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-89,5,main] finished managed 87 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-89,5,main] started managed 247
Thread[ForkJoinPool-1-worker-81,5,main] finished managed 88 : 2018-04-10T12:21:37.359Z
Thread[ForkJoinPool-1-worker-81,5,main] started managed 248
Thread[ForkJoinPool-1-worker-75,5,main] finished managed 89 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-124,5,main] finished managed 91 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-67,5,main] finished managed 90 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-67,5,main] started managed 251
Thread[ForkJoinPool-1-worker-118,5,main] finished managed 92 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-118,5,main] started managed 252
Thread[ForkJoinPool-1-worker-96,5,main] finished managed 95 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-104,5,main] finished managed 94 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-96,5,main] started managed 253
Thread[ForkJoinPool-1-worker-110,5,main] finished managed 93 : 2018-04-10T12:21:37.358Z
Thread[ForkJoinPool-1-worker-110,5,main] started managed 255
Thread[ForkJoinPool-1-worker-104,5,main] started managed 254
Thread[ForkJoinPool-1-worker-124,5,main] started managed 250
Thread[ForkJoinPool-1-worker-75,5,main] started managed 249
Thread[ForkJoinPool-1-worker-95,5,main] started managed 246
Thread[ForkJoinPool-1-worker-103,5,main] started managed 245
Thread[ForkJoinPool-1-worker-109,5,main] started managed 244
Thread[ForkJoinPool-1-worker-117,5,main] started managed 243
Thread[ForkJoinPool-1-worker-80,5,main] started managed 241
Thread[ForkJoinPool-1-worker-88,5,main] started managed 238
Thread[ForkJoinPool-1-worker-102,5,main] started managed 237
Thread[ForkJoinPool-1-worker-122,5,main] started managed 233
Thread[ForkJoinPool-1-worker-65,5,main] started managed 232
Thread[ForkJoinPool-1-worker-73,5,main] started managed 231
Thread[ForkJoinPool-1-worker-79,5,main] started managed 230
Thread[ForkJoinPool-1-worker-101,5,main] started managed 227
Thread[ForkJoinPool-1-worker-6,5,main] finished managed 133 : 2018-04-10T12:21:38.340Z
Thread[ForkJoinPool-1-worker-33,5,main] finished managed 140 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-10,5,main] finished managed 139 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-62,5,main] finished managed 149 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-14,5,main] finished managed 150 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-62,5,main] started managed 259
Thread[ForkJoinPool-1-worker-12,5,main] finished managed 138 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-40,5,main] finished managed 137 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-44,5,main] finished managed 152 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-54,5,main] finished managed 156 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-4,5,main] finished managed 134 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-115,5,main] finished managed 128 : 2018-04-10T12:21:38.339Z
Thread[ForkJoinPool-1-worker-47,5,main] finished managed 162 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-56,5,main] finished managed 164 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-58,5,main] finished managed 166 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-50,5,main] finished managed 167 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-8,5,main] finished managed 146 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-21,5,main] finished managed 169 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-28,5,main] finished managed 170 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-43,5,main] finished managed 171 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-7,5,main] finished managed 142 : 2018-04-10T12:21:38.340Z
Thread[ForkJoinPool-1-worker-48,5,main] finished managed 129 : 2018-04-10T12:21:38.339Z
Thread[ForkJoinPool-1-worker-0,5,main] finished managed 174 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-2,5,main] finished managed 160 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-36,5,main] finished managed 141 : 2018-04-10T12:21:38.340Z
Thread[ForkJoinPool-1-worker-29,5,main] finished managed 175 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-34,5,main] finished managed 158 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-1,5,main] finished managed 132 : 2018-04-10T12:21:38.339Z
Thread[ForkJoinPool-1-worker-24,5,main] finished managed 179 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-31,5,main] finished managed 157 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-57,5,main] finished managed 153 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-30,5,main] finished managed 181 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-9,5,main] finished managed 147 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-41,5,main] finished managed 144 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-59,5,main] finished managed 143 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-22,5,main] finished managed 172 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-13,5,main] finished managed 187 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-15,5,main] finished managed 186 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-55,5,main] finished managed 184 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-27,5,main] finished managed 183 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-20,5,main] finished managed 182 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-32,5,main] finished managed 180 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-39,5,main] finished managed 178 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-17,5,main] finished managed 177 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-37,5,main] finished managed 176 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-51,5,main] finished managed 173 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-52,5,main] finished managed 168 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-49,5,main] finished managed 163 : 2018-04-10T12:21:38.344Z
Thread[ForkJoinPool-1-worker-16,5,main] finished managed 165 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-63,5,main] finished managed 192 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-46,5,main] finished managed 193 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-26,5,main] finished managed 190 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-25,5,main] finished managed 191 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-45,5,main] finished managed 189 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-5,5,main] finished managed 131 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-3,5,main] finished managed 130 : 2018-04-10T12:21:38.339Z
Thread[ForkJoinPool-1-worker-42,5,main] finished managed 161 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-53,5,main] finished managed 159 : 2018-04-10T12:21:38.343Z
Thread[ForkJoinPool-1-worker-35,5,main] finished managed 135 : 2018-04-10T12:21:38.340Z
Thread[ForkJoinPool-1-worker-90,5,main] finished managed 155 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-11,5,main] finished managed 136 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-10,5,main] started managed 258
Thread[ForkJoinPool-1-worker-19,5,main] finished managed 151 : 2018-04-10T12:21:38.342Z
Thread[ForkJoinPool-1-worker-6,5,main] started managed 256
Thread[ForkJoinPool-1-worker-33,5,main] started managed 257
Thread[ForkJoinPool-1-worker-18,5,main] finished managed 148 : 2018-04-10T12:21:38.341Z
Thread[ForkJoinPool-1-worker-38,5,main] finished managed 188 : 2018-04-10T12:21:38.347Z
Thread[ForkJoinPool-1-worker-60,5,main] finished managed 185 : 2018-04-10T12:21:38.346Z
Thread[ForkJoinPool-1-worker-61,5,main] finished managed 145 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-23,5,main] finished managed 154 : 2018-04-10T12:21:38.345Z
Thread[ForkJoinPool-1-worker-72,5,main] finished managed 196 : 2018-04-10T12:21:38.359Z
Thread[ForkJoinPool-1-worker-78,5,main] finished managed 201 : 2018-04-10T12:21:38.359Z
Thread[ForkJoinPool-1-worker-112,5,main] finished managed 203 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-100,5,main] finished managed 202 : 2018-04-10T12:21:38.359Z
Thread[ForkJoinPool-1-worker-77,5,main] finished managed 204 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-91,5,main] finished managed 205 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-127,5,main] finished managed 199 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-71,5,main] finished managed 209 : 2018-04-10T12:21:38.361Z
Thread[ForkJoinPool-1-worker-125,5,main] finished managed 206 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-107,5,main] finished managed 208 : 2018-04-10T12:21:38.360Z
Thread[ForkJoinPool-1-worker-92,5,main] finished managed 210 : 2018-04-10T12:21:38.361Z
Thread[ForkJoinPool-1-worker-76,5,main] finished managed 207 : 2018-04-10T12:21:38.361Z
Thread[ForkJoinPool-1-worker-82,5,main] finished managed 211 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-105,5,main] finished managed 215 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-97,5,main] finished managed 216 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-68,5,main] finished managed 212 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-111,5,main] finished managed 213 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-119,5,main] finished managed 214 : 2018-04-10T12:21:38.403Z
Thread[ForkJoinPool-1-worker-64,5,main] finished managed 197 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-70,5,main] finished managed 200 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-113,5,main] finished managed 224 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-85,5,main] finished managed 195 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-86,5,main] finished managed 194 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-84,5,main] finished managed 223 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-106,5,main] finished managed 221 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-120,5,main] finished managed 220 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-126,5,main] finished managed 219 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-69,5,main] finished managed 218 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-83,5,main] finished managed 217 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-93,5,main] finished managed 228 : 2018-04-10T12:21:38.405Z
Thread[ForkJoinPool-1-worker-121,5,main] finished managed 198 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-101,5,main] finished managed 227 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-79,5,main] finished managed 230 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-65,5,main] finished managed 232 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-73,5,main] finished managed 231 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-122,5,main] finished managed 233 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-88,5,main] finished managed 238 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-102,5,main] finished managed 237 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-80,5,main] finished managed 241 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-117,5,main] finished managed 243 : 2018-04-10T12:21:38.408Z
Thread[ForkJoinPool-1-worker-109,5,main] finished managed 244 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-103,5,main] finished managed 245 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-95,5,main] finished managed 246 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-75,5,main] finished managed 249 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-124,5,main] finished managed 250 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-110,5,main] finished managed 255 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-104,5,main] finished managed 254 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-96,5,main] finished managed 253 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-67,5,main] finished managed 251 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-118,5,main] finished managed 252 : 2018-04-10T12:21:38.407Z
Thread[ForkJoinPool-1-worker-123,5,main] finished managed 242 : 2018-04-10T12:21:38.406Z
Thread[ForkJoinPool-1-worker-81,5,main] finished managed 248 : 2018-04-10T12:21:38.406Z
Thread[ForkJoinPool-1-worker-89,5,main] finished managed 247 : 2018-04-10T12:21:38.406Z
Thread[ForkJoinPool-1-worker-66,5,main] finished managed 240 : 2018-04-10T12:21:38.406Z
Thread[ForkJoinPool-1-worker-74,5,main] finished managed 239 : 2018-04-10T12:21:38.406Z
Thread[ForkJoinPool-1-worker-94,5,main] finished managed 236 : 2018-04-10T12:21:38.405Z
Thread[ForkJoinPool-1-worker-108,5,main] finished managed 234 : 2018-04-10T12:21:38.405Z
Thread[ForkJoinPool-1-worker-116,5,main] finished managed 235 : 2018-04-10T12:21:38.405Z
Thread[ForkJoinPool-1-worker-87,5,main] finished managed 229 : 2018-04-10T12:21:38.405Z
Thread[ForkJoinPool-1-worker-114,5,main] finished managed 226 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-98,5,main] finished managed 222 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-99,5,main] finished managed 225 : 2018-04-10T12:21:38.404Z
Thread[ForkJoinPool-1-worker-62,5,main] finished managed 259 : 2018-04-10T12:21:39.343Z
Thread[ForkJoinPool-1-worker-6,5,main] finished managed 256 : 2018-04-10T12:21:39.349Z
Thread[ForkJoinPool-1-worker-33,5,main] finished managed 257 : 2018-04-10T12:21:39.350Z
Thread[ForkJoinPool-1-worker-10,5,main] finished managed 258 : 2018-04-10T12:21:39.349Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 0
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 0 : 2018-04-10T12:21:40.357Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 1
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 1 : 2018-04-10T12:21:41.362Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 2
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 2 : 2018-04-10T12:21:42.365Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 3
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 3 : 2018-04-10T12:21:43.371Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 4
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 4 : 2018-04-10T12:21:44.375Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 5
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 5 : 2018-04-10T12:21:45.376Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 6
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 6 : 2018-04-10T12:21:46.381Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 7
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 7 : 2018-04-10T12:21:47.385Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 8
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 8 : 2018-04-10T12:21:48.390Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 9
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 9 : 2018-04-10T12:21:49.392Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 10
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 10 : 2018-04-10T12:21:50.397Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 11
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 11 : 2018-04-10T12:21:51.398Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 12
Thread[ForkJoinPool-1-worker-10,5,main] finished unmanaged 12 : 2018-04-10T12:21:52.403Z
Thread[ForkJoinPool-1-worker-10,5,main] started unmanaged 13

--
Cheers,

_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: Strange FJP behavior (bug?)

JSR166 Concurrency mailing list
On 04/10/2018 08:25 AM, Viktor Klang via Concurrency-interest wrote:

> We've observed, and isolated, a strange behavior with ForkJoinPool in
> relation to capped ForkJoinThreadWorkerFactories and ManagedBlocker code
> followed by unmanaged blocking.
>
> */And only a single thread continues to process the rest of the
> workload, one item at a time!/*
>

Yes, this is unexpected, and possibly a policy bug.
I will further investigate.

-Doug
_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: Strange FJP behavior (bug?)

JSR166 Concurrency mailing list
In reply to this post by JSR166 Concurrency mailing list
On 04/10/2018 08:25 AM, Viktor Klang via Concurrency-interest wrote:

> We've observed, and isolated, a strange behavior with ForkJoinPool in
> relation to capped ForkJoinThreadWorkerFactories and ManagedBlocker code
> followed by unmanaged blocking.
>
> *Expected behavior:*
> Pool scales up to the limit of workers as given by the pool, as a result
> of the managed blocking, then either terminates those extra threads or
> uses them to help out processing the work.
>
> *Observed behavior:*
> Threads are created during the managed blocking, but then get stuck in
> this stack frame:
>

To get the effect you want, use the jdk9+ FJP constructor that
was designed (with your input :-) to support it. Try it with:

  public static void main(final String[] args) throws Exception {
      final ForkJoinPool fjp =
          new ForkJoinPool(CORES,
                           ForkJoinPool.defaultForkJoinWorkerThreadFactory,
                           null,
                           true,
                           CORES,
                           MAX_THREADS,
                           1,
                           x -> true, // continue if saturated
                           60, TimeUnit.SECONDS);

Your attempt to emulate the "saturate" predicate by keeping
track of counts in allocate()/deallocate() maintains minimal
progress but as you saw, it will not usually reactivate
available threads.

I don't know of a way to avoid this on pre-jdk9 versions.

(Also, ignore the comment on this example in other thread.
The symptoms are almost the same as recursive blocking
because in both cases threads continue even though doing so
is not guaranteed to maintain liveness.)

-Doug

_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: Strange FJP behavior (bug?)

JSR166 Concurrency mailing list


On Sun, Apr 15, 2018 at 10:39 PM, Doug Lea via Concurrency-interest <[hidden email]> wrote:
On 04/10/2018 08:25 AM, Viktor Klang via Concurrency-interest wrote:
> We've observed, and isolated, a strange behavior with ForkJoinPool in
> relation to capped ForkJoinThreadWorkerFactories and ManagedBlocker code
> followed by unmanaged blocking.
>
> *Expected behavior:*
> Pool scales up to the limit of workers as given by the pool, as a result
> of the managed blocking, then either terminates those extra threads or
> uses them to help out processing the work.
>
> *Observed behavior:*
> Threads are created during the managed blocking, but then get stuck in
> this stack frame:
>

To get the effect you want, use the jdk9+ FJP constructor that
was designed (with your input :-) to support it. Try it with:

  public static void main(final String[] args) throws Exception {
      final ForkJoinPool fjp =
          new ForkJoinPool(CORES,
                           ForkJoinPool.defaultForkJoinWorkerThreadFactory,
                           null,
                           true,
                           CORES,
                           MAX_THREADS,
                           1,
                           x -> true, // continue if saturated
                           60, TimeUnit.SECONDS);

I do need to try to work around this bug on non-jdk9 runtimes. :)
 

Your attempt to emulate the "saturate" predicate by keeping
track of counts in allocate()/deallocate() maintains minimal
progress but as you saw, it will not usually reactivate
available threads.

Alas, there's tons of work, and all but one of the workers are stuck in awaitWork?
 

I don't know of a way to avoid this on pre-jdk9 versions.

(Also, ignore the comment on this example in other thread.
The symptoms are almost the same as recursive blocking
because in both cases threads continue even though doing so
is not guaranteed to maintain liveness.)

-Doug

_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://cs.oswego.edu/mailman/listinfo/concurrency-interest



--
Cheers,

_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://cs.oswego.edu/mailman/listinfo/concurrency-interest