This discussion is archived
3 Replies Latest reply: Nov 21, 2013 4:08 AM by jim_b_o RSS

Reasons For Very Slow OC:SweepSwitch ?

jim_b_o Newbie
Currently Being Moderated

I have a system configured as noted below.  GC performs well most of the time, i.e. YCs every 20-30 seconds with max pause around 13-15 ms, OCs every 45-60 minutes with max pause around 10-30 ms.  YC KeepArea is 25% and GC Trigger self tuned to 23.4%.

However once in a while I get a long pause during OC.  Pause diagnostics show that the problem is with the OC:SweepSwitch as shown in the log below.

 

According to the docs (Understanding Memory Management - Release R28), OC:SweepSwitch is 'A short pause to switch halves'.  However I have captured pauses of up to 5 seconds in the logs and have other data that suggests I've had pauses as long as 10 seconds.  In these latter cases I didn't have enough diagnostics to show for certain that it was the OC:SweepSwitch as I have been progressively increasing the diagnostics, but everything that I do have shows that the variance in pause time is always in OC:SweepSwitch and the other aspects stay in a reasonable range.

 

I suspect that there may also be a pattern in that the very slow OC:SweepSwitch occurs on the first OC after switching back from genconpar to genconcon as highlighted below.

 

Any thoughts on why OC:SweepSwitch might sometimes be slow would be much appreciated.

 

Operating System: Linux 2.6.32-279.14.1.el6.x86_64 

VM Version: Oracle JRockit(R) version R28.2.4-14-151097-1.6.0_33-20120618-1634-linux-x86_64

GC settings: -Xms1g -Xmx1g -Xns:400m -Xgc:gencon

 

