8200720: Print additional information in thread dump (times, allocated bytes etc.)
authorghaug
Mon, 25 Jun 2018 16:00:56 +0200
changeset 50785 d1b24f2ceca5
parent 50784 57f5cba78093
child 50786 f249187b6c3d
8200720: Print additional information in thread dump (times, allocated bytes etc.) Reviewed-by: dholmes, clanger, cjplummer, sspitsyn
src/hotspot/share/classfile/klassFactory.cpp
src/hotspot/share/runtime/globals.hpp
src/hotspot/share/runtime/thread.cpp
src/hotspot/share/runtime/thread.hpp
src/hotspot/share/runtime/threadStatisticalInfo.hpp
src/hotspot/share/runtime/vm_operations.cpp
src/hotspot/share/runtime/vm_operations.hpp
src/hotspot/share/services/attachListener.cpp
src/hotspot/share/services/diagnosticCommand.cpp
src/hotspot/share/services/diagnosticCommand.hpp
src/jdk.jcmd/share/classes/sun/tools/jstack/JStack.java
--- a/src/hotspot/share/classfile/klassFactory.cpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/classfile/klassFactory.cpp	Mon Jun 25 16:00:56 2018 +0200
@@ -197,6 +197,9 @@
 
   ClassFileStream* old_stream = stream;
 
+  // increment counter
+  THREAD->statistical_info().incr_define_class_count();
+
   // Skip this processing for VM anonymous classes
   if (host_klass == NULL) {
     stream = check_class_file_load_hook(stream,
--- a/src/hotspot/share/runtime/globals.hpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/runtime/globals.hpp	Mon Jun 25 16:00:56 2018 +0200
@@ -661,6 +661,9 @@
   product(bool, PrintCompilation, false,                                    \
           "Print compilations")                                             \
                                                                             \
+  product(bool, PrintExtendedThreadInfo, false,                             \
+          "Print more information in thread dump")                          \
+                                                                            \
   diagnostic(bool, TraceNMethodInstalls, false,                             \
           "Trace nmethod installation")                                     \
                                                                             \
--- a/src/hotspot/share/runtime/thread.cpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/runtime/thread.cpp	Mon Jun 25 16:00:56 2018 +0200
@@ -93,6 +93,7 @@
 #include "runtime/thread.inline.hpp"
 #include "runtime/threadCritical.hpp"
 #include "runtime/threadSMR.inline.hpp"
+#include "runtime/threadStatisticalInfo.hpp"
 #include "runtime/timer.hpp"
 #include "runtime/timerTrace.hpp"
 #include "runtime/vframe.inline.hpp"
@@ -869,13 +870,29 @@
   }
 }
 
