我们已经制作了一个在12核IBM机器上的RedHat Linux 5.2的JBoss 4.2.3中运行的webapp。最近,我们看到响应时间较长,这似乎是GC活动引起的。模式大致如下:
所有请求似乎都以正常速率发送,但是直到突然所有“响应”被“丢弃”之前,才发送字节。
同时,gc.log具有以下模式:
//从这里开始无响应
36788.309:[GC [1 CMS初始标记:1919297K(4456448K)] 1969797K(5111808K),0.1473460秒] [时间:用户= 0.15 sys = 0.00,实际= 0.15秒]
停止应用程序线程的总时间:0.1530790秒
36788.457:[CMS-concurrent-mark-start]
36793.886:[CMS并发标记:5.429 / 5.429秒](CMS并发标记产生了46次)
[时间:用户= 6.69 sys = 0.07,实际= 5.43秒]
36793.886:[CMS-concurrent-preclean-start]
(cardTable:15956张卡,重新扫描15956张卡,1次迭代)
36793.988:[CMS-concurrent-preclean:0.089 / 0.101秒](CMS-concurrent-preclean产生了9次)
[时间:用户= 0.12 sys = 0.01,真实= 0.10秒]
36793.988:[CMS-concurrent-abortable-preclean-start]
(cardTable:75张卡,重新扫描75张卡,1次迭代)
应用时间:5.6923460秒
停止应用程序线程的总时间:0.0170000秒
(cardTable:96张卡,重新扫描96张卡,1次迭代)
(cardTable:207张卡,重新扫描207张卡,1次迭代)
(cardTable:45张卡片,重新扫描45张卡片,重复1次)
(cardTable:157张卡,重新扫描157张卡,1次迭代)
(cardTable:88张卡,重新扫描88张卡,1次迭代)
(cardTable:213张卡片,重新扫描213张卡片,1次迭代)
(cardTable:84张卡,重新扫描84张卡,1次迭代)
(cardTable:143张卡,重新扫描143张卡,1次迭代)
(cardTable:40张卡,重新扫描40张卡,1次迭代)
(cardTable:109张卡,重新扫描109张卡,1次迭代)
(cardTable:77张卡,重新扫描77张卡,1次迭代)
(cardTable:156张卡,重新扫描156张卡,1次迭代)
(cardTable:132张卡,重新扫描132张卡,1次迭代)
(cardTable:119张卡,重新扫描119张卡,1次迭代)
(cardTable:115张卡,重新扫描115张卡,1次迭代)
(cardTable:195张卡,重新扫描195张卡,1次迭代)
(cardTable:163张卡,重新扫描163张卡,1次迭代)
(cardTable:166张卡,重新扫描166张卡,1次迭代)
(cardTable:149张卡,重新扫描149张卡,1次迭代)
(cardTable:218张卡,重新扫描218张卡,1次迭代)
(cardTable:46张卡,重新扫描46张卡,1次迭代)
(cardTable:57张卡,重新扫描57张卡,1次迭代)
(cardTable:213张卡片,重新扫描213张卡片,1次迭代)
(cardTable:189张卡,重新扫描189张卡,1次迭代)
(cardTable:104张卡,重新扫描104张卡,1次迭代)
(cardTable:60张卡,重新扫描60张卡,1次迭代)
(cardTable:368张卡,重新扫描368张卡,1次迭代)
(cardTable:118张卡片,重新扫描118张卡片,1次迭代)
(cardTable:129张卡,重新扫描129张卡,1次迭代)
(cardTable:291张卡,重新扫描291张卡,1次迭代)
(cardTable:105张卡,重新扫描的105张卡,1次迭代)
(cardTable:63张卡,重新扫描63张卡,1次迭代)
(cardTable:73张卡,重新扫描73张卡,1次迭代)
(cardTable:165张卡,重新扫描165张卡,1次迭代)
(cardTable:69张卡,重新扫描69张卡,1次迭代)
(cardTable:157张卡,重新扫描157张卡,1次迭代)
CMS:因时间而中止预清洗[37次迭代,13次等待,4954张卡片]] 36799.161:[CMS-concurrent-abortable-preclean:2.965 / 5.173 secs](CMS-concurrent-abortable-preclean产生166次)
[时间:用户= 5.12 sys = 0.10,实际= 5.17秒]
申请时间:4.9945030秒
36799.172:[GC [YG占用:572074 K(655360 K)] 36799.172:[GC 36799.173:[ParNew
所需的幸存者大小67108864字节,新阈值2(最大15)
-年龄1:59654872字节,总计59654872
-年龄2:26827232字节,总计86482104
-年龄3:2613360字节,总计89095464
-年龄4:929600字节,总计90025064
-年龄5:893176字节,总计90918240
-年龄6:795736字节,总计91713976
-7岁:809240字节,总计92523216
-年龄8:936216字节,总计93459432
-年龄9:971376字节,总计94430808
-年龄10:624472字节,总计95055280
-年龄11:883616字节,总共95938896
-年龄12:817296字节,总计96756192
-年龄13:977992字节,总计97734184
-年龄14:733816字节,总计98468000
-年龄15:654744字节,总计99122744
:572074K-> 110988K(655360K),0.1855140秒] 2491372K-> 2031059K(5111808K)icms_dc = 0,0.1866380秒] [时间:用户= 0.72 sys = 0.00,真实= 0.19秒]
36799.359:[重新扫描(并行)(幸存者:12chunks)在第三线程完成年轻一代重新扫描工作:0.032秒
在第二线程完成年轻一代重新扫描工作:0.035秒
在第0个线程中完成年轻一代重新扫描工作:0.035秒
在第1个线程中完成年轻一代重新扫描工作:0.035秒
在第一个线程中完成剩余的根重新扫描工作:0.030秒
在第3个线程中完成剩余的根重新扫描工作:0.033秒
在第二线程中完成剩余的根重新扫描工作:0.032秒
在第0个线程中完成剩余的根重新扫描工作:0.042秒
在第2个线程中完成脏卡重新扫描工作:0.029秒
在第3个线程中完成脏卡重新扫描工作:0.031秒
在第0个线程中完成脏卡重新扫描工作:0.019秒
完成脏卡的第1个线程的重新扫描工作:0.031秒
在第3个线程中完成窃取的作品:0.000秒
在第0个线程中完成的工作窃取:0.000秒
在第2个线程中完成窃取的工作:0.000秒
在第一个线程中完成的工作窃取:0.000秒
,0.0959640秒] 36799.455:[弱引用处理,0.0121220秒] [1 CMS备注:1920070K(4456448K)] 2031059K(5111808K),0.2952350秒] [时间:用户= 1.11 sys = 0.00,真实= 0.30秒]
停止应用程序线程的总时间:0.3066430秒
36799.468:[CMS-concurrent-sweep-start]
36805.824:[CMS并发扫描:6.355 / 6.356秒](CMS并发扫描产生515次)
[时间:user = 8.76 sys = 0.24,真实= 6.35秒]
36805.824:[CMS-concurrent-reset-start]
36805.903:[CMS并发重置:0.079 / 0.079秒](CMS并发重置产生0次)
[时间:用户= 0.64 sys = 0.01,真实= 0.07秒]
应用时间:6.5590510秒
//关于此处,服务器开始发送响应
36806.044:[GC 36806.045:[ParNew
所需的幸存者大小67108864字节,新阈值2(最大15)
-年龄1:55456640字节,总计55456640
-年龄2:54278984字节,总计109735624
:635276K-> 131072K(655360K),0.3230430秒] 2554507K-> 2089990K(5111808K)icms_dc = 0,0.3242750秒] [时间:用户= 1.02 sys = 0.02,真实= 0.33秒]
停止应用程序线程的总时间:0.3422430秒
应用时间:0.7628480秒
我们已经尝试了各种GC设置,但最终总是或多或少像这样。
我们当前的参数:
-Xms4096m -Xmx5120m -XX:MaxPermSize = 384m
-XX:+ UseConcMarkSweepGC -XX:+ ExplicitGCInvokesConcurrent
-XX:+ PrintClassHistogram -XX:+ PrintGCApplicationConcurrentTime
-XX:+ PrintGCApplicationStoppedTime -XX:+ PrintGCDetails
-XX:ReservedCodeCacheSize = 64m -XX:NewSize = 768m -XX:SurvivorRatio = 4
-XX:+ CMSParallelRemarkEnabled -XX:+ CMSScavengeBeforeRemark -XX:+ CMSIncrementalMode
-XX:+ CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin = 0 -XX:CMSIncrementalDutyCycle = 10
-XX:+ UseTLAB -XX:ParallelGCThreads = 4
-XX:+ UseParNewGC -XX:MaxGCPauseMillis = 1000 -XX:GCTimeRatio = 10
-XX:+ CMSPermGenSweepingEnabled
-XX:+ PrintCMSInitiationStatistics -XX:PrintCMSStatistics = 1 -XX:+ PrintGCTaskTimeStamps
-XX:+ PrintGCTimeStamps
-verbose:gc -XX:+ TraceClassLoading -XX:+ TraceClassUnloading
-XX:+ PrintTenuringDistribution
我们如何避免不响应?
最佳答案
GC日志包括以下行:
应用程序线程停止的总时间:...秒
除非我弄错了,否则它们加起来不到1秒。这不会使您的Web应用程序在任何相当长的时间内无响应。
我建议原因可能是其他原因。一种可能性是您正在突破计算机的极限,并且运行GC的额外负担导致请求积压。例如,由于您已经配置了4个并行GC线程,所以我希望在GC运行时(16秒?),理论上的最大请求速率下降33%。这可能导致大量的请求积压。
您的计算机的第二种可能性是物理内存不足,GC正在将其推入轻微的虚拟内存崩溃情况。