Druid Kinesis Ingestion Fails with "Unhealthy Tasks" error

After switching from Tranquility to the native Kinesis ingestion, the tasks run well for a little while, but then they fail with messages like:

This in the supervisor logs:

    {
      "timestamp": "2022-09-28T03:34:42.203Z",
      "exceptionClass": "java.util.concurrent.ExecutionException",
      "message": "org.apache.druid.indexing.common.IndexTaskClient$TaskNotRunnableException: Aborting request because task [index_kin_events_xxxxx] is not runnable",

And this in the task logs:
"errorMsg": "org.apache.druid.java.util.common.ISE: Could not allocate segment for row with timestamp[2022-09-23T..."

After resetting and/or pausing and resuming the supervisor, the ingestion tasks can start working again, but then they eventually fail after a few hours-a few days.

Note the datasource name is the same as the old tranquility data source.

Would anyone know the issue is here or where I should start looking?

Thanks

Could you provide the whole stack trace for the task?

“id”: “index_kin_events_xxxxxxx_xxxxxx”,
“groupId”: “index_kin_events”,
“type”: “index_kin”,
“createdTime”: “2022-09-28T17:01:18.408Z”,
“queueInsertionTime”: “1970-01-01T00:00:00.000Z”,
“statusCode”: “FAILED”,
“status”: “FAILED”,
“runnerStatusCode”: “WAITING”,
“duration”: 15481,
“location”: {
“host”: “xx-mm-1”,
“port”: 8105,
“tlsPort”: -1
},
“dataSource”: “events”,
“errorMsg”: “org.apache.druid.java.util.common.ISE: Could not allocate segment for row with timestamp[2022-09-23T…”
}

Is the above what you need @Sergio_Ferragut ?

@jamesvk that is the status report. I’m thinking of the task log. If the task log is still available you should be able to get it using the API:
/druid/indexer/v1/task/$WORKER_TASK_ID/log

Replace $WORKER_TASK_ID for your task’s ID.

Got it here is the full log : 1/2

0.184: [GC pause (G1 Evacuation Pause) (young), 0.0041749 secs]
   [Parallel Time: 2.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 184.4, Avg: 185.1, Max: 186.3, Diff: 2.0]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
      [Object Copy (ms): Min: 0.3, Avg: 1.2, Max: 1.7, Diff: 1.4, Sum: 4.9]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.6, Avg: 1.8, Max: 2.5, Diff: 2.0, Sum: 7.1]
      [GC Worker End (ms): Min: 186.9, Avg: 186.9, Max: 186.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12288.0K(12288.0K)->0.0B(12288.0K) Survivors: 0.0B->2048.0K Heap: 12288.0K(246.0M)->2097.0K(246.0M)]
 [Times: user=0.01 sys=0.01, real=0.00 secs] 
0.271: [GC pause (G1 Evacuation Pause) (young), 0.0030678 secs]
   [Parallel Time: 2.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 271.4, Avg: 271.6, Max: 272.2, Diff: 0.8]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.3]
      [Object Copy (ms): Min: 0.9, Avg: 1.2, Max: 1.6, Diff: 0.7, Sum: 4.8]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.2, Avg: 1.7, Max: 1.9, Diff: 0.7, Sum: 6.9]
      [GC Worker End (ms): Min: 273.3, Avg: 273.3, Max: 273.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12288.0K(12288.0K)->0.0B(22528.0K) Survivors: 2048.0K->2048.0K Heap: 14385.0K(246.0M)->2721.0K(246.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
0.387: [GC pause (G1 Evacuation Pause) (young), 0.0041017 secs]
   [Parallel Time: 2.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 386.7, Avg: 387.0, Max: 387.5, Diff: 0.8]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 1.0, Max: 2, Diff: 2, Sum: 4]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.9, Diff: 0.9, Sum: 1.1]
      [Object Copy (ms): Min: 1.2, Avg: 1.6, Max: 2.0, Diff: 0.8, Sum: 6.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 5.2, Max: 8, Diff: 7, Sum: 21]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.7, Avg: 2.2, Max: 2.6, Diff: 0.8, Sum: 9.0]
      [GC Worker End (ms): Min: 389.2, Avg: 389.2, Max: 389.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 22528.0K(22528.0K)->0.0B(144.0M) Survivors: 2048.0K->3072.0K Heap: 25249.0K(246.0M)->4359.5K(246.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.285: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0133778 secs]
   [Parallel Time: 6.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 1284.7, Avg: 1284.8, Max: 1285.2, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 0.9, Avg: 1.5, Max: 1.9, Diff: 0.9, Sum: 6.0]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Processed Buffers: Min: 0, Avg: 0.8, Max: 1, Diff: 1, Sum: 3]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.9, Diff: 0.8, Sum: 1.2]
      [Object Copy (ms): Min: 3.8, Avg: 4.5, Max: 4.9, Diff: 1.2, Sum: 18.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 6.0, Avg: 6.4, Max: 6.5, Diff: 0.6, Sum: 25.5]
      [GC Worker End (ms): Min: 1291.2, Avg: 1291.2, Max: 1291.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 6.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 6.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 133.0M(144.0M)->0.0B(133.0M) Survivors: 3072.0K->14336.0K Heap: 137.3M(246.0M)->15107.5K(246.0M)]
 [Times: user=0.02 sys=0.01, real=0.01 secs] 
