JDK-8246019 : PerfClassTraceTime slows down VM start-up
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 15
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2020-05-27
  • Updated: 2024-11-13
  • Resolved: 2020-07-06
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 16
16 b05Fixed
Related Reports
Relates :  
Relates :  
Description
PerfClassTraceTime consumes 0.5% of start-up time of "java -version".

Since this is a very rarely used feature, maybe it should be enabled only if -Xlog:startuptime is specified.

=======
diff -r 0702191777c9 src/hotspot/share/classfile/classLoader.cpp
--- a/src/hotspot/share/classfile/classLoader.cpp	Thu May 21 15:56:27 2020 -0700
+++ b/src/hotspot/share/classfile/classLoader.cpp	Wed May 27 13:36:53 2020 -0700
@@ -1642,7 +1642,7 @@
 // Please keep following two functions at end of this file. With them placed at top or in middle of the file,
 // they could get inlined by agressive compiler, an unknown trick, see bug 6966589.
 void PerfClassTraceTime::initialize() {
-  if (!UsePerfData) return;
+  if (!UsePerfData || !log_is_enabled(Info, startuptime)) return;
 
   if (_eventp != NULL) {
     // increment the event counter
@@ -1671,7 +1671,7 @@
 }
 
 PerfClassTraceTime::~PerfClassTraceTime() {
-  if (!UsePerfData) return;
+  if (!UsePerfData || !log_is_enabled(Info, startuptime)) return;
 
   // stop the thread-local timer as the event completes
   // and resume the thread-local timer of the event next on the stack
========

Results of " perf stat -r 200 bin/java -Xshare:on -XX:SharedArchiveFile=jdk2.jsa -Xint -version "
   1:     58501988    58181961 (-320027)      -----     40.816    40.529 ( -0.287)      --    
   2:     58500115    58191736 (-308379)      -----     40.160    39.960 ( -0.200)      -     
   3:     58504839    58180395 (-324444)      -----     40.598    40.266 ( -0.332)      --    
   4:     58502647    58179564 (-323083)      -----     40.372    40.173 ( -0.199)      -     
   5:     58496091    58181745 (-314346)      -----     40.775    40.479 ( -0.296)      --    
   6:     58503236    58180618 (-322618)      -----     40.227    40.321 (  0.094)     +      
   7:     58498331    58186460 (-311871)      -----     40.664    39.997 ( -0.667)      ----- 
   8:     58496502    58180974 (-315528)      -----     40.713    40.449 ( -0.264)      --    
   9:     58493768    58179520 (-314248)      -----     40.122    40.270 (  0.148)     +      
  10:     58501299    58180943 (-320356)      -----     40.197    40.571 (  0.374)   +++      
============================================================
          58499881    58182391 (-317490)      -----     40.464    40.301 ( -0.163)      -     
instr delta =      -317490    -0.5427%
time  delta =       -0.163 ms -0.4017%

PerfClassTraceTime was used 539 times during "java -version", so each instance takes about 590 instructions.


Comments
URL: https://hg.openjdk.java.net/jdk/jdk/rev/d90de88ba4d0 User: iklam Date: 2020-07-06 22:15:29 +0000
06-07-2020

The PerfCounters, as far as I know, are not connected to unified logging, so can't be controlled by it.
27-05-2020