src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
author erikj
Tue, 12 Sep 2017 19:03:39 +0200
changeset 47216 71c04702a3d5
parent 47106 hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp@bed18a111b90
child 47799 1772ebf07d1f
permissions -rw-r--r--
8187443: Forest Consolidation: Move files to unified layout Reviewed-by: darcy, ihse
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     1
/*
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
     2
 * Copyright (c) 2013, 2017, Oracle and/or its affiliates. All rights reserved.
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     3
 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     4
 *
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     5
 * This code is free software; you can redistribute it and/or modify it
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     6
 * under the terms of the GNU General Public License version 2 only, as
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     7
 * published by the Free Software Foundation.
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     8
 *
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
     9
 * This code is distributed in the hope that it will be useful, but WITHOUT
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    10
 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    11
 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    12
 * version 2 for more details (a copy is included in the LICENSE file that
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    13
 * accompanied this code).
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    14
 *
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    15
 * You should have received a copy of the GNU General Public License version
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    16
 * 2 along with this work; if not, write to the Free Software Foundation,
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    17
 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    18
 *
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    19
 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    20
 * or visit www.oracle.com if you need additional information or have any
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    21
 * questions.
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    22
 *
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    23
 */
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    24
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    25
#include "precompiled.hpp"
30764
fec48bf5a827 8079792: GC directory structure cleanup
pliden
parents: 30172
diff changeset
    26
#include "gc/g1/g1CollectedHeap.inline.hpp"
fec48bf5a827 8079792: GC directory structure cleanup
pliden
parents: 30172
diff changeset
    27
#include "gc/g1/g1GCPhaseTimes.hpp"
38172
90f405aac699 8155524: HotCardCache shouldn't be part of ConcurrentG1Refine
kbarrett
parents: 37242
diff changeset
    28
#include "gc/g1/g1HotCardCache.hpp"
30764
fec48bf5a827 8079792: GC directory structure cleanup
pliden
parents: 30172
diff changeset
    29
#include "gc/g1/g1StringDedup.hpp"
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
    30
#include "gc/shared/workerDataArray.inline.hpp"
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    31
#include "memory/resourceArea.hpp"
35061
be6025ebffea 8145092: Use Unified Logging for the GC logging
brutisso
parents: 34612
diff changeset
    32
#include "logging/log.hpp"
46701
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
    33
#include "logging/logStream.hpp"
35907
57bdb6243428 8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents: 35887
diff changeset
    34
#include "runtime/timer.hpp"
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    35
#include "runtime/os.hpp"
46681
f17cefd211b4 8183935: G1GCPhaseTimes and G1RootProcessor do not include macros.hpp
mgerdin
parents: 46670
diff changeset
    36
#include "utilities/macros.hpp"
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    37
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
    38
static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
35061
be6025ebffea 8145092: Use Unified Logging for the GC logging
brutisso
parents: 34612
diff changeset
    39
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
    40