1.298: [GC concurrent-root-region-scan-start]
1.304: [GC concurrent-root-region-scan-end, 0.0063137 secs]
1.304: [GC concurrent-mark-start]
1.305: [GC concurrent-mark-end, 0.0004540 secs]
1.305: [GC remark 1.305: [Finalize Marking, 0.0001815 secs] 1.305: [GC ref-proc, 0.0001814 secs] 1.305: [Unloading, 0.0031435 secs], 0.0036287 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.309: [GC cleanup 16645K->16382K(246M), 0.0004752 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
1.309: [GC concurrent-cleanup-start]
1.309: [GC concurrent-cleanup-end, 0.0000114 secs]
2.211: [GC pause (G1 Evacuation Pause) (young), 0.0232891 secs]
   [Parallel Time: 17.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 2211.0, Avg: 2212.5, Max: 2213.9, Diff: 2.9]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 2.4, Diff: 2.4, Sum: 3.5]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 0.5]
         [Processed Buffers: Min: 0, Avg: 0.8, Max: 2, Diff: 2, Sum: 3]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 3.8, Max: 10.6, Diff: 10.6, Sum: 15.0]
      [Object Copy (ms): Min: 4.1, Avg: 11.1, Max: 14.3, Diff: 10.3, Sum: 44.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 5]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 14.6, Avg: 16.1, Max: 17.5, Diff: 2.9, Sum: 64.3]
      [GC Worker End (ms): Min: 2228.5, Avg: 2228.5, Max: 2228.5, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 5.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 133.0M(133.0M)->0.0B(131.0M) Survivors: 14336.0K->16384.0K Heap: 147.5M(246.0M)->17408.0K(246.0M)]
 [Times: user=0.07 sys=0.01, real=0.02 secs] 
2.990: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0255154 secs]
   [Parallel Time: 22.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 2990.2, Avg: 2990.7, Max: 2992.1, Diff: 1.9]
      [Ext Root Scanning (ms): Min: 1.8, Avg: 2.8, Max: 3.5, Diff: 1.7, Sum: 11.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.1, Avg: 3.5, Max: 12.6, Diff: 12.5, Sum: 14.0]
      [Object Copy (ms): Min: 3.0, Avg: 12.9, Max: 18.2, Diff: 15.2, Sum: 51.5]
      [Termination (ms): Min: 0.0, Avg: 3.0, Max: 4.0, Diff: 4.0, Sum: 12.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 20.8, Avg: 22.2, Max: 22.7, Diff: 1.9, Sum: 88.9]
      [GC Worker End (ms): Min: 3012.9, Avg: 3012.9, Max: 3012.9, Diff: 0.0]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 119.0M(131.0M)->0.0B(131.0M) Survivors: 16384.0K->16384.0K Heap: 135.5M(246.0M)->16896.0K(246.0M)]
 [Times: user=0.09 sys=0.00, real=0.02 secs] 
