0 Replies Latest reply: Jun 19, 2012 2:27 AM by 944481 RSS

    weird GC situation in WebLogic 10.3.4 with JRockit1.6.0_27

    944481
      In the first 5 hours, GC is normal (4 or 5 YC, then 1 OC), and then there is only OC left. OC is very frequent, once per ms. But what weird is the size of OC in the output is only around 200MB. How is this possible for the setting like this: Heap size: 786432KB, maximal heap size: 1048576KB, nursery size: 315392KB?

      Thank in advance for any comments!

      Java version "1.6.0_17"
      Java<TM> SET Runtime Environment (build 1.6.0_17-b04)
      Oracle JRockit(R) (build R28.0.0-679-130297-1.6.0_17-20100312-2123-windows-ia32, compiled mode)

      [INFO ][memory ] GC mode: Garbage collection optimized for short pausetimes, strategy: Generational Concurrent Mark & Sweep.
      +_[INFO ][memory ] Heap size: 786432KB, maximal heap size: 1048576KB, nursery size: 315392KB._+*
      [INFO ][memory ] <start>-<end>: <type> <before>KB-><after>KB (<heap>KB), <time> ms, sum of pauses <pause> ms.
      [INFO ][memory ] <start> - start time of collection (seconds since jvm start).
      [INFO ][memory ] <type> - OC (old collection) or YC (young collection).
      [INFO ][memory ] <end> - end time of collection (seconds since jvm start).
      [INFO ][memory ] <before> - memory used by objects before collection (KB).
      [INFO ][memory ] <after> - memory used by objects after collection (KB).
      [INFO ][memory ] <heap> - size of heap after collection (KB).
      [INFO ][memory ] <time> - total time of collection (milliseconds).
      [INFO ][memory ] <pause> - total sum of pauses during collection (milliseconds).
      [INFO ][memory ] Run with -Xverbose:gcpause to see individual phases.

      [INFO ][memory ] [OC#13] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#13] 6975.016-6975.395: OC 429229KB->126461KB (786432KB), 0.379 s, sum of pauses 63.077 ms, longest pause 38.684 ms.
      [INFO ][memory ] [YC#58] 6980.432-6980.456: YC 526992KB->291218KB (786432KB), 0.024 s, sum of pauses 23.671 ms, longest pause 23.671 ms.
      [INFO ][memory ] [YC#59] 6985.666-6985.692: YC 599956KB->364888KB (786432KB), 0.027 s, sum of pauses 26.523 ms, longest pause 26.523 ms.
      [INFO ][memory ] [YC#60] 6988.709-6988.730: YC 662879KB->426977KB (786432KB), 0.022 s, sum of pauses 21.702 ms, longest pause 21.702 ms.
      [INFO ][memory ] [OC#14] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#14] 6994.199-6994.577: OC 706415KB->127126KB (786432KB), 0.378 s, sum of pauses 71.130 ms, longest pause 39.413 ms.
      [INFO ][memory ] [YC#61] 6998.612-6998.642: YC 536131KB->302324KB (786432KB), 0.030 s, sum of pauses 30.138 ms, longest pause 30.138 ms.
      [INFO ][memory ] [YC#62] 7003.815-7003.836: YC 605982KB->370250KB (786432KB), 0.021 s, sum of pauses 21.217 ms, longest pause 21.217 ms.
      [INFO ][memory ] [YC#63] 7006.204-7006.231: YC 679599KB->444414KB (786432KB), 0.027 s, sum of pauses 26.808 ms, longest pause 26.808 ms.
      [INFO ][memory ] [OC#15] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#15] 7009.979-7010.341: OC 624880KB->130008KB (786432KB), 0.363 s, sum of pauses 73.581 ms, longest pause 39.984 ms.
      [INFO ][memory ] [YC#64] 7014.838-7014.870: YC 530276KB->294310KB (786432KB), 0.031 s, sum of pauses 31.191 ms, longest pause 31.191 ms.
      [INFO ][memory ] [YC#65] 7020.333-7020.361: YC 603181KB->367187KB (786432KB), 0.028 s, sum of pauses 27.820 ms, longest pause 27.820 ms.
      [INFO ][memory ] [YC#66] 7023.590-7023.614: YC 661276KB->425823KB (786432KB), 0.024 s, sum of pauses 23.865 ms, longest pause 23.865 ms.
      [INFO ][memory ] [OC#16] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#16] 7028.416-7028.877: OC 681087KB->129159KB (786432KB), 0.461 s, sum of pauses 61.651 ms, longest pause 33.651 ms.
      [INFO ][memory ] [YC#67] 7031.958-7031.980: YC 527378KB->291739KB (786432KB), 0.022 s, sum of pauses 21.950 ms, longest pause 21.950 ms.
      [INFO ][memory ] [YC#68] 7038.467-7038.490: YC 597892KB->362609KB (786432KB), 0.023 s, sum of pauses 22.934 ms, longest pause 22.934 ms.
      [INFO ][memory ] [YC#69] 7040.907-7040.931: YC 661396KB->425903KB (786432KB), 0.025 s, sum of pauses 24.287 ms, longest pause 24.287 ms.
      [INFO ][memory ] [OC#17] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#17] 7045.368-7045.750: OC 695532KB->131855KB (786432KB), 0.383 s, sum of pauses 91.983 ms, longest pause 59.362 ms.
      [INFO ][memory ] [YC#70] 7050.277-7050.305: YC 533494KB->297463KB (786432KB), 0.028 s, sum of pauses 27.892 ms, longest pause 27.892 ms.
      [INFO ][memory ] [YC#71] 7055.643-7055.668: YC 606436KB->370859KB (786432KB), 0.025 s, sum of pauses 24.846 ms, longest pause 24.846 ms.
      [INFO ][memory ] [YC#72] 7058.061-7058.087: YC 677691KB->441982KB (786432KB), 0.026 s, sum of pauses 25.795 ms, longest pause 25.795 ms.
      [INFO ][memory ] [OC#18] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#18] 7061.305-7061.763: OC 615651KB->130176KB (786432KB), 0.458 s, sum of pauses 59.495 ms, longest pause 30.006 ms.
      [INFO ][memory ] [YC#73] 7065.933-7065.961: YC 526038KB->289944KB (786432KB), 0.028 s, sum of pauses 27.350 ms, longest pause 27.350 ms.
      [INFO ][memory ] [YC#74] 7071.243-7071.272: YC 598522KB->363397KB (786432KB), 0.028 s, sum of pauses 28.081 ms, longest pause 28.081 ms.
      [INFO ][memory ] [YC#75] 7073.983-7074.010: YC 660981KB->424759KB (786432KB), 0.027 s, sum of pauses 27.161 ms, longest pause 27.161 ms.
      [INFO ][memory ] [OC#19] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#19] 7079.584-7079.947: OC 719010KB->128772KB (786432KB), 0.362 s, sum of pauses 73.342 ms, longest pause 44.206 ms.
      [INFO ][memory ] [YC#76] 7083.641-7083.668: YC 525502KB->290909KB (786432KB), 0.027 s, sum of pauses 27.056 ms, longest pause 27.056 ms.
      [INFO ][memory ] [YC#77] 7088.734-7088.755: YC 593892KB->358124KB (786432KB), 0.021 s, sum of pauses 20.809 ms, longest pause 20.809 ms.
      [INFO ][memory ] [YC#78] 7091.729-7091.752: YC 669650KB->434487KB (786432KB), 0.023 s, sum of pauses 22.577 ms, longest pause 22.577 ms.
      [INFO ][memory ] [OC#20] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#20] 7096.616-7097.014: OC 674696KB->132714KB (786432KB), 0.398 s, sum of pauses 62.841 ms, longest pause 31.281 ms.
      [INFO ][memory ] [YC#79] 7101.187-7101.210: YC 530959KB->295828KB (786432KB), 0.023 s, sum of pauses 23.273 ms, longest pause 23.273 ms.
      [INFO ][memory ] [YC#80] 7105.939-7105.961: YC 594712KB->358682KB (786432KB), 0.021 s, sum of pauses 21.262 ms, longest pause 21.262 ms.
      [INFO ][memory ] [YC#81] 7109.819-7109.842: YC 661500KB->426061KB (786432KB), 0.023 s, sum of pauses 22.800 ms, longest pause 22.800 ms.
      [INFO ][memory ] [OC#21] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#21] 7113.521-7113.917: OC 710828KB->132141KB (786432KB), 0.396 s, sum of pauses 74.579 ms, longest pause 47.357 ms.
      [INFO ][memory ] [YC#82] 7120.728-7120.760: YC 539135KB->304771KB (786432KB), 0.033 s, sum of pauses 32.498 ms, longest pause 32.498 ms.
      [INFO ][memory ] [YC#83] 7122.966-7122.988: YC 594740KB->359526KB (786432KB), 0.022 s, sum of pauses 21.848 ms, longest pause 21.848 ms.
      [INFO ][memory ] [YC#84] 7128.733-7128.762: YC 683295KB->448990KB (786432KB), 0.029 s, sum of pauses 28.823 ms, longest pause 28.823 ms.
      [INFO ][memory ] [OC#22] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#22] 7131.037-7131.456: OC 696780KB->135907KB (786432KB), 0.419 s, sum of pauses 59.353 ms, longest pause 32.236 ms.
      [INFO ][memory ] [YC#85] 7138.068-7138.092: YC 549646KB->314767KB (786432KB), 0.024 s, sum of pauses 24.099 ms, longest pause 24.099 ms.
      [INFO ][memory ] [YC#86] 7140.137-7140.160: YC 623093KB->387517KB (786432KB), 0.024 s, sum of pauses 23.331 ms, longest pause 23.331 ms.
      [INFO ][memory ] [YC#87] 7145.879-7145.903: YC 700581KB->466186KB (786432KB), 0.024 s, sum of pauses 23.407 ms, longest pause 23.407 ms.
      [INFO ][memory ] [OC#23] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#23] 7147.109-7147.546: OC 576861KB->131707KB (786432KB), 0.437 s, sum of pauses 68.992 ms, longest pause 43.976 ms.
      [INFO ][memory ] [YC#88] 7152.264-7152.287: YC 528000KB->293290KB (786432KB), 0.023 s, sum of pauses 22.875 ms, longest pause 22.875 ms.
      [INFO ][memory ] [YC#89] 7156.470-7156.494: YC 599120KB->363562KB (786432KB), 0.024 s, sum of pauses 24.099 ms, longest pause 24.099 ms.
      [INFO ][memory ] [YC#90] 7161.084-7161.112: YC 679127KB->443229KB (786432KB), 0.029 s, sum of pauses 28.392 ms, longest pause 28.392 ms.
      [INFO ][memory ] [OC#24] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#24] 7163.087-7163.513: OC 650430KB->130494KB (786432KB), 0.425 s, sum of pauses 65.819 ms, longest pause 41.217 ms.
      [INFO ][memory ] [YC#91] 7168.193-7168.215: YC 532757KB->297763KB (786432KB), 0.023 s, sum of pauses 22.385 ms, longest pause 22.385 ms.
      [INFO ][memory ] [YC#92] 7171.615-7171.642: YC 604364KB->369403KB (786432KB), 0.027 s, sum of pauses 26.524 ms, longest pause 26.524 ms.
      [INFO ][memory ] [YC#93] 7175.444-7175.469: YC 677177KB->441343KB (786432KB), 0.025 s, sum of pauses 25.195 ms, longest pause 25.195 ms.
      [INFO ][memory ] [OC#25] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#25] 7177.841-7178.240: OC 659374KB->130924KB (786432KB), 0.399 s, sum of pauses 78.386 ms, longest pause 42.303 ms.
      [INFO ][memory ] [YC#94] 7183.090-7183.117: YC 540339KB->305016KB (786432KB), 0.027 s, sum of pauses 26.922 ms, longest pause 26.922 ms.
      [INFO ][memory ] [YC#95] 7186.590-7186.618: YC 610141KB->374157KB (786432KB), 0.028 s, sum of pauses 27.922 ms, longest pause 27.922 ms.
      [INFO ][memory ] [YC#96] 7189.914-7189.941: YC 681482KB->445877KB (786432KB), 0.027 s, sum of pauses 26.939 ms, longest pause 26.939 ms.
      [INFO ][memory ] [OC#26] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#26] 7191.992-7192.374: OC 622099KB->130293KB (786432KB), 0.382 s, sum of pauses 59.752 ms, longest pause 32.346 ms.
      [INFO ][memory ] [YC#97] 7197.404-7197.431: YC 534800KB->299351KB (786432KB), 0.027 s, sum of pauses 26.518 ms, longest pause 26.518 ms.
      [INFO ][memory ] [YC#98] 7201.452-7201.474: YC 603141KB->367070KB (786432KB), 0.023 s, sum of pauses 22.198 ms, longest pause 22.198 ms.
      [INFO ][memory ] [YC#99] 7203.989-7204.010: YC 671784KB->435760KB (786432KB), 0.021 s, sum of pauses 20.713 ms, longest pause 20.713 ms.
      [INFO ][memory ] [OC#27] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#27] 7206.855-7207.213: OC 628570KB->132658KB (786432KB), 0.358 s, sum of pauses 67.570 ms, longest pause 38.896 ms.
      [INFO ][memory ] [YC#100] 7211.582-7211.605: YC 534350KB->298593KB (786432KB), 0.024 s, sum of pauses 23.378 ms, longest pause 23.378 ms.
      [INFO ][memory ] [YC#101] 7215.240-7215.262: YC 605381KB->369544KB (786432KB), 0.022 s, sum of pauses 21.712 ms, longest pause 21.712 ms.
      [INFO ][memory ] [YC#102] 7219.118-7219.143: YC 669530KB->433503KB (786432KB), 0.025 s, sum of pauses 24.924 ms, longest pause 24.924 ms.
      [INFO ][memory ] [OC#28] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#28] 7222.032-7222.388: OC 670496KB->128033KB (786432KB), 0.356 s, sum of pauses 52.587 ms, longest pause 28.657 ms.
      [INFO ][memory ] [YC#103] 7226.969-7226.992: YC 537671KB->301833KB (786432KB), 0.023 s, sum of pauses 22.738 ms, longest pause 22.738 ms.
      [INFO ][memory ] [YC#104] 7230.955-7230.976: YC 609349KB->373880KB (786432KB), 0.022 s, sum of pauses 21.488 ms, longest pause 21.488 ms.
      [INFO ][memory ] [YC#105] 7234.478-7234.504: YC 688681KB->453714KB (786432KB), 0.026 s, sum of pauses 25.742 ms, longest pause 25.742 ms.
      [INFO ][memory ] [OC#29] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#29] 7236.693-7237.087: OC 622595KB->133987KB (786432KB), 0.394 s, sum of pauses 77.630 ms, longest pause 46.848 ms.
      [INFO ][memory ] [YC#106] 7241.852-7241.875: YC 541243KB->305725KB (786432KB), 0.024 s, sum of pauses 23.677 ms, longest pause 23.677 ms.
      [INFO ][memory ] [YC#107] 7245.871-7245.891: YC 617442KB->381645KB (786432KB), 0.020 s, sum of pauses 19.820 ms, longest pause 19.820 ms.
      [INFO ][memory ] [YC#108] 7248.908-7248.937: YC 683698KB->449286KB (786432KB), 0.030 s, sum of pauses 29.499 ms, longest pause 29.499 ms.
      [INFO ][memory ] [OC#30] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#30] 7251.192-7251.509: OC 634742KB->137112KB (786432KB), 0.316 s, sum of pauses 54.832 ms, longest pause 27.584 ms.
      [INFO ][memory ] [YC#109] 7256.237-7256.259: YC 542584KB->307067KB (786432KB), 0.022 s, sum of pauses 21.834 ms, longest pause 21.834 ms.
      [INFO ][memory ] [YC#110] 7260.825-7260.845: YC 612836KB->376617KB (786432KB), 0.021 s, sum of pauses 20.524 ms, longest pause 20.524 ms.
      [INFO ][memory ] [YC#111] 7263.169-7263.195: YC 682285KB->446711KB (786432KB), 0.026 s, sum of pauses 25.938 ms, longest pause 25.938 ms.
      [INFO ][memory ] [OC#31] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#31] 7265.954-7266.396: OC 596981KB->138824KB (786432KB), 0.442 s, sum of pauses 77.472 ms, longest pause 48.458 ms.
      [INFO ][memory ] [YC#112] 7270.571-7270.600: YC 537817KB->301890KB (786432KB), 0.029 s, sum of pauses 28.439 ms, longest pause 28.439 ms.
      [INFO ][memory ] [YC#113] 7275.077-7275.109: YC 606693KB->370973KB (786432KB), 0.032 s, sum of pauses 31.919 ms, longest pause 31.919 ms.
      [INFO ][memory ] [YC#114] 7277.309-7277.332: YC 666136KB->431394KB (786432KB), 0.023 s, sum of pauses 23.011 ms, longest pause 23.011 ms.
      [INFO ][memory ] [OC#32] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#32] 7281.857-7282.256: OC 651388KB->135407KB (786432KB), 0.399 s, sum of pauses 70.352 ms, longest pause 35.036 ms.
      [INFO ][memory ] [YC#115] 7284.756-7284.785: YC 522545KB->288246KB (786432KB), 0.030 s, sum of pauses 29.607 ms, longest pause 29.607 ms.
      [INFO ][memory ] [YC#116] 7290.687-7290.717: YC 598317KB->363496KB (786432KB), 0.029 s, sum of pauses 28.973 ms, longest pause 28.973 ms.
      [INFO ][memory ] [YC#117] 7292.315-7292.342: YC 662954KB->427925KB (786432KB), 0.026 s, sum of pauses 26.211 ms, longest pause 26.211 ms.
      [INFO ][memory ] [OC#33] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#33] 7296.936-7297.330: OC 680242KB->131954KB (786432KB), 0.393 s, sum of pauses 69.195 ms, longest pause 39.012 ms.
      [INFO ][memory ] [YC#118] 7300.371-7300.399: YC 537931KB->302286KB (786432KB), 0.028 s, sum of pauses 27.929 ms, longest pause 27.929 ms.
      [INFO ][memory ] [YC#119] 7305.490-7305.512: YC 608818KB->373345KB (786432KB), 0.022 s, sum of pauses 21.779 ms, longest pause 21.779 ms.
      [INFO ][memory ] [YC#120] 7308.289-7308.312: YC 679655KB->443680KB (786432KB), 0.023 s, sum of pauses 23.003 ms, longest pause 23.003 ms.
      [INFO ][memory ] [OC#34] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#34] 7311.538-7311.878: OC 633813KB->134713KB (786432KB), 0.340 s, sum of pauses 57.311 ms, longest pause 29.618 ms.
      [INFO ][memory ] [YC#121] 7315.891-7315.918: YC 546053KB->310284KB (786432KB), 0.027 s, sum of pauses 26.757 ms, longest pause 26.757 ms.
      [INFO ][memory ] [YC#122] 7320.279-7320.308: YC 614950KB->379351KB (786432KB), 0.028 s, sum of pauses 28.136 ms, longest pause 28.136 ms.
      [INFO ][memory ] [YC#123] 7322.837-7322.860: YC 686891KB->451302KB (786432KB), 0.023 s, sum of pauses 22.644 ms, longest pause 22.644 ms.
      [INFO ][memory ] [OC#35] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#35] 7324.714-7325.037: OC 560988KB->137206KB (786432KB), 0.323 s, sum of pauses 57.880 ms, longest pause 33.623 ms.
      [INFO ][memory ] [YC#124] 7329.186-7329.211: YC 533179KB->297806KB (786432KB), 0.024 s, sum of pauses 24.119 ms, longest pause 24.119 ms.
      [INFO ][memory ] [YC#125] 7333.814-7333.834: YC 600267KB->364321KB (786432KB), 0.020 s, sum of pauses 20.292 ms, longest pause 20.292 ms.
      [INFO ][memory ] [YC#126] 7336.265-7336.287: YC 675265KB->439348KB (786432KB), 0.022 s, sum of pauses 21.805 ms, longest pause 21.805 ms.
      [INFO ][memory ] [OC#36] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.
      [INFO ][memory ] [OC#36] 7340.468-7340.821: OC 638167KB->134000KB (786432KB), 0.353 s, sum of pauses 53.402 ms, longest pause 28.940 ms.
      [INFO ][memory ] [YC#127] 7344.179-7344.210: YC 530322KB->296545KB (786432KB), 0.031 s, sum of pauses 30.444 ms, longest pause 30.444 ms.
      [INFO ][memory ] [YC#128] 7349.081-7349.102: YC 600865KB->364975KB (786432KB), 0.022 s, sum of pauses 21.785 ms, longest pause 21.785 ms.
      [INFO ][memory ] [YC#129] 7351.772-7351.800: YC 667148KB->430863KB (786432KB), 0.027 s, sum of pauses 27.073 ms, longest pause 27.073 ms.
      [INFO ][memory ] [OC#37] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.
      [INFO ][memory ] [OC#37] 7355.844-7356.178: OC 689678KB->129595KB (786432KB), 0.334 s, sum of pauses 64.755 ms, longest pause 38.444 ms.
      ...
      ...
      ...
      *+[INFO ][memory ] [OC#742] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.+*
      *+[INFO ][memory ] [OC#742] 31956.493-31959.719: OC 248807KB->212349KB (1048576KB), 3.226 s, sum of pauses 514.202 ms, longest pause 442.323 ms.+*
      *+[INFO ][memory ] [YC#5097] 31961.439-31961.592: YC 585639KB->433633KB (1048576KB), 0.153 s, sum of pauses 153.078 ms, longest pause 153.078 ms.+*
      *+[INFO ][memory ] [OC#743] 31959.719-31962.069: OC 225189KB->197022KB (1048576KB), 2.350 s, sum of pauses 213.626 ms, longest pause 160.635 ms.+*
      *+[INFO ][memory ] [OC#744] 31962.069-31963.707: OC 221557KB->185468KB (1048576KB), 1.638 s, sum of pauses 334.646 ms, longest pause 299.131 ms.+*
      *+[INFO ][memory ] [OC#745] 31963.707-31964.561: OC 200236KB->173396KB (1048576KB), 0.853 s, sum of pauses 122.359 ms, longest pause 96.682 ms.+*
      *+[INFO ][memory ] [OC#746] 31964.561-31965.861: OC 180937KB->171776KB (1048576KB), 1.300 s, sum of pauses 384.987 ms, longest pause 356.112 ms.+*
      *+[INFO ][memory ] [OC#747] 31965.861-31967.462: OC 184299KB->177718KB (1048576KB), 1.600 s, sum of pauses 530.566 ms, longest pause 500.967 ms.+*
      *+[INFO ][memory ] [OC#748] 31967.462-31968.835: OC 189076KB->172004KB (1048576KB), 1.373 s, sum of pauses 390.794 ms, longest pause 360.474 ms.+*
      *+[INFO ][memory ] [OC#749] 31968.835-31969.831: OC 183204KB->172676KB (1048576KB), 0.996 s, sum of pauses 183.733 ms, longest pause 153.955 ms.+*
      *+[INFO ][memory ] [OC#750] 31969.831-31971.216: OC 176788KB->172922KB (1048576KB), 1.385 s, sum of pauses 321.941 ms, longest pause 280.294 ms.+*
      *+[INFO ][memory ] [OC#751] 31971.218-31973.063: OC 195987KB->173440KB (1048576KB), 1.845 s, sum of pauses 477.271 ms, longest pause 448.157 ms.+*
      [INFO ][memory ] [OC#752] 31973.064-31974.457: OC 198556KB->176050KB (1048576KB), 1.393 s, sum of pauses 350.123 ms, longest pause 316.217 ms.
      [INFO ][memory ] [OC#753] 31974.457-31975.948: OC 188475KB->170594KB (1048576KB), 1.491 s, sum of pauses 97.269 ms, longest pause 68.903 ms.
      [INFO ][memory ] [OC#754] 31975.948-31977.252: OC 198170KB->171003KB (1048576KB), 1.304 s, sum of pauses 348.444 ms, longest pause 312.287 ms.
      [INFO ][memory ] [OC#755] 31977.252-31979.065: OC 197425KB->174072KB (1048576KB), 1.812 s, sum of pauses 525.035 ms, longest pause 501.005 ms.
      [INFO ][memory ] [OC#756] 31979.065-31980.335: OC 195865KB->171314KB (1048576KB), 1.270 s, sum of pauses 316.407 ms, longest pause 290.474 ms.
      [INFO ][memory ] [OC#757] 31980.335-31981.254: OC 181430KB->171255KB (1048576KB), 0.919 s, sum of pauses 78.320 ms, longest pause 46.071 ms.
      [INFO ][memory ] [OC#758] 31981.254-31982.685: OC 180859KB->168535KB (1048576KB), 1.430 s, sum of pauses 313.408 ms, longest pause 290.152 ms.
      [INFO ][memory ] [OC#759] 31982.685-31983.786: OC 194201KB->177940KB (1048576KB), 1.101 s, sum of pauses 93.673 ms, longest pause 68.650 ms.
      [INFO ][memory ] [OC#760] 31983.786-31985.612: OC 219420KB->181945KB (1048576KB), 1.826 s, sum of pauses 357.063 ms, longest pause 317.556 ms.
      [INFO ][memory ] [OC#761] 31985.612-31986.856: OC 242998KB->164457KB (1048576KB), 1.244 s, sum of pauses 84.100 ms, longest pause 49.026 ms.
      [INFO ][memory ] [OC#762] 31986.856-31988.324: OC 169862KB->172867KB (1048576KB), 1.469 s, sum of pauses 346.685 ms, longest pause 320.328 ms.
      [INFO ][memory ] [OC#763] 31988.325-31989.199: OC 184195KB->166044KB (1048576KB), 0.874 s, sum of pauses 70.446 ms, longest pause 40.929 ms.
      [INFO ][memory ] [OC#764] 31989.199-31990.198: OC 172843KB->164541KB (1048576KB), 0.999 s, sum of pauses 208.866 ms, longest pause 177.411 ms.
      [INFO ][memory ] [OC#765] 31990.198-31991.245: OC 173912KB->166522KB (1048576KB), 1.047 s, sum of pauses 288.506 ms, longest pause 256.437 ms.
      [INFO ][memory ] [OC#766] 31991.245-31992.592: OC 174257KB->167545KB (1048576KB), 1.347 s, sum of pauses 402.224 ms, longest pause 376.187 ms.
      [INFO ][memory ] [OC#767] 31992.593-31993.563: OC 181141KB->171184KB (1048576KB), 0.970 s, sum of pauses 83.579 ms, longest pause 59.967 ms.
      [INFO ][memory ] [OC#768] 31993.563-31994.843: OC 178787KB->178592KB (1048576KB), 1.280 s, sum of pauses 330.871 ms, longest pause 303.184 ms.
      [INFO ][memory ] [OC#769] 31994.843-31996.621: OC 193924KB->170683KB (1048576KB), 1.778 s, sum of pauses 91.446 ms, longest pause 62.944 ms.
      [INFO ][memory ] [OC#770] 31996.621-31997.829: OC 193717KB->171805KB (1048576KB), 1.208 s, sum of pauses 308.729 ms, longest pause 278.069 ms.
      [INFO ][memory ] [OC#771] 31997.829-31999.603: OC 179735KB->172733KB (1048576KB), 1.774 s, sum of pauses 524.798 ms, longest pause 501.120 ms.
      [INFO ][memory ] [OC#772] 31999.603-32000.995: OC 203988KB->172388KB (1048576KB), 1.392 s, sum of pauses 344.273 ms, longest pause 318.040 ms.
      [INFO ][memory ] [OC#773] 32000.995-32001.673: OC 182461KB->163352KB (1048576KB), 0.678 s, sum of pauses 57.002 ms, longest pause 28.478 ms.
      [INFO ][memory ] [OC#774] 32001.674-32003.009: OC 169665KB->169613KB (1048576KB), 1.335 s, sum of pauses 240.729 ms, longest pause 217.584 ms.
      [INFO ][memory ] [OC#775] 32003.009-32004.021: OC 195016KB->176710KB (1048576KB), 1.011 s, sum of pauses 67.807 ms, longest pause 41.742 ms.
      [INFO ][memory ] [OC#776] 32004.021-32006.270: OC 197504KB->168759KB (1048576KB), 2.249 s, sum of pauses 527.264 ms, longest pause 500.583 ms.
      [INFO ][memory ] [OC#777] 32006.271-32007.272: OC 190769KB->189661KB (1048576KB), 1.001 s, sum of pauses 101.859 ms, longest pause 66.498 ms.