G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
    41
  _max_gc_threads(max_gc_threads),
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
    42
  _gc_start_counter(0),
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
    43
  _gc_pause_time_ms(0.0),
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
    44
  _ref_phase_times((GCTimer*)gc_timer, max_gc_threads)
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    45
{
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
    46
  assert(max_gc_threads > 0, "Must have some GC threads");
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    47
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    48
  _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    49
  _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
29694
442c3305ba39 8027962: Per-phase timing measurements for strong roots processing
brutisso
parents: 29680
diff changeset
    50
442c3305ba39 8027962: Per-phase timing measurements for strong roots processing
brutisso
parents: 29680
diff changeset
    51
  // Root scanning phases
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    52
  _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    53
  _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    54
  _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    55
  _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    56
  _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    57
  _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    58
  _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    59
  _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    60
  _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    61
  _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    62
  _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    63
  _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    64
  _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
29694
442c3305ba39 8027962: Per-phase timing measurements for strong roots processing
brutisso
parents: 29680
diff changeset
    65
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    66
  _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
38172
90f405aac699 8155524: HotCardCache shouldn't be part of ConcurrentG1Refine
kbarrett
parents: 37242
diff changeset
    67
  if (G1HotCardCache::default_use_cache()) {
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    68
    _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    69
  } else {
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    70
    _gc_par_phases[ScanHCC] = NULL;
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    71
  }
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    72
  _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    73
  _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
42650
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
    74
#if INCLUDE_AOT
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
    75
  _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
    76
#endif
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    77
  _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    78
  _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    79
  _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    80
  _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    81
  _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    82
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
    83
  _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
46778
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    84
  _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
    85
  _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
46778
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    86
  _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
    87
  _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
46778
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    88
  _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
    89
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    90
  _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
46778
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    91
  _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    92
  _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    93
  _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    94
  _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
f504c6f2eea5 8183121: Add information about scanned and skipped cards during UpdateRS
tschatzl
parents: 46701
diff changeset
    95
  _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, ScanRSSkippedCards);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    96
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
    97
  _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    98
  _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
    99
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   100
  if (UseStringDeduplication) {
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   101
    _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   102
    _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   103
  } else {
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   104
    _gc_par_phases[StringDedupQueueFixup] = NULL;
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   105
    _gc_par_phases[StringDedupTableFixup] = NULL;
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   106
  }
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   107
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   108
  _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   109
  _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   110
  _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
36367
313c87c050f7 8076463: Add logging for the preserve CM referents task
tschatzl
parents: 35907
diff changeset
   111
39979
b17e445924da 8034842: Parallelize the Free CSet phase in G1
tschatzl
parents: 38172
diff changeset
   112
  _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
b17e445924da 8034842: Parallelize the Free CSet phase in G1
tschatzl
parents: 38172
diff changeset
   113
  _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
b17e445924da 8034842: Parallelize the Free CSet phase in G1
tschatzl
parents: 38172
diff changeset
   114
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   115
  _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   116
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   117
  reset();
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   118
}
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   119
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   120
void G1GCPhaseTimes::reset() {
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   121
  _cur_collection_par_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   122
  _cur_collection_code_root_fixup_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   123
  _cur_strong_code_root_purge_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   124
  _cur_evac_fail_recalc_used = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   125
  _cur_evac_fail_remove_self_forwards = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   126
  _cur_string_dedup_fixup_time_ms = 0.0;
46330
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   127
  _cur_prepare_tlab_time_ms = 0.0;
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   128
  _cur_resize_tlab_time_ms = 0.0;
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   129
  _cur_derived_pointer_table_update_time_ms = 0.0;
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   130
  _cur_clear_ct_time_ms = 0.0;
33577
d6c1611973dc 8060017: G1: Report heap sizing time
ecaspole
parents: 33204
diff changeset
   131
  _cur_expand_heap_time_ms = 0.0;
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   132
  _cur_ref_proc_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   133
  _cur_ref_enq_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   134
  _cur_collection_start_sec = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   135
  _root_region_scan_wait_time_ms = 0.0;
34612
ed475e8089ef 8144145: G1GCPhaseTimes should allow externally accounted time
ehelin
parents: 33739
diff changeset
   136
  _external_accounted_time_ms = 0.0;
42048
c1f066b53dd7 8160055: Misplaced call to ClassLoaderDataGraph::clear_claimed_marks during initial mark
jprovino
parents: 39979
diff changeset
   137
  _recorded_clear_claimed_marks_time_ms = 0.0;
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   138
  _recorded_young_cset_choice_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   139
  _recorded_non_young_cset_choice_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   140
  _recorded_redirty_logged_cards_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   141
  _recorded_preserve_cm_referents_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   142
  _recorded_merge_pss_time_ms = 0.0;
46330
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   143
  _recorded_start_new_cset_time_ms = 0.0;
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   144
  _recorded_total_free_cset_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   145
  _recorded_serial_free_cset_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   146
  _cur_fast_reclaim_humongous_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   147
  _cur_fast_reclaim_humongous_register_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   148
  _cur_fast_reclaim_humongous_total = 0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   149
  _cur_fast_reclaim_humongous_candidates = 0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   150
  _cur_fast_reclaim_humongous_reclaimed = 0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   151
  _cur_verify_before_time_ms = 0.0;
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   152
  _cur_verify_after_time_ms = 0.0;
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   153
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   154
  for (int i = 0; i < GCParPhasesSentinel; i++) {
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   155
    if (_gc_par_phases[i] != NULL) {
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   156
      _gc_par_phases[i]->reset();
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   157
    }
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   158
  }
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   159
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   160
  _ref_phase_times.reset();
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   161
}
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   162
42545
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   163
void G1GCPhaseTimes::note_gc_start() {
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   164
  _gc_start_counter = os::elapsed_counter();
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   165
  reset();
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   166
}
af9f4bf4d6d8 8168904: Initialize and reset G1 phase times to zero
ehelin
parents: 42048
diff changeset
   167
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   168
#define ASSERT_PHASE_UNINITIALIZED(phase) \
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   169
    assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   170
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   171
double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   172
  double value = _gc_par_phases[phase]->get(worker);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   173
  if (value != WorkerDataArray<double>::uninitialized()) {
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   174
    return value;
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   175
  }
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   176
  return 0.0;
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   177
}
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   178
13516
f7adc27fb367 7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents: 13288
diff changeset
   179