3.016: [GC concurrent-root-region-scan-start]
3.042: [GC concurrent-root-region-scan-end, 0.0267468 secs]
3.043: [GC concurrent-mark-start]
3.043: [GC concurrent-mark-end, 0.0004570 secs]
3.043: [GC remark 3.043: [Finalize Marking, 0.0002218 secs] 3.043: [GC ref-proc, 0.0002193 secs] 3.044: [Unloading, 0.0091560 secs], 0.0097503 secs]
 [Times: user=0.04 sys=0.00, real=0.01 secs] 
3.053: [GC cleanup 20991K->20991K(246M), 0.0004696 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-28 17:31:16,995 main WARN JNDI lookup class is not available because this JRE does not support JNDI. JNDI string lookups will not be available, continuing configuration. Ignoring java.lang.ClassNotFoundException: org.apache.logging.log4j.core.lookup.JndiLookup
2022-09-28 17:31:17,026 main WARN JNDI lookup class is not available because this JRE does not support JNDI. JNDI string lookups will not be available, continuing configuration. Ignoring java.lang.ClassNotFoundException: org.apache.logging.log4j.core.lookup.JndiLookup
3.725: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0204642 secs]
   [Parallel Time: 17.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 3724.9, Avg: 3724.9, Max: 3724.9, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.8, Avg: 2.2, Max: 2.6, Diff: 0.9, Sum: 8.6]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.1, Avg: 1.3, Max: 2.4, Diff: 2.3, Sum: 5.2]
      [Object Copy (ms): Min: 12.8, Avg: 14.2, Max: 15.5, Diff: 2.8, Sum: 56.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 17.7, Avg: 17.7, Max: 17.8, Diff: 0.0, Sum: 71.0]
      [GC Worker End (ms): Min: 3742.7, Avg: 3742.7, Max: 3742.7, Diff: 0.0]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 131.0M(131.0M)->0.0B(131.0M) Survivors: 16384.0K->16384.0K Heap: 147.5M(246.0M)->21421.0K(246.0M)]
 [Times: user=0.06 sys=0.01, real=0.02 secs] 

full log 2/2:

3.745: [GC concurrent-root-region-scan-start]
3.767: [GC concurrent-root-region-scan-end, 0.0220778 secs]
3.767: [GC concurrent-mark-start]
3.779: [GC concurrent-mark-end, 0.0116908 secs]
3.779: [GC remark 3.779: [Finalize Marking, 0.0001618 secs] 3.780: [GC ref-proc, 0.0002387 secs] 3.780: [Unloading, 0.0069072 secs], 0.0074568 secs]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
3.787: [GC cleanup 27054K->27054K(246M), 0.0004357 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
3.812: [GC pause (G1 Evacuation Pause) (young), 0.0156479 secs]
   [Parallel Time: 14.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 3811.7, Avg: 3811.8, Max: 3811.8, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.6, Avg: 1.1, Max: 2.4, Diff: 1.9, Sum: 4.4]
      [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.1]
         [Processed Buffers: Min: 0, Avg: 2.0, Max: 5, Diff: 5, Sum: 8]
      [Scan RS (ms): Min: 0.0, Avg: 0.4, Max: 0.7, Diff: 0.6, Sum: 1.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.6, Sum: 1.0]
      [Object Copy (ms): Min: 12.2, Avg: 12.6, Max: 12.9, Diff: 0.7, Sum: 50.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 14.6, Avg: 14.7, Max: 14.7, Diff: 0.0, Sum: 58.6]
      [GC Worker End (ms): Min: 3826.4, Avg: 3826.4, Max: 3826.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 8192.0K(1024.0K)->0.0B(104.0M) Survivors: 16384.0K->3072.0K Heap: 29613.0K(246.0M)->20480.0K(246.0M)]
 [Times: user=0.05 sys=0.02, real=0.02 secs] 
5.624: [GC pause (G1 Evacuation Pause) (young), 0.0091916 secs]
   [Parallel Time: 7.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 5624.2, Avg: 5624.2, Max: 5624.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.5, Avg: 1.6, Max: 1.7, Diff: 0.3, Sum: 6.4]
      [Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.8, Diff: 0.1, Sum: 2.9]
         [Processed Buffers: Min: 2, Avg: 15.0, Max: 29, Diff: 27, Sum: 60]
      [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 0.8]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]
      [Object Copy (ms): Min: 4.3, Avg: 4.4, Max: 4.6, Diff: 0.3, Sum: 17.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 7.0, Avg: 7.0, Max: 7.1, Diff: 0.0, Sum: 28.2]
      [GC Worker End (ms): Min: 5631.2, Avg: 5631.2, Max: 5631.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 99328.0K(99328.0K)->0.0B(137.0M) Survivors: 3072.0K->10240.0K Heap: 117.0M(246.0M)->28160.5K(246.0M)]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
