技术文章 - CS244589
Windchill 方法服务器过早退出
已修改: 27-Mar-2019
适用于
- Windchill PDMLink 10.1 to 10.2
说明
- 方法服务器进程崩溃并生成 hs_err<pid>.log 文件
- 从方法服务器日志中中可以看到,首先发生内存不足和长时间垃圾回收的问题,然后方法服务器进程崩溃并生成 hs_err<pid>.log 文件
2016-08-16 17:15:48,932 WARN [Service Thread] wt.jmx.notif.memory - Time=2016-08-16 09:15:45.212 +0000, Name=MemoryNotifier, SourceObjectName=com.ptc:wt.subsystem=Monitors,wt.monitorType=Memory, class=class javax.management.Notification, type=java.management.memory.collection.threshold.exceeded, userData=[count=11,poolName=PS Old Gen,usage=[committed=4294967296,init=4294967296,max=4294967296,used=4294453424]], message=Memory usage exceeds collection usage threshold, JVM Name=14711@xxxxxxxxxxx, Threshold ……
2016-08-16 17:15:48,945 WARN [wt.jmx.core.SharedScheduledExecutor.worker] wt.jmx.notif.gc - Time=2016-08-16 09:15:45.208 +0000, Name=GarbageCollectionNotifier, SourceObjectName=com.ptc:wt.subsystem=Monitors,wt.monitorType=GarbageCollection, class=class javax.management.Notification, type=wt.jmx.core.mbeans.GarbageCollectionMonitorMBean.percentTimeSpentInGCThreshold.exceeded.initial, userData=80.77735437050731, message=Garbage collection time threshold exceeded; percentage time in garbage collection: 80.777%, JVM Name=14711@xxxxxxxxxxx, PercentTimeSpentInGCThreshold=15.0, HeapPercentUsage=87.41278183456961, StartTime=1471096949118, Uptime=241999814, Detailed GC Data=[[Name=PS ……
……
2016-08-16 17:16:05,150 INFO [Periodic-Stack-Logger] wt.jmx.core.mbeans.PeriodicStackLoggingDelegate - Full thread stack trace (14711@xxxxxxxxxxx; 2016-08-16 09:15:48.948 +0000)
……
"ajp-bio-8010-exec-38" Id=26675 daemon prio=5 RUNNABLE (in native)
Blocked (cnt): 753; Waited (cnt): 565
CPU nanos: 81231170167; User nanos: 74550000000; Bytes allocated: 16454763632
Servlet request: 2upeib;irt957yx;14711;sq2zvp;74659; Method context: 2upeib;irt957yx;14711;sq2zvp;74660
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
- locked java.io.BufferedInputStream@13915775
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:687)
......
2016-08-16 17:15:48,945 WARN [wt.jmx.core.SharedScheduledExecutor.worker] wt.jmx.notif.gc - Time=2016-08-16 09:15:45.208 +0000, Name=GarbageCollectionNotifier, SourceObjectName=com.ptc:wt.subsystem=Monitors,wt.monitorType=GarbageCollection, class=class javax.management.Notification, type=wt.jmx.core.mbeans.GarbageCollectionMonitorMBean.percentTimeSpentInGCThreshold.exceeded.initial, userData=80.77735437050731, message=Garbage collection time threshold exceeded; percentage time in garbage collection: 80.777%, JVM Name=14711@xxxxxxxxxxx, PercentTimeSpentInGCThreshold=15.0, HeapPercentUsage=87.41278183456961, StartTime=1471096949118, Uptime=241999814, Detailed GC Data=[[Name=PS ……
……
2016-08-16 17:16:05,150 INFO [Periodic-Stack-Logger] wt.jmx.core.mbeans.PeriodicStackLoggingDelegate - Full thread stack trace (14711@xxxxxxxxxxx; 2016-08-16 09:15:48.948 +0000)
……
"ajp-bio-8010-exec-38" Id=26675 daemon prio=5 RUNNABLE (in native)
Blocked (cnt): 753; Waited (cnt): 565
CPU nanos: 81231170167; User nanos: 74550000000; Bytes allocated: 16454763632
Servlet request: 2upeib;irt957yx;14711;sq2zvp;74659; Method context: 2upeib;irt957yx;14711;sq2zvp;74660
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
- locked java.io.BufferedInputStream@13915775
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:687)
......
- 从 hs_err<pid>.log 文件可以看出,发生问题的线程与垃圾收集有关
Stack: [0x00007f2e735f6000,0x00007f2e736f7000], sp=0x00007f2e736f56c0, free space=1021k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x708d0b] invoke_string_value_callback(int (*)(long, long, long*, unsigned short const*, int, void*), CallbackWrapper*, oopDesc*, void*)+0x11b
V [libjvm.so+0x70a9b6] IterateThroughHeapObjectClosure::do_object(oopDesc*)+0x476
V [libjvm.so+0x7d4c04] MutableSpace::object_iterate(ObjectClosure*)+0x74
V [libjvm.so+0x880420] PSYoungGen::object_iterate(ObjectClosure*)+0x20
V [libjvm.so+0x833718] ParallelScavengeHeap::object_iterate(ObjectClosure*)+0x18
V [libjvm.so+0x70b8c3] VM_HeapIterateOperation::doit()+0x43
V [libjvm.so+0x99bc15] VM_Operation::evaluate()+0x55
V [libjvm.so+0x99a04a] VMThread::evaluate_operation(VM_Operation*)+0xba
V [libjvm.so+0x99a3ce] VMThread::loop()+0x1ce
V [libjvm.so+0x99a840] VMThread::run()+0x70
V [libjvm.so+0x815538] java_start(Thread*)+0x108
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x708d0b] invoke_string_value_callback(int (*)(long, long, long*, unsigned short const*, int, void*), CallbackWrapper*, oopDesc*, void*)+0x11b
V [libjvm.so+0x70a9b6] IterateThroughHeapObjectClosure::do_object(oopDesc*)+0x476
V [libjvm.so+0x7d4c04] MutableSpace::object_iterate(ObjectClosure*)+0x74
V [libjvm.so+0x880420] PSYoungGen::object_iterate(ObjectClosure*)+0x20
V [libjvm.so+0x833718] ParallelScavengeHeap::object_iterate(ObjectClosure*)+0x18
V [libjvm.so+0x70b8c3] VM_HeapIterateOperation::doit()+0x43
V [libjvm.so+0x99bc15] VM_Operation::evaluate()+0x55
V [libjvm.so+0x99a04a] VMThread::evaluate_operation(VM_Operation*)+0xba
V [libjvm.so+0x99a3ce] VMThread::loop()+0x1ce
V [libjvm.so+0x99a840] VMThread::run()+0x70
V [libjvm.so+0x815538] java_start(Thread*)+0x108
这是文章 244589 的 PDF 版本,可能已过期。最新版本 CS244589