[Thu Nov 14 02:22:09 2013] [OC#83] GC reason: GC trigger reached.

[Thu Nov 14 02:22:09 2013] [OC#83] 282232.476: OC started.

[Thu Nov 14 02:22:09 2013] [OC#83] Compaction reason: Normal.

[Thu Nov 14 02:22:09 2013] [OC#83] Compacting 32 of 4096 parts at index 2752. Compaction type is external. Exceptional: No.

[Thu Nov 14 02:22:09 2013] [OC#83] Compaction area start: 0xeb000000, end: 0xeb800000. Timeout: 333.333 ms.

[Thu Nov 14 02:22:09 2013] [OC#83] Compactset limit (per thread): 10200 (dynamic), using matrixes.

[Thu Nov 14 02:22:09 2013] [OC#83] Starting initial marking phase (OC1).

[Thu Nov 14 02:22:09 2013] [OC#83] SemiRef phase WeakJNIHandles run in single threaded mode.

[Thu Nov 14 02:22:09 2013] [OC#83] SemiRef phase ClassConstraints run in single threaded mode.

[Thu Nov 14 02:22:09 2013] [OC#83] Initial marking phase promoted 16503 objects (1088KB).

[Thu Nov 14 02:22:09 2013] [OC#83] Starting concurrent marking phase (OC2).

[Thu Nov 14 02:22:10 2013] [OC#83] Concurrent mark phase lasted 207.213 ms.

[Thu Nov 14 02:22:10 2013] [OC#83] Starting precleaning phase (OC3).

[Thu Nov 14 02:22:10 2013] [OC#83] Precleaning phase lasted 16.991 ms.

[Thu Nov 14 02:22:10 2013] [OC#83] Starting final marking phase (OC4).

[Thu Nov 14 02:22:10 2013] [OC#83] SemiRef phase WeakJNIHandles run in single threaded mode.

[Thu Nov 14 02:22:10 2013] [OC#83] SemiRef phase ClassConstraints run in single threaded mode.

[Thu Nov 14 02:22:10 2013] [OC#83] SemiRef phase FinalMemleak run in single threaded mode.

[Thu Nov 14 02:22:10 2013] [OC#83] Final marking phase promoted 33496 objects (1972KB).

[Thu Nov 14 02:22:10 2013] [OC#83] Removing 15 permanent work packets from pool, now 277 packets.

[Thu Nov 14 02:22:10 2013] [OC#83] Total mark time: 262.350 ms.

[Thu Nov 14 02:22:10 2013] [OC#83] Ending marking phase.

[Thu Nov 14 02:22:10 2013] [OC#83] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.

[Thu Nov 14 02:22:10 2013] [OC#83] Starting concurrent sweeping phase.

[Thu Nov 14 02:22:10 2013] [OC#83] Total sweep time: 547.824 ms.

[Thu Nov 14 02:22:10 2013] [OC#83] Ending sweeping phase.

[Thu Nov 14 02:22:10 2013] [OC#83] Average compact time ratio (move phase/total time): 1.000000.

[Thu Nov 14 02:22:10 2013] [OC#83] Compaction too short, increasing compact ratio.

[Thu Nov 14 02:22:10 2013] [OC#83] Compaction time, total: 10.630 ms (target 478.617 ms).

[Thu Nov 14 02:22:10 2013] [OC#83] Compaction moved 19375 objects and left 2 objects. Total moved size 994752B.

[Thu Nov 14 02:22:10 2013] [OC#83] Compaction added 8257504B of free memory in 3 parts.

[Thu Nov 14 02:22:10 2013] [OC#83] Found 26089 references.

[Thu Nov 14 02:22:10 2013] [OC#83] Updated 22524 references.

[Thu Nov 14 02:22:10 2013] [OC#83] GC Trigger is now 23.4%, was 23.4%.

[Thu Nov 14 02:22:10 2013] [OC#83] [---]   816.920 ms (282232.476000-282233.293000)  OC

[Thu Nov 14 02:22:10 2013] [OC#83] [con]     0.020 ms (282232.476000-282232.476000)  OC:PreGC

[Thu Nov 14 02:22:10 2013] [OC#83] [pau]    17.291 ms (282232.476000-282232.493000)  OC:Initial

[Thu Nov 14 02:22:10 2013] [OC#83] [con]   223.511 ms (282232.494000-282232.717000)  OC:ConcurrentMark

[Thu Nov 14 02:22:10 2013] [OC#83] [pau]    33.006 ms (282232.718000-282232.751000)  OC:Main

[Thu Nov 14 02:22:10 2013] [OC#83] [con]     4.586 ms (282232.751000-282232.755000)  OC:ConcurrentSweep1

[Thu Nov 14 02:22:10 2013] [OC#83] [pau]   524.649 ms (282232.756000-282233.281000)  OC:SweepSwitch

[Thu Nov 14 02:22:10 2013] [OC#83] [con]     5.071 ms (282233.281000-282233.286000)  OC:ConcurrentSweep2

[Thu Nov 14 02:22:10 2013] [OC#83] [pau]     0.278 ms (282233.287000-282233.287000)  OC:Cleanup

[Thu Nov 14 02:22:10 2013] [OC#83] [con]     6.117 ms (282233.287000-282233.293000)  OC:PostGC

[Thu Nov 14 02:22:10 2013] [OC#83] Page faults before OC: 3, page faults after OC: 3, pages in heap: 262144.

[Thu Nov 14 02:22:10 2013] [OC#83] Nursery size after OC: 409600KB. (Free: 400339KB Parts: 10999)

[Thu Nov 14 02:22:10 2013] [OC#83] 282232.476-282233.293: OC 880239KB->146686KB (1048576KB), 0.817 s, sum of pauses 575.224 ms, longest pause 524.649 ms.

  • 1. Re: Reasons For Very Slow OC:SweepSwitch ?
    jim_b_o Newbie
    Currently Being Moderated

    For completeness, here's some of the logging from the 5 second pause:

     

     

    [Wed Nov 13 21:57:12 2013] [OC#78] Ending marking phase.

    [Wed Nov 13 21:57:12 2013] [OC#78] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.

    [Wed Nov 13 21:57:12 2013] [OC#78] Starting concurrent sweeping phase.

    [Wed Nov 13 21:57:17 2013] [OC#78] Total sweep time: 5062.965 ms.

    [Wed Nov 13 21:57:17 2013] [OC#78] Ending sweeping phase.

    [Wed Nov 13 21:57:17 2013] [OC#78] Average compact time ratio (move phase/total time): 1.000000.

    [Wed Nov 13 21:57:17 2013] [OC#78] Compaction too short, increasing compact ratio.

    [Wed Nov 13 21:57:17 2013] [OC#78] Compaction time, total: 5.676 ms (target 469.430 ms).

    [Wed Nov 13 21:57:17 2013] [OC#78] Compaction moved 9219 objects and left 0 objects. Total moved size 275376B.

    [Wed Nov 13 21:57:17 2013] [OC#78] Compaction added 8113200B of free memory in 1 parts.

    [Wed Nov 13 21:57:17 2013] [OC#78] Found 10883 references.

    [Wed Nov 13 21:57:17 2013] [OC#78] Updated 9843 references.

    [Wed Nov 13 21:57:17 2013] [OC#78] GC Trigger is now 23.4%, was 23.4%.

    [Wed Nov 13 21:57:17 2013] [OC#78] Page faults before OC: 3, page faults after OC: 3, pages in heap: 262144.

    [Wed Nov 13 21:57:17 2013] [OC#78] Nursery size after OC: 409601KB. (Free: 391603KB Parts: 31038)

    [Wed Nov 13 21:57:17 2013] [OC#78] 266334.577-266339.997: OC 596853KB->206122KB (1048576KB), 5.419 s, sum of pauses 5100.214 ms, longest pause 5033.852 ms.

     

     

    This was prior to turning on pause diagnostics, but once again it was during the concurrent sweep after a change from genconpar to genconcon.

  • 2. Re: Reasons For Very Slow OC:SweepSwitch ?
    jim_b_o Newbie
    Currently Being Moderated

    So the workarounds to avoid resuming genconcon after an emergency genconpar (and hence the slow OC:SweepSwitch in that next genconcon) are:

    1. Set -XXgcTrigger:value to a higher value to avoid ever entering genconpar.  The value for this is of course guess work based off observed worst case behaviour.
    2. Always use genconpar, i.e. -Xgc:genconpar instead of -Xgc:gencon.

     

    But the question remains, why the slow OC:SweepSwitch?  Maybe something to do with rebuilding the info needed for concurrent sweep lost during the parallel sweep?

  • 3. Re: Reasons For Very Slow OC:SweepSwitch ?
    jim_b_o Newbie
    Currently Being Moderated

    Here's further evidence of the relationship between OC:SweepSwitch duration and the change back from genconpar to genconcon:

     

    [gcpause][Sun Nov 17 22:05:12 2013] [OC#1] [pau]     0.026 ms (8133.479000-8133.479000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 00:59:42 2013] [OC#2] [pau]     0.052 ms (18602.842000-18602.842000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 03:51:21 2013] [OC#3] [pau]     0.108 ms (28901.888000-28901.888000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 06:13:04 2013] [OC#4] [pau]     0.073 ms (37405.622000-37405.622000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 07:59:13 2013] [OC#5] [pau]     0.088 ms (43774.279000-43774.280000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 09:07:30 2013] [OC#6] [pau]     0.164 ms (47870.649000-47870.649000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 10:17:27 2013] [OC#7] [pau]     0.145 ms (52068.451000-52068.452000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 11:43:45 2013] [OC#8] [pau]     0.140 ms (57246.512000-57246.512000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 13:04:21 2013] [OC#9] [pau]     0.214 ms (62081.874000-62081.874000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 14:04:50 2013] [OC#10] [pau]     0.153 ms (65710.995000-65710.995000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 14:55:06 2013] [OC#11] [pau]     0.241 ms (68727.544000-68727.544000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 15:51:29 2013] [OC#12] [pau]     0.275 ms (72110.455000-72110.456000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 17:04:57 2013] [OC#13] [pau]     0.074 ms (76517.794000-76517.794000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 18:29:03 2013] [OC#14] [pau]     0.107 ms (81564.034000-81564.034000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 20:16:37 2013] [OC#15] [pau]     0.197 ms (88018.613000-88018.614000)  OC:SweepSwitch

    [gcpause][Mon Nov 18 21:58:31 2013] [OC#16] [pau]     0.184 ms (94132.146000-94132.146000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 00:33:31 2013] [OC#17] [pau]     1.117 ms (103432.288000-103432.289000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 02:10:43 2013] [OC#18] [pau]     0.160 ms (109263.934000-109263.934000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 04:57:43 2013] [OC#19] [pau]     0.116 ms (119284.218000-119284.218000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 07:22:42 2013] [OC#20] [pau]     0.129 ms (127982.836000-127982.836000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 08:11:17 2013] [OC#21] [pau]     0.206 ms (130898.369000-130898.370000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 08:50:16 2013] [OC#22] [pau]     0.137 ms (133237.519000-133237.519000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 09:55:50 2013] [OC#23] [pau]     0.152 ms (137171.316000-137171.317000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 10:54:52 2013] [OC#24] [pau]     0.183 ms (140713.362000-140713.363000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 12:00:55 2013] [OC#25] [pau]     2.332 ms (144676.227000-144676.229000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 13:21:16 2013] [OC#26] [pau]     0.255 ms (149497.526000-149497.526000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 14:19:49 2013] [OC#27] [pau]     5.131 ms (153010.400000-153010.406000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 15:01:01 2013] [OC#28] [pau]     5.506 ms (155482.243000-155482.249000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 15:35:53 2013] [OC#29] [pau]    23.916 ms (157573.941000-157573.965000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 16:28:56 2013] [OC#30] [pau]     5.929 ms (160756.959000-160756.965000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 17:34:58 2013] [OC#31] [pau]     3.021 ms (164718.697000-164718.700000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 19:18:20 2013] [OC#32] [pau]     3.466 ms (170921.046000-170921.050000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 21:47:47 2013] [OC#33] [pau]    27.020 ms (179888.242000-179888.269000)  OC:SweepSwitch

    [gcpause][Tue Nov 19 23:28:41 2013] [OC#34] [pau]     2.055 ms (185942.485000-185942.487000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 01:14:31 2013] [OC#35] [pau]     0.170 ms (192292.368000-192292.368000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 03:44:56 2013] [OC#36] [pau]     0.122 ms (201317.479000-201317.479000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 06:42:40 2013] [OC#37] [pau]     0.036 ms (211981.095000-211981.095000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 08:14:26 2013] [OC#38] [pau]     0.144 ms (217487.302000-217487.303000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 09:18:57 2013] [OC#39] [pau]     0.053 ms (221357.737000-221357.737000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 10:16:00 2013] [OC#40] [pau]     0.385 ms (224781.542000-224781.542000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 11:42:28 2013] [OC#41] [pau]     0.205 ms (229968.982000-229968.982000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 13:04:26 2013] [OC#42] [pau]     0.817 ms (234886.751000-234886.752000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 13:47:51 2013] [OC#43] [pau]     0.267 ms (237491.749000-237491.749000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 14:40:02 2013] [OC#44] [pau]     0.659 ms (240623.498000-240623.499000)  OC:SweepSwitch

    [memory ][Wed Nov 20 15:20:41 2013] [OC#45] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.

    [memory ][Wed Nov 20 15:28:37 2013] [OC#46] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.

    [gcpause][Wed Nov 20 15:28:41 2013] [OC#46] [pau]  3952.538 ms (243538.617000-243542.569000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 15:43:24 2013] [OC#47] [pau]  1983.519 ms (244423.362000-244425.346000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 16:19:07 2013] [OC#48] [pau]   713.398 ms (246567.264000-246567.977000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 17:22:26 2013] [OC#49] [pau]   366.701 ms (250366.670000-250367.036000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 18:40:57 2013] [OC#50] [pau]   334.209 ms (255077.865000-255078.199000)  OC:SweepSwitch

    [memory ][Wed Nov 20 19:01:21 2013] [OC#51] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.

    [memory ][Wed Nov 20 19:11:02 2013] [OC#52] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.

    [gcpause][Wed Nov 20 19:11:06 2013] [OC#52] [pau]  3711.973 ms (256882.946000-256886.658000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 19:36:38 2013] [OC#53] [pau]  1937.625 ms (258417.212000-258419.149000)  OC:SweepSwitch

    [gcpause][Wed Nov 20 20:21:29 2013] [OC#54] [pau]   749.551 ms (261109.484000-261110.234000)  OC:SweepSwitch

    [memory ][Wed Nov 20 22:00:02 2013] [OC#55] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested.

    [memory ][Wed Nov 20 23:10:50 2013] [OC#56] Changing GC strategy from: genconpar to: genconcon, reason: Return to basic strategy.

    [gcpause][Wed Nov 20 23:10:50 2013] [OC#56] [pau]   250.782 ms (271271.023000-271271.273000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 01:02:31 2013] [OC#57] [pau]    40.474 ms (277972.097000-277972.137000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 03:02:49 2013] [OC#58] [pau]    12.065 ms (285189.777000-285189.789000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 05:46:14 2013] [OC#59] [pau]    12.259 ms (294995.474000-294995.486000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 07:19:36 2013] [OC#60] [pau]    20.071 ms (300596.964000-300596.984000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 08:15:40 2013] [OC#61] [pau]    21.200 ms (303961.056000-303961.077000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 09:09:02 2013] [OC#62] [pau]    12.951 ms (307163.383000-307163.396000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 09:56:44 2013] [OC#63] [pau]    11.973 ms (310024.797000-310024.809000)  OC:SweepSwitch

    [gcpause][Thu Nov 21 11:08:48 2013] [OC#64] [pau]    11.100 ms (314348.735000-314348.746000)  OC:SweepSwitch

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points