6.209: [GC pause (G1 Evacuation Pause) (young), 0.0120857 secs]
   [Parallel Time: 9.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 6209.5, Avg: 6209.5, Max: 6209.6, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.2, Avg: 1.8, Max: 2.4, Diff: 1.2, Sum: 7.0]
      [Update RS (ms): Min: 0.4, Avg: 0.7, Max: 1.0, Diff: 0.6, Sum: 2.8]
         [Processed Buffers: Min: 1, Avg: 14.0, Max: 46, Diff: 45, Sum: 56]
      [Scan RS (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 2.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Object Copy (ms): Min: 6.4, Avg: 6.7, Max: 7.0, Diff: 0.6, Sum: 26.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 9.9, Avg: 9.9, Max: 9.9, Diff: 0.0, Sum: 39.5]
      [GC Worker End (ms): Min: 6219.4, Avg: 6219.4, Max: 6219.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 109.0M(98304.0K)->0.0B(133.0M) Survivors: 10240.0K->14336.0K Heap: 136.5M(246.0M)->31744.5K(246.0M)]
 [Times: user=0.04 sys=0.01, real=0.01 secs] 
8.072: [GC pause (G1 Evacuation Pause) (young), 0.0152186 secs]
   [Parallel Time: 13.5 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 8071.6, Avg: 8071.6, Max: 8071.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.9, Max: 2.4, Diff: 0.8, Sum: 7.7]
      [Update RS (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 3.1]
         [Processed Buffers: Min: 2, Avg: 14.2, Max: 49, Diff: 47, Sum: 57]
      [Scan RS (ms): Min: 0.2, Avg: 0.5, Max: 0.6, Diff: 0.4, Sum: 2.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.6, Sum: 0.9]
      [Object Copy (ms): Min: 9.8, Avg: 10.0, Max: 10.1, Diff: 0.3, Sum: 39.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 13.4, Avg: 13.4, Max: 13.4, Diff: 0.1, Sum: 53.7]
      [GC Worker End (ms): Min: 8085.0, Avg: 8085.1, Max: 8085.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 133.0M(133.0M)->0.0B(128.0M) Survivors: 14336.0K->19456.0K Heap: 164.0M(246.0M)->45219.0K(246.0M)]
 [Times: user=0.05 sys=0.00, real=0.02 secs] 
8.396: [GC pause (G1 Evacuation Pause) (young), 0.0174840 secs]
   [Parallel Time: 16.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 8395.8, Avg: 8395.9, Max: 8395.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.3, Avg: 3.2, Max: 7.1, Diff: 5.8, Sum: 12.7]
      [Update RS (ms): Min: 0.0, Avg: 0.7, Max: 1.2, Diff: 1.2, Sum: 2.7]
         [Processed Buffers: Min: 0, Avg: 8.5, Max: 23, Diff: 23, Sum: 34]
      [Scan RS (ms): Min: 0.0, Avg: 0.6, Max: 1.0, Diff: 1.0, Sum: 2.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.6, Sum: 0.9]
      [Object Copy (ms): Min: 9.1, Avg: 11.6, Max: 12.6, Diff: 3.5, Sum: 46.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 2.0, Max: 4, Diff: 3, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 16.3, Avg: 16.3, Max: 16.3, Diff: 0.1, Sum: 65.2]
      [GC Worker End (ms): Min: 8412.1, Avg: 8412.2, Max: 8412.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 128.0M(128.0M)->0.0B(128.0M) Survivors: 19456.0K->19456.0K Heap: 172.2M(246.0M)->61440.0K(246.0M)]
 [Times: user=0.06 sys=0.01, real=0.02 secs] 
8.701: [GC pause (G1 Evacuation Pause) (young), 0.0134007 secs]
   [Parallel Time: 12.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 8700.7, Avg: 8705.7, Max: 8713.2, Diff: 12.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 1.0, Max: 2.1, Diff: 2.1, Sum: 4.2]
      [Update RS (ms): Min: 0.0, Avg: 1.2, Max: 2.4, Diff: 2.4, Sum: 4.8]
         [Processed Buffers: Min: 0, Avg: 9.5, Max: 31, Diff: 31, Sum: 38]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]
      [Object Copy (ms): Min: 0.0, Avg: 4.9, Max: 7.5, Diff: 7.5, Sum: 19.7]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.0, Avg: 7.6, Max: 12.6, Diff: 12.6, Sum: 30.3]
      [GC Worker End (ms): Min: 8713.3, Avg: 8713.3, Max: 8713.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 128.0M(128.0M)->0.0B(124.0M) Survivors: 19456.0K->19456.0K Heap: 188.0M(246.0M)->75776.0K(246.0M)]
 [Times: user=0.03 sys=0.01, real=0.01 secs] 
