Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8341089

G1: Occasional very long gc minor pauses caused by long Optional Code Root Scan

XMLWordPrintable

    • generic
    • generic

      ADDITIONAL SYSTEM INFORMATION :
      Java 23 (temurin)

      A DESCRIPTION OF THE PROBLEM :
      Since we upgraded to jdk 23 (from jdk 22.0.2) we can see ocasionally (once or twice per day) very long g1 minor pauses. Our minor pauses are about 100ms, we almost never have G1 full pauses.

      I don't see any reason to get this pauses. Pause total time is 5382ms and Optional code root scan is 5140ms.

      This is the gc log for this pause:

      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) Pause Young (Mixed) (G1 Evacuation Pause)
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) Heap before GC invocations=2151 (full 0):
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) garbage-first heap total reserved 30408704K, committed 26116096K, used 23915172K [0x00000000c0000000, 0x0000000800000000)
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) region size 16384K, 551 young (9027584K), 48 survivors (786432K)
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) remaining free region(s) on each NUMA node: 0=63 1=66
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) Metaspace used 593595K, committed 619968K, reserved 1572864K
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) class space used 82423K, committed 98944K, reserved 1048576K
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) Using 43 workers of 43 for evacuation
      [2024-09-24T20:13:20.169+0000][14972391ms] GC(2151) Desired survivor size 578813952 bytes, new threshold 7 (max threshold 15)
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) TLAB totals: thrds: 1377 refills: 107443 max: 9060 slow allocs: 9097 max 1113 waste: 2.2% gc: 112913416B max: 2055672B slow: 65446328B max: 5385328B
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Mutator refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 32475
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Concurrent refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 0
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Total refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 32475
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Generate dirty cards rate: 2.68 cards/ms
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Mutator Allocation stats, regions: 484, wasted size: 21040B ( 0.0%)
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Mutator Allocation stats, regions: 19, wasted size: 368B ( 0.0%)
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Start adding marking candidates to collection set. Min 10 regions, max 160 regions, available 77 regionstime remaining 236.13ms, optional threshold 47.23ms
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Finish adding marking candidates to collection set (Predicted time too high).
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Finish adding marking candidates to collection set. Initial: 75, optional: 1, pinned: 0, predicted initial time: 181.59ms, predicted optional time: 42.98ms, time remaining: 0.00ms
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Start adding retained candidates to collection set. Min 1 regions, available 0, time remaining 0.00ms, optional remaining 90.00ms
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Retained candidates exhausted.
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Finish adding retained candidates to collection set. Initial: 0, optional: 0, pinned: 0, predicted initial time: 0.00ms, predicted optional time: 0.00ms, time remaining: 0.00ms optional time remaining 90.00ms
      [2024-09-24T20:13:20.169+0000][14972392ms] GC(2151) Humongous region 436 (object size 8388624 @ 0x0000000274000000) remset 7 code roots 0 marked 0 pinned count 0 reclaim candidate 0 type array 0
      [2024-09-24T20:13:20.171+0000][14972393ms] GC(2151) Running G1 Merge Heap Roots using 43 workers for 626 regions
      [2024-09-24T20:13:20.175+0000][14972397ms] GC(2151) Visited cards 23645696 Total dirty 27361280 (86.42%) Total old 68517888 (34.51%)
      [2024-09-24T20:13:20.332+0000][14972554ms] GC(2151) Prepared 1 regions out of 1 for optional evacuation. Total predicted time: 42.977ms
      [2024-09-24T20:13:20.332+0000][14972554ms] GC(2151) Running G1 Merge Heap Roots using 1 workers for 1 regions
      [2024-09-24T20:13:20.341+0000][14972564ms] GC(2151) Visited cards 8210432 Total dirty 27131904 (30.26%) Total old 71958528 (11.41%)
      [2024-09-24T20:13:25.508+0000][14977730ms] GC(2151) ReferenceProcessor::execute queues: 43, RefProcThreadModel::Multi, marks_oops_alive: false
      [2024-09-24T20:13:25.520+0000][14977743ms] GC(2151) ReferenceProcessor::execute queues: 43, RefProcThreadModel::Multi, marks_oops_alive: true
      [2024-09-24T20:13:25.524+0000][14977746ms] GC(2151) ReferenceProcessor::execute queues: 2, RefProcThreadModel::Multi, marks_oops_alive: false
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Running G1 Rebuild Free List Task using 43 workers for rebuilding free list of regions
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Young PLAB allocation: allocated: 778294616B, wasted: 509640B, unused: 124933368B, used: 652851608B, undo waste: 0B,
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Young other allocation: region end waste: 7959048B, regions filled: 53, num plab filled: 298, direct allocated: 74439200B, num direct allocated: 27, failure used: 0B, failure wasted: 0B
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Young sizing: calculated: 128978512B, actual: 123903704B
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Old PLAB allocation: allocated: 918852624B, wasted: 422904B, unused: 42779120B, used: 875650600B, undo waste: 0B,
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Old other allocation: region end waste: 1005760B, regions filled: 56, num plab filled: 1894, direct allocated: 10223408B, num direct allocated: 39, failure used: 0B, failure wasted: 0B
      [2024-09-24T20:13:25.550+0000][14977773ms] GC(2151) Old sizing: calculated: 174928968B, actual: 131812744B
      [2024-09-24T20:13:25.551+0000][14977773ms] G1 Service Thread (Card Set Free Memory Task) (run 0.018ms after schedule)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Heap expansion: short term pause time ratio 0.75% long term pause time ratio 0.95% threshold 7.69% pause time ratio 7.69% fully expanded false resize by 0B
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 14998831104B allocation request: 0B threshold: 14453541907B (54.05) source: end of GC
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) MMU target violated: 451.0ms (450.0ms/451.0ms)
      [2024-09-24T20:13:25.551+0000][14977773ms] Old generation allocation in the last mutator period, old gen allocated: 918852624B, humongous allocated: 0B, old gen growth: 918852624B.
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Basic information (value update), threshold: 14450523242B (54.04), target occupancy: 26742882304B, current occupancy: 15836512928B, recent allocation size: 918852624B, recent allocation duration: 13875.85ms, recent old gen allocation rate: 66219534.22B/s, recent marking phase length: 26015.46ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Adaptive IHOP information (value update), threshold: 14450523242B (56.88), internal target occupancy: 25405738188B, occupancy: 15836512928B, additional buffer size: 10435428352B, predicted old gen allocation rate: 20740218.20B/s, predicted marking phase length: 25061.77ms, prediction active: true
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) GC refinement: goal: 2634715 + 21501 / 45.00ms, actual: 607271 / 12.58ms,
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) New pending cards target: 2392857
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Pre Evacuate Collection Set: 1.08ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Pre Evacuate Prepare: 0.37ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) JT Retire TLABs And Flush Logs (ms): Min: 0.00, Avg: 0.18, Max: 0.23, Diff: 0.23, Sum: 1.93, Workers: 11
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Non-JT Flush Logs (ms): Min: 0.05, Avg: 0.05, Max: 0.05, Diff: 0.00, Sum: 0.05, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Choose Collection Set: 0.15ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Region Register: 0.54ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Prepare Heap Roots: 0.01ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merge Heap Roots: 4.78ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Prepare Merge Heap Roots: 0.06ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Remembered Sets (ms): Min: 1.59, Avg: 2.59, Max: 3.42, Diff: 1.83, Sum: 111.41, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Eager Reclaim (ms): skipped
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Inline: Min: 31, Avg: 195.1, Max: 541, Diff: 510, Sum: 8390, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged ArrayOfCards: Min: 247, Avg: 814.3, Max: 2359, Diff: 2112, Sum: 35015, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl: Min: 112, Avg: 202.0, Max: 315, Diff: 203, Sum: 8687, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Full: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl Inline: Min: 85, Avg: 333.2, Max: 623, Diff: 538, Sum: 14326, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl ArrayOfCards: Min: 365, Avg: 1102.1, Max: 1882, Diff: 1517, Sum: 47392, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl BitMap: Min: 34, Avg: 180.9, Max: 327, Diff: 293, Sum: 7777, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl Full: Min: 0, Avg: 0.0, Max: 1, Diff: 1, Sum: 1, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Cards: Min: 56485, Avg: 111059.8, Max: 143044, Diff: 86559, Sum: 4775572, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Distribute Log Buffers: 0.83ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Log Buffers (ms): Min: 0.00, Avg: 0.83, Max: 1.15, Diff: 1.14, Sum: 35.69, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dirty Cards: Min: 0, Avg: 14122.6, Max: 28366, Diff: 28366, Sum: 607271, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Skipped Cards: Min: 0, Avg: 1000.1, Max: 4098, Diff: 4098, Sum: 43003, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Evacuate Collection Set: 156.12ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Ext Root Scanning (ms): Min: 0.05, Avg: 1.06, Max: 18.50, Diff: 18.45, Sum: 45.49, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scan Heap Roots (ms): Min: 29.54, Avg: 78.22, Max: 92.30, Diff: 62.77, Sum: 3363.53, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Cards: Min: 40892, Avg: 104980.2, Max: 133039, Diff: 92147, Sum: 4514147, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Blocks: Min: 22397, Avg: 55413.9, Max: 70581, Diff: 48184, Sum: 2382798, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Claimed Chunks: Min: 1670, Avg: 4296.1, Max: 5660, Diff: 3990, Sum: 184732, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Found Roots: Min: 78169, Avg: 191819.8, Max: 269545, Diff: 191376, Sum: 8248253, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Code Root Scan (ms): Min: 0.07, Avg: 3.60, Max: 7.39, Diff: 7.32, Sum: 154.70, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Nmethods: Min: 0, Avg: 134.6, Max: 342, Diff: 342, Sum: 5789, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Object Copy (ms): Min: 49.78, Avg: 72.33, Max: 125.69, Diff: 75.90, Sum: 3110.04, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Termination (ms): Min: 0.16, Avg: 0.25, Max: 0.29, Diff: 0.14, Sum: 10.54, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 43, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) GC Worker Other (ms): Min: 0.08, Avg: 0.12, Max: 0.30, Diff: 0.22, Sum: 5.27, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) GC Worker Total (ms): Min: 145.22, Avg: 155.57, Max: 156.07, Diff: 10.85, Sum: 6689.57, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merge Optional Heap Roots: 9.85ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Prepare Optional Merge Heap Roots: 0.05ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Remembered Sets (ms): Min: 9.42, Avg: 9.42, Max: 9.42, Diff: 0.00, Sum: 9.42, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Inline: Min: 2, Avg: 2.0, Max: 2, Diff: 0, Sum: 2, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged ArrayOfCards: Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl: Min: 822, Avg: 822.0, Max: 822, Diff: 0, Sum: 822, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Full: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl Inline: Min: 214, Avg: 214.0, Max: 214, Diff: 0, Sum: 214, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl ArrayOfCards: Min: 4070, Avg: 4070.0, Max: 4070, Diff: 0, Sum: 4070, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl BitMap: Min: 2292, Avg: 2292.0, Max: 2292, Diff: 0, Sum: 2292, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Howl Full: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merged Cards: Min: 861245, Avg: 861245.0, Max: 861245, Diff: 0, Sum: 861245, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Evacuate Optional Collection Set: 5162.17ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Scan Heap Roots (ms): Min: 2.62, Avg: 13.52, Max: 18.15, Diff: 15.53, Sum: 581.52, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Cards: Min: 812, Avg: 13733.8, Max: 18158, Diff: 17346, Sum: 590554, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Blocks: Min: 518, Avg: 8363.6, Max: 11558, Diff: 11040, Sum: 359636, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Claimed Chunks: Min: 94, Avg: 1491.7, Max: 2130, Diff: 2036, Sum: 64144, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Found Roots: Min: 18143, Avg: 49450.2, Max: 66134, Diff: 47991, Sum: 2126359, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Refs: Min: 12346, Avg: 21218.1, Max: 34888, Diff: 22542, Sum: 912380, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Used Memory: Min: 103984, Avg: 178338.4, Max: 293192, Diff: 189208, Sum: 7668552, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Object Copy (ms): Min: 0.04, Avg: 0.77, Max: 1.86, Diff: 1.82, Sum: 33.28, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Code Root Scan (ms): Min: 4976.81, Avg: 5067.57, Max: 5140.43, Diff: 163.62, Sum: 217905.55, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Scanned Nmethods: Min: 355, Avg: 1074.7, Max: 1574, Diff: 1219, Sum: 46213, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Termination (ms): Min: 0.10, Avg: 73.24, Max: 163.56, Diff: 163.46, Sum: 3149.48, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Optional Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 43, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Post Evacuate Collection Set: 53.87ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) NMethod List Cleanup: 6.95ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Reference Processing: 20.30ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Notify Soft/WeakReferences: 16.5ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Balance queues: 4.4ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) SoftRef (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.02, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) WeakRef (ms): Min: 0.88, Avg: 1.83, Max: 2.91, Diff: 2.03, Sum: 78.69, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) FinalRef (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.05, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total (ms): Min: 2.68, Avg: 9.66, Max: 12.00, Diff: 9.32, Sum: 415.42, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Notify and keep alive finalizable: 3.4ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Balance queues: 0.0ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) FinalRef (ms): Min: 1.03, Avg: 3.03, Max: 3.39, Diff: 2.36, Sum: 130.20, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Notify PhantomReferences: 0.3ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Balance queues: 0.0ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) PhantomRef (ms): Min: 0.11, Avg: 0.13, Max: 0.14, Diff: 0.04, Sum: 0.25, Workers: 2
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) SoftReference Discovered: 0, Dropped: 0, Processed: 0
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) WeakReference Discovered: 207121, Dropped: 185671, Processed: 21450
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) FinalReference Discovered: 235, Dropped: 0, Processed: 235
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) PhantomReference Discovered: 1408, Dropped: 980, Processed: 428
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Weak Processing: 7.13ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) VM Weak Min: 0.00, Avg: 0.02, Max: 0.07, Diff: 0.07, Sum: 0.73, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 763.0, Max: 3884, Diff: 3884, Sum: 32807, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.01, Diff: 0.00, Sum: 0.06, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.2, Max: 4, Diff: 4, Sum: 9, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 8.5, Max: 64, Diff: 64, Sum: 364, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.04, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) StringTable Weak Min: 0.00, Avg: 0.44, Max: 6.95, Diff: 6.95, Sum: 19.03, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 1.1, Max: 6, Diff: 6, Sum: 47, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 10075.7, Max: 13936, Diff: 13936, Sum: 433256, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) ResolvedMethodTable Weak Min: 0.00, Avg: 0.06, Max: 0.07, Diff: 0.07, Sum: 2.43, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 1925.9, Max: 2624, Diff: 2624, Sum: 82812, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.01, Diff: 0.01, Sum: 0.11, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 0.0, Max: 1, Diff: 1, Sum: 1, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) StringDedup Table Weak Min: 0.00, Avg: 5.62, Max: 6.56, Diff: 6.56, Sum: 241.75, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 75.8, Max: 147, Diff: 147, Sum: 3261, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 180854.0, Max: 211881, Diff: 211881, Sum: 7776720, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) StringDedup Requests0 Weak Min: 0.00, Avg: 0.42, Max: 0.47, Diff: 0.47, Sum: 17.92, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 1.2, Max: 51, Diff: 51, Sum: 51, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 6041.3, Max: 7424, Diff: 7424, Sum: 259776, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.01, Diff: 0.01, Sum: 0.10, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.08, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Post Evacuate Cleanup 1: 5.38ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Merge Per-Thread State (ms): Min: 5.33, Avg: 5.33, Max: 5.33, Diff: 0.00, Sum: 5.33, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Copied Bytes: Min: 24450160, Avg: 37515460.8, Max: 98895728, Diff: 74445568, Sum: 1613164816, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) LAB Waste: Min: 1728, Avg: 21687.1, Max: 428720, Diff: 426992, Sum: 932544, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) LAB Undo Waste: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Evac Fail Extra Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Clear Logged Cards (ms): Min: 0.00, Avg: 0.34, Max: 0.68, Diff: 0.68, Sum: 14.79, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Recalculate Used Memory (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Post Evacuate Cleanup 2: 13.81ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Update Derived Pointers (ms): Min: 2.01, Avg: 2.01, Max: 2.01, Diff: 0.00, Sum: 2.01, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Eagerly Reclaim Humongous Objects (ms): skipped
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Humongous Total: skipped
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Humongous Candidates: skipped
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Humongous Reclaimed: skipped
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Sample CSet Candidates (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Redirty Logged Cards (ms): Min: 0.00, Avg: 0.55, Max: 1.16, Diff: 1.16, Sum: 23.55, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Redirtied Cards: Min: 0, Avg: 63065.5, Max: 144031, Diff: 144031, Sum: 2711818, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Resize TLABs (ms): Min: 0.00, Avg: 0.01, Max: 0.06, Diff: 0.06, Sum: 0.46, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Free Collection Set (ms): Min: 0.00, Avg: 0.81, Max: 12.97, Diff: 12.97, Sum: 34.66, Workers: 43
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Rebuild Free List: 0.27ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Prepare For Mutator: 0.02ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Expand Heap After Collection: 0.00ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Other: -5.98ms
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Coarsening (recent): Inline->AoC 0 (0) AoC->Howl 0 (0) Howl->Full 0 (0) Inline->AoC 0 (0) AoC->BitMap 0 (0) BitMap->Full 0 (0)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Coarsening (all): Inline->AoC 12351359 (144) AoC->Howl 2179572 (987) Howl->Full 0 (0) Inline->AoC 13798899 (761) AoC->BitMap 4630189 (5578) BitMap->Full 809 (2)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Eden regions: 503->0(26) (0: 267->0, 1: 236->0)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Survivor regions: 48->53(69) (0: 22->24, 1: 26->29)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Old regions: 913->893
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Humongous regions: 1->1
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Metaspace: 593595K(619968K)->593595K(619968K) NonClass: 511171K(521024K)->511171K(521024K) Class: 82423K(98944K)->82423K(98944K)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Heap after GC invocations=2152 (full 0):
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) garbage-first heap total reserved 30408704K, committed 26116096K, used 15465344K [0x00000000c0000000, 0x0000000800000000)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) region size 16384K, 53 young (868352K), 53 survivors (868352K)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) remaining free region(s) on each NUMA node: 0=340 1=307
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Metaspace used 593595K, committed 619968K, reserved 1572864K
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) class space used 82423K, committed 98944K, reserved 1048576K
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Placement match ratio: 58% 441964/759086 (0: 57% 381991/667008, 1: 99% 59973/60778)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Allocated NUMA ids 0 1 Total
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Requested NUMA id 0 381991 285017 667008
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) 1 805 59973 60778
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Any 15411 15889 31300
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Worker task locality match ratio: 50% 534819/1061923 (0: 48% 209686/436747, 1: 52% 325133/625176)
      [2024-09-24T20:13:25.551+0000][14977773ms] GC(2151) Pause Young (Mixed) (G1 Evacuation Pause) 23397M->15102M(25504M) 5382.168ms
      [2024-09-24T20:13:25.551+0000][14977774ms] GC(2151) User=191.67s Sys=13.81s Real=5.38s


      This is another pause:

      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) Pause Young (Mixed) (G1 Evacuation Pause)
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) Heap before GC invocations=1312 (full 1):
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) garbage-first heap total reserved 30408704K, committed 7110656K, used 6626927K [0x00000000c0000000, 0x0000000800000000)
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) region size 16384K, 21 young (344064K), 3 survivors (49152K)
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) remaining free region(s) on each NUMA node: 0=16 1=11
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) Metaspace used 542381K, committed 564608K, reserved 1572864K
      [2024-09-24T16:02:19.579+0000][7056141ms] GC(1313) class space used 73901K, committed 87552K, reserved 1048576K
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Using 43 workers of 43 for evacuation
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Desired survivor size 25165824 bytes, new threshold 1 (max threshold 15)
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) TLAB totals: thrds: 167 refills: 9866 max: 1150 slow allocs: 1276 max 200 waste: 3.3% gc: 3148576B max: 156480B slow: 5996144B max: 682152B
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Mutator refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 3356
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Concurrent refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 0
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Total refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 3356
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Generate dirty cards rate: 0.60 cards/ms
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Mutator Allocation stats, regions: 17, wasted size: 1368B ( 0.0%)
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Mutator Allocation stats, regions: 1, wasted size: 0B ( 0.0%)
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Start adding marking candidates to collection set. Min 2 regions, max 44 regions, available 1 regionstime remaining 250.78ms, optional threshold 50.16ms
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Marking candidates exhausted.
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Added 1 marking candidates to collection set although the predicted time was too high.
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Finish adding marking candidates to collection set. Initial: 1, optional: 0, pinned: 0, predicted initial time: 603.90ms, predicted optional time: 0.00ms, time remaining: 0.00ms
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Start adding retained candidates to collection set. Min 1 regions, available 0, time remaining 0.00ms, optional remaining 90.00ms
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Retained candidates exhausted.
      [2024-09-24T16:02:19.580+0000][7056141ms] GC(1313) Finish adding retained candidates to collection set. Initial: 0, optional: 0, pinned: 0, predicted initial time: 0.00ms, predicted optional time: 0.00ms, time remaining: 0.00ms optional time remaining 90.00ms
      [2024-09-24T16:02:19.580+0000][7056142ms] GC(1313) Humongous region 41 (object size 8388624 @ 0x00000000e9000000) remset 0 code roots 0 marked 0 pinned count 0 reclaim candidate 0 type array 0
      [2024-09-24T16:02:19.581+0000][7056143ms] GC(1313) Running G1 Merge Heap Roots using 43 workers for 22 regions
      [2024-09-24T16:02:19.585+0000][7056146ms] GC(1313) Visited cards 10139264 Total dirty 12517376 (81.00%) Total old 14057472 (72.13%)
      [2024-09-24T16:02:23.952+0000][7060514ms] GC(1313) ReferenceProcessor::execute queues: 3, RefProcThreadModel::Multi, marks_oops_alive: false
      [2024-09-24T16:02:23.953+0000][7060514ms] GC(1313) ReferenceProcessor::execute queues: 43, RefProcThreadModel::Multi, marks_oops_alive: true
      [2024-09-24T16:02:23.955+0000][7060516ms] GC(1313) Skipped PhantomRefsPhase of Reference Processing: no references
      [2024-09-24T16:02:23.973+0000][7060535ms] GC(1313) Running G1 Rebuild Free List Task using 43 workers for rebuilding free list of regions
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Young PLAB allocation: allocated: 21890960B, wasted: 18512B, unused: 8792272B, used: 13080176B, undo waste: 0B,
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Young other allocation: region end waste: 0B, regions filled: 2, num plab filled: 150, direct allocated: 16432B, num direct allocated: 1, failure used: 0B, failure wasted: 0B
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Young sizing: calculated: 2616032B, actual: 3480312B
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Old PLAB allocation: allocated: 44188896B, wasted: 85712B, unused: 8159224B, used: 35943960B, undo waste: 0B,
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Old other allocation: region end waste: 0B, regions filled: 4, num plab filled: 119, direct allocated: 6245128B, num direct allocated: 3, failure used: 0B, failure wasted: 0B
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Old sizing: calculated: 7188792B, actual: 9093864B
      [2024-09-24T16:02:23.974+0000][7060535ms] G1 Service Thread (Card Set Free Memory Task) (run 0.031ms after schedule)
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Heap expansion: short term pause time ratio 1.57% long term pause time ratio 7.32% threshold 3.60% pause time ratio 7.69% fully expanded false resize by 0B
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 6509559808B allocation request: 0B threshold: 6416773183B (88.13) source: end of GC
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) MMU target violated: 451.0ms (450.0ms/451.0ms)
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) do not continue mixed GCs (candidate old regions not available)
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 6509559808B allocation request: 0B threshold: 6416773183B (88.13) source: end of GC
      [2024-09-24T16:02:23.974+0000][7060535ms] Old generation allocation in the last mutator period, old gen allocated: 44188896B, humongous allocated: 0B, old gen growth: 44188896B.
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) GC refinement: goal: 2049325 + 2320 / 45.00ms, actual: 244428 / 5.92ms,
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) New pending cards target: 1953255
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Pre Evacuate Collection Set: 0.61ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Pre Evacuate Prepare: 0.28ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) JT Retire TLABs And Flush Logs (ms): Min: 0.00, Avg: 0.12, Max: 0.20, Diff: 0.19, Sum: 0.93, Workers: 8
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Non-JT Flush Logs (ms): Min: 0.02, Avg: 0.02, Max: 0.02, Diff: 0.00, Sum: 0.02, Workers: 1
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Choose Collection Set: 0.03ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Region Register: 0.30ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Prepare Heap Roots: 0.01ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Merge Heap Roots: 4.49ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Prepare Merge Heap Roots: 0.06ms
      [2024-09-24T16:02:23.974+0000][7060535ms] GC(1313) Remembered Sets (ms): Min: 0.00, Avg: 0.52, Max: 3.44, Diff: 3.44, Sum: 22.37, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Eager Reclaim (ms): skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Inline: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged ArrayOfCards: Min: 0, Avg: 0.0, Max: 1, Diff: 1, Sum: 1, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Howl: Min: 0, Avg: 8.6, Max: 56, Diff: 56, Sum: 371, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Full: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Howl Inline: Min: 0, Avg: 2.3, Max: 36, Diff: 36, Sum: 98, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Howl ArrayOfCards: Min: 0, Avg: 1.3, Max: 22, Diff: 22, Sum: 54, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Howl BitMap: Min: 0, Avg: 65.5, Max: 405, Diff: 405, Sum: 2816, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Howl Full: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merged Cards: Min: 8, Avg: 40485.4, Max: 257446, Diff: 257438, Sum: 1740873, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Distribute Log Buffers: 0.52ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Log Buffers (ms): Min: 0.00, Avg: 0.33, Max: 0.65, Diff: 0.65, Sum: 14.30, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dirty Cards: Min: 0, Avg: 5684.4, Max: 12970, Diff: 12970, Sum: 244428, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Skipped Cards: Min: 0, Avg: 0.5, Max: 7, Diff: 7, Sum: 22, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Evacuate Collection Set: 4362.93ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Ext Root Scanning (ms): Min: 0.06, Avg: 1.67, Max: 35.96, Diff: 35.90, Sum: 71.89, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Scan Heap Roots (ms): Min: 18.55, Avg: 37.29, Max: 55.80, Diff: 37.26, Sum: 1603.58, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Scanned Cards: Min: 5093, Avg: 41906.0, Max: 60179, Diff: 55086, Sum: 1801960, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Scanned Blocks: Min: 2337, Avg: 18495.1, Max: 27526, Diff: 25189, Sum: 795290, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Claimed Chunks: Min: 251, Avg: 1842.2, Max: 2753, Diff: 2502, Sum: 79213, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Found Roots: Min: 12393, Avg: 102484.6, Max: 155254, Diff: 142861, Sum: 4406837, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Code Root Scan (ms): Min: 4203.27, Avg: 4229.41, Max: 4317.52, Diff: 114.25, Sum: 181864.56, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Scanned Nmethods: Min: 14, Avg: 714.2, Max: 1256, Diff: 1242, Sum: 30711, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Object Copy (ms): Min: 1.01, Avg: 4.99, Max: 19.77, Diff: 18.77, Sum: 214.56, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Termination (ms): Min: 0.15, Avg: 86.67, Max: 98.38, Diff: 98.23, Sum: 3726.94, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 43, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) GC Worker Other (ms): Min: 0.02, Avg: 0.05, Max: 0.14, Diff: 0.11, Sum: 1.96, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) GC Worker Total (ms): Min: 4345.29, Avg: 4360.08, Max: 4362.83, Diff: 17.54, Sum: 187483.48, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Post Evacuate Collection Set: 25.98ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) NMethod List Cleanup: 4.48ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Reference Processing: 2.28ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Notify Soft/WeakReferences: 0.5ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Balance queues: 0.2ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) SoftRef (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 3
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) WeakRef (ms): Min: 0.06, Avg: 0.12, Max: 0.19, Diff: 0.12, Sum: 0.36, Workers: 3
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) FinalRef (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 3
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total (ms): Min: 0.20, Avg: 0.21, Max: 0.23, Diff: 0.04, Sum: 0.64, Workers: 3
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Notify and keep alive finalizable: 1.8ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Balance queues: 0.0ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) FinalRef (ms): Min: 0.13, Avg: 0.52, Max: 1.65, Diff: 1.53, Sum: 22.33, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Notify PhantomReferences: 0.0ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) PhantomRef (ms): skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) SoftReference Discovered: 0, Dropped: 0, Processed: 0
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) WeakReference Discovered: 2559, Dropped: 61, Processed: 2498
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) FinalReference Discovered: 12, Dropped: 0, Processed: 12
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) PhantomReference Discovered: 0, Dropped: 0, Processed: 0
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Weak Processing: 10.04ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) VM Weak Min: 0.00, Avg: 0.01, Max: 0.11, Diff: 0.11, Sum: 0.55, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 647.6, Max: 6208, Diff: 6208, Sum: 27847, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.02, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.2, Max: 6, Diff: 6, Sum: 10, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 3.2, Max: 64, Diff: 64, Sum: 138, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.02, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) StringTable Weak Min: 0.00, Avg: 0.46, Max: 9.84, Diff: 9.84, Sum: 19.98, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.2, Max: 4, Diff: 4, Sum: 8, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 10005.7, Max: 45632, Diff: 45632, Sum: 430246, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) ResolvedMethodTable Weak Min: 0.00, Avg: 0.04, Max: 0.06, Diff: 0.06, Sum: 1.52, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 1511.0, Max: 2852, Diff: 2852, Sum: 64971, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.01, Diff: 0.01, Sum: 0.09, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 0.0, Max: 1, Diff: 1, Sum: 1, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) StringDedup Table Weak Min: 0.00, Avg: 6.79, Max: 9.03, Diff: 9.03, Sum: 292.12, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 1.3, Max: 11, Diff: 11, Sum: 58, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 113116.2, Max: 179226, Diff: 179226, Sum: 4863997, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.04, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) StringDedup Requests1 Weak Min: 0.00, Avg: 0.12, Max: 0.17, Diff: 0.17, Sum: 5.11, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.2, Max: 8, Diff: 8, Sum: 8, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 1446.7, Max: 2624, Diff: 2624, Sum: 62208, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.06, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Post Evacuate Cleanup 1: 0.35ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Merge Per-Thread State (ms): Min: 0.29, Avg: 0.29, Max: 0.29, Diff: 0.00, Sum: 0.29, Workers: 1
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Copied Bytes: Min: 4880, Avg: 1285713.9, Max: 8231728, Diff: 8226848, Sum: 55285696, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) LAB Waste: Min: 0, Avg: 2423.8, Max: 62968, Diff: 62968, Sum: 104224, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) LAB Undo Waste: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Evac Fail Extra Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Clear Logged Cards (ms): Min: 0.00, Avg: 0.03, Max: 0.08, Diff: 0.08, Sum: 0.08, Workers: 3
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Recalculate Used Memory (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Post Evacuate Cleanup 2: 8.39ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Update Derived Pointers (ms): Min: 1.15, Avg: 1.15, Max: 1.15, Diff: 0.00, Sum: 1.15, Workers: 1
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Eagerly Reclaim Humongous Objects (ms): skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Humongous Total: skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Humongous Candidates: skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Humongous Reclaimed: skipped
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Redirty Logged Cards (ms): Min: 0.00, Avg: 0.00, Max: 0.03, Diff: 0.03, Sum: 0.10, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Redirtied Cards: Min: 0, Avg: 42.7, Max: 869, Diff: 869, Sum: 1834, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Resize TLABs (ms): Min: 0.00, Avg: 0.01, Max: 0.06, Diff: 0.06, Sum: 0.34, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Free Collection Set (ms): Min: 0.00, Avg: 0.18, Max: 7.73, Diff: 7.73, Sum: 7.85, Workers: 43
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Rebuild Free List: 0.39ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Prepare For Mutator: 0.04ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Expand Heap After Collection: 0.00ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Other: 0.43ms
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Coarsening (recent): Inline->AoC 0 (0) AoC->Howl 0 (0) Howl->Full 0 (0) Inline->AoC 0 (0) AoC->BitMap 0 (0) BitMap->Full 0 (0)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Coarsening (all): Inline->AoC 2630775 (52) AoC->Howl 505167 (272) Howl->Full 18 (0) Inline->AoC 3045886 (217) AoC->BitMap 932116 (1158) BitMap->Full 233 (0)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Eden regions: 18->0(19) (0: 15->0, 1: 3->0)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Survivor regions: 3->2(3) (0: 2->1, 1: 1->1)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Old regions: 385->387
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Humongous regions: 1->1
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Metaspace: 542381K(564608K)->542381K(564608K) NonClass: 468479K(477056K)->468479K(477056K) Class: 73901K(87552K)->73901K(87552K)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Heap after GC invocations=1313 (full 1):
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) garbage-first heap total reserved 30408704K, committed 7110656K, used 6360004K [0x00000000c0000000, 0x0000000800000000)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) region size 16384K, 2 young (32768K), 2 survivors (32768K)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) remaining free region(s) on each NUMA node: 0=29 1=15
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Metaspace used 542381K, committed 564608K, reserved 1572864K
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) class space used 73901K, committed 87552K, reserved 1048576K
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Placement match ratio: 57% 123608/217977 (0: 56% 107561/190470, 1: 98% 16047/16299)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Allocated NUMA ids 0 1 Total
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Requested NUMA id 0 107561 82909 190470
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) 1 252 16047 16299
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Any 5491 5717 11208
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Worker task locality match ratio: 50% 310541/615046 (0: 49% 127291/260640, 1: 52% 183250/354406)
      [2024-09-24T16:02:23.974+0000][7060536ms] GC(1313) Pause Young (Mixed) (G1 Evacuation Pause) 6472M->6210M(6944M) 4394.964ms
      [2024-09-24T16:02:23.975+0000][7060536ms] GC(1313) User=95.25s Sys=11.14s Real=4.40s


      REGRESSION : Last worked in version 23

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      Run the application for a few hours, ocasionally we get this very long pauses for no reason at all. They can happen even when the application is at low traffic

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      Pauses should be about the other minor gcs, usually 100-200 ms at most

      CUSTOMER SUBMITTED WORKAROUND :
      Revert back to jdk22.0.2

      FREQUENCY : occasionally


            Unassigned Unassigned
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated: