Frequent GC (ParNew) when indexing 500,000 users in Lucene

Question

We are indexing a lot of user information in Lucene, running 500 in batches a time. While indexing I see very frequent GCs (ParNew). Is this normal behavior or should I look into GC tuning?

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

I would say normal behavior: from the log above, It looks like the JVM invests about 4% of its time taking out the garbage which is normal (~0.02 second per cleanup, every 1/2 second).
Where is this question coming from: Do you even consider the process as being slow? or you're just making sure it's normal?

Generally speaking, if you're indexing in batch mode, and therefore care less about system responsiveness and more about the total throughput, then you'll want to run with a throughput collector as your GC Policy.