JVM gc 参数 GCTaskTimeStampEntries Bug 记录

生产现象描述

不久前，有个学生微信私聊问了我这样一个线上问题：

小A：黄老师，您好，这是之前遇到了一个tomcat总是重启的一个现象，就是这个参数异常了，后来查到了是jvm的一个bug，但是没太理解这个bug的逻辑，想请问下，您知道这块的逻辑细节嘛？多谢

然后给了我这样一张图：

然后给了我这个链接：https://support.oracle.com/knowledge/Middleware/1289749_1.html

于是我点开了进去，仅仅是提了个BUG，并没有bug的描述和原理。所以写下这篇文章用于记载这个bug的原理。

参数解释

我们先来看Hotspot源码中对其定义的描述：

 product(uintx, GCTaskTimeStampEntries, 200, "Number of time stamp entries per gc worker thread") 

可以看到该参数用于控制记录GC工作线程（gc worker thread）执行时间戳的记录实体大小。

参数初始化原理

在parallelScavenge 包下的GCTaskThread.cpp文件中创建了GCTaskThread工作线程，我们看到名字为ParallelGC，典型的垃圾回收器组合：PS+PO。而这个GC工作线程便是PS的工作线程。我们关注构造器初始化列表的：

1. _time_stamps
   定义：GCTaskTimeStamp* time_stamps。在C类语言中我们知道数组就是指针，我们使用GCTaskTimeStamp[GCTaskTimeStampEntries] _time_stamps时，这里的time_stamps就等于GCTaskTimeStamp* _time_stamps，而我们这里需要使用宏NEW_C_HEAP_ARRAY创建数组，所以我们使用指针形式来表示（PS：给没有C语言基础的朋友看的，因为我这边学员Java语言的偏多，懂得忽略）。所以该变量用于表示记录时间戳实体GCTaskTimeStamp的数组，默认大小为200。
2. _time_stamp_index
   定义：uint time_stamp_index 。一个无符号的time_stamps数组下标索引。

很清晰：我们使用time_stamps变量来表示GCTaskTimeStamp的实体记录数组，使用time_stamp_index 变量来记录使用的_time_stamps数组下标。初始化过程如下。

GCTaskThread::GCTaskThread(GCTaskManager* manager,
                           uint           which,
                           uint           processor_id) :
_manager(manager),
_processor_id(processor_id),
_time_stamps(NULL),
_time_stamp_index(0)
{
    if (!os::create_thread(this, os::pgc_thread))
        vm_exit_out_of_memory(0, OOM_MALLOC_ERROR, "Cannot create GC thread. Out of system resources.");
    // 如果设置打印GC任务执行时间戳，那么根据GCTaskTimeStampEntries参数来创建GCTaskTimeStamp数组，也即创建GCTaskTimeStamp[] 数组，默认为200个
    if (PrintGCTaskTimeStamps) {
        _time_stamps = NEW_C_HEAP_ARRAY(GCTaskTimeStamp, GCTaskTimeStampEntries, mtGC);
        guarantee(_time_stamps != NULL, "Sanity");
    }
    set_id(which);
    set_name("GC task thread#%d (ParallelGC)", which);
}

参数使用原理

我们知道线程之间通讯最简单的方式就是通过共享阻塞队列的方式来通讯，比如Java的BlockingQueue接口的子类，当然在C++中是另外的队列，当GCTaskThread启动后，将会执行GCTaskThread::run方法，在该方法的for循环中，接收来自GCTaskManager传递下来的任务对象GCTask，然后调用其do_it方法执行。详细描述如下。

