可读的JVM GC时间戳

当我们诊断Java应用程序的问题时，能够查到垃圾回收的状况是非常有帮助的。一个基本的最基础的方法是开启垃圾回收日志。

也许你已经知道了，如果我们把下面的参数加到java启动命令行中，

-Xloggc:<file_name> –XX:+PrintGCDetails -XX:+PrintGCDateStamps

JVM就会将垃圾回收信息写到-Xloggc设置的文件中。日志格式如下：

2010-04-22T18:12:27.796+0200: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828+0200: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859+0200: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890+0200: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

加粗的部分显示了垃圾回收时间的开始日期及时间。

不幸的是-XX:+PrintGCDateStamps参数只有Java 6u4及以后版本的JVM才可用。所以，如果我们很不幸而且我们的应用程序跑在就版本的JVM上，我们就被迫使用，

-Xloggc:<file> –XX:+PrintGCDetails

这样，得到的垃圾回收信息如下：

22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

现在，加粗的数字表示从JVM启动时间开始的秒间隔。

这种情况下就很难把GC事件和其他日志文件中的信息关联到一起了:(

有没有简单的办法来处理gc日志文件并从秒间隔中关联出日期和时间呢？看起来是可以的，但是秒间隔从什么时候开始呢？换句话说，我们怎么得知JVM的启动日期和时间呢？

为了使用最最基础的方法，我们应该从同一个GC日志文件中分析出日期和时间。这样我们就要用到文件的属性了。我们有如下不同的选择：

Unix	Windows
Access time	Access time
Change time	Creation time
Modify time	Modify time

我们抛弃掉access time、cheng time及creation time，因为他们不是在所有平台上都可用的。这样我们只剩下修改时间（modify time），表示文件最后一次修改的时间。

在Windows上，当文件被拷贝到其他地方时，修改时间是保持不变的。但是当我们在Unix上拷贝GC日志文件时，我们需要使用-p选项来保持时间戳属性。

GC日志文件的最后修改时间应该和日志文件中最后一个记录的GC时间的时间戳保持一致。好吧，更精确点，由于日志行是在GC执行时一点一点写的，最后修改时间应该是确切等于最后的秒间隔加上GC的执行时间。

22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

在我们的方法中由于不需要精确时间，我们抛弃执行时间，进而得到每次垃圾回收时间发生的粗略时间。然而，我们必须注意在大的heap中，有时间GC的执行时间可以长达几秒。

当我们最近在一个客户那里体验这个方案时，我们需要快速开发一个简单的轻便的脚本，所以就选择Python来实现这个功能。你已经知道了我们不仅仅用Java吧。

#!/usr/bin/env python
 
import sys, os, datetime
 
# true if string is a positive float
def validSeconds(str_sec):
    try:
        return 0 < float(str_sec)
    except ValueError:
        return False
 
# show usage                
if len(sys.argv) < 2:
    print "Usage: %s <gc.log>" % (sys.argv[0])
    sys.exit(1)
 
file_str = sys.argv[1]
lastmod_date = datetime.datetime.fromtimestamp(os.path.getmtime(file_str))
 
file = open(file_str, 'r')
lines = file.readlines()
file.close()
 
# get last elapsed time
for line in reversed(lines):
    parts = line.split(':')
    if validSeconds(parts[0]):
        break
 
# calculate start time
start_date = lastmod_date - datetime.timedelta(seconds=float(parts[0]))
 
# print file prepending human readable time where appropiate  
for line in lines:
    parts = line.split(':')
    if not validSeconds(parts[0]):
        print line.rstrip()
        continue
    line_date = start_date + datetime.timedelta(seconds=float(parts[0]))
    print "%s: %s" % (line_date.isoformat(), line.rstrip())

这个脚本的输出可以重定向到另一个文件中，在哪里可以得到：

2010-04-22T18:12:27.796375: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828375: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859375: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890375: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

你可能注意到了日期的格式并不是和-XX:+PrintGCDateStamps参数100%的一致。但这足以看出每个GC时间发生的时间。

原文：http://www.theserverlabs.com/blog/2010/05/26/human-readable-jvm-gc-timestamps/

PS：翻译这篇blog主要是想和大家分享这个python脚本，非常的使用。在运维类似于Hadoop这样的分布式大集群试，master的GC日志是一定要打开，因为各种各样的问题都可能和GC有关。但由于某些原因，如JDK版本或历史原因，可能配置了–XX:+PrintGCDetails而不是-XX:+PrintGCDateStamps，这样就非常需要本文的脚本来转换时间格式。当然最好是配上-XX:+PrintGCDateStamps参数。