void G1GCPhaseTimes::note_gc_end() {
35907
57bdb6243428 8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents: 35887
diff changeset
   180
  _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   181
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   182
  double uninitialized = WorkerDataArray<double>::uninitialized();
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   183
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   184
  for (uint i = 0; i < _max_gc_threads; i++) {
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   185
    double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   186
    if (worker_start != uninitialized) {
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   187
      assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   188
      double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   189
      record_time_secs(GCWorkerTotal, i , total_worker_time);
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   190
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   191
      double worker_known_time =
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   192
          worker_time(ExtRootScan, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   193
          + worker_time(SATBFiltering, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   194
          + worker_time(UpdateRS, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   195
          + worker_time(ScanRS, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   196
          + worker_time(CodeRoots, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   197
          + worker_time(ObjCopy, i)
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   198
          + worker_time(Termination, i);
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   199
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   200
      record_time_secs(Other, i, total_worker_time - worker_known_time);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   201
    } else {
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   202
      // Make sure all slots are uninitialized since this thread did not seem to have been started
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   203
      ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   204
      ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   205
      ASSERT_PHASE_UNINITIALIZED(SATBFiltering);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   206
      ASSERT_PHASE_UNINITIALIZED(UpdateRS);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   207
      ASSERT_PHASE_UNINITIALIZED(ScanRS);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   208
      ASSERT_PHASE_UNINITIALIZED(CodeRoots);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   209
      ASSERT_PHASE_UNINITIALIZED(ObjCopy);
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   210
      ASSERT_PHASE_UNINITIALIZED(Termination);
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   211
    }
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   212
  }
23472
35e93890ed88 8029075: String deduplication in G1
pliden
parents: 23455
diff changeset
   213
}
35e93890ed88 8029075: String deduplication in G1
pliden
parents: 23455
diff changeset
   214
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   215
#undef ASSERT_PHASE_UNINITIALIZED
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   216
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   217
// record the time a phase took in seconds
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   218
void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   219
  _gc_par_phases[phase]->set(worker_i, secs);
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   220
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   221
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   222
// add a number of seconds to a phase
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   223
void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   224
  _gc_par_phases[phase]->add(worker_i, secs);
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   225
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   226
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   227
void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   228
  _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   229
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   230
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   231
// return the average time for a phase in milliseconds
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   232
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   233
  return _gc_par_phases[phase]->average() * 1000.0;
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   234
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   235
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   236
size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   237
  assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   238
  return _gc_par_phases[phase]->thread_work_items(index)->sum();
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   239
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   240
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   241
template <class T>
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   242
void G1GCPhaseTimes::details(T* phase, const char* indent) const {
46701
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   243
  LogTarget(Trace, gc, phases, task) lt;
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   244
  if (lt.is_enabled()) {
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   245
    LogStream ls(lt);
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   246
    ls.print("%s", indent);
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   247
    phase->print_details_on(&ls);
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   248
  }
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   249
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   250
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   251
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   252
  out->print("%s", Indents[indent]);
37214
bc4e0e0995e6 8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents: 37209
diff changeset
   253
  phase->print_summary_on(out, print_sum);
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   254
  details(phase, Indents[indent]);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   255
46571
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   256
  for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   257
    WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   258
    if (work_items != NULL) {
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   259
      out->print("%s", Indents[indent + 1]);
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   260
      work_items->print_summary_on(out, true);
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   261
      details(work_items, Indents[indent + 1]);
c70b36f0730d 8178148: Log more detailed information about scan rs phase
tschatzl
parents: 46353
diff changeset
   262
    }
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   263
  }
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   264
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   265
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   266
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) const {
46701
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   267
  LogTarget(Debug, gc, phases) lt;
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   268
  if (lt.is_enabled()) {
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   269
    ResourceMark rm;
46701
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   270
    LogStream ls(lt);
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   271
    log_phase(phase, 2, &ls, true);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   272
  }
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   273
}
35061
be6025ebffea 8145092: Use Unified Logging for the GC logging
brutisso
parents: 34612
diff changeset
   274
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   275
void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
46701
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   276
  LogTarget(Trace, gc, phases) lt;
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   277
  if (lt.is_enabled()) {
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   278
    LogStream ls(lt);
f559541c0daa 8181917: Refactor UL LogStreams to avoid using resource area
stuefe
parents: 46681
diff changeset
   279
    log_phase(phase, 3, &ls, print_sum);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   280
  }
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   281
}
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   282
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   283
#define TIME_FORMAT "%.1lfms"
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   284
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   285
void G1GCPhaseTimes::info_time(const char* name, double value) const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   286
  log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   287
}
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   288
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   289
void G1GCPhaseTimes::debug_time(const char* name, double value) const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   290
  log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   291
}
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   292
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   293
void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   294
  LogTarget(Debug, gc, phases) lt;
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   295
  LogTarget(Debug, gc, phases, ref) lt2;
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   296
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   297
  if (lt.is_enabled()) {
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   298
    LogStream ls(lt);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   299
    ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   300
  } else if (lt2.is_enabled()) {
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   301
    LogStream ls(lt2);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   302
    ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   303
  }
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   304
}
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   305
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   306
void G1GCPhaseTimes::trace_time(const char* name, double value) const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   307
  log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   308
}
35061
be6025ebffea 8145092: Use Unified Logging for the GC logging
brutisso
parents: 34612
diff changeset
   309
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   310
void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   311
  log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   312
}
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   313
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   314
double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   315
  const double sum_ms = _root_region_scan_wait_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   316
                        _recorded_young_cset_choice_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   317
                        _recorded_non_young_cset_choice_time_ms +