void GCTaskThread::run() {
    ...
    // 时间戳对象
    TimeStamp timer;
    for (;;) {
        HandleMark   hm_inner;
        ResourceMark rm_inner;
        for (;; ) {
            GCTask* task = manager()->get_task(which());
            bool is_idle_task = task->is_idle_task();
            if (PrintGCTaskTimeStamps) {
                // 如果打印GC时间戳，那么需要保证当前TimeStamp为最新，保证精度
                timer.update();
            }
            // 获取执行前时间戳
            jlong entry_time = timer.ticks();
            // 任务名
            char* name = task->name();
            // 执行任务
            task->do_it(manager(), which());
            // 如果不是空闲任务，那么通知manager完成执行，并且根据PrintGCTaskTimeStamps参数记录时间戳
            if (!is_idle_task) {
                manager()->note_completion(which());
                if (PrintGCTaskTimeStamps) {
                    // 更新执行完成的时间戳
                    timer.update();
                    // 构建GCTaskTimeStamp任务时间戳对象，并设置任务名、执行开始前的时间、执行后的时间。注意这里的_time_stamp_index++，我们知道该变量用于指明存储GCTaskTimeStamp对象的数组下标，而这里并没有判断是否超过了界限
                    GCTaskTimeStamp* time_stamp = time_stamp_at(_time_stamp_index++);
                    time_stamp->set_name(name);
                    time_stamp->set_entry_time(entry_time);
                    time_stamp->set_exit_time(timer.ticks());
                }
            } 
            ...
        }
    }
}

我们在上面看到最后会通过time_stamp_at(_time_stamp_index++)方法找到一个空闲的下标来保存GCTaskTimeStamp，我们来看该方法的实现：

GCTaskTimeStamp* GCTaskThread::time_stamp_at(uint index) {
    guarantee(index < GCTaskTimeStampEntries, "increase GCTaskTimeStampEntries");
    return &(_time_stamps[index]);
}

我们在JVM 挂掉的时候信息提示就是："increase GCTaskTimeStampEntries"，因为这里的下标已经超过了定义的下标，而这正是导致JVM Crash的原因所在。

那么问题来了：我们知道当GCTaskThread接到一个GCTask后，就执行，然后保存GCTaskTimeStamp对象，由谁来使用这个数组呢？我们来看以下方法：

void GCTaskThread::print_task_time_stamps() {
    // 必须设置了PrintGCTaskTimeStamps参数，同时_time_stamps数组已经创建
    assert(PrintGCTaskTimeStamps, "Sanity");
    assert(_time_stamps != NULL, "Sanity (Probably set PrintGCTaskTimeStamps late)");
    tty->print_cr("GC-Thread %u entries: %d", id(), _time_stamp_index);
    // 遍历打印
    for(uint i=0; i<_time_stamp_index; i++) {
        GCTaskTimeStamp* time_stamp = time_stamp_at(i);
        tty->print_cr("\t[ %s " INT64_FORMAT " " INT64_FORMAT " ]",
                      time_stamp->name(),
                      time_stamp->entry_time(),
                      time_stamp->exit_time());
    }
    // 完成后复原_time_stamp_index索引下标
    _time_stamp_index = 0;
}

该方法由GCTaskManager在完成一次完整GC后通过以下方法调用：

void GCTaskManager::print_task_time_stamps() {
    // 遍历所有GC线程，调用他们的print_task_time_stamps打印时间戳
    for(uint i=0; i<ParallelGCThreads; i++) {
        GCTaskThread* t = thread(i);
        t->print_task_time_stamps();
    }
}

Bug原因分析

现在我们可以来定义这个Bug 出现的原因了。是由于_time_stamp_index下标在放置时并没有判断界限，所以便在GCTaskThread::time_stamp_at方法中参数校验失败，从而导致JVM Crash 并给出提示信息："increase GCTaskTimeStampEntries"，如果我们在一次完整的PS GC中执行了超过200个以上的任务，同时开启了PrintGCTaskTimeStamps参数，那么就会导致该Bug出现。

Bug解决方案

1. 关闭PrintGCTaskTimeStamps参数 关闭该参数将无法看到GC的详细信息，平时可以关掉，如果线上服务器发生了STW时间较长时，那么可以开启查看日志信息
2. 增加GCTaskTimeStampEntries大小 无谓的增加了内存大小，因为该内存的分配空间是JVM的进程的堆内存空间，相对于64位的OS，大内存的机器来说影响较小，但是对内存敏感时酌情调整，不过有时候我们并不会执行超过200个Task的GC任务，所以按需调整。如果我们无法升级JVM版本，也即JDK版本，那么可以根据PrintGCTaskTimeStamps+GCTaskTimeStampEntries来控制该Bug。
3. 升级JVM版本