8.945: [GC pause (G1 Evacuation Pause) (young), 0.0142056 secs]
   [Parallel Time: 13.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 8944.6, Avg: 8946.4, Max: 8948.3, Diff: 3.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 3.7]
      [Update RS (ms): Min: 0.0, Avg: 2.4, Max: 7.8, Diff: 7.8, Sum: 9.5]
         [Processed Buffers: Min: 1, Avg: 13.8, Max: 37, Diff: 36, Sum: 55]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2]
      [Object Copy (ms): Min: 2.9, Avg: 7.0, Max: 8.6, Diff: 5.7, Sum: 28.1]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.9, Diff: 0.9, Sum: 2.1]
         [Termination Attempts: Min: 1, Avg: 3.0, Max: 5, Diff: 4, Sum: 12]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 9.0, Avg: 10.9, Max: 12.6, Diff: 3.6, Sum: 43.7]
      [GC Worker End (ms): Min: 8957.2, Avg: 8957.4, Max: 8957.9, Diff: 0.6]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 124.0M(124.0M)->0.0B(123.0M) Survivors: 19456.0K->13312.0K Heap: 198.0M(246.0M)->78848.0K(246.0M)]
 [Times: user=0.04 sys=0.01, real=0.01 secs] 
9.141: [GC pause (G1 Evacuation Pause) (young), 0.0241882 secs]
   [Parallel Time: 23.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9141.2, Avg: 9147.1, Max: 9153.8, Diff: 12.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 1.1, Max: 2.1, Diff: 2.1, Sum: 4.2]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 0.8, Diff: 0.8, Sum: 1.6]
         [Processed Buffers: Min: 0, Avg: 2.8, Max: 8, Diff: 8, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.0, Avg: 7.7, Max: 20.1, Diff: 20.1, Sum: 30.9]
      [Termination (ms): Min: 0.0, Avg: 8.1, Max: 10.8, Diff: 10.8, Sum: 32.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 10.6, Avg: 17.3, Max: 23.2, Diff: 12.6, Sum: 69.1]
      [GC Worker End (ms): Min: 9164.3, Avg: 9164.4, Max: 9164.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 123.0M(123.0M)->0.0B(119.0M) Survivors: 13312.0K->11264.0K Heap: 200.0M(246.0M)->84480.0K(246.0M)]
 [Times: user=0.09 sys=0.00, real=0.03 secs] 
9.332: [GC pause (G1 Evacuation Pause) (young), 0.0286312 secs]
   [Parallel Time: 22.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9332.5, Avg: 9335.8, Max: 9337.3, Diff: 4.8]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 3.0, Diff: 3.0, Sum: 3.0]
      [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.8, Diff: 0.8, Sum: 1.2]
         [Processed Buffers: Min: 0, Avg: 2.8, Max: 10, Diff: 10, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 16.8, Avg: 17.4, Max: 17.8, Diff: 1.0, Sum: 69.5]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 17.1, Avg: 18.6, Max: 21.9, Diff: 4.8, Sum: 74.3]
      [GC Worker End (ms): Min: 9354.4, Avg: 9354.4, Max: 9354.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 6.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 6.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 119.0M(119.0M)->0.0B(101376.0K) Survivors: 11264.0K->17408.0K Heap: 201.5M(246.0M)->103.0M(246.0M)]
 [Times: user=0.11 sys=0.00, real=0.03 secs] 
