2

Linux サーバー上に verbose:gc がオンの Glassfish サーバーがあり、gc.log ファイルに出力されます。

フラグを使用します-XX:+PrintGCDetails。生成されたファイルには、次のような行が含まれています。

14.796: [GC [PSYoungGen: 432125K->45845K(454336K)] 537435K->153491K(624832K), 0.0304470 secs] [Times: user=0.12 sys=0.01, real=0.02 secs]
15.337: [GC [PSYoungGen: 269819K->25031K(464768K)] 377465K->154113K(635264K), 0.0361400 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]
15.373: [Full GC (System) [PSYoungGen: 25031K->0K(464768K)] [PSOldGen: 129081K->123718K(170496K)] 154113K->123718K(635264K) [PSPermGen: 92038K->92038K(184384K)], 0.3855460 secs]

ご覧のとおり、最後の行にはその[Times: ...]部分が含まれていません。次の GC イベントが発生すると[Times: ...]、前の行の一部が書き込まれ、次に別の部分的な行が書き込まれるため、GC イベント行はログ ファイルに完全には書き込まれません。

14.796: [GC [PSYoungGen: 432125K->45845K(454336K)] 537435K->153491K(624832K), 0.0304470 secs] [Times: user=0.12 sys=0.01, real=0.02 secs]
15.337: [GC [PSYoungGen: 269819K->25031K(464768K)] 377465K->154113K(635264K), 0.0361400 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]
15.373: [Full GC (System) [PSYoungGen: 25031K->0K(464768K)] [PSOldGen: 129081K->123718K(170496K)] 154113K->123718K(635264K) [PSPermGen: 92038K->92038K(184384K)], 0.3855460 secs] [Times: user=0.38 sys=0.01, real=0.39 secs]
3617.352: [GC [PSYoungGen: 431872K->8052K(439936K)] 585800K->161981K(718144K), 0.0085710 secs]

行が終了していないため、改行が存在しないため、行は次のようなツールに表示されませんmultitail

フラグを使用すると、-XX:+PrintGCこの問題はなくなります。しかし、完全な詳細が必要なため、これは良い解決策ではありません。

Linux で動作する JVM バージョン:

java version "1.6.0_26"
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)

問題は、JVM に強制的にログ行を書き込むこと (一種のフラッシュ トリック) は可能かということです。または、最後の部分なしで GC の詳細を取得することは可能ですか?

4

1 に答える 1

2

-XX:+PrintGCDetailsフラッシュしていないように見えるOpenJDK 6/7ソースをチェックする

TraceCPUTime::~TraceCPUTime() {
  if (_active) {
    bool valid = false;
    if (!_error) {
      double real_secs;                 // walk clock time
      double system_secs;               // system time
      double user_secs;                 // user time for all threads

      double real_time, user_time, system_time;
      valid = os::getTimesSecs(&real_time, &user_time, &system_time);
      if (valid) {

        user_secs = user_time - _starting_user_time;
        system_secs = system_time - _starting_system_time;
        real_secs = real_time - _starting_real_time;

        _logfile->print(" [Times: user=%3.2f sys=%3.2f, real=%3.2f secs] ",
          user_secs, system_secs, real_secs);

      } else {
        _logfile->print("[Invalid result in TraceCPUTime]");
      }
    } else {
      _logfile->print("[Error in TraceCPUTime]");
    }
     if (_print_cr) {
      _logfile->print_cr("");
    }
  }
}

このバグレポートのおかげで、OpenJDK 8 で修正されました。

TraceCPUTime::~TraceCPUTime() {
  if (_active) {
    bool valid = false;
    if (!_error) {
      double real_secs;                 // walk clock time
      double system_secs;               // system time
      double user_secs;                 // user time for all threads

      double real_time, user_time, system_time;
      valid = os::getTimesSecs(&real_time, &user_time, &system_time);
      if (valid) {

        user_secs = user_time - _starting_user_time;
        system_secs = system_time - _starting_system_time;
        real_secs = real_time - _starting_real_time;

        _logfile->print(" [Times: user=%3.2f sys=%3.2f, real=%3.2f secs] ",
           user_secs, system_secs, real_secs);

      } else {
        _logfile->print("[Invalid result in TraceCPUTime]");
      }
    } else {
      _logfile->print("[Error in TraceCPUTime]");
    }
    if (_print_cr) {
      _logfile->print_cr("");
    }
    _logfile->flush();
  }
}

誰かが 6/7 に対して提出した場合、バックポートされる可能性があります。

于 2013-03-05T17:01:07.543 に答える