tomcat - 在 Lucene 中索引 500,000 个用户时频繁的 GC (ParNew)

Question

我们在Lucene中对大量的用户信息进行索引，一次批量运行500个。在索引时我看到非常频繁的 GC (ParNew)。这是正常行为还是我应该研究 GC 调优？

2012-08-15 10:33:06,136 INFO  LuceneIndex-INFO - Indexing operations number for User index: 500 / batch size: 500
2569.177: [GC 2569.177: [ParNew: 35167K->1679K(38336K), 0.0136120 secs] 582353K->548865K(4190080K), 0.0138380 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2569.501: [GC 2569.502: [ParNew: 35791K->2304K(38336K), 0.0153980 secs] 582977K->549490K(4190080K), 0.0156060 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2570.061: [GC 2570.061: [ParNew: 36416K->2383K(38336K), 0.0419800 secs] 583602K->550107K(4190080K), 0.0421810 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 
2570.495: [GC 2570.495: [ParNew: 36495K->3327K(38336K), 0.0156630 secs] 584219K->551277K(4190080K), 0.0158750 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2571.002: [GC 2571.002: [ParNew: 37439K->2196K(38336K), 0.0163630 secs] 585389K->550513K(4190080K), 0.0165770 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2571.581: [GC 2571.581: [ParNew: 36308K->2599K(38336K), 0.0318710 secs] 584625K->551456K(4190080K), 0.0320840 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 
2572.154: [GC 2572.154: [ParNew: 36711K->2806K(38336K), 0.0256790 secs] 585568K->552168K(4190080K), 0.0259410 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 
2572.769: [GC 2572.769: [ParNew: 36918K->2781K(38336K), 0.0270240 secs] 586280K->552530K(4190080K), 0.0273190 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 
2573.440: [GC 2573.440: [ParNew: 36893K->2771K(38336K), 0.0179540 secs] 586642K->552988K(4190080K), 0.0182890 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2574.002: [GC 2574.002: [ParNew: 36883K->3823K(38336K), 0.0178490 secs] 587100K->554556K(4190080K), 0.0181850 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2574.417: [GC 2574.417: [ParNew: 37935K->2550K(38336K), 0.0346110 secs] 588668K->553727K(4190080K), 0.0348370 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 
2575.001: [GC 2575.001: [ParNew: 36662K->2824K(38336K), 0.0169600 secs] 587839K->554396K(4190080K), 0.0171800 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2575.586: [GC 2575.587: [ParNew: 36936K->3126K(38336K), 0.0173760 secs] 588508K->555255K(4190080K), 0.0177080 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2576.143: [GC 2576.143: [ParNew: 37238K->2125K(38336K), 0.0181420 secs] 589367K->554934K(4190080K), 0.0184010 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2576.640: [GC 2576.640: [ParNew: 36237K->2038K(38336K), 0.0179820 secs] 589046K->555251K(4190080K), 0.0182770 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2577.148: [GC 2577.148: [ParNew: 36150K->2999K(38336K), 0.0169140 secs] 589363K->556690K(4190080K), 0.0172490 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2577.687: [GC 2577.687: [ParNew: 37111K->2951K(38336K), 0.0182880 secs] 590802K->557188K(4190080K), 0.0184980 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2578.180: [GC 2578.180: [ParNew: 37063K->3038K(38336K), 0.0197550 secs] 591300K->557791K(4190080K), 0.0200550 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2578.569: [GC 2578.570: [ParNew: 37136K->3104K(38336K), 0.0213140 secs] 591889K->558271K(4190080K), 0.0215390 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2578.608: [GC 2578.608: [ParNew: 37216K->1994K(38336K), 0.0167620 secs] 592383K->557626K(4190080K), 0.0169510 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2578.638: [GC 2578.638: [ParNew: 36079K->1685K(38336K), 0.0140540 secs] 591711K->557938K(4190080K), 0.0142940 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2578.666: [GC 2578.666: [ParNew: 35797K->1196K(38336K), 0.0180850 secs] 592050K->557998K(4190080K), 0.0182930 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2579.027: [GC 2579.027: [ParNew: 35308K->763K(38336K), 0.0123190 secs] 592110K->557885K(4190080K), 0.0125280 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
2579.592: [GC 2579.592: [ParNew: 34875K->3337K(38336K), 0.0200230 secs] 591997K->560478K(4190080K), 0.0202360 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2580.223: [GC 2580.223: [ParNew: 37449K->2553K(38336K), 0.0390630 secs] 594590K->562692K(4190080K), 0.0392720 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 
2580.704: [GC 2580.705: [ParNew: 36665K->1774K(38336K), 0.0137640 secs] 596804K->561913K(4190080K), 0.0140930 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

Answer 1

我会说正常行为:从上面的日志来看，JVM 似乎投入了大约 4% 的时间来清除垃圾，这是正常的(每次清理约 0.02 秒，每 1/2 秒)。
这个问题来自哪里:你甚至认为这个过程很慢吗？或者您只是确保它正常？

一般来说，如果您在批处理模式下建立索引，因此不太关心系统响应速度而更关心总吞吐量，那么您将希望使用吞吐量收集器作为您的 GC Policy. 运行。