9.475: [GC pause (G1 Evacuation Pause) (young), 0.0070217 secs]
   [Parallel Time: 4.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9475.1, Avg: 9476.2, Max: 9479.7, Diff: 4.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 1.0, Max: 1.4, Diff: 1.4, Sum: 3.8]
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 3.1]
         [Processed Buffers: Min: 0, Avg: 14.8, Max: 29, Diff: 29, Sum: 59]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 1.4, Max: 2.0, Diff: 2.0, Sum: 5.6]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.0, Avg: 3.5, Max: 4.7, Diff: 4.7, Sum: 14.1]
      [GC Worker End (ms): Min: 9479.7, Avg: 9479.8, Max: 9479.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 101376.0K(101376.0K)->0.0B(104.0M) Survivors: 17408.0K->11264.0K Heap: 202.0M(246.0M)->100352.0K(246.0M)]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
9.622: [GC pause (G1 Evacuation Pause) (young), 0.0205637 secs]
   [Parallel Time: 20.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9621.8, Avg: 9623.9, Max: 9627.9, Diff: 6.0]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.8, Diff: 1.8, Sum: 3.5]
      [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.1]
         [Processed Buffers: Min: 0, Avg: 2.0, Max: 4, Diff: 4, Sum: 8]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 13.9, Avg: 16.7, Max: 17.7, Diff: 3.8, Sum: 66.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 14.0, Avg: 17.9, Max: 20.0, Diff: 6.0, Sum: 71.6]
      [GC Worker End (ms): Min: 9641.8, Avg: 9641.8, Max: 9641.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 104.0M(104.0M)->0.0B(80896.0K) Survivors: 11264.0K->15360.0K Heap: 202.0M(246.0M)->122.0M(246.0M)]
 [Times: user=0.08 sys=0.00, real=0.02 secs] 
9.739: [GC pause (G1 Evacuation Pause) (young), 0.0160355 secs]
   [Parallel Time: 15.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9739.4, Avg: 9741.6, Max: 9748.2, Diff: 8.7]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.3, Diff: 1.3, Sum: 3.7]
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.2, Diff: 1.2, Sum: 3.3]
         [Processed Buffers: Min: 0, Avg: 4.5, Max: 7, Diff: 7, Sum: 18]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 6.3, Avg: 11.0, Max: 12.7, Diff: 6.4, Sum: 43.9]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 6.6, Avg: 13.1, Max: 15.3, Diff: 8.7, Sum: 52.4]
      [GC Worker End (ms): Min: 9754.7, Avg: 9754.8, Max: 9754.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 80896.0K(80896.0K)->0.0B(77824.0K) Survivors: 15360.0K->12288.0K Heap: 201.0M(246.0M)->124.0M(246.0M)]
 [Times: user=0.06 sys=0.00, real=0.01 secs] 
9.861: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0321250 secs]
   [Parallel Time: 27.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9861.0, Avg: 9861.5, Max: 9862.8, Diff: 1.8]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 1.6, Max: 3.0, Diff: 2.9, Sum: 6.5]
      [Update RS (ms): Min: 0.2, Avg: 1.2, Max: 1.6, Diff: 1.4, Sum: 4.6]
         [Processed Buffers: Min: 1, Avg: 6.0, Max: 9, Diff: 8, Sum: 24]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 15.0, Avg: 17.3, Max: 23.8, Diff: 8.8, Sum: 69.2]
      [Termination (ms): Min: 0.0, Avg: 6.5, Max: 8.7, Diff: 8.7, Sum: 26.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 25.4, Avg: 26.7, Max: 27.1, Diff: 1.8, Sum: 106.7]
      [GC Worker End (ms): Min: 9888.2, Avg: 9888.2, Max: 9888.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 4.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 77824.0K(77824.0K)->0.0B(62464.0K) Survivors: 12288.0K->11264.0K Heap: 200.0M(246.0M)->139.5M(246.0M)]
 [Times: user=0.13 sys=0.00, real=0.03 secs] 
