diff --git a/src/hotspot/os/posix/os_posix.cpp b/src/hotspot/os/posix/os_posix.cpp index 448ebce620ab2..19920ffea2e4f 100644 --- a/src/hotspot/os/posix/os_posix.cpp +++ b/src/hotspot/os/posix/os_posix.cpp @@ -76,6 +76,7 @@ #include #include #include +#include #include #include #include @@ -1511,6 +1512,17 @@ jlong os::elapsed_frequency() { bool os::supports_vtime() { return true; } +double os::elapsed_process_vtime() { + struct rusage usage; + int retval = getrusage(RUSAGE_SELF, &usage); + if (retval == 0) { + return usage.ru_utime.tv_sec + usage.ru_stime.tv_sec + + (usage.ru_utime.tv_usec + usage.ru_stime.tv_usec) / (1000.0 * 1000.0); + } else { + return -1; + } +} + // Return the real, user, and system times in seconds from an // arbitrary fixed point in the past. bool os::getTimesSecs(double* process_real_time, diff --git a/src/hotspot/os/windows/os_windows.cpp b/src/hotspot/os/windows/os_windows.cpp index 9e536d2df97aa..89ba497939e8d 100644 --- a/src/hotspot/os/windows/os_windows.cpp +++ b/src/hotspot/os/windows/os_windows.cpp @@ -1209,6 +1209,39 @@ double os::elapsedVTime() { } } +double os::elapsed_process_vtime() { + FILETIME create; + FILETIME exit; + FILETIME kernel; + FILETIME user; + + if (GetProcessTimes(GetCurrentProcess(), &create, &exit, &kernel, &user) == 0) { + return -1; + } + + SYSTEMTIME user_total; + if (FileTimeToSystemTime(&user, &user_total) == 0) { + return -1; + } + + + SYSTEMTIME kernel_total; + if (FileTimeToSystemTime(&kernel, &kernel_total) == 0) { + return -1; + } + + double user_seconds = + double(user_total.wHour) * 3600.0 + double(user_total.wMinute) * 60.0 + + double(user_total.wSecond) + double(user_total.wMilliseconds) / 1000.0; + + double kernel_seconds = double(kernel_total.wHour) * 3600.0 + + double(kernel_total.wMinute) * 60.0 + + double(kernel_total.wSecond) + + double(kernel_total.wMilliseconds) / 1000.0; + + return user_seconds + kernel_seconds; +} + jlong os::javaTimeMillis() { FILETIME wt; GetSystemTimeAsFileTime(&wt); diff --git a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp index 705dcd7895bb9..f66fd97eecbf8 100644 --- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp +++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp @@ -1470,6 +1470,8 @@ bool G1CollectedHeap::concurrent_mark_is_terminating() const { } void G1CollectedHeap::stop() { + log_gc_vtime(); + // Stop all concurrent threads. We do this to make sure these threads // do not continue to execute and access resources (e.g. logging) // that are destroyed during shutdown. @@ -1478,6 +1480,26 @@ void G1CollectedHeap::stop() { _cm_thread->stop(); } +class G1VCPUThreadClosure : public ThreadClosure { +private: + volatile jlong _vtime = 0; + +public: + virtual void do_thread(Thread *thread) { + Atomic::add(&_vtime, os::thread_cpu_time(thread)); + } + jlong vtime() { return _vtime; }; +}; + +double G1CollectedHeap::elapsed_gc_vtime() { + G1VCPUThreadClosure cl; + _cr->threads_do(&cl); + _cm->threads_do(&cl); + _workers->threads_do(&cl); + return ((double) cl.vtime() + os::thread_cpu_time(_service_thread) + os::thread_cpu_time(_cm_thread) + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC; +} + + void G1CollectedHeap::safepoint_synchronize_begin() { SuspendibleThreadSet::synchronize(); } diff --git a/src/hotspot/share/gc/g1/g1CollectedHeap.hpp b/src/hotspot/share/gc/g1/g1CollectedHeap.hpp index fbd1fe6165f58..b6e9955a06642 100644 --- a/src/hotspot/share/gc/g1/g1CollectedHeap.hpp +++ b/src/hotspot/share/gc/g1/g1CollectedHeap.hpp @@ -932,6 +932,8 @@ class G1CollectedHeap : public CollectedHeap { GrowableArray memory_managers() override; GrowableArray memory_pools() override; + double elapsed_gc_vtime() override; + void fill_with_dummy_object(HeapWord* start, HeapWord* end, bool zap) override; static void start_codecache_marking_cycle_if_inactive(bool concurrent_mark_start); diff --git a/src/hotspot/share/gc/parallel/parallelScavengeHeap.cpp b/src/hotspot/share/gc/parallel/parallelScavengeHeap.cpp index 0235864992f22..0d363da35629e 100644 --- a/src/hotspot/share/gc/parallel/parallelScavengeHeap.cpp +++ b/src/hotspot/share/gc/parallel/parallelScavengeHeap.cpp @@ -160,6 +160,27 @@ void ParallelScavengeHeap::initialize_serviceability() { } +void ParallelScavengeHeap::stop() { + log_gc_vtime(); +} + +class ParallelVCPUThreadClosure : public ThreadClosure { +private: + volatile jlong _vtime = 0; + +public: + virtual void do_thread(Thread *thread) { + Atomic::add(&_vtime, os::thread_cpu_time(thread)); + } + jlong vtime() { return _vtime; }; +}; + +double ParallelScavengeHeap::elapsed_gc_vtime() { + ParallelVCPUThreadClosure cl; + workers().threads_do(&cl); + return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC; +} + void ParallelScavengeHeap::safepoint_synchronize_begin() { if (UseStringDeduplication) { SuspendibleThreadSet::synchronize(); diff --git a/src/hotspot/share/gc/parallel/parallelScavengeHeap.hpp b/src/hotspot/share/gc/parallel/parallelScavengeHeap.hpp index 2ce36a6f961b7..86caf7f0f6326 100644 --- a/src/hotspot/share/gc/parallel/parallelScavengeHeap.hpp +++ b/src/hotspot/share/gc/parallel/parallelScavengeHeap.hpp @@ -214,6 +214,9 @@ class ParallelScavengeHeap : public CollectedHeap { void gc_threads_do(ThreadClosure* tc) const override; void print_tracing_info() const override; + void stop() override; + double elapsed_gc_vtime() override; + WorkerThreads* safepoint_workers() override { return &_workers; } PreGenGCValues get_pre_gc_values() const; diff --git a/src/hotspot/share/gc/serial/serialHeap.cpp b/src/hotspot/share/gc/serial/serialHeap.cpp index 27d94593765e7..0ca16cf927609 100644 --- a/src/hotspot/share/gc/serial/serialHeap.cpp +++ b/src/hotspot/share/gc/serial/serialHeap.cpp @@ -145,6 +145,14 @@ GrowableArray SerialHeap::memory_pools() { return memory_pools; } +void SerialHeap::stop() { + log_gc_vtime(); +} + +double SerialHeap::elapsed_gc_vtime() { + return (double) Universe::heap()->vm_vtime() / NANOSECS_PER_SEC; +} + void SerialHeap::safepoint_synchronize_begin() { if (UseStringDeduplication) { SuspendibleThreadSet::synchronize(); diff --git a/src/hotspot/share/gc/serial/serialHeap.hpp b/src/hotspot/share/gc/serial/serialHeap.hpp index 34c79ac0a1855..34c35c65a2561 100644 --- a/src/hotspot/share/gc/serial/serialHeap.hpp +++ b/src/hotspot/share/gc/serial/serialHeap.hpp @@ -274,6 +274,9 @@ class SerialHeap : public CollectedHeap { GrowableArray memory_managers() override; GrowableArray memory_pools() override; + void stop() override; + double elapsed_gc_vtime() override; + DefNewGeneration* young_gen() const { return _young_gen; } diff --git a/src/hotspot/share/gc/shared/collectedHeap.cpp b/src/hotspot/share/gc/shared/collectedHeap.cpp index 2d23dce9488d9..178f05b70fc63 100644 --- a/src/hotspot/share/gc/shared/collectedHeap.cpp +++ b/src/hotspot/share/gc/shared/collectedHeap.cpp @@ -66,6 +66,7 @@ size_t CollectedHeap::_lab_alignment_reserve = SIZE_MAX; Klass* CollectedHeap::_filler_object_klass = nullptr; size_t CollectedHeap::_filler_array_max_size = 0; size_t CollectedHeap::_stack_chunk_max_size = 0; +jlong CollectedHeap::_vm_vtime = 0; class GCLogMessage : public FormatBuffer<512> {}; @@ -213,6 +214,27 @@ void CollectedHeap::print() const { print_gc_on(tty); } +void CollectedHeap::log_gc_vtime() { + if (os::is_thread_cpu_time_supported()) { + double process_vtime = os::elapsed_process_vtime(); + double gc_vtime = elapsed_gc_vtime(); + + if (process_vtime == -1 || gc_vtime == -1) return; + + log_info(gc, cpu)("Process CPU time: %fs", process_vtime); + log_info(gc, cpu)("GC CPU time: %fs", gc_vtime); + double cost = -1; + if (gc_vtime > process_vtime || process_vtime == 0 || gc_vtime == 0) { + // This can happen e.g. for short running processes with + // low CPU utilization + cost = 0; + } else { + cost = 100 * gc_vtime / process_vtime; + } + log_info(gc)("GC CPU cost: %2.2f%%", cost); + } +} + void CollectedHeap::trace_heap(GCWhen::Type when, const GCTracer* gc_tracer) { const GCHeapSummary& heap_summary = create_heap_summary(); gc_tracer->report_gc_heap_summary(when, heap_summary); diff --git a/src/hotspot/share/gc/shared/collectedHeap.hpp b/src/hotspot/share/gc/shared/collectedHeap.hpp index d50c09f70a769..1a80ce21a63fb 100644 --- a/src/hotspot/share/gc/shared/collectedHeap.hpp +++ b/src/hotspot/share/gc/shared/collectedHeap.hpp @@ -132,6 +132,8 @@ class CollectedHeap : public CHeapObj { NOT_PRODUCT(volatile size_t _promotion_failure_alot_count;) NOT_PRODUCT(volatile size_t _promotion_failure_alot_gc_number;) + static jlong _vm_vtime; + // Reason for current garbage collection. Should be set to // a value reflecting no collection between collections. GCCause::Cause _gc_cause; @@ -246,6 +248,14 @@ class CollectedHeap : public CHeapObj { virtual void safepoint_synchronize_begin() {} virtual void safepoint_synchronize_end() {} + static jlong vm_vtime() { + return _vm_vtime; + } + + static void add_vm_vtime(jlong time) { + _vm_vtime += time; + } + void initialize_reserved_region(const ReservedHeapSpace& rs); virtual size_t capacity() const = 0; @@ -455,6 +465,9 @@ class CollectedHeap : public CHeapObj { // Default implementation does nothing. virtual void print_tracing_info() const = 0; + virtual double elapsed_gc_vtime() { return -1; }; + void log_gc_vtime(); + void print_before_gc() const; void print_after_gc() const; diff --git a/src/hotspot/share/gc/shared/gcVMOperations.hpp b/src/hotspot/share/gc/shared/gcVMOperations.hpp index bc370358ff851..68166aff196cd 100644 --- a/src/hotspot/share/gc/shared/gcVMOperations.hpp +++ b/src/hotspot/share/gc/shared/gcVMOperations.hpp @@ -93,6 +93,8 @@ class VM_GC_Sync_Operation : public VM_Operation { virtual bool doit_prologue(); // Releases the Heap_lock. virtual void doit_epilogue(); + + bool operation_is_gc() const { return true; } }; class VM_Verify : public VM_GC_Sync_Operation { diff --git a/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp b/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp index 55dfb2e8de400..d51393674b36b 100644 --- a/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp +++ b/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp @@ -2202,6 +2202,7 @@ uint ShenandoahHeap::max_workers() { } void ShenandoahHeap::stop() { + log_gc_vtime(); // The shutdown sequence should be able to terminate when GC is running. // Step 0. Notify policy to disable event recording and prevent visiting gc threads during shutdown @@ -2219,6 +2220,23 @@ void ShenandoahHeap::stop() { } } +class ShenandoahCPUThreadClosure : public ThreadClosure { +private: + volatile jlong _vtime = 0; + +public: + virtual void do_thread(Thread *thread) { + Atomic::add(&_vtime, os::thread_cpu_time(thread)); + } + jlong vtime() { return _vtime; }; +}; + +double ShenandoahHeap::elapsed_gc_vtime() { + ShenandoahCPUThreadClosure cl; + ShenandoahHeap::heap()->gc_threads_do(&cl); + return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC; +} + void ShenandoahHeap::stw_unload_classes(bool full_gc) { if (!unload_classes()) return; ClassUnloadingContext ctx(_workers->active_workers(), diff --git a/src/hotspot/share/gc/shenandoah/shenandoahHeap.hpp b/src/hotspot/share/gc/shenandoah/shenandoahHeap.hpp index 4124bf8be7f5a..e165a1cf1181d 100644 --- a/src/hotspot/share/gc/shenandoah/shenandoahHeap.hpp +++ b/src/hotspot/share/gc/shenandoah/shenandoahHeap.hpp @@ -209,6 +209,8 @@ class ShenandoahHeap : public CollectedHeap { void stop() override; + double elapsed_gc_vtime() override; + void prepare_for_verify() override; void verify(VerifyOption vo) override; diff --git a/src/hotspot/share/gc/shenandoah/shenandoahVMOperations.hpp b/src/hotspot/share/gc/shenandoah/shenandoahVMOperations.hpp index 09971bb26302e..2117ba26675dd 100644 --- a/src/hotspot/share/gc/shenandoah/shenandoahVMOperations.hpp +++ b/src/hotspot/share/gc/shenandoah/shenandoahVMOperations.hpp @@ -55,6 +55,8 @@ class VM_ShenandoahOperation : public VM_Operation { void log_active_generation(const char* prefix); bool doit_prologue() override; void doit_epilogue() override; + + bool operation_is_gc() const override { return true; } }; class VM_ShenandoahReferenceOperation : public VM_ShenandoahOperation { diff --git a/src/hotspot/share/gc/z/zCollectedHeap.cpp b/src/hotspot/share/gc/z/zCollectedHeap.cpp index 87cfeb012eca2..814ff65b379ee 100644 --- a/src/hotspot/share/gc/z/zCollectedHeap.cpp +++ b/src/hotspot/share/gc/z/zCollectedHeap.cpp @@ -105,11 +105,31 @@ class ZStopConcurrentGCThreadClosure : public ThreadClosure { void ZCollectedHeap::stop() { log_info_p(gc, exit)("Stopping ZGC"); + log_gc_vtime(); ZAbort::abort(); ZStopConcurrentGCThreadClosure cl; gc_threads_do(&cl); } +class ZVCPUThreadClosure : public ThreadClosure { +private: + volatile jlong _vtime = 0; +public: + virtual void do_thread(Thread *thread) { + if (thread->is_ConcurrentGC_thread() || + strstr(thread->name(), "ZWorker") != nullptr) { + Atomic::add(&_vtime, os::thread_cpu_time(thread)); + } + } + jlong vtime() { return _vtime; }; +}; + +double ZCollectedHeap::elapsed_gc_vtime() { + ZVCPUThreadClosure cl; + gc_threads_do(&cl); + return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC; +} + size_t ZCollectedHeap::max_capacity() const { return _heap.max_capacity(); } diff --git a/src/hotspot/share/gc/z/zCollectedHeap.hpp b/src/hotspot/share/gc/z/zCollectedHeap.hpp index 871ff81bfdf5d..64010fd196bdb 100644 --- a/src/hotspot/share/gc/z/zCollectedHeap.hpp +++ b/src/hotspot/share/gc/z/zCollectedHeap.hpp @@ -91,6 +91,8 @@ class ZCollectedHeap : public CollectedHeap { GrowableArray memory_managers() override; GrowableArray memory_pools() override; + double elapsed_gc_vtime() override; + void object_iterate(ObjectClosure* cl) override; ParallelObjectIteratorImpl* parallel_object_iterator(uint nworkers) override; diff --git a/src/hotspot/share/gc/z/zGeneration.cpp b/src/hotspot/share/gc/z/zGeneration.cpp index 534f0195c90fe..d08d8639a3fb3 100644 --- a/src/hotspot/share/gc/z/zGeneration.cpp +++ b/src/hotspot/share/gc/z/zGeneration.cpp @@ -442,6 +442,8 @@ class VM_ZOperation : public VM_Operation { OopMapCache::try_trigger_cleanup(); } + bool operation_is_gc() const { return true; } + bool success() const { return _success; } diff --git a/src/hotspot/share/runtime/cpuTimeCounters.cpp b/src/hotspot/share/runtime/cpuTimeCounters.cpp index 5b2e76fed7f65..0ff90d5276218 100644 --- a/src/hotspot/share/runtime/cpuTimeCounters.cpp +++ b/src/hotspot/share/runtime/cpuTimeCounters.cpp @@ -126,3 +126,7 @@ void ThreadTotalCPUTimeClosure::do_thread(Thread* thread) { // must ensure the thread exists and has not terminated. _total += os::thread_cpu_time(thread); } + +void ThreadTotalCPUTimeClosure::inc_total(jlong value) { + _total += value; +} diff --git a/src/hotspot/share/runtime/cpuTimeCounters.hpp b/src/hotspot/share/runtime/cpuTimeCounters.hpp index 3137caf43592e..64aace4fe6817 100644 --- a/src/hotspot/share/runtime/cpuTimeCounters.hpp +++ b/src/hotspot/share/runtime/cpuTimeCounters.hpp @@ -109,6 +109,7 @@ class ThreadTotalCPUTimeClosure: public ThreadClosure { ~ThreadTotalCPUTimeClosure(); virtual void do_thread(Thread* thread); + void inc_total(jlong value); }; #endif // SHARE_RUNTIME_CPUTIMECOUNTERS_HPP diff --git a/src/hotspot/share/runtime/os.hpp b/src/hotspot/share/runtime/os.hpp index b26ec280e7242..699955a7b9a18 100644 --- a/src/hotspot/share/runtime/os.hpp +++ b/src/hotspot/share/runtime/os.hpp @@ -299,6 +299,7 @@ class os: AllStatic { // returns the elapsed virtual time for the current thread. static bool supports_vtime(); static double elapsedVTime(); + static double elapsed_process_vtime(); // Return current local time in a string (YYYY-MM-DD HH:MM:SS). // It is MT safe, but not async-safe, as reading time zone diff --git a/src/hotspot/share/runtime/vmOperation.hpp b/src/hotspot/share/runtime/vmOperation.hpp index ac5d37381f9fe..32a72c0e3e0aa 100644 --- a/src/hotspot/share/runtime/vmOperation.hpp +++ b/src/hotspot/share/runtime/vmOperation.hpp @@ -168,6 +168,8 @@ class VM_Operation : public StackObj { // or concurrently with Java threads running. virtual bool evaluate_at_safepoint() const { return true; } + virtual bool operation_is_gc() const { return false; } + // Debugging virtual void print_on_error(outputStream* st) const; virtual const char* name() const { return _names[type()]; } diff --git a/src/hotspot/share/runtime/vmThread.cpp b/src/hotspot/share/runtime/vmThread.cpp index 0ff5e5d227b5b..8f04c6e97dd7d 100644 --- a/src/hotspot/share/runtime/vmThread.cpp +++ b/src/hotspot/share/runtime/vmThread.cpp @@ -271,7 +271,8 @@ static void post_vm_operation_event(EventExecuteVMOperation* event, VM_Operation void VMThread::evaluate_operation(VM_Operation* op) { ResourceMark rm; - + const bool gcLogging = log_is_enabled(Info, gc) || log_is_enabled(Info, gc, cpu); + jlong start = 0; { PerfTraceTime vm_op_timer(perf_accumulated_vm_operation_time()); HOTSPOT_VMOPS_BEGIN( @@ -279,6 +280,9 @@ void VMThread::evaluate_operation(VM_Operation* op) { op->evaluate_at_safepoint() ? 0 : 1); EventExecuteVMOperation event; + if (gcLogging && os::is_thread_cpu_time_supported()) { + start = os::thread_cpu_time(this); + } op->evaluate(); if (event.should_commit()) { post_vm_operation_event(&event, op); @@ -289,11 +293,18 @@ void VMThread::evaluate_operation(VM_Operation* op) { op->evaluate_at_safepoint() ? 0 : 1); } - if (UsePerfData && os::is_thread_cpu_time_supported()) { - assert(Thread::current() == this, "Must be called from VM thread"); - // Update vm_thread_cpu_time after each VM operation. - ThreadTotalCPUTimeClosure tttc(CPUTimeGroups::CPUTimeType::vm); - tttc.do_thread(this); + if (os::is_thread_cpu_time_supported()) { + jlong end = gcLogging || UsePerfData ? os::thread_cpu_time(this) : 0; + if (gcLogging) { + jlong duration = end > start ? end - start : 0; + Universe::heap()->add_vm_vtime(duration); + } + if (UsePerfData) { + assert(Thread::current() == this, "Must be called from VM thread"); + // Update vm_thread_cpu_time after each VM operation. + ThreadTotalCPUTimeClosure tttc(CPUTimeGroups::CPUTimeType::vm); + tttc.inc_total(end); + } } }