Instrumenting Zero and Shark

Every so often I find myself adding little bits of code to Zero or Shark, to figure out obscure bugs or to see whether working on some optimization or another is worthwhile. I did it again today, and thought I’d write a little tutorial.

The first versions of Shark implemented a lot of things the same way as the interpreter, ie slowly. Since February I’ve been slowly replacing these interpreter-isms with implementations that are more compiler-like, and today there’s only one left: invokeinterface. The reason I left it until last is that it’s the biggest and the ugliest: it’ll no doubt be a pig to do, and quite frankly I don’t really want to do it. To see if I could get away with not bothering with it, I decided to instrument Shark so I could run SPECjvm98 and have it print out the number of times Shark-compiled code executed an invokeinterface for every benchmark.

First, I needed somewhere to store the counter. I decided to put it in the individual thread’s JavaThread objects as they’re easy to get at from both C++ and Shark, and they’re thread-specific so you don’t have to worry about locking.

diff -r 4cc0bc87aef4 ports/hotspot/src/os_cpu/linux_zero/vm/thread_linux_zero.hpp
--- a/ports/hotspot/src/os_cpu/linux_zero/vm/thread_linux_zero.hpp	Fri May 29 12:46:07 2009 +0100
+++ b/ports/hotspot/src/os_cpu/linux_zero/vm/thread_linux_zero.hpp	Fri May 29 14:44:04 2009 +0100
@@ -32,6 +32,25 @@
     _top_zero_frame = NULL;
   }

+ private:
+  int _interface_call_count;
+
+ public:
+  int interface_call_count() const
+  {
+    return _interface_call_count;
+  }
+  void set_interface_call_count(int interface_call_count)
+  {
+    _interface_call_count = interface_call_count;
+  }
+
+ public:
+  static ByteSize interface_call_count_offset()
+  {
+    return byte_offset_of(JavaThread, _interface_call_count);
+  }
+
  public:
   ZeroStack *zero_stack()
   {

So we have the field itself, a getter and setter to access it from C++, and a static method to expose the offset of the field in the thread object to Shark. Next we need to make Shark update the counter:

diff -r 4cc0bc87aef4 ports/hotspot/src/share/vm/shark/sharkTopLevelBlock.cpp
--- a/ports/hotspot/src/share/vm/shark/sharkTopLevelBlock.cpp	Fri May 29 12:46:07 2009 +0100
+++ b/ports/hotspot/src/share/vm/shark/sharkTopLevelBlock.cpp	Fri May 29 14:44:04 2009 +0100
@@ -985,6 +985,16 @@
 // Interpreter-style interface call lookup
 Value* SharkTopLevelBlock::get_interface_callee(SharkValue *receiver)
 {
+  Value *count_addr = builder()->CreateAddressOfStructEntry(
+    thread(),
+    JavaThread::interface_call_count_offset(),
+    PointerType::getUnqual(SharkType::jint_type()));
+  builder()->CreateStore(
+    builder()->CreateAdd(
+      builder()->CreateLoad(count_addr),
+      LLVMValue::jint_constant(1)),
+    count_addr);
+
   SharkConstantPool constants(this);
   Value *cache = constants.cache_entry_at(iter()->get_method_index());

We’re almost ready to add the SPECjvm98-specific bits now, but there’s one thing left. Some of the benchmarks are multithreaded, but we have one counter per thread; we need a way to set and get the counters from all running threads. HotSpot has some code to iterate over all the threads in the VM, but it’s all private to the Threads class. Not to worry though, we’ll just stick it in there:

diff -r 4cc0bc87aef4 openjdk-ecj/hotspot/src/share/vm/runtime/thread.hpp
--- a/openjdk-ecj/hotspot/src/share/vm/runtime/thread.hpp	Fri May 29 12:46:07 2009 +0100
+++ b/openjdk-ecj/hotspot/src/share/vm/runtime/thread.hpp	Fri May 29 14:44:04 2009 +0100
@@ -1669,6 +1669,9 @@
   // Deoptimizes all frames tied to marked nmethods
   static void deoptimized_wrt_marked_nmethods();

+ public:
+  static void reset_interface_call_counts();
+  static int  interface_call_counts_total();
 };

diff -r 4cc0bc87aef4 openjdk-ecj/hotspot/src/share/vm/runtime/thread.cpp
--- a/openjdk-ecj/hotspot/src/share/vm/runtime/thread.cpp	Fri May 29 12:46:07 2009 +0100
+++ b/openjdk-ecj/hotspot/src/share/vm/runtime/thread.cpp	Fri May 29 14:44:04 2009 +0100
@@ -3828,6 +3828,21 @@
   }
 }

