性能问答>JVM参数配置中打印GC日志使用不同时戳的意义>
4回复
2年前

JVM参数配置中打印GC日志使用不同时戳的意义



PrintGCTimeStamps和PrintGCDateStamps对打印日志消耗会有所不同吗?感觉第一种显示的比较直观,想请教下专家们打印成第二种的意义是什么呢。

4919 阅读
请先登录,再评论

感谢专家的解答,其实是说错了,觉得第二种比较直观。会认真看专家得解答的。

2年前

PrintGCTimeStamps主要打印针对JVM启动的时候的相对时间,而PrintGCDateStamps会打印具体的时间,实现不一样消耗肯定不一样
这里可以大概说一下实现,下面是PrintGCTimeStamps在linux下的实现,如果该os支持monotonic time,也就是会算出从os重启的时候到现在的ticks,这种写法哪怕修改了系统时间也不会对这个值有影响,否则的话就直接是gettimeofday获取当前系统时间,这样一来,PrintGCTimeStamps就是打印从JVM启动到现在打印日志的相对时间值,单位转化到了秒

void outputStream::stamp() {
  if (! _stamp.is_updated()) {
    _stamp.update(); // start at 0 on first call to stamp()
  }

  // outputStream::stamp() may get called by ostream_abort(), use snprintf
  // to avoid allocating large stack buffer in print().
  char buf[40];
  jio_snprintf(buf, sizeof(buf), "%.3f", _stamp.seconds());
  print_raw(buf);
}

double TimeStamp::seconds() const {
  assert(is_updated(), "must not be clear");
  jlong new_count = os::elapsed_counter();
  return TimeHelper::counter_to_seconds(new_count - _counter);
}

// on linux
jlong os::elapsed_counter() {
  return javaTimeNanos() - initial_time_count;
}
jlong os::javaTimeNanos() {
  if (Linux::supports_monotonic_clock()) {
    struct timespec tp;
    int status = Linux::clock_gettime(CLOCK_MONOTONIC, &tp);
    assert(status == 0, "gettime error");
    jlong result = jlong(tp.tv_sec) * (1000 * 1000 * 1000) + jlong(tp.tv_nsec);
    return result;
  } else {
    timeval time;
    int status = gettimeofday(&time, NULL);
    assert(status != -1, "linux error");
    jlong usecs = jlong(time.tv_sec) * (1000 * 1000) + jlong(time.tv_usec);
    return 1000 * usecs;
  }
}

而PrintGCDateStamps的实现如下:

void outputStream::date_stamp(bool guard,
                              const char* prefix,
                              const char* suffix) {
  if (!guard) {
    return;
  }
  print_raw(prefix);
  static const char error_time[] = "yyyy-mm-ddThh:mm:ss.mmm+zzzz";
  static const int buffer_length = 32;
  char buffer[buffer_length];
  const char* iso8601_result = os::iso8601_time(buffer, buffer_length);
  if (iso8601_result != NULL) {
    print_raw(buffer);
  } else {
    print_raw(error_time);
  }
  print_raw(suffix);
  return;
}

char* os::iso8601_time(char* buffer, size_t buffer_length) {
  // Output will be of the form "YYYY-MM-DDThh:mm:ss.mmm+zzzz\0"
  //                                      1         2
  //                             12345678901234567890123456789
  static const char* iso8601_format =
    "%04d-%02d-%02dT%02d:%02d:%02d.%03d%c%02d%02d";
  static const size_t needed_buffer = 29;

  // Sanity check the arguments
  if (buffer == NULL) {
    assert(false, "NULL buffer");
    return NULL;
  }
  if (buffer_length < needed_buffer) {
    assert(false, "buffer_length too small");
    return NULL;
  }
  // Get the current time
  jlong milliseconds_since_19700101 = javaTimeMillis();
  const int milliseconds_per_microsecond = 1000;
  const time_t seconds_since_19700101 =
    milliseconds_since_19700101 / milliseconds_per_microsecond;
  const int milliseconds_after_second =
    milliseconds_since_19700101 % milliseconds_per_microsecond;
  // Convert the time value to a tm and timezone variable
  struct tm time_struct;
  if (localtime_pd(&seconds_since_19700101, &time_struct) == NULL) {
    assert(false, "Failed localtime_pd");
    return NULL;
  }
  const time_t zone = get_timezone(&time_struct);

  // If daylight savings time is in effect,
  // we are 1 hour East of our time zone
  const time_t seconds_per_minute = 60;
  const time_t minutes_per_hour = 60;
  const time_t seconds_per_hour = seconds_per_minute * minutes_per_hour;
  time_t UTC_to_local = zone;
  if (time_struct.tm_isdst > 0) {
    UTC_to_local = UTC_to_local - seconds_per_hour;
  }
  // Compute the time zone offset.
  //    localtime_pd() sets timezone to the difference (in seconds)
  //    between UTC and and local time.
  //    ISO 8601 says we need the difference between local time and UTC,
  //    we change the sign of the localtime_pd() result.
  const time_t local_to_UTC = -(UTC_to_local);
  // Then we have to figure out if if we are ahead (+) or behind (-) UTC.
  char sign_local_to_UTC = '+';
  time_t abs_local_to_UTC = local_to_UTC;
  if (local_to_UTC < 0) {
    sign_local_to_UTC = '-';
    abs_local_to_UTC = -(abs_local_to_UTC);
  }
  // Convert time zone offset seconds to hours and minutes.
  const time_t zone_hours = (abs_local_to_UTC / seconds_per_hour);
  const time_t zone_min =
    ((abs_local_to_UTC % seconds_per_hour) / seconds_per_minute);

  // Print an ISO 8601 date and time stamp into the buffer
  const int year = 1900 + time_struct.tm_year;
  const int month = 1 + time_struct.tm_mon;
  const int printed = jio_snprintf(buffer, buffer_length, iso8601_format,
                                   year,
                                   month,
                                   time_struct.tm_mday,
                                   time_struct.tm_hour,
                                   time_struct.tm_min,
                                   time_struct.tm_sec,
                                   milliseconds_after_second,
                                   sign_local_to_UTC,
                                   zone_hours,
                                   zone_min);
  if (printed == 0) {
    assert(false, "Failed jio_printf");
    return NULL;
  }
  return buffer;
}
jlong os::javaTimeMillis() {
  timeval time;
  int status = gettimeofday(&time, NULL);
  assert(status != -1, "linux error");
  return jlong(time.tv_sec) * 1000  +  jlong(time.tv_usec / 1000);
}

主要是通过gettimeofday来获取时间,然后再将起做格式化输出

所以从性能角度来讲,肯定后者消耗性能更多

那为什么会有第二种做法呢,可以想象一下这个场景,如果一个请求过来处理,处理时间比较慢,那可能会怀疑处理期间是否可能有GC发生,如果我们明确知道请求发起的时间,又知道请求结束的时间,同时通过GC日志还知道GC发生的时间,是不是有理由判断这个请求处理期间其实有GC的影响的,如果仅仅是打印相对时间,你还得先知道JVM是什么时候启动的,再转换成对应的时间点,才能判断,输出完整的时间这对我们结合其他的一些分析场景来说是有挺大意义的

42年前
回复 Nana:

gc日志本身不是很频繁,后面那个就可以,性能问题可忽略,源码在openjdk官方下载

2年前回复
回复 你假笨:

想请教下假笨专家,这2种您会比较推荐使用哪一种。代码实现是从github上获取吗?

2年前回复