记一次gc超时排查过程
背景
最近发现监控偶尔集中出现接口异常、超时等报警，查询日志发现是调用接口超时，由于每次出现的报警时间都不一致，并且也很快恢复，以为是偶发的大批量任务导致的，因此没有进行集中排查。直到发现基本每天都开始出现，并且也逐渐影响到其他业务线获取数据，开始仔细观察排查原因。
排查到具体现象如下，每次出现超时，GC监控都有如下现象：老年代突然激增，然后没有触发fullgc，而是通过多次的youonggc清理内存，并且yonggc的耗时时间也很高，导致在这段时间内，提供给外部的接口调用超时。
排查过程
问题定位
根据gc监控图，开始逐步排查定位出现问题的原因：
1 内存飙升首先想到的是不是存在内存溢出或泄露的场景，但是在对应机器日志里搜索OOM关键字，没有找到内存溢出的异常日志。jvm相关的配置中，也只有发生OOM，才会dump下对应的堆转储文件，但是现在没有出现OOM，获取不到对应的堆转储文件，因此没办法直接进行内存分析。
2 如果存在大批量任务调用，可能也会导致短时间内存飙升。由于这个异常是最近才出现的，所以检查了最近新增的定时任务，以及发生时间段内的定时任务，发现都正常，查看机器调用量也都在正常水平。并且gc的现象并不是每天固定12点左右出现的，有时也会出现在凌晨、下午等时间，都是随机出现，因此排除是定时任务的原因
3 是不是存在大json，导致直接晋升到老年代。导出了出现问题前后10分钟左右的日志，由于历史原因，该应用提供的接口有300个，所以日志很多，排查也更加麻烦、耗时。不过查看日志并分析之后，也没有发现存在大json的情况。
排查到此有点陷入困境，没有发生问题时刻的堆dump文件，没办法进行堆分析；问题发生的时间也都是随机的，所以也没办法通过实时诊断工具来提前预判进行采样；日志分析也基本排除了代码问题，只能把发生问题时的堆dump下来。
dump堆文件
出现问题时，没有发生OOM，所以就无法通过jvm自动dump堆文件。思路有两个：写定时任务，通过代码获取gc相关状态，提前预判可能出现问题，dump出堆文件；第二种思路和第一种基本一致，不过不需要改业务代码，而是通过脚本进行监控。 将对应的脚本写入jvm配置里的start_after.sh、start_before.sh。
具体逻辑
监控java进程的gc状态，在老年代内存使用率过高时，dump出堆文件。此处使用【老年代内存使用率】来作为一个评判标准，这也是从前几次线上gc监控得出的结论，每次都是老年代激增打满，触发多次yonggc。如果通过yonggc耗时进行监控的话，逻辑上会有问题：如果监控younggc耗时过高，在dump文件的话，实际上在监控到耗时过高的时候，gc行为已经发生了，否则也统计不到时间，所以此时老年代已经清理了，在dump文件也是清理之后的，分析不出来。所以需要清理之前的堆文件。
在dump过一次文件之后，脚本停止，接下来就是实现每一步的脚本。
获取java进程pid
获取java进程pid，需要检测java进程启动，项目需检测tomcat启动成功之后，再进行gc的监控。直接监控启动日志里的【startup in】关键字进行判断
APP_LOG="/export/Logs/Domains/agent_soa.jzt.jd.com/server1/logs/catalina.out" #应用启动日志路径
STARTUP_LOG_FILE="$LOG_DIR/java_startup.log" #应用启动监控日志
# 监控tomcat启动成功
check_app_started_by_log() {
local log_file="${1:-$APP_LOG}"
local max_attempts=60
local attempt=0
echo "[$(date "+%Y-%m-%d %H:%M:%S")] INFO: 开始检测应用启动日志..." >> "$STARTUP_LOG_FILE"
# 等待日志文件出现
while [ $attempt -lt $max_attempts ] && [ ! -f "$log_file" ]; do
echo "[$(date)] INFO: 等待日志文件出现... ($((attempt+1))/$max_attempts)" >> "$STARTUP_LOG_FILE"
sleep 20
attempt=$((attempt+1))
done
if [ ! -f "$log_file" ]; then
echo "[$(date)] ERROR: 日志文件未找到: $log_file" >> "$STARTUP_LOG_FILE"
return 1
fi
# 检测启动完成标志
attempt=0
while [ $attempt -lt $max_attempts ]; do
# 检查是否有 "startup in" 或类似的启动完成标志
if grep -q "startup in" "$log_file"; then
echo "[$(date)] SUCCESS: 检测到应用启动完成标志" >> "$STARTUP_LOG_FILE"
return 0
fi
echo "[$(date)] INFO: 等待应用启动完成... ($((attempt+1))/$max_attempts)" >> "$STARTUP_LOG_FILE"
sleep 20
attempt=$((attempt+1))
done
echo "[$(date)] ERROR: 在日志中未检测到启动完成标志" >> "$STARTUP_LOG_FILE"
return 1
}
当catalina.out中出现日志时，每20s检测一次日志文件中是否存在【startup in】成功的标志。通过这种方式来判断tomcat启动成功。并且在启动成功之后，通过应用名获取对应java进程的pid，tomcat应用对应的应用名是：org.apache.catalina.startup.Bootstrap
APP_NAME="org.apache.catalina.startup.Bootstrap" #tomcat应用名
jps -l | grep "$APP_NAME" | grep -v "jps" | awk '{print $1}'
获取gc相关状态
jstat -gc pid
返回的有17个属性，顺序和含义如下：
| S0C | S1C | S0U | S1U | EC | EU | OC | OU | MC | MU | CCSC | CCSU | YGC | YCGT | FGC | FGCT | GCT |
| 第一个幸存者空间容量 | 第二个幸存者空间容量 | 第一个幸存者空间使用量 | 第二个幸存者空间使用量 | 伊甸园空间容量 | 伊甸园空间使用率 | 老年代容量 | 老年代使用量 | 元空间容量 | 元空间使用量 | 压缩类空间容量 | 压缩类空间使用量 | Young GC次数 | Young GC总耗时（秒） | Full GC次数 | Full GC总耗时（秒） | GC总耗时（秒） |
脚本主要使用OC和OU，即第7和第8个属性，通过这两个属性计算出老年代使用率，与阈值进行对比，具体逻辑如下：
CHECK_INTERVAL=5 # 检查间隔（秒）
OLD_MEMORY_THRESHOLD=90 # 老年代使用率阈值
# 监控内存使用率（eden,old）,在gc发生前进行dump
monitor_memory_used() {
local pid=$1
echo "[$(date)] 开始监控堆内存使用率，触发阈值: ${OLD_MEMORY_THRESHOLD}%" >> "$MEMORY_MONITOR_LOG"
while true; do
# 检查进程是否还存在
if ! ps -p $pid > /dev/null 2>&1; then
echo "[$(date "+%Y-%m-%d %H:%M:%S")] INFO: Java进程已退出，停止监控" >> "$MEMORY_MONITOR_LOG"
return 0
fi
sleep $CHECK_INTERVAL
# 获取堆内存信息
local memory_info=$(jstat -gc $pid 2>/dev/null | tail -1)
local eden_used=$(echo "$memory_info" | awk '{print $6}')
local eden_capacity=$(echo "$memory_info" | awk '{print $5}')
local old_used=$(echo "$memory_info" | awk '{print $8}')
local old_capacity=$(echo "$memory_info" | awk '{print $7}')
echo "[$(date)] 内存情况，eden_used:${eden_used},eden_capacity:${eden_capacity};old_used:${old_used},old_capacity:${old_capacity}" >> "$MEMORY_MONITOR_LOG"
# 计算eden、old内存使用率
local eden_usage=$(echo "$eden_used $eden_capacity" | awk '{printf "%d", $1/$2*100}')
local old_usage=$(echo "$old_used $old_capacity" | awk '{printf "%d", $1/$2*100}')
# 计算是否超过阈值
local judge_result=$(echo "$old_usage $OLD_MEMORY_THRESHOLD" | awk '{print $1 - $2}')
echo "[$(date)] Eden使用率: ${eden_usage}%, Old使用率: ${old_usage}%, 是否超过阈值:${judge_result}" >> "$MEMORY_MONITOR_LOG"
if [ $judge_result -gt 0 ]; then
echo "[$(date)] ALERT: 内存使用率超过阈值 ${OLD_MEMORY_THRESHOLD}%" >> "$MEMORY_MONITOR_LOG"
dump_heap_info $pid "内存使用率过高 Eden:${eden_usage}% Old:${old_usage}%"
return 0
fi
done
}
每5秒获取一次gc状态，获取OC和OU，计算出老年代使用率，判断是否大于阈值，如果大于阈值，调用方法执行dump命令，获取此时的堆文件。
dump文件
满足阈值条件后，执行dump动作，除了dump堆文件，还可以输出线程信息及内存对象统计等
#输出堆内存详情
dump_heap_info() {
local pid=$1
local reason=$2
local timestamp=$(date "+%Y%m%d_%H%M%S")
echo "[$(date "+%Y-%m-%d %H:%M:%S")] WARNING: $reason" >> "$MEMORY_MONITOR_LOG"
echo "开始收集堆内存信息..." >> "$MEMORY_MONITOR_LOG"
#并行执行多个诊断命令
echo "=== 堆内存快照 (PID: $pid, 时间: $timestamp, 原因: $reason) ===" >> "$MEMORY_MONITOR_LOG"
# 1. 生成标准的.hprof堆dump文件
echo "生成.hprof堆dump文件..." >> "$MEMORY_MONITOR_LOG"
jmap -dump:live,format=b,file="$DUMP_DIR/heap_${timestamp}.hprof" $pid > /dev/null 2>&1
# 2. 输出jmap heap概要信息
echo "执行jmap -heap..." >> "$MEMORY_MONITOR_LOG"
jmap -heap $pid > "$DUMP_DIR/heap_summary_${timestamp}.log" 2>/dev/null
# 3. 输出jstat GC详细信息
echo "执行jstat -gc..." >> "$MEMORY_MONITOR_LOG"
jstat -gc $pid 1000 3 > "$DUMP_DIR/gc_detail_${timestamp}.log" 2>/dev/null
# 4. 输出jstack线程信息
echo "执行jstack..." >> "$MEMORY_MONITOR_LOG"
jstack $pid > "$DUMP_DIR/threads_${timestamp}.log" 2>/dev/null
# 5. 输出jmap histo内存对象统计
echo "执行jmap -histo..." >> "$MEMORY_MONITOR_LOG"
jmap -histo $pid > "$DUMP_DIR/histo_${timestamp}.log" 2>/dev/null
# 记录操作结果到监控日志
echo "堆内存信息收集完成" >> "$MEMORY_MONITOR_LOG"
echo "生成的文件:" >> "$MEMORY_MONITOR_LOG"
ls -la "$DUMP_DIR" | grep "$timestamp" >> "$MEMORY_MONITOR_LOG"
# 检查.hprof文件是否成功生成
if [ -f "$DUMP_DIR/heap_${timestamp}.hprof" ]; then
hprof_size=$(du -h "$DUMP_DIR/heap_${timestamp}.hprof" | awk '{print $1}')
echo "成功生成.hprof文件，大小: $hprof_size" >> "$MEMORY_MONITOR_LOG"
else
echo "警告: .hprof文件生成可能失败" >> "$MEMORY_MONITOR_LOG"
fi
echo "==============================================" >> "$MEMORY_MONITOR_LOG"
}
# 主函数
main() {
echo "[$(date "+%Y-%m-%d %H:%M:%S")] 开始检测Tomcat进程启动状态..." >> "$STARTUP_LOG_FILE"
# 等待Java进程启动
if check_app_started_by_log; then
echo "[$(date)] SUCCESS: 应用启动完成" >> "$STARTUP_LOG_FILE"
# 获取PID用于GC监控
local pid=$(get_java_pid)
if [ -n "$pid" ]; then
echo "[$(date)] INFO: 找到Java进程PID: $pid" >> "$STARTUP_LOG_FILE"
echo "[$(date)] INFO: 开始内存监控..." >> "$STARTUP_LOG_FILE"
monitor_memory_used $pid
echo "[$(date)] INFO: 内存监控已完成" >> "$STARTUP_LOG_FILE"
else
echo "[$(date)] ERROR: 未找到Java进程" >> "$STARTUP_LOG_FILE"
fi
exit 0
else
echo "[$(date)] ERROR: 应用启动检测失败" >> "$STARTUP_LOG_FILE"
exit 1
fi
}
#执行主函数
main
分析dump文件
原因推断
从概览中看，堆使用大小一共只有670M左右，但jvm监控老年代已经大于3G。继续查看支配树，也没有占比特别大的类型。但在【不可达对象】里，字符类型占据了2.77G，却没有触发fullGc回收。追溯到问题刚开始发生的时间附近，并没有大批量处理数据的场景，分析可能是jvm参数配置的问题。
应用配置的jvm参数
-Xms8192m -Xmx8192m -XX:MaxMetaspaceSize=1024m -XX:MetaspaceSize=1024m -XX:MaxDirectMemorySize=1966m -XX:InitiatingHeapOccupancyPercent=40 -XX:G1ReservePercent=10 -XX:ParallelGCThreads=8 -XX:CICompilerCount=3 -Djava.library.path=/usr/local/lib -server -XX:+UseG1GC -XX:MaxGCPauseMillis=200
使用G1垃圾回收机制，XX:InitiatingHeapOccupancyPercent=40在内存使用率达到40%时，触发G1并发标记周期。在G1垃圾回收器中，老年代通过mixedGC进行回收，而mixedGC是在并发标记完成之后才启动。那么反过来老年代一直没有回收，是因为本次并发标记一直未完成，或者还没有开始并发标记，因此产生该现象的原因可能是并发标记周期过长。
并发标记的触发条件，即XX:InitiatingHeapOccupancyPercent=40的配置，根据上述的jvm参数配置，在堆内存达到3.2G时触发并发标记。在【并发标记】周期内，应用还在同时创建大量对象，年轻代满后再触发younggc，younggc回收后导致对象引用关系发生变化，写屏障记录变化，【并发标记】需要处理这些变化，标记任务堆积，【并发标记】线程繁忙（出现问题时间，cpu有20%左右升高），最终导致并发标记处理效率变低，从而延迟。
观察参考线上其他正常的应用的jvm配置，是没有设置-XX:InitiatingHeapOccupancyPercent和-XX:G1ReservePercent的，可能是参数过度调优了。将这两个参数去掉，充分发挥G1的自适应机制，G1会根据历史的GC数据，动态计算最有的IHOP的值，重新部署代码上线，一周没有在出现超时异常的报警。
问题复现
按上述逻辑，删除-XX:InitiatingHeapOccupancyPercent和-XX:G1ReservePercent之后，线上很长时间都没出现问题，本以为已经解决。大概过了半个月，发现younggc耗时还是有一个突刺
现象和之前的一样，只不过younggc的耗时没有之前那么高，CPU也没有升很多（4%左右），所以没有导致接口出现超时，但是问题还是存在。为了详细查看下gc到底是哪个步骤超时，在jvm配置中添加一下配置，打印gc详细日志：
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finest
-Xloggc:/export/Logs/gc.log
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
该配置打印出每次gc的详细过程。部署一天之后，查看监控问题再次发生，下载出对应的gc日志，搜索younggc耗时过高时间前后的gc日志。
[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 1.2502035 secs]
[Parallel Time: 1008.2 ms, GC Workers: 8]
[GC Worker Start (ms): 16097834.2 16097834.3 16097834.3 16097834.3 16097834.3 16097834.4 16097834.4 16097834.4
Min: 16097834.2, Avg: 16097834.3, Max: 16097834.4, Diff: 0.2]
[Ext Root Scanning (ms): 8.1 2.5 4.7 2.6 2.4 2.5 2.5 2.5
Min: 2.4, Avg: 3.5, Max: 8.1, Diff: 5.7, Sum: 27.7]
[Thread Roots (ms): 0.0 1.2 1.2 1.2 1.1 1.1 1.1 1.1
Min: 0.0, Avg: 1.0, Max: 1.2, Diff: 1.2, Sum: 7.9]
[StringTable Roots (ms): 0.0 1.5 0.0 1.6 1.6 1.0 1.5 1.6
Min: 0.0, Avg: 1.1, Max: 1.6, Diff: 1.6, Sum: 8.8]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.5 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.5]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 3.6 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.4, Max: 3.6, Diff: 3.6, Sum: 3.6]
[CLDG Roots (ms): 8.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 1.0, Max: 8.0, Diff: 8.0, Sum: 8.0]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 26.9 32.1 30.1 32.1 32.1 32.1 32.1 32.1
Min: 26.9, Avg: 31.2, Max: 32.1, Diff: 5.2, Sum: 249.4]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 21.7 26.8 24.8 26.9 26.9 26.8 26.9 26.9
Min: 21.7, Avg: 26.0, Max: 26.9, Diff: 5.3, Sum: 207.7]
[Processed Buffers: 255 334 232 235 297 291 320 334
Min: 232, Avg: 287.2, Max: 334, Diff: 102, Sum: 2298]
[Scan RS (ms): 5.2 5.2 5.2 5.2 5.2 5.2 5.2 5.1
Min: 5.1, Avg: 5.2, Max: 5.2, Diff: 0.1, Sum: 41.5]
[Code Root Scanning (ms): 0.0 0.1 0.1 0.0 0.0 0.1 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Object Copy (ms): 973.1 973.3 973.2 973.3 973.3 973.3 973.3 973.4
Min: 973.1, Avg: 973.3, Max: 973.4, Diff: 0.2, Sum: 7786.1]
[Termination (ms): 0.0 0.0 0.0 0.1 0.1 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Termination Attempts: 44 34 47 36 37 39 46 1
Min: 1, Avg: 35.5, Max: 47, Diff: 46, Sum: 284]
[GC Worker Other (ms): 0.0 0.1 0.1 0.0 0.1 0.1 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): 1008.1 1008.1 1008.0 1008.1 1008.0 1008.0 1008.0 1007.9
Min: 1007.9, Avg: 1008.0, Max: 1008.1, Diff: 0.2, Sum: 8064.2]
[GC Worker End (ms): 16098842.3 16098842.4 16098842.3 16098842.4 16098842.4 16098842.3 16098842.3 16098842.3
Min: 16098842.3, Avg: 16098842.4, Max: 16098842.4, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 241.2 ms]
[Evacuation Failure: 227.5 ms]
[Recalculate Used: 0.0 ms]
[Remove Self Forwards: 227.5 ms]
[Restore RemSet: 0.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 8.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.9 ms]
[Parallel Redirty: 0.7 0.7 0.7 0.6 0.6 0.6 0.6 0.6
Min: 0.6, Avg: 0.6, Max: 0.7, Diff: 0.1, Sum: 5.1]
[Redirtied Cards: 79330 73702 69015 73797 73221 68409 69670 61368
Min: 61368, Avg: 71064.0, Max: 79330, Diff: 17962, Sum: 568512]
[Humongous Register: 0.6 ms]
[Humongous Total: 72]
[Humongous Candidate: 52]
[Humongous Reclaim: 1.5 ms]
[Humongous Reclaimed: 36]
[Free CSet: 0.8 ms]
[Young Free CSet: 0.8 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 4884.0M(4884.0M)->0.0B(3168.0M) Survivors: 28.0M->52.0M Heap: 7934.4M(8192.0M)->4016.0M(8192.0M)]
[Times: user=2.96 sys=0.57, real=1.25 secs]
本次younggc总体耗时1.25秒，GC出现【to-space exhausted】空间耗尽，表明G1在进行年轻代垃圾回收时，没有空闲region存放存活的对象，查看每个步骤的耗时：
1> 发现在对象copy阶段耗时最高【Object Copy (ms): 973.1 973.3 973.2 973.3 973.3 973.3 973.3 973.4】，达到970ms，
2> Evacuation Failure（转移失败）: 227.5 ms，当G1无法申请到新region时（堆空间已满），会触发转移失败。在gc过程中，发现无法为某个对象分配区域region时，gc会停止copy过程，在原内存地址给该对象一个"自我转发"的指针，表示该对象本该被移走，但是因为没有空间了，所以还保留在这里。
G1ParScanThreadState::do_copy_to_survivor_space(G1HeapRegionAttr const region_attr,
oop const old,
markWord const old_mark) {
//源对象region必须在回收的cset集合，且不能已经被转发
assert(region_attr.is_in_cset(),
"Unexpected region attr type: %s", region_attr.get_type_str());
assert(!old_mark.is_forwarded(), "precondition");
Klass* klass = UseCompactObjectHeaders
? old_mark.klass()
: old->klass();
const size_t word_sz = old->size_given_klass(klass);
//特殊对象处理：对象所在的region被固定，且对象是基本类型的数组，不允许移动
if (region_attr.is_pinned() && klass->is_typeArray_klass()) {
return handle_evacuation_failure_par(old, old_mark, klass, region_attr, word_sz, true /* cause_pinned */);
}
uint age = 0;
//根据对象的年龄，决定目标区域是拷贝到survivor区域还是晋升到老年代;并尝试分配
G1HeapRegionAttr dest_attr = next_region_attr(region_attr, old_mark, age);
G1HeapRegion* const from_region = _g1h->heap_region_containing(old);
uint node_index = from_region->node_index();
// 先尝试在GC线程本地的plab中快速分配内存
HeapWord* obj_ptr = _plab_allocator->plab_allocate(dest_attr, word_sz, node_index);
//plab分配失败
if (obj_ptr == nullptr) {
//尝试在共享的全局空间中分配
obj_ptr = allocate_copy_slow(&dest_attr, klass, word_sz, age, node_index);
if (obj_ptr == nullptr) {
//全局分配也失败，表示内存空间不足，对应gc日志的（to-space exhausted）
return handle_evacuation_failure_par(old, old_mark, klass, region_attr, word_sz, false /* cause_pinned */);
}
}
assert(obj_ptr != nullptr, "when we get here, allocation should have succeeded");
assert(_g1h->is_in_reserved(obj_ptr), "Allocated memory should be in the heap");
//钩子函数，模拟失败场景测试
if (inject_allocation_failure(from_region->hrm_index())) {
undo_allocation(dest_attr, obj_ptr, word_sz, node_index);
return handle_evacuation_failure_par(old, old_mark, klass, region_attr, word_sz, false /* cause_pinned */);
}
//执行对象拷贝
Prefetch::write(obj_ptr, PrefetchCopyIntervalInBytes);
Copy::aligned_disjoint_words(cast_from_oop<HeapWord*>(old), obj_ptr, word_sz);
const oop obj = cast_to_oop(obj_ptr);
const oop forward_ptr = old->forward_to_atomic(obj, old_mark, memory_order_relaxed);
//处理成功更新gc相关数据
if (forward_ptr == nullptr) {
{
const uint young_index = from_region->young_index_in_cset();
assert((from_region->is_young() && young_index > 0) ||
(!from_region->is_young() && young_index == 0), "invariant" );
_surviving_young_words[young_index] += word_sz;
}
if (dest_attr.is_young()) {
if (age < markWord::max_age) {
age++;
obj->incr_age();
}
_age_table.add(age, word_sz);
} else {
update_bot_after_copying(obj, word_sz);
}
{
assert(dest_attr.is_young() == _g1h->heap_region_containing(obj)->is_survivor(), "must be");
G1SkipCardEnqueueSetter x(&_scanner, dest_attr.is_young());
do_iterate_object(obj, old, klass, region_attr, dest_attr, age);
}
return obj;
} else {
//因为是并发，其他线程如果先处理完成，撤回指针设置操作，返回其他线程设置的指针
_plab_allocator->undo_allocation(dest_attr, obj_ptr, word_sz, node_index);
return forward_ptr;
}
}
//空间耗尽的核心处理逻辑
G1ParScanThreadState::handle_evacuation_failure_par(oop old, markWord m, Klass* klass, G1HeapRegionAttr attr, size_t word_sz, bool cause_pinned) {
//cause_pinned: false表示空间耗尽；true表示分区被固定
assert(_g1h->is_in_cset(old), "Object " PTR_FORMAT " should be in the CSet", p2i(old));
//原子性的自我转发，对像old的mark word修改为一个指向自身的特殊转发指针
oop forward_ptr = old->forward_to_self_atomic(m, memory_order_relaxed);
if (forward_ptr == nullptr) {
//记录失败信息，包含region对象信息和失败原因
G1HeapRegion* r = _g1h->heap_region_containing(old);
record_evacuation_failed_region(r, _worker_id, cause_pinned);
//标记失败对象bitmap为存活，避免被当做垃圾回收掉
_g1h->mark_evac_failure_object(_worker_id, old, word_sz);
_evacuation_failed_info.register_copy_failure(word_sz);
{
//处理对象引用
G1SkipCardEnqueueSetter x(&_scanner, false /* skip_card_enqueue */);
do_iterate_object(old, old, klass, attr, attr, m.age());
}
return old;
} else {
//其他线程已处理，直接返回当前
assert(old == forward_ptr || !_g1h->is_in_cset(forward_ptr),
"Object " PTR_FORMAT " forwarded to: " PTR_FORMAT " "
"should not be in the CSet",
p2i(old), p2i(forward_ptr));
return forward_ptr;
}
}
在发送Evacuation Failure时，G1会触发担保机制，执行一次STW、单线程的FullGc，但是从监控上看并没有执行FullGc操作。查看源码如上，为G1垃圾回收器对象复制逻辑，在空间耗尽时（handle_evacuation_failure_par），执行一个原子性操作，将对象old设置一个指向自己的指针。该操作也是并发执行，所以可能其他线程提前已经设置成功，那么就直接返回。如果本次设置成功，则还会处理记录对应的失败信息及原因。源码中也没有调用对应的do_full_collection触发FullGC。在早期的JDK（jdk7）中，由于G1还不太成熟，处理Evacuation Failure比较简单粗暴，会直接使用FullGC。而对于当前的版本，G1的核心算法得到了重大增强，其中一个关键的改进就是引入了Evacuation Failure的原地处理机制。首要策略：尽力在原地处理Evacuation Failure，将其作为一次延长了的Young GC的一部分，这是默认且首选的行为，避免由于FullGC导致的长时间暂停。
当前G1垃圾回收发生Evacuation Failure，除了上述停止拷贝、设置自我转发、尽力完成本次GC（eden空间释放），还会进行空间分配的策略调整，减少eden区空间，以降低下一次gc压力。本次gc完成后，G1策略逻辑会评估当前堆状态，例如监测到老年代堆空间很高，G1会异步的、很快的启动一次并发标记用于触发mixed gc回收老年代空间。
从下面gc日志也可以看出：发生超时前一次gc，eden空间是4G。在发生超时后，eden空间调整为3G；并且在超时后的下一次gc开始，看到有【initial-mark】标记，表示本次gc暂停，同时也启动并发标记周期，他被整合在了一次younggc中，避免多次STW。紧随其后的是完整的并发标记周期：根区域扫描 –> 并发标记 –> 最终标记（STW） –> 清理（并发清理）。
并发标记之后，会通过多次mixed gc进行回收（年轻代、老年代），三次mixed回收了大量老年代的空间，并且在最后一次mixed gc后，eden区空间获取巨量提升。
前一次gc：[Eden: 4888.0M(4888.0M)->0.0B(4884.0M) Survivors: 24.0M->28.0M Heap: 6269.3M(8192.0M)->1388.4M(8192.0M)]
超时gc：[Eden: 4884.0M(4884.0M)->0.0B(3168.0M) Survivors: 28.0M->52.0M Heap: 7934.4M(8192.0M)->4016.0M(8192.0M)]
后一次gc启动：[GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0927648 secs]
并发标记:
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0373856 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.5074515 secs]
[Finalize Marking, 0.0053514 secs]
[GC ref-proc, 0.0240335 secs]
[System Dictionary Unloading, 0.0088980 secs]
[Parallel Unloading, 0.0493995 secs]
[Deallocate Metadata, 0.0028566 secs], 0.0624284 secs], 0.0938051 secs]
[Times: user=0.33 sys=0.15, real=0.09 secs]
[GC cleanup 4079M->3059M(8192M), 0.0067314 secs]
[Times: user=0.02 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0006846 secs]
#多次mixed gc
[GC pause (G1 Evacuation Pause) (young), 0.0426753 secs]
[Eden: 3132.0M(3132.0M)->0.0B(344.0M) Survivors: 68.0M->64.0M Heap: 6144.9M(8192.0M)->3007.3M(8192.0M)]
[GC pause (G1 Evacuation Pause) (mixed), 0.0244336 secs]
[Eden: 344.0M(344.0M)->0.0B(388.0M) Survivors: 64.0M->20.0M Heap: 3351.3M(8192.0M)->2185.8M(8192.0M)]
[GC pause (G1 Evacuation Pause) (mixed), 0.0362865 secs]
[Eden: 388.0M(388.0M)->0.0B(4892.0M) Survivors: 20.0M->20.0M Heap: 1804.0M(8192.0M)->1200.9M(8192.0M)]
从监控上看老年代突增突降，有可能是存在大对象直接分配到老年代，不过从gc日志上看，并没有【Humongous Allocation】类型的标识，因此不是巨型对象导致的。另一种可能是短时间内创建了大量的对象，迅速填满eden区触发younggc，并且还在不停的创建，在导致Survivor区也填满时，直接晋升到老年代，不过从监控上看，虽然对应时间内调用量有所增加，但是并没有很明显的突刺，也算是在日常正常的水平内。
目前看现象大概率是第二种原因，但是因为应用提供的服务非常多（300多个对外接口），直接从日志中查看比较困难，并且在同一时间只有一个或几个机器出现该现象，其他机器正常。所以本次先通过参数调优进行解决，出现以上问题有两个重要因素：一是eden区空间过大，日常最高达到5G（内存一共8G），触发younggc频率低，但是处理数据量大。二是预留空间及Survivor区空间不足，极端情况下，无法容纳本该在Survivor区的对象，导致直接晋升老年代。
对于上述两种情况，增加以下jvm参数，调整预留空间大小，及eden区大小范围：
-XX:G1ReservePercent=15
-XX:G1NewSizePercent=20
-XX:G1MaxNewSizePercent=40
添加以上参数上线后，观察到老年代突增突降的现象还存在，不过现象出现时，younggc耗时已经降至毫秒级，暂时不影响其他的业务。
后续调整
1、最重要的还是将应用拆分，由于历史原因，代码中融合的服务非常多，并且随着业务发展，后续也会越来越多。一旦出现问题，影响的范围也会更大，需要尽快按照业务域的不同，将应用拆分成多个微服务，这样也同时能避免由于机器问题不同业务间相互影响。
2、继续观察发生问题期间日志情况，排查出调用量较高，或者批量查询的情况，对代码进行优化。
线程监控
使用脚本直接dump文件是很危险的行为，但是是否可以用脚本来监控线程，比如检测内存使用率过高，导出当前线程的一些状态指标进行简单分析，导出线程状态对机器的性能影响，要远远小于dump文件。