我们来看新版的JVM对于time_stamp_index的使用改进。此时我们就可以从新版的JDK版本中看到，当超过GCTaskTimeStampEntries设置的大小后，将不再尝试向time_stamp数组中存放时间戳，而是打印警告日志。同时在最后遍历time_stamp数组时，通过 MIN2(time_stamp_index, GCTaskTimeStampEntries)来计算遍历的最大索引下标，从而避免出现了数组越界问题。详细优化代码如下。

// 取index处下标的GCTaskTimeStamp改进：
GCTaskTimeStamp* GCTaskThread::time_stamp_at(uint index) {
 assert(index < GCTaskTimeStampEntries, "Precondition");
 if (_time_stamps == NULL) {
 // 使用懒初始化的方式来创建time_stamps
 GCTaskTimeStamp* time_stamps = NEW_C_HEAP_ARRAY(GCTaskTimeStamp, GCTaskTimeStampEntries, mtGC);
 // 原子性设置_time_stamps，如果替换失败，那么释放临时变量time_stamps的空间
 if (!Atomic::replace_if_null(time_stamps, &_time_stamps)) {
 FREE_C_HEAP_ARRAY(GCTaskTimeStamp, time_stamps);
        }
    }
 return &(_time_stamps[index]);
}

// 执行改进
void GCTaskThread::run() {
    ...
 for (;;) {
            ...
 for (;; ) {
                    ...
 if (!is_idle_task) {
 manager()->note_completion(which());
 // 记录开启，那么调用add_task_timestamp方法记录时间戳
 if (log_is_enabled(Debug, gc, task, time)) {
 timer.update();
 add_task_timestamp(name, entry_time, timer.ticks());
                            }
                        }
                    ...
                }
        }
}

// 添加任务执行时间戳
void GCTaskThread::add_task_timestamp(const char* name, jlong t_entry, jlong t_exit) {
 // 如果超过了GCTaskTimeStampEntries参数限制，那么打印warning信息，否则添加到数组中
 if (_time_stamp_index < GCTaskTimeStampEntries) {
 GCTaskTimeStamp* time_stamp = time_stamp_at(_time_stamp_index);
 time_stamp->set_name(name);
 time_stamp->set_entry_time(t_entry);
 time_stamp->set_exit_time(t_exit);
    } else {
 if (_time_stamp_index == GCTaskTimeStampEntries) {
 log_warning(gc, task, time)("GC-thread %u: Too many timestamps, ignoring future ones. "
 "Increase GCTaskTimeStampEntries to get more info.",
 id());
        }
 // Let _time_stamp_index keep counting to give the user an idea about how many
 // are needed.
    }
 _time_stamp_index++;
}

// 打印所有任务时间戳优化
void GCTaskThread::print_task_time_stamps() {
 if (_time_stamps != NULL) {
 log_debug(gc, task, time)("GC-Thread %u entries: %d%s", id(),
 _time_stamp_index,
 _time_stamp_index >= GCTaskTimeStampEntries ? " (overflow)" : "");
 // 遍历的索引以GCTaskTimeStampEntries为限制，取_time_stamp_index和GCTaskTimeStampEntries最小值
 const uint max_index = MIN2(_time_stamp_index, GCTaskTimeStampEntries);
 // 循环打印
 for (uint i = 0; i < max_index; i++) {
 GCTaskTimeStamp* time_stamp = time_stamp_at(i);
 log_debug(gc, task, time)("\t[ %s " JLONG_FORMAT " " JLONG_FORMAT " ]",
 time_stamp->name(),
 time_stamp->entry_time(),
 time_stamp->exit_time());
        }
 // 打印数据后重置_time_stamp_index
 _time_stamp_index = 0;
    }
}