46353
1df99120f158 8176885: Clear Claimed Marks log message at wrong location in the log
tschatzl
parents: 46340
diff changeset
   318
                        _cur_fast_reclaim_humongous_register_time_ms +
1df99120f158 8176885: Clear Claimed Marks log message at wrong location in the log
tschatzl
parents: 46340
diff changeset
   319
                        _recorded_clear_claimed_marks_time_ms;
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   320
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   321
  info_time("Pre Evacuate Collection Set", sum_ms);
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   322
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   323
  if (_root_region_scan_wait_time_ms > 0.0) {
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   324
    debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   325
  }
46330
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   326
  debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   327
  debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   328
  if (G1EagerReclaimHumongousObjects) {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   329
    debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   330
    trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   331
    trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   332
  }
27251
7d667f91ec8d 6979279: remove special-case code for ParallelGCThreads==0
mlarsson
parents: 26701
diff changeset
   333
46353
1df99120f158 8176885: Clear Claimed Marks log message at wrong location in the log
tschatzl
parents: 46340
diff changeset
   334
  if (_recorded_clear_claimed_marks_time_ms > 0.0) {
1df99120f158 8176885: Clear Claimed Marks log message at wrong location in the log
tschatzl
parents: 46340
diff changeset
   335
    debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
1df99120f158 8176885: Clear Claimed Marks log message at wrong location in the log
tschatzl
parents: 46340
diff changeset
   336
  }
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   337
  return sum_ms;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   338
}
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   339
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   340
double G1GCPhaseTimes::print_evacuate_collection_set() const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   341
  const double sum_ms = _cur_collection_par_time_ms;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   342
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   343
  info_time("Evacuate Collection Set", sum_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   344
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   345
  trace_phase(_gc_par_phases[GCWorkerStart], false);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   346
  debug_phase(_gc_par_phases[ExtRootScan]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   347
  for (int i = ThreadRoots; i <= SATBFiltering; i++) {
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   348
    trace_phase(_gc_par_phases[i]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   349
  }
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   350
  debug_phase(_gc_par_phases[UpdateRS]);
38172
90f405aac699 8155524: HotCardCache shouldn't be part of ConcurrentG1Refine
kbarrett
parents: 37242
diff changeset
   351
  if (G1HotCardCache::default_use_cache()) {
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   352
    trace_phase(_gc_par_phases[ScanHCC]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   353
  }
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   354
  debug_phase(_gc_par_phases[ScanRS]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   355
  debug_phase(_gc_par_phases[CodeRoots]);
42650
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
   356
#if INCLUDE_AOT
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
   357
  debug_phase(_gc_par_phases[AOTCodeRoots]);
1f304d0c888b 8171008: Integrate AOT compiler into JDK
kvn
parents: 42557
diff changeset
   358
#endif
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   359
  debug_phase(_gc_par_phases[ObjCopy]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   360
  debug_phase(_gc_par_phases[Termination]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   361
  debug_phase(_gc_par_phases[Other]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   362
  debug_phase(_gc_par_phases[GCWorkerTotal]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   363
  trace_phase(_gc_par_phases[GCWorkerEnd], false);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   364
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   365
  return sum_ms;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   366
}
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   367
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   368
double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   369
  const double evac_fail_handling = _cur_evac_fail_recalc_used +
46670
55a3c36b64b2 8183539: Remove G1RemSet::_into_cset_dirty_card_queue_set
ehelin
parents: 46571
diff changeset
   370
                                    _cur_evac_fail_remove_self_forwards;
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   371
  const double sum_ms = evac_fail_handling +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   372
                        _cur_collection_code_root_fixup_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   373
                        _recorded_preserve_cm_referents_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   374
                        _cur_ref_proc_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   375
                        _cur_ref_enq_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   376
                        _cur_clear_ct_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   377
                        _recorded_merge_pss_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   378
                        _cur_strong_code_root_purge_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   379
                        _recorded_redirty_logged_cards_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   380
                        _recorded_total_free_cset_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   381
                        _cur_fast_reclaim_humongous_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   382
                        _cur_expand_heap_time_ms +
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   383
                        _cur_string_dedup_fixup_time_ms;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   384
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   385
  info_time("Post Evacuate Collection Set", sum_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   386
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   387
  debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   388
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   389
  debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   390
  trace_phase(_gc_par_phases[PreserveCMReferents]);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   391
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   392
  debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   393
  _ref_phase_times.print_all_references(2, false);
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   394
23472
35e93890ed88 8029075: String deduplication in G1
pliden
parents: 23455
diff changeset
   395
  if (G1StringDedup::is_enabled()) {
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   396
    debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   397
    debug_phase(_gc_par_phases[StringDedupQueueFixup]);
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   398
    debug_phase(_gc_par_phases[StringDedupTableFixup]);
23472
35e93890ed88 8029075: String deduplication in G1
pliden
parents: 23455
diff changeset
   399
  }
36374
613f27cc37b9 8150068: Log the main G1 phases at info level
brutisso
parents: 36368
diff changeset
   400
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   401
  debug_time("Clear Card Table", _cur_clear_ct_time_ms);
39979
b17e445924da 8034842: Parallelize the Free CSet phase in G1
tschatzl
parents: 38172
diff changeset
   402
23455
e541bff96524 8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents: 23454
diff changeset
   403
  if (G1CollectedHeap::heap()->evacuation_failed()) {
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   404
    debug_time("Evacuation Failure", evac_fail_handling);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   405
    trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   406
    trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
23455
e541bff96524 8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents: 23454
diff changeset
   407
  }
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   408
46795
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   409
  debug_time_for_reference("Reference Enqueuing", _cur_ref_enq_time_ms);
623a5e42deb6 8173335: Improve logging for j.l.ref.reference processing
sangheki
parents: 46778
diff changeset
   410
  _ref_phase_times.print_enqueue_phase(2, false);
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   411
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   412
  debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   413
  debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   414
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   415
  debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
46340
9c2be834d6e3 8176881: DerivedPointerTable Update log message in wrong order in regards to Redirty Cards
tschatzl
parents: 46330
diff changeset
   416
  trace_phase(_gc_par_phases[RedirtyCards]);
46330
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   417
#if defined(COMPILER2) || INCLUDE_JVMCI
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   418
  debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   419
#endif
42048
c1f066b53dd7 8160055: Misplaced call to ClassLoaderDataGraph::clear_claimed_marks during initial mark
jprovino
parents: 39979
diff changeset
   420
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   421
  debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   422
  trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   423
  trace_phase(_gc_par_phases[YoungFreeCSet]);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   424
  trace_phase(_gc_par_phases[NonYoungFreeCSet]);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   425
28379
e6784fc8fff2 8048179: Early reclaim of large objects that are referenced by a few objects
tschatzl
parents: 27251
diff changeset
   426
  if (G1EagerReclaimHumongousObjects) {
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   427
    debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   428
    trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
25889
221296ac4359 8027959: Early reclamation of large objects in G1
tschatzl
parents: 25492
diff changeset
   429
  }
46330
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   430
  debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   431
  if (UseTLAB && ResizeTLAB) {
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   432
    debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
40e2718fac10 8155094: Add logging for long lasting methods found in JDK-8152948
tschatzl
parents: 42650
diff changeset
   433
  }
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   434
  debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   435
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   436
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   437
  return sum_ms;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   438
}
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   439
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   440
void G1GCPhaseTimes::print_other(double accounted_ms) const {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   441
  info_time("Other", _gc_pause_time_ms - accounted_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   442
}
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   443
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   444
void G1GCPhaseTimes::print() {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   445
  note_gc_end();
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   446
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   447
  if (_cur_verify_before_time_ms > 0.0) {
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   448
    debug_time("Verify Before", _cur_verify_before_time_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   449
  }
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   450
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   451
  double accounted_ms = 0.0;
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   452
  accounted_ms += print_pre_evacuate_collection_set();
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   453
  accounted_ms += print_evacuate_collection_set();
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   454
  accounted_ms += print_post_evacuate_collection_set();
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   455
  print_other(accounted_ms);
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   456
13516
f7adc27fb367 7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents: 13288
diff changeset
   457
  if (_cur_verify_after_time_ms > 0.0) {
42557
ee4c7799659d 8167679: G1 phase logging is messy
ehelin
parents: 42545
diff changeset
   458
    debug_time("Verify After", _cur_verify_after_time_ms);
13516
f7adc27fb367 7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents: 13288
diff changeset
   459
  }
13288
331d5b6725f3 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff changeset
   460
}
29680
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   461
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   462
G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   463
    _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   464
  if (_phase_times != NULL) {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   465
    _start_time = os::elapsedTime();
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   466
  }
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   467
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   468
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   469
G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   470
  if (_phase_times != NULL) {
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   471
    _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   472
  }
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   473
}
e5203ed6d805 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents: 28379
diff changeset
   474