-void Thread::print_on(outputStream* st) const {
+void Thread::print_on(outputStream* st, bool print_extended_info) const {
   // get_priority assumes osthread initialized
   if (osthread() != NULL) {
     int os_prio;
     if (os::get_native_priority(this, &os_prio) == OS_OK) {
       st->print("os_prio=%d ", os_prio);
     }
+
+    st->print("cpu=%.2fms ",
+              os::thread_cpu_time(const_cast<Thread*>(this), true) / 1000000.0
+              );
+    st->print("elapsed=%.2fs ",
+              _statistical_info.getElapsedTime() / 1000.0
+              );
+    if (is_Java_thread() && (PrintExtendedThreadInfo || print_extended_info)) {
+      size_t allocated_bytes = (size_t) const_cast<Thread*>(this)->cooked_allocated_bytes();
+      st->print("allocated=" SIZE_FORMAT "%s ",
+                byte_size_in_proper_unit(allocated_bytes),
+                proper_unit_for_byte_size(allocated_bytes)
+                );
+      st->print("defined_classes=" INT64_FORMAT " ", _statistical_info.getDefineClassCount());
+    }
+
     st->print("tid=" INTPTR_FORMAT " ", p2i(this));
     osthread()->print_on(st);
   }
@@ -2871,7 +2888,7 @@
 #endif // PRODUCT
 
 // Called by Threads::print() for VM_PrintThreads operation
-void JavaThread::print_on(outputStream *st) const {
+void JavaThread::print_on(outputStream *st, bool print_extended_info) const {
   st->print_raw("\"");
   st->print_raw(get_thread_name());
   st->print_raw("\" ");
@@ -2881,7 +2898,7 @@
     if (java_lang_Thread::is_daemon(thread_oop))  st->print("daemon ");
     st->print("prio=%d ", java_lang_Thread::priority(thread_oop));
   }
-  Thread::print_on(st);
+  Thread::print_on(st, print_extended_info);
   // print guess for valid stack memory region (assume 4K pages); helps lock debugging
   st->print_cr("[" INTPTR_FORMAT "]", (intptr_t)last_Java_sp() & ~right_n_bits(12));
   if (thread_oop != NULL) {
@@ -4531,7 +4548,8 @@
 
 // Threads::print_on() is called at safepoint by VM_PrintThreads operation.
 void Threads::print_on(outputStream* st, bool print_stacks,
-                       bool internal_format, bool print_concurrent_locks) {
+                       bool internal_format, bool print_concurrent_locks,
+                       bool print_extended_info) {
   char buf[32];
   st->print_raw_cr(os::local_time_string(buf, sizeof(buf)));
 
@@ -4554,7 +4572,7 @@
 
   ALL_JAVA_THREADS(p) {
     ResourceMark rm;
-    p->print_on(st);
+    p->print_on(st, print_extended_info);
     if (print_stacks) {
       if (internal_format) {
         p->trace_stack();
--- a/src/hotspot/share/runtime/thread.hpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/runtime/thread.hpp	Mon Jun 25 16:00:56 2018 +0200
@@ -44,6 +44,7 @@
 #include "runtime/stubRoutines.hpp"
 #include "runtime/threadHeapSampler.hpp"
 #include "runtime/threadLocalStorage.hpp"
+#include "runtime/threadStatisticalInfo.hpp"
 #include "runtime/unhandledOops.hpp"
 #include "utilities/align.hpp"
 #include "utilities/exceptions.hpp"
@@ -341,6 +342,8 @@
                                                 // the Java heap
   ThreadHeapSampler _heap_sampler;              // For use when sampling the memory.
 
+  ThreadStatisticalInfo _statistical_info;      // Statistics about the thread
+
   JFR_ONLY(DEFINE_THREAD_LOCAL_FIELD_JFR;)      // Thread-local data for jfr
 
   int   _vm_operation_started_count;            // VM_Operation support
@@ -521,6 +524,8 @@
 
   ThreadHeapSampler& heap_sampler()     { return _heap_sampler; }
 
+  ThreadStatisticalInfo& statistical_info() { return _statistical_info; }
+
   JFR_ONLY(DEFINE_THREAD_LOCAL_ACCESSOR_JFR;)
 
   bool is_trace_suspend()               { return (_suspend_flags & _trace_flag) != 0; }
@@ -638,7 +643,8 @@
   void    set_lgrp_id(int value) { _lgrp_id = value; }
 
   // Printing
-  virtual void print_on(outputStream* st) const;
+  void print_on(outputStream* st, bool print_extended_info) const;
+  virtual void print_on(outputStream* st) const { print_on(st, false); }
   void print() const { print_on(tty); }
   virtual void print_on_error(outputStream* st, char* buf, int buflen) const;
   void print_value_on(outputStream* st) const;
@@ -1759,7 +1765,8 @@
 
   // Misc. operations
   char* name() const { return (char*)get_thread_name(); }
-  void print_on(outputStream* st) const;
+  void print_on(outputStream* st, bool print_extended_info) const;
+  void print_on(outputStream* st) const { print_on(st, false); }
   void print_value();
   void print_thread_state_on(outputStream*) const      PRODUCT_RETURN;
   void print_thread_state() const                      PRODUCT_RETURN;
@@ -2173,10 +2180,10 @@
 
   // Verification
   static void verify();
-  static void print_on(outputStream* st, bool print_stacks, bool internal_format, bool print_concurrent_locks);
+  static void print_on(outputStream* st, bool print_stacks, bool internal_format, bool print_concurrent_locks, bool print_extended_info);
   static void print(bool print_stacks, bool internal_format) {
     // this function is only used by debug.cpp
-    print_on(tty, print_stacks, internal_format, false /* no concurrent lock printed */);
+    print_on(tty, print_stacks, internal_format, false /* no concurrent lock printed */, false /* simple format */);
   }
   static void print_on_error(outputStream* st, Thread* current, char* buf, int buflen);
   static void print_on_error(Thread* this_thread, outputStream* st, Thread* current, char* buf,
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/src/hotspot/share/runtime/threadStatisticalInfo.hpp	Mon Jun 25 16:00:56 2018 +0200
@@ -0,0 +1,48 @@
+/*
+ * Copyright (c) 2018, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2018 SAP SE. 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.
+ *
+ */
+
+#ifndef SHARE_VM_RUNTIME_THREADSTATISTICS_HPP
+#define SHARE_VM_RUNTIME_THREADSTATISTICS_HPP
+
+#include "jni.h"
+#include "runtime/os.hpp"
+#include "utilities/globalDefinitions.hpp"
+
+
+class ThreadStatisticalInfo {
+  // The time stamp the thread was started.
+  const uint64_t _start_time_stamp;
+  uint64_t _define_class_count;
+
+public:
+  ThreadStatisticalInfo() : _start_time_stamp(os::javaTimeMillis()), _define_class_count(0) {}
+  uint64_t getStartTime() const             { return _start_time_stamp; }
+  uint64_t getDefineClassCount() const                    { return  _define_class_count; }
+  void     setDefineClassCount(uint64_t defineClassCount) { _define_class_count = defineClassCount; }
+  void     incr_define_class_count()                      { _define_class_count += 1; }
+  uint64_t getElapsedTime() const           { return os::javaTimeMillis() - getStartTime(); }
+};
+
+#endif // SHARE_VM_RUNTIME_THREADSTATISTICS_HPP
--- a/src/hotspot/share/runtime/vm_operations.cpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/runtime/vm_operations.cpp	Mon Jun 25 16:00:56 2018 +0200
@@ -212,7 +212,7 @@
 }
 
 void VM_PrintThreads::doit() {
-  Threads::print_on(_out, true, false, _print_concurrent_locks);
+  Threads::print_on(_out, true, false, _print_concurrent_locks, _print_extended_info);
 }
 
 void VM_PrintThreads::doit_epilogue() {
--- a/src/hotspot/share/runtime/vm_operations.hpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/runtime/vm_operations.hpp	Mon Jun 25 16:00:56 2018 +0200
@@ -372,10 +372,17 @@
  private:
   outputStream* _out;
   bool _print_concurrent_locks;
+  bool _print_extended_info;
  public:
-  VM_PrintThreads()                                                { _out = tty; _print_concurrent_locks = PrintConcurrentLocks; }
-  VM_PrintThreads(outputStream* out, bool print_concurrent_locks)  { _out = out; _print_concurrent_locks = print_concurrent_locks; }
-  VMOp_Type type() const                                           {  return VMOp_PrintThreads; }
+  VM_PrintThreads()
+    : _out(tty), _print_concurrent_locks(PrintConcurrentLocks), _print_extended_info(false)
+  {}
+  VM_PrintThreads(outputStream* out, bool print_concurrent_locks, bool print_extended_info)
+    : _out(out), _print_concurrent_locks(print_concurrent_locks), _print_extended_info(print_extended_info)
+  {}
+  VMOp_Type type() const {
+    return VMOp_PrintThreads;
+  }
   void doit();
   bool doit_prologue();
   void doit_epilogue();
--- a/src/hotspot/share/services/attachListener.cpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/services/attachListener.cpp	Mon Jun 25 16:00:56 2018 +0200
@@ -168,12 +168,20 @@
 //
 static jint thread_dump(AttachOperation* op, outputStream* out) {
   bool print_concurrent_locks = false;
-  if (op->arg(0) != NULL && strcmp(op->arg(0), "-l") == 0) {
-    print_concurrent_locks = true;
+  bool print_extended_info = false;
+  if (op->arg(0) != NULL) {
+    for (int i = 0; op->arg(0)[i] != 0; ++i) {
+      if (op->arg(0)[i] == 'l') {
+        print_concurrent_locks = true;
+      }
+      if (op->arg(0)[i] == 'e') {
+        print_extended_info = true;
+      }
+    }
   }
 
   // thread stacks
-  VM_PrintThreads op1(out, print_concurrent_locks);
+  VM_PrintThreads op1(out, print_concurrent_locks, print_extended_info);
   VMThread::execute(&op1);
 
   // JNI global handles
--- a/src/hotspot/share/services/diagnosticCommand.cpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/services/diagnosticCommand.cpp	Mon Jun 25 16:00:56 2018 +0200
@@ -612,13 +612,15 @@
 
 ThreadDumpDCmd::ThreadDumpDCmd(outputStream* output, bool heap) :
                                DCmdWithParser(output, heap),
-  _locks("-l", "print java.util.concurrent locks", "BOOLEAN", false, "false") {
+  _locks("-l", "print java.util.concurrent locks", "BOOLEAN", false, "false"),
+  _extended("-e", "print extended thread information", "BOOLEAN", false, "false") {
   _dcmdparser.add_dcmd_option(&_locks);
+  _dcmdparser.add_dcmd_option(&_extended);
 }
 
 void ThreadDumpDCmd::execute(DCmdSource source, TRAPS) {
   // thread stacks
-  VM_PrintThreads op1(output(), _locks.value());
+  VM_PrintThreads op1(output(), _locks.value(), _extended.value());
   VMThread::execute(&op1);
 
   // JNI global handles
--- a/src/hotspot/share/services/diagnosticCommand.hpp	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/hotspot/share/services/diagnosticCommand.hpp	Mon Jun 25 16:00:56 2018 +0200
@@ -446,6 +446,7 @@
 class ThreadDumpDCmd : public DCmdWithParser {
 protected:
   DCmdArgument<bool> _locks;
+  DCmdArgument<bool> _extended;
 public:
   ThreadDumpDCmd(outputStream* output, bool heap);
   static const char* name() { return "Thread.print"; }
--- a/src/jdk.jcmd/share/classes/sun/tools/jstack/JStack.java	Tue Jun 26 08:13:02 2018 +0100
+++ b/src/jdk.jcmd/share/classes/sun/tools/jstack/JStack.java	Mon Jun 25 16:00:56 2018 +0200
@@ -48,6 +48,7 @@
         checkForUnsupportedOptions(args);
 
         boolean locks = false;
+        boolean extended = false;
 
         // Parse the options (arguments starting with "-" )
         int optionCount = 0;
@@ -67,7 +68,11 @@
                 if (arg.equals("-l")) {
                     locks = true;
                 } else {
-                    usage(1);
+                    if (arg.equals("-e")) {
+                        extended = true;
+                    } else {
+                        usage(1);
+                    }
                 }
             }
             optionCount++;
@@ -81,12 +86,14 @@
 
         // pass -l to thread dump operation to get extra lock info
         String pidArg = args[optionCount];
-        String params[];
+        String params[]= new String[] { "" };
+        if (extended) {
+            params[0] += "-e ";
+        }
         if (locks) {
-            params = new String[] { "-l" };
-        } else {
-            params = new String[0];
+            params[0] += "-l";
         }
+
         ProcessArgumentMatcher ap = new ProcessArgumentMatcher(pidArg);
         Collection<String> pids = ap.getVirtualMachinePids(JStack.class);
 
@@ -170,11 +177,12 @@
     // print usage message
     private static void usage(int exit) {
         System.err.println("Usage:");
-        System.err.println("    jstack [-l] <pid>");
+        System.err.println("    jstack [-l][-e] <pid>");
         System.err.println("        (to connect to running process)");
         System.err.println("");
         System.err.println("Options:");
         System.err.println("    -l  long listing. Prints additional information about locks");
+        System.err.println("    -e  extended listing. Prints additional information about threads");
         System.err.println("    -? -h --help -help to print this help message");
         System.exit(exit);
     }