0 Replies Latest reply: Sep 23, 2009 8:41 AM by 843829 RSS

    Minor ParNew pauses increases over time

    843829
      The minor collection pause times in my application is increasing over time and I would like to know how to avoid this.
      The application is build to process hundreds of transactions per second and the increasing pause times result in timeouts.

      The application is running under JVM 1.6.0_14 on a Windows 2003 Server and currently I'm using the following start parameter:

      -showversion
      -server
      -ea
      -Xms300m
      -Xmx400m
      -Xmn30m
      -XX:+UseConcMarkSweepGC
      -Xloggc:gclog/gc000_xms300_xmx400_xmn30.log
      -XX:+PrintGCDetails
      -XX:+PrintGCDateStamps
      -XX:+PrintGCApplicationStoppedTime
      -XX:+PrintGCApplicationConcurrentTime

      The 2 following extracts of the log file are showing the problem (there is no major collect between the two snippets, but a minor collect every 80 ms):
      2009-09-23T14:09:49.187-0700: 10.342: [GC 10.342: [ParNew: 24878K->386K(27648K), 0.0013783 secs] 136504K->112020K(304128K), 0.0014636 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
      Total time for which application threads were stopped: 0.0017690 seconds
      Application time: 0.0814967 seconds
      2009-09-23T14:09:49.281-0700: 10.425: [GC 10.425: [ParNew: 24962K->352K(27648K), 0.0013271 secs] 136596K->111995K(304128K), 0.0013913 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0017181 seconds
      Application time: 0.0837235 seconds
      2009-09-23T14:09:49.359-0700: 10.511: [GC 10.511: [ParNew: 24924K->324K(27648K), 0.0013117 secs] 136567K->111976K(304128K), 0.0013792 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0019678 seconds
      Application time: 0.0808623 seconds
      2009-09-23T14:09:49.453-0700: 10.594: [GC 10.594: [ParNew: 24900K->349K(27648K), 0.0014511 secs] 136552K->112017K(304128K), 0.0015347 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0023314 seconds
      Application time: 0.0821778 seconds
      2009-09-23T14:09:49.531-0700: 10.678: [GC 10.678: [ParNew: 24925K->329K(27648K), 0.0017667 secs] 136593K->112012K(304128K), 0.0018501 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0021375 seconds
      Application time: 0.0922261 seconds
      2009-09-23T14:09:49.625-0700: 10.772: [GC 10.772: [ParNew: 24890K->292K(27648K), 0.0016424 secs] 136574K->111982K(304128K), 0.0017169 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0020180 seconds
      Application time: 0.0882618 seconds
      ...
      2009-09-23T14:18:50.921-0700: 552.232: [GC 552.232: [ParNew: 24943K->427K(27648K), 0.0020968 secs] 268548K->244049K(304128K), 0.0021806 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0024265 seconds
      Application time: 0.0662072 seconds
      2009-09-23T14:18:50.984-0700: 552.301: [GC 552.301: [ParNew: 25003K->387K(27648K), 0.0020612 secs] 268625K->244033K(304128K), 0.0021437 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0024181 seconds
      Application time: 0.0678746 seconds
      2009-09-23T14:18:51.062-0700: 552.371: [GC 552.371: [ParNew: 24963K->378K(27648K), 0.0020318 secs] 268609K->244054K(304128K), 0.0021140 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0023469 seconds
      Application time: 0.0695142 seconds
      2009-09-23T14:18:51.125-0700: 552.443: [GC 552.443: [ParNew: 24954K->427K(27648K), 0.0019645 secs] 268630K->244128K(304128K), 0.0020504 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0022722 seconds
      Application time: 0.0671585 seconds
      2009-09-23T14:18:51.203-0700: 552.512: [GC 552.512: [ParNew: 25003K->388K(27648K), 0.0021312 secs] 268704K->244116K(304128K), 0.0022164 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0024814 seconds
      Application time: 0.0659481 seconds
      2009-09-23T14:18:51.265-0700: 552.581: [GC 552.581: [ParNew: 24964K->338K(27648K), 0.0020067 secs] 268692K->244095K(304128K), 0.0020762 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0022895 seconds
      Application time: 0.0677174 seconds
      2009-09-23T14:18:51.343-0700: 552.651: [GC 552.651: [ParNew: 24905K->358K(27648K), 0.0019867 secs] 268662K->244135K(304128K), 0.0020609 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0022811 seconds
      Application time: 0.0706161 seconds
      2009-09-23T14:18:51.406-0700: 552.724: [GC 552.724: [ParNew: 24922K->379K(27648K), 0.0020075 secs] 268699K->244175K(304128K), 0.0020806 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0023529 seconds
      Application time: 0.0667540 seconds
      2009-09-23T14:18:51.484-0700: 552.793: [GC 552.793: [ParNew: 24943K->428K(27648K), 0.0019558 secs] 268739K->244246K(304128K), 0.0020377 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0022742 seconds
      Application time: 0.0649235 seconds
      2009-09-23T14:18:51.546-0700: 552.860: [GC 552.860: [ParNew: 25004K->360K(27648K), 0.0078005 secs] 268822K->244198K(304128K), 0.0078823 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
      Total time for which application threads were stopped: 0.0081097 seconds
      Application time: 0.0672468 seconds
      2009-09-23T14:18:51.625-0700: 552.935: [GC 552.935: [ParNew: 24926K->470K(27648K), 0.0020212 secs] 268764K->244331K(304128K), 0.0021091 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0023611 seconds
      Application time: 0.0630043 seconds
      2009-09-23T14:18:51.687-0700: 553.001: [GC 553.001: [ParNew: 25046K->379K(27648K), 0.0021851 secs] 268907K->244267K(304128K), 0.0022700 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0024963 seconds
      Application time: 0.0640096 seconds
      2009-09-23T14:18:51.750-0700: 553.067: [GC 553.067: [ParNew: 24955K->362K(27648K), 0.0037314 secs] 268843K->244277K(304128K), 0.0038170 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
      Total time for which application threads were stopped: 0.0041037 seconds
      Application time: 0.0661800 seconds
      2009-09-23T14:18:51.828-0700: 553.138: [GC 553.138: [ParNew: 24938K->394K(27648K), 0.0019381 secs] 268853K->244328K(304128K), 0.0020201 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0022702 seconds
      Application time: 0.0678144 seconds
      2009-09-23T14:18:51.890-0700: 553.208: [GC 553.208: [ParNew: 24970K->408K(27648K), 0.0020513 secs] 268904K->244362K(304128K), 0.0021326 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      Total time for which application threads were stopped: 0.0024465 seconds
      Application time: 0.0347021 seconds