9.893: [GC concurrent-root-region-scan-start]
9.916: [GC concurrent-root-region-scan-end, 0.0232715 secs]
9.916: [GC concurrent-mark-start]
9.981: [GC pause (G1 Evacuation Pause) (young), 0.0120123 secs]
   [Parallel Time: 11.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 9980.7, Avg: 9982.9, Max: 9988.2, Diff: 7.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 1.0, Max: 1.7, Diff: 1.7, Sum: 3.9]
      [Update RS (ms): Min: 0.0, Avg: 0.9, Max: 1.2, Diff: 1.2, Sum: 3.7]
         [Processed Buffers: Min: 0, Avg: 15.0, Max: 24, Diff: 24, Sum: 60]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 3.6, Avg: 7.0, Max: 8.4, Diff: 4.9, Sum: 27.9]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 1.5]
         [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 5]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 4.1, Avg: 9.4, Max: 11.5, Diff: 7.5, Sum: 37.5]
      [GC Worker End (ms): Min: 9992.2, Avg: 9992.2, Max: 9992.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 62464.0K(62464.0K)->0.0B(52224.0K) Survivors: 11264.0K->9216.0K Heap: 200.5M(246.0M)->152.5M(246.0M)]
 [Times: user=0.05 sys=0.00, real=0.01 secs] 
10.045: [GC pause (G1 Evacuation Pause) (young), 0.0059633 secs]
   [Parallel Time: 5.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 10045.3, Avg: 10045.7, Max: 10047.1, Diff: 1.8]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.3, Diff: 1.3, Sum: 3.6]
      [Update RS (ms): Min: 1.2, Avg: 2.1, Max: 3.9, Diff: 2.7, Sum: 8.3]
         [Processed Buffers: Min: 3, Avg: 5.8, Max: 8, Diff: 5, Sum: 23]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.1, Avg: 1.5, Max: 2.1, Diff: 2.0, Sum: 5.9]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 2.2, Max: 3, Diff: 2, Sum: 9]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 3.4, Avg: 4.8, Max: 5.3, Diff: 1.9, Sum: 19.1]
      [GC Worker End (ms): Min: 10050.5, Avg: 10050.5, Max: 10050.6, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 52224.0K(52224.0K)->0.0B(48128.0K) Survivors: 9216.0K->8192.0K Heap: 203.5M(246.0M)->159.5M(246.0M)]
 [Times: user=0.02 sys=0.00, real=0.00 secs] 
10.110: [GC concurrent-mark-end, 0.1936381 secs]
10.114: [GC remark 10.114: [Finalize Marking, 0.0004503 secs] 10.115: [GC ref-proc, 0.0003554 secs] 10.115: [Unloading, 0.0146498 secs], 0.0159935 secs]
 [Times: user=0.06 sys=0.00, real=0.02 secs] 
10.131: [GC cleanup 202M->189M(246M), 0.0006012 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
10.131: [GC concurrent-cleanup-start]
10.131: [GC concurrent-cleanup-end, 0.0000268 secs]
10.141: [GC pause (G1 Evacuation Pause) (young), 0.0170902 secs]
   [Parallel Time: 5.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 10141.5, Avg: 10144.1, Max: 10146.7, Diff: 5.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.8, Max: 1.6, Diff: 1.6, Sum: 3.3]
      [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.0]
         [Processed Buffers: Min: 0, Avg: 1.8, Max: 4, Diff: 4, Sum: 7]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 1.4, Max: 2.8, Diff: 2.8, Sum: 5.6]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.7, Diff: 0.7, Sum: 0.9]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.0, Avg: 2.7, Max: 5.6, Diff: 5.6, Sum: 10.8]
      [GC Worker End (ms): Min: 10146.7, Avg: 10146.8, Max: 10147.1, Diff: 0.4]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 11.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 8.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 48128.0K(48128.0K)->0.0B(260.0M) Survivors: 8192.0K->5120.0K Heap: 193.5M(246.0M)->150.0M(492.0M)]
 [Times: user=0.06 sys=0.00, real=0.02 secs] 