+void Threads::reset_interface_call_counts()
+{
+  ALL_JAVA_THREADS(thread) {
+    thread->set_interface_call_count(0);
+  }
+}
+
+int Threads::interface_call_counts_total()
+{
+  int total = 0;
+  ALL_JAVA_THREADS(thread) {
+    total += thread->interface_call_count();
+  }
+  return total;
+}

 // Lifecycle management for TSM ParkEvents.
 // ParkEvents are type-stable (TSM).

Now we’re ready to add some SPECjvm98-specific code. A quick poke around in SPECjvm98 brings up the method spec.harness.ProgramRunner::runOnce as a likely place to hook ourselves in. This will be run by the interpreter — Shark won’t compile it as it’s only called a few times — so we put our code into the C++ interpreter’s normal entry which is the bit that executes bytecode methods:

diff -r 4cc0bc87aef4 ports/hotspot/src/cpu/zero/vm/cppInterpreter_zero.cpp
--- a/ports/hotspot/src/cpu/zero/vm/cppInterpreter_zero.cpp	Fri May 29 12:46:07 2009 +0100
+++ b/ports/hotspot/src/cpu/zero/vm/cppInterpreter_zero.cpp	Fri May 29 14:44:04 2009 +0100
@@ -42,6 +42,26 @@
   JavaThread *thread = (JavaThread *) THREAD;
   ZeroStack *stack = thread->zero_stack();

+  char *benchmark = NULL;
+  {
+    ResourceMark rm;
+    const char *name = method->name_and_sig_as_C_string();
+    if (strstr(name, "spec.harness.ProgramRunner.runOnce(") == name) {
+      intptr_t *locals = stack->sp() + method->size_of_parameters() - 1;
+      if (LOCALS_INT(5) == 100) {
+        Threads::reset_interface_call_counts();
+
+        name = LOCALS_OBJECT(1)->klass()->klass_part()->name()->as_C_string();
+        const char *limit = name + strlen(name);
+        while (*(--limit) != '/');
+        const char *start = limit;
+        while (*(--start) != '/');
+        start++;
+        benchmark = strndup(start, limit - start);
+      }
+    }
+  }
+
   // Adjust the caller's stack frame to accomodate any additional
   // local variables we have contiguously with our parameters.
   int extra_locals = method->max_locals() - method->size_of_parameters();
@@ -59,6 +79,12 @@

   // Execute those bytecodes!
   main_loop(0, THREAD);
+
+  if (benchmark) {
+    tty->print_cr("%s: %d interface calls",
+                  benchmark, Threads::interface_call_counts_total());
+    free(benchmark);
+  }
 }

 void CppInterpreter::main_loop(int recurse, TRAPS)

This looks a little messy, but what it’s basically doing is spotting calls to spec.harness.ProgramRunner::runOnce and extracting the name of the benchmark from its arguments. It is complicated by the fact that SPECjvm98 intersperses full runs with hidden tenth-speed ones, so we use the speed argument (in LOCALS_INT(5)) to ignore the hidden runs.

Now we’re ready to run the benchmarks and see what happens:

SPECjvm98 results with instrumented VM

Looks like making invokeinterface faster is worthwhile after all! Now all I have to do is do it ;)