From 14eb5ad0dc987ffe3621f4eeeebeb6b5a2cd691b Mon Sep 17 00:00:00 2001 From: Sangheon Kim Date: Thu, 8 Sep 2022 18:20:03 +0000 Subject: [PATCH] 8291753: Add JFR event for GC CPU Time Reviewed-by: tschatzl, ayang --- src/hotspot/share/gc/g1/g1CollectedHeap.cpp | 4 +- src/hotspot/share/gc/g1/g1ConcurrentMark.hpp | 2 + src/hotspot/share/gc/g1/g1FullCollector.cpp | 5 +- src/hotspot/share/gc/g1/g1FullCollector.hpp | 7 +- src/hotspot/share/gc/g1/g1FullGCScope.cpp | 9 +- src/hotspot/share/gc/g1/g1FullGCScope.hpp | 5 +- src/hotspot/share/gc/g1/g1VMOperations.cpp | 5 +- .../share/gc/parallel/psParallelCompact.cpp | 2 +- src/hotspot/share/gc/parallel/psScavenge.cpp | 2 +- .../share/gc/serial/defNewGeneration.cpp | 17 ++-- .../share/gc/serial/defNewGeneration.hpp | 5 ++ src/hotspot/share/gc/shared/gcTrace.cpp | 10 ++- src/hotspot/share/gc/shared/gcTrace.hpp | 6 +- src/hotspot/share/gc/shared/gcTraceSend.cpp | 17 +++- src/hotspot/share/gc/shared/gcTraceTime.cpp | 26 +++--- src/hotspot/share/gc/shared/gcTraceTime.hpp | 9 +- .../share/gc/shared/genCollectedHeap.cpp | 5 +- src/hotspot/share/jfr/metadata/metadata.xml | 8 ++ src/jdk.jfr/share/conf/jfr/default.jfc | 12 ++- src/jdk.jfr/share/conf/jfr/profile.jfc | 16 ++-- .../jfr/event/gc/collection/GCEventAll.java | 10 ++- .../event/gc/detailed/TestGCCPUTimeEvent.java | 88 +++++++++++++++++++ test/lib/jdk/test/lib/jfr/EventNames.java | 1 + 23 files changed, 216 insertions(+), 55 deletions(-) create mode 100644 test/jdk/jdk/jfr/event/gc/detailed/TestGCCPUTimeEvent.java diff --git a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp index 37aed2374ff6..e8c4e0fad1ba 100644 --- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp +++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp @@ -1099,7 +1099,7 @@ bool G1CollectedHeap::do_full_collection(bool explicit_gc, G1FullGCMark gc_mark; GCTraceTime(Info, gc) tm("Pause Full", NULL, gc_cause(), true); - G1FullCollector collector(this, explicit_gc, do_clear_all_soft_refs, do_maximal_compaction); + G1FullCollector collector(this, explicit_gc, do_clear_all_soft_refs, do_maximal_compaction, gc_mark.tracer()); collector.prepare_collection(); collector.collect(); @@ -2854,7 +2854,7 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus GCIdMark gc_id_mark; SvcGCMarker sgcm(SvcGCMarker::MINOR); - GCTraceCPUTime tcpu; + GCTraceCPUTime tcpu(_gc_tracer_stw); _bytes_used_during_gc = 0; diff --git a/src/hotspot/share/gc/g1/g1ConcurrentMark.hpp b/src/hotspot/share/gc/g1/g1ConcurrentMark.hpp index cb574f9df095..8cf593ff59fd 100644 --- a/src/hotspot/share/gc/g1/g1ConcurrentMark.hpp +++ b/src/hotspot/share/gc/g1/g1ConcurrentMark.hpp @@ -608,6 +608,8 @@ class G1ConcurrentMark : public CHeapObj { ConcurrentGCTimer* gc_timer_cm() const { return _gc_timer_cm; } + G1OldTracer* gc_tracer_cm() const { return _gc_tracer_cm; } + private: // Rebuilds the remembered sets for chosen regions in parallel and concurrently // to the application. Also scrubs dead objects to ensure region is parsable. diff --git a/src/hotspot/share/gc/g1/g1FullCollector.cpp b/src/hotspot/share/gc/g1/g1FullCollector.cpp index 3287a7916962..39a65eedc154 100644 --- a/src/hotspot/share/gc/g1/g1FullCollector.cpp +++ b/src/hotspot/share/gc/g1/g1FullCollector.cpp @@ -111,9 +111,10 @@ uint G1FullCollector::calc_active_workers() { G1FullCollector::G1FullCollector(G1CollectedHeap* heap, bool explicit_gc, bool clear_soft_refs, - bool do_maximal_compaction) : + bool do_maximal_compaction, + G1FullGCTracer* tracer) : _heap(heap), - _scope(heap->monitoring_support(), explicit_gc, clear_soft_refs, do_maximal_compaction), + _scope(heap->monitoring_support(), explicit_gc, clear_soft_refs, do_maximal_compaction, tracer), _num_workers(calc_active_workers()), _oop_queue_set(_num_workers), _array_queue_set(_num_workers), diff --git a/src/hotspot/share/gc/g1/g1FullCollector.hpp b/src/hotspot/share/gc/g1/g1FullCollector.hpp index 5f4d7d22958b..b163a8eca8dc 100644 --- a/src/hotspot/share/gc/g1/g1FullCollector.hpp +++ b/src/hotspot/share/gc/g1/g1FullCollector.hpp @@ -63,9 +63,11 @@ class G1FullGCSubjectToDiscoveryClosure: public BoolObjectClosure { // to have the same structure as the Young GC logging. class G1FullGCMark : StackObj { GCIdMark _gc_id; + G1FullGCTracer _tracer; GCTraceCPUTime _cpu_time; public: - G1FullGCMark() : _gc_id(), _cpu_time() { } + G1FullGCMark() : _gc_id(), _tracer(), _cpu_time(&_tracer) { } + G1FullGCTracer* tracer() { return &_tracer; } }; // The G1FullCollector holds data associated with the current Full GC. @@ -96,7 +98,8 @@ class G1FullCollector : StackObj { G1FullCollector(G1CollectedHeap* heap, bool explicit_gc, bool clear_soft_refs, - bool do_maximal_compaction); + bool do_maximal_compaction, + G1FullGCTracer* tracer); ~G1FullCollector(); void prepare_collection(); diff --git a/src/hotspot/share/gc/g1/g1FullGCScope.cpp b/src/hotspot/share/gc/g1/g1FullGCScope.cpp index de3beb4c2782..70621ac34493 100644 --- a/src/hotspot/share/gc/g1/g1FullGCScope.cpp +++ b/src/hotspot/share/gc/g1/g1FullGCScope.cpp @@ -39,15 +39,16 @@ G1FullGCJFRTracerMark::~G1FullGCJFRTracerMark() { G1FullGCScope::G1FullGCScope(G1MonitoringSupport* monitoring_support, bool explicit_gc, bool clear_soft, - bool do_maximal_compaction) : + bool do_maximal_compaction, + G1FullGCTracer* tracer) : _rm(), _explicit_gc(explicit_gc), _g1h(G1CollectedHeap::heap()), _svc_marker(SvcGCMarker::FULL), _timer(), - _tracer(), + _tracer(tracer), _active(), - _tracer_mark(&_timer, &_tracer), + _tracer_mark(&_timer, _tracer), _soft_refs(clear_soft, _g1h->soft_ref_policy()), _monitoring_scope(monitoring_support, true /* full_gc */, true /* all_memory_pools_affected */), _heap_printer(_g1h), @@ -68,7 +69,7 @@ STWGCTimer* G1FullGCScope::timer() { } G1FullGCTracer* G1FullGCScope::tracer() { - return &_tracer; + return _tracer; } size_t G1FullGCScope::region_compaction_threshold() const { diff --git a/src/hotspot/share/gc/g1/g1FullGCScope.hpp b/src/hotspot/share/gc/g1/g1FullGCScope.hpp index a6e079f4d63d..80dce2535ddf 100644 --- a/src/hotspot/share/gc/g1/g1FullGCScope.hpp +++ b/src/hotspot/share/gc/g1/g1FullGCScope.hpp @@ -51,7 +51,7 @@ class G1FullGCScope : public StackObj { G1CollectedHeap* _g1h; SvcGCMarker _svc_marker; STWGCTimer _timer; - G1FullGCTracer _tracer; + G1FullGCTracer* _tracer; IsGCActiveMark _active; G1FullGCJFRTracerMark _tracer_mark; ClearedAllSoftRefs _soft_refs; @@ -63,7 +63,8 @@ class G1FullGCScope : public StackObj { G1FullGCScope(G1MonitoringSupport* monitoring_support, bool explicit_gc, bool clear_soft, - bool do_maximal_compaction); + bool do_maximal_compaction, + G1FullGCTracer* tracer); bool is_explicit_gc(); bool should_clear_soft_refs(); diff --git a/src/hotspot/share/gc/g1/g1VMOperations.cpp b/src/hotspot/share/gc/g1/g1VMOperations.cpp index a4633f9c2b9f..cd7f09ac2ef3 100644 --- a/src/hotspot/share/gc/g1/g1VMOperations.cpp +++ b/src/hotspot/share/gc/g1/g1VMOperations.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2021, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -27,6 +27,7 @@ #include "gc/g1/g1ConcurrentMarkThread.inline.hpp" #include "gc/g1/g1Policy.hpp" #include "gc/g1/g1VMOperations.hpp" +#include "gc/g1/g1Trace.hpp" #include "gc/shared/concurrentGCBreakpoints.hpp" #include "gc/shared/gcCause.hpp" #include "gc/shared/gcId.hpp" @@ -172,8 +173,8 @@ void VM_G1CollectForAllocation::doit() { void VM_G1PauseConcurrent::doit() { GCIdMark gc_id_mark(_gc_id); - GCTraceCPUTime tcpu; G1CollectedHeap* g1h = G1CollectedHeap::heap(); + GCTraceCPUTime tcpu(g1h->concurrent_mark()->gc_tracer_cm()); // GCTraceTime(...) only supports sub-phases, so a more verbose version // is needed when we report the top-level pause phase. diff --git a/src/hotspot/share/gc/parallel/psParallelCompact.cpp b/src/hotspot/share/gc/parallel/psParallelCompact.cpp index 03249c85e919..fa4c35c30032 100644 --- a/src/hotspot/share/gc/parallel/psParallelCompact.cpp +++ b/src/hotspot/share/gc/parallel/psParallelCompact.cpp @@ -1742,7 +1742,7 @@ bool PSParallelCompact::invoke_no_policy(bool maximum_heap_compaction) { Threads::number_of_non_daemon_threads()); ParallelScavengeHeap::heap()->workers().set_active_workers(active_workers); - GCTraceCPUTime tcpu; + GCTraceCPUTime tcpu(&_gc_tracer); GCTraceTime(Info, gc) tm("Pause Full", NULL, gc_cause, true); heap->pre_full_gc_dump(&_gc_timer); diff --git a/src/hotspot/share/gc/parallel/psScavenge.cpp b/src/hotspot/share/gc/parallel/psScavenge.cpp index 717cac93a268..428e09f1bdc0 100644 --- a/src/hotspot/share/gc/parallel/psScavenge.cpp +++ b/src/hotspot/share/gc/parallel/psScavenge.cpp @@ -405,7 +405,7 @@ bool PSScavenge::invoke_no_policy() { { ResourceMark rm; - GCTraceCPUTime tcpu; + GCTraceCPUTime tcpu(&_gc_tracer); GCTraceTime(Info, gc) tm("Pause Young", NULL, gc_cause, true); TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(heap->young_gc_manager(), gc_cause); diff --git a/src/hotspot/share/gc/serial/defNewGeneration.cpp b/src/hotspot/share/gc/serial/defNewGeneration.cpp index d293bc684a2c..709386d19fce 100644 --- a/src/hotspot/share/gc/serial/defNewGeneration.cpp +++ b/src/hotspot/share/gc/serial/defNewGeneration.cpp @@ -186,6 +186,8 @@ DefNewGeneration::DefNewGeneration(ReservedSpace rs, _pretenure_size_threshold_words = PretenureSizeThreshold >> LogHeapWordSize; _gc_timer = new (ResourceObj::C_HEAP, mtGC) STWGCTimer(); + + _gc_tracer = new (ResourceObj::C_HEAP, mtGC) DefNewTracer(); } void DefNewGeneration::compute_space_boundaries(uintx minimum_eden_size, @@ -528,8 +530,7 @@ void DefNewGeneration::collect(bool full, SerialHeap* heap = SerialHeap::heap(); _gc_timer->register_gc_start(); - DefNewTracer gc_tracer; - gc_tracer.report_gc_start(heap->gc_cause(), _gc_timer->gc_start()); + _gc_tracer->report_gc_start(heap->gc_cause(), _gc_timer->gc_start()); _old_gen = heap->old_gen(); @@ -547,7 +548,7 @@ void DefNewGeneration::collect(bool full, GCTraceTime(Trace, gc, phases) tm("DefNew", NULL, heap->gc_cause()); - heap->trace_heap_before_gc(&gc_tracer); + heap->trace_heap_before_gc(_gc_tracer); // These can be shared for all code paths IsAliveClosure is_alive(this); @@ -590,8 +591,8 @@ void DefNewGeneration::collect(bool full, ReferenceProcessorPhaseTimes pt(_gc_timer, rp->max_num_queues()); SerialGCRefProcProxyTask task(is_alive, keep_alive, evacuate_followers); const ReferenceProcessorStats& stats = rp->process_discovered_references(task, pt); - gc_tracer.report_gc_reference_stats(stats); - gc_tracer.report_tenuring_threshold(tenuring_threshold()); + _gc_tracer->report_gc_reference_stats(stats); + _gc_tracer->report_tenuring_threshold(tenuring_threshold()); pt.print_all_references(); assert(heap->no_allocs_since_save_marks(), "save marks have not been newly set."); @@ -645,7 +646,7 @@ void DefNewGeneration::collect(bool full, // Inform the next generation that a promotion failure occurred. _old_gen->promotion_failure_occurred(); - gc_tracer.report_promotion_failed(_promotion_failed_info); + _gc_tracer->report_promotion_failed(_promotion_failed_info); // Reset the PromotionFailureALot counters. NOT_PRODUCT(heap->reset_promotion_should_fail();) @@ -653,11 +654,11 @@ void DefNewGeneration::collect(bool full, // We should have processed and cleared all the preserved marks. _preserved_marks_set.reclaim(); - heap->trace_heap_after_gc(&gc_tracer); + heap->trace_heap_after_gc(_gc_tracer); _gc_timer->register_gc_end(); - gc_tracer.report_gc_end(_gc_timer->gc_end(), _gc_timer->time_partitions()); + _gc_tracer->report_gc_end(_gc_timer->gc_end(), _gc_timer->time_partitions()); } void DefNewGeneration::init_assuming_no_promotion_failure() { diff --git a/src/hotspot/share/gc/serial/defNewGeneration.hpp b/src/hotspot/share/gc/serial/defNewGeneration.hpp index 2b794d30089a..be742e284c35 100644 --- a/src/hotspot/share/gc/serial/defNewGeneration.hpp +++ b/src/hotspot/share/gc/serial/defNewGeneration.hpp @@ -41,6 +41,7 @@ class ContiguousSpace; class CSpaceCounters; class DefNewYoungerGenClosure; class DefNewScanClosure; +class DefNewTracer; class ScanWeakRefClosure; class SerialHeap; class STWGCTimer; @@ -141,6 +142,8 @@ class DefNewGeneration: public Generation { STWGCTimer* _gc_timer; + DefNewTracer* _gc_tracer; + StringDedup::Requests _string_dedup_requests; enum SomeProtectedConstants { @@ -327,6 +330,8 @@ class DefNewGeneration: public Generation { return _promo_failure_scan_stack.is_empty(); } + DefNewTracer* gc_tracer() const { return _gc_tracer; } + protected: // If clear_space is true, clear the survivor spaces. Eden is // cleared if the minimum size of eden is 0. If mangle_space diff --git a/src/hotspot/share/gc/shared/gcTrace.cpp b/src/hotspot/share/gc/shared/gcTrace.cpp index aeddbee841c7..19fc54956ec3 100644 --- a/src/hotspot/share/gc/shared/gcTrace.cpp +++ b/src/hotspot/share/gc/shared/gcTrace.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2020, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -37,6 +37,10 @@ #include "utilities/macros.hpp" #include "utilities/ticks.hpp" +bool GCTracer::should_report_cpu_time_event() const { + return should_send_cpu_time_event(); +} + void GCTracer::report_gc_start_impl(GCCause::Cause cause, const Ticks& timestamp) { _shared_gc_info.set_cause(cause); _shared_gc_info.set_start_timestamp(timestamp); @@ -59,6 +63,10 @@ void GCTracer::report_gc_end(const Ticks& timestamp, TimePartitions* time_partit report_gc_end_impl(timestamp, time_partitions); } +void GCTracer::report_cpu_time_event(double user_time, double system_time, double real_time) const { + send_cpu_time_event(user_time, system_time, real_time); +} + void GCTracer::report_gc_reference_stats(const ReferenceProcessorStats& rps) const { send_reference_stats_event(REF_SOFT, rps.soft_count()); send_reference_stats_event(REF_WEAK, rps.weak_count()); diff --git a/src/hotspot/share/gc/shared/gcTrace.hpp b/src/hotspot/share/gc/shared/gcTrace.hpp index 75273418cff2..49286ab8c3af 100644 --- a/src/hotspot/share/gc/shared/gcTrace.hpp +++ b/src/hotspot/share/gc/shared/gcTrace.hpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2021, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -96,12 +96,14 @@ class GCTracer : public ResourceObj { SharedGCInfo _shared_gc_info; public: + bool should_report_cpu_time_event() const; void report_gc_start(GCCause::Cause cause, const Ticks& timestamp); void report_gc_end(const Ticks& timestamp, TimePartitions* time_partitions); void report_gc_heap_summary(GCWhen::Type when, const GCHeapSummary& heap_summary) const; void report_metaspace_summary(GCWhen::Type when, const MetaspaceSummary& metaspace_summary) const; void report_gc_reference_stats(const ReferenceProcessorStats& rp) const; void report_object_count_after_gc(BoolObjectClosure* object_filter) NOT_SERVICES_RETURN; + void report_cpu_time_event(double user_time, double system_time, double real_time) const; protected: GCTracer(GCName name) : _shared_gc_info(name) {} @@ -109,12 +111,14 @@ class GCTracer : public ResourceObj { virtual void report_gc_end_impl(const Ticks& timestamp, TimePartitions* time_partitions); private: + bool should_send_cpu_time_event() const; void send_garbage_collection_event() const; void send_gc_heap_summary_event(GCWhen::Type when, const GCHeapSummary& heap_summary) const; void send_meta_space_summary_event(GCWhen::Type when, const MetaspaceSummary& meta_space_summary) const; void send_metaspace_chunk_free_list_summary(GCWhen::Type when, Metaspace::MetadataType mdtype, const MetaspaceChunkFreeListSummary& summary) const; void send_reference_stats_event(ReferenceType type, size_t count) const; void send_phase_events(TimePartitions* time_partitions) const; + void send_cpu_time_event(double user_time, double system_time, double real_time) const; }; class YoungGCTracer : public GCTracer { diff --git a/src/hotspot/share/gc/shared/gcTraceSend.cpp b/src/hotspot/share/gc/shared/gcTraceSend.cpp index d57af7ceaf12..5ee37592f286 100644 --- a/src/hotspot/share/gc/shared/gcTraceSend.cpp +++ b/src/hotspot/share/gc/shared/gcTraceSend.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2021, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -36,6 +36,10 @@ typedef uintptr_t TraceAddress; +bool GCTracer::should_send_cpu_time_event() const { + return EventGCCPUTime::is_enabled(); +} + void GCTracer::send_garbage_collection_event() const { EventGarbageCollection event(UNTIMED); if (event.should_commit()) { @@ -50,6 +54,17 @@ void GCTracer::send_garbage_collection_event() const { } } +void GCTracer::send_cpu_time_event(double user_time, double system_time, double real_time) const { + EventGCCPUTime e; + if (e.should_commit()) { + e.set_gcId(GCId::current()); + e.set_userTime((size_t)(user_time * NANOUNITS)); + e.set_systemTime((size_t)(system_time * NANOUNITS)); + e.set_realTime((size_t)(real_time * NANOUNITS)); + e.commit(); + } +} + void GCTracer::send_reference_stats_event(ReferenceType type, size_t count) const { EventGCReferenceStatistics e; if (e.should_commit()) { diff --git a/src/hotspot/share/gc/shared/gcTraceTime.cpp b/src/hotspot/share/gc/shared/gcTraceTime.cpp index 3cb5b0f7164d..2477b801c073 100644 --- a/src/hotspot/share/gc/shared/gcTraceTime.cpp +++ b/src/hotspot/share/gc/shared/gcTraceTime.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2015, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "gc/shared/collectedHeap.hpp" #include "gc/shared/gcTraceTime.inline.hpp" +#include "gc/shared/gcTrace.hpp" #include "logging/log.hpp" #include "logging/logStream.hpp" #include "memory/universe.hpp" @@ -70,16 +71,18 @@ void GCTraceTimeLoggerImpl::log_end(Ticks end) { out.print_cr(" %.3fms", duration_in_ms); } -GCTraceCPUTime::GCTraceCPUTime() : - _active(log_is_enabled(Info, gc, cpu)), +GCTraceCPUTime::GCTraceCPUTime(GCTracer* tracer) : + _active(log_is_enabled(Info, gc, cpu) || + (tracer != nullptr && tracer->should_report_cpu_time_event())), _starting_user_time(0.0), _starting_system_time(0.0), - _starting_real_time(0.0) + _starting_real_time(0.0), + _tracer(tracer) { if (_active) { bool valid = os::getTimesSecs(&_starting_real_time, - &_starting_user_time, - &_starting_system_time); + &_starting_user_time, + &_starting_system_time); if (!valid) { log_warning(gc, cpu)("TraceCPUTime: os::getTimesSecs() returned invalid result"); _active = false; @@ -92,10 +95,13 @@ GCTraceCPUTime::~GCTraceCPUTime() { double real_time, user_time, system_time; bool valid = os::getTimesSecs(&real_time, &user_time, &system_time); if (valid) { - log_info(gc, cpu)("User=%3.2fs Sys=%3.2fs Real=%3.2fs", - user_time - _starting_user_time, - system_time - _starting_system_time, - real_time - _starting_real_time); + user_time -= _starting_user_time; + system_time -= _starting_system_time; + real_time -= _starting_real_time; + log_info(gc, cpu)("User=%3.2fs Sys=%3.2fs Real=%3.2fs", user_time, system_time, real_time); + if (_tracer != nullptr) { + _tracer->report_cpu_time_event(user_time, system_time, real_time); + } } else { log_warning(gc, cpu)("TraceCPUTime: os::getTimesSecs() returned invalid result"); } diff --git a/src/hotspot/share/gc/shared/gcTraceTime.hpp b/src/hotspot/share/gc/shared/gcTraceTime.hpp index fbd46b5393d3..955f267ddefa 100644 --- a/src/hotspot/share/gc/shared/gcTraceTime.hpp +++ b/src/hotspot/share/gc/shared/gcTraceTime.hpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2019, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -32,13 +32,16 @@ #include "memory/allocation.hpp" #include "utilities/ticks.hpp" +class GCTracer; + class GCTraceCPUTime : public StackObj { bool _active; // true if times will be measured and printed double _starting_user_time; // user time at start of measurement double _starting_system_time; // system time at start of measurement double _starting_real_time; // real time at start of measurement - public: - GCTraceCPUTime(); + GCTracer* _tracer; +public: + GCTraceCPUTime(GCTracer* tracer); ~GCTraceCPUTime(); }; diff --git a/src/hotspot/share/gc/shared/genCollectedHeap.cpp b/src/hotspot/share/gc/shared/genCollectedHeap.cpp index 9b2d3eb7f371..ae1ff143b505 100644 --- a/src/hotspot/share/gc/shared/genCollectedHeap.cpp +++ b/src/hotspot/share/gc/shared/genCollectedHeap.cpp @@ -31,6 +31,7 @@ #include "code/icBuffer.hpp" #include "compiler/oopMap.hpp" #include "gc/serial/defNewGeneration.hpp" +#include "gc/serial/genMarkSweep.hpp" #include "gc/serial/markSweep.hpp" #include "gc/shared/adaptiveSizePolicy.hpp" #include "gc/shared/cardTableBarrierSet.hpp" @@ -535,7 +536,7 @@ void GenCollectedHeap::do_collection(bool full, if (do_young_collection) { GCIdMark gc_id_mark; - GCTraceCPUTime tcpu; + GCTraceCPUTime tcpu(((DefNewGeneration*)_young_gen)->gc_tracer()); GCTraceTime(Info, gc) t("Pause Young", NULL, gc_cause(), true); print_heap_before_gc(); @@ -585,7 +586,7 @@ void GenCollectedHeap::do_collection(bool full, if (do_full_collection) { GCIdMark gc_id_mark; - GCTraceCPUTime tcpu; + GCTraceCPUTime tcpu(GenMarkSweep::gc_tracer()); GCTraceTime(Info, gc) t("Pause Full", NULL, gc_cause(), true); print_heap_before_gc(); diff --git a/src/hotspot/share/jfr/metadata/metadata.xml b/src/hotspot/share/jfr/metadata/metadata.xml index d92107424886..43f43a84cb80 100644 --- a/src/hotspot/share/jfr/metadata/metadata.xml +++ b/src/hotspot/share/jfr/metadata/metadata.xml @@ -497,6 +497,14 @@ + + + + + + + diff --git a/src/jdk.jfr/share/conf/jfr/default.jfc b/src/jdk.jfr/share/conf/jfr/default.jfc index 1c7b55dbf55d..8870bc8b2cf7 100644 --- a/src/jdk.jfr/share/conf/jfr/default.jfc +++ b/src/jdk.jfr/share/conf/jfr/default.jfc @@ -426,6 +426,10 @@ true + + true + + true @@ -859,10 +863,10 @@ - diff --git a/src/jdk.jfr/share/conf/jfr/profile.jfc b/src/jdk.jfr/share/conf/jfr/profile.jfc index d8f51ed8d3de..c6d6268959e6 100644 --- a/src/jdk.jfr/share/conf/jfr/profile.jfc +++ b/src/jdk.jfr/share/conf/jfr/profile.jfc @@ -128,7 +128,7 @@ false - + true true @@ -364,7 +364,7 @@ true 0 ms - true + true @@ -426,6 +426,10 @@ true + + true + + true @@ -859,10 +863,10 @@ - diff --git a/test/jdk/jdk/jfr/event/gc/collection/GCEventAll.java b/test/jdk/jdk/jfr/event/gc/collection/GCEventAll.java index 6668078a2f63..023acfb144b4 100644 --- a/test/jdk/jdk/jfr/event/gc/collection/GCEventAll.java +++ b/test/jdk/jdk/jfr/event/gc/collection/GCEventAll.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2013, 2019, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2013, 2022, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -267,13 +267,17 @@ private void verifySingleGcBatch(List batches) { Instant batchStartTime = endEvent.getStartTime(); Instant batchEndTime = endEvent.getEndTime(); for (RecordedEvent event : batch.getEvents()) { - if (event.getEventType().getName().contains("AllocationRequiringGC")) { + String name = event.getEventType().getName(); + if (name.contains("AllocationRequiringGC")) { // Unlike other events, these are sent *before* a GC. Asserts.assertLessThanOrEqual(event.getStartTime(), batchStartTime, "Timestamp in event after start event, should be sent before GC start"); } else { Asserts.assertGreaterThanOrEqual(event.getStartTime(), batchStartTime, "startTime in event before batch start event, should be sent after GC start"); } - Asserts.assertLessThanOrEqual(event.getEndTime(), batchEndTime, "endTime in event after batch end event, should be sent before GC end"); + // GCCPUTime is generated after GC is completed. + if (!EventNames.GCCPUTime.equals(name)) { + Asserts.assertLessThanOrEqual(event.getEndTime(), batchEndTime, "endTime in event after batch end event, should be sent before GC end"); + } } // Verify that all required events has been received. diff --git a/test/jdk/jdk/jfr/event/gc/detailed/TestGCCPUTimeEvent.java b/test/jdk/jdk/jfr/event/gc/detailed/TestGCCPUTimeEvent.java new file mode 100644 index 000000000000..9e7d7ca54137 --- /dev/null +++ b/test/jdk/jdk/jfr/event/gc/detailed/TestGCCPUTimeEvent.java @@ -0,0 +1,88 @@ +/* + * Copyright (c) 2022, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ +package jdk.jfr.event.gc.detailed; + +import java.util.List; + +import jdk.jfr.Recording; +import jdk.jfr.consumer.RecordedEvent; +import jdk.test.lib.jfr.EventNames; +import jdk.test.lib.jfr.Events; +import jdk.test.whitebox.WhiteBox; + +/** + * @test id=Serial + * @key jfr + * @requires vm.hasJFR + * @requires vm.gc.Serial + * @library /test/lib /test/jdk + * @build jdk.test.whitebox.WhiteBox + * @run driver jdk.test.lib.helpers.ClassFileInstaller jdk.test.whitebox.WhiteBox + * @run main/othervm -Xbootclasspath/a:. -Xmx32m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+UseSerialGC jdk.jfr.event.gc.detailed.TestGCCPUTimeEvent + */ + +/** + * @test id=Parallel + * @key jfr + * @requires vm.hasJFR + * @requires vm.gc.Parallel + * @library /test/lib /test/jdk + * @build jdk.test.whitebox.WhiteBox + * @run driver jdk.test.lib.helpers.ClassFileInstaller jdk.test.whitebox.WhiteBox + * @run main/othervm -Xbootclasspath/a:. -Xmx32m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+UseParallelGC jdk.jfr.event.gc.detailed.TestGCCPUTimeEvent + */ + +/** + * @test id=G1 + * @key jfr + * @requires vm.hasJFR + * @requires vm.gc.G1 + * @library /test/lib /test/jdk + * @build jdk.test.whitebox.WhiteBox + * @run driver jdk.test.lib.helpers.ClassFileInstaller jdk.test.whitebox.WhiteBox + * @run main/othervm -Xbootclasspath/a:. -Xmx32m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+UseG1GC jdk.jfr.event.gc.detailed.TestGCCPUTimeEvent + */ + +public class TestGCCPUTimeEvent { + private static final String EVENT_NAME = EventNames.GCCPUTime; + + public static void main(String[] args) throws Exception { + + try (Recording recording = new Recording()) { + + // Activate the event we are interested in and start recording + recording.enable(EVENT_NAME); + recording.start(); + + // Guarantee one young GC. + WhiteBox.getWhiteBox().youngGC(); + recording.stop(); + + // Verify recording + List events = Events.fromRecording(recording); + Events.hasEvent(events, EVENT_NAME); + + recording.close(); + } + } +} diff --git a/test/lib/jdk/test/lib/jfr/EventNames.java b/test/lib/jdk/test/lib/jfr/EventNames.java index 91cc11e62bc2..5d2f205580c8 100644 --- a/test/lib/jdk/test/lib/jfr/EventNames.java +++ b/test/lib/jdk/test/lib/jfr/EventNames.java @@ -146,6 +146,7 @@ public class EventNames { public final static String ZUnmap = PREFIX + "ZUnmap"; public final static String GCLocker = PREFIX + "GCLocker"; public static final String SystemGC = PREFIX + "SystemGC"; + public static final String GCCPUTime = PREFIX + "GCCPUTime"; // Compiler public final static String Compilation = PREFIX + "Compilation";