10.583: [GC pause (G1 Evacuation Pause) (young), 0.0179116 secs]
   [Parallel Time: 12.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 10582.9, Avg: 10585.5, Max: 10588.2, Diff: 5.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.8, Diff: 1.8, Sum: 3.5]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 0.7, Diff: 0.7, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 12.8, Max: 47, Diff: 47, Sum: 51]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 6.8, Avg: 8.1, Max: 9.6, Diff: 2.8, Sum: 32.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 6.8, Avg: 9.5, Max: 12.1, Diff: 5.3, Sum: 37.8]
      [GC Worker End (ms): Min: 10595.0, Avg: 10595.0, Max: 10595.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 260.0M(260.0M)->0.0B(566.0M) Survivors: 5120.0K->24576.0K Heap: 410.0M(492.0M)->169.5M(984.0M)]
 [Times: user=0.04 sys=0.01, real=0.02 secs] 
11.330: [GC pause (G1 Evacuation Pause) (young), 0.0109454 secs]
   [Parallel Time: 5.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 11329.7, Avg: 11329.8, Max: 11329.8, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.0, Avg: 1.1, Max: 1.2, Diff: 0.2, Sum: 4.4]
      [Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.2, Sum: 0.9]
         [Processed Buffers: Min: 1, Avg: 12.2, Max: 45, Diff: 44, Sum: 49]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 4.0, Avg: 4.1, Max: 4.2, Diff: 0.2, Sum: 16.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 5.6, Avg: 5.6, Max: 5.6, Diff: 0.0, Sum: 22.3]
      [GC Worker End (ms): Min: 11335.3, Avg: 11335.3, Max: 11335.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 566.0M(566.0M)->0.0B(815.0M) Survivors: 24576.0K->26624.0K Heap: 735.5M(984.0M)->171.0M(1402.0M)]
 [Times: user=0.02 sys=0.01, real=0.01 secs] 
12.161: [GC pause (G1 Evacuation Pause) (young), 0.0183852 secs]
   [Parallel Time: 17.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 12161.0, Avg: 12161.1, Max: 12161.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.8, Avg: 0.9, Max: 1.2, Diff: 0.4, Sum: 3.7]
      [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.9]
         [Processed Buffers: Min: 1, Avg: 13.0, Max: 28, Diff: 27, Sum: 52]
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 15.7, Avg: 15.7, Max: 15.8, Diff: 0.2, Sum: 63.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms): Min: 17.1, Avg: 17.2, Max: 17.2, Diff: 0.1, Sum: 68.6]
      [GC Worker End (ms): Min: 12178.2, Avg: 12178.2, Max: 12178.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 815.0M(815.0M)->0.0B(788.0M) Survivors: 26624.0K->54272.0K Heap: 986.0M(1402.0M)->198.5M(1402.0M)]
 [Times: user=0.07 sys=0.00, real=0.02 secs] 
Finished peon task
Heap
 garbage-first heap   total 1435648K, used 769536K [0x0000000700000000, 0x0000000700102bd0, 0x00000007c0000000)
  region size 1024K, 607 young (621568K), 53 survivors (54272K)
 Metaspace       used 63611K, capacity 65250K, committed 65356K, reserved 1105920K
  class space    used 8076K, capacity 8504K, committed 8524K, reserved 1048576K

@Sergio_Ferragut added the log above

That is a garbage collection log, we’re looking for the task execution log. Did you try the API?

/druid/indexer/v1/task/$WORKER_TASK_ID/log

Hi @Sergio_Ferragut Yes, I used: /druid/indexer/v1/task/$WORKER_TASK_ID/log to get the logs I pasted above. I got the “$WORKER_TASK_ID” from the ingestion “Tasks” section:

Screen Shot 2022-09-29 at 8.57.19 AM

It seems like the logs are not complete. Maybe it could be a similar issue as here: https://groups.google.com/g/druid-user/c/aYs3qk9wfBM
?

I am getting the same log output when I visit the log in the s3 file it gets pushed to.

@jamesvk, It does look like you are running into the same issue described in that older question. The thread isn’t very clear on the cause but you might want to check your log4j configuration as a next lead.

Your original problem is likely unrelated to the logging problem. In your original issue, you mention that it works for a while. Does it reach the point of publishing a segment? Perhaps you are dealing with a memory issue which only occurs as it tries to complete a segment which would indicate the need to adjust memory settings in the MM’s druid.indexer.runner.javaOptsArray so that the tasks have enough. It would be great to solve the logging issue so that you can confirm/deny this theory.