Logging all method calls by modifying OpenJDK

[Andrew Dinn]

On 13/11/17 15:37, Stefano Cristalli wrote:
> I'm trying to modify the OpenJDK 9 in order to log every method called
> by a Java program, in particular I'm experimenting with a very simple
> class with a main that calls one of its own static methods that prints
> a line on stdout once every two seconds (waiting done with
> Thread.sleep) After reading a blog post (https://gbenson.net/?p=118),
> I've put logging code inside javaCalls::call. It works, logging lots
> of calls from the JVM start up to the call to Myclass.main, then it
> stops (my program keeps printing). After exiting the program with
> CTRL^C, the logging resumes and logs methods such as Thread.exit. I
> then tried another way: to instrument
> hotspot/src/share/vm/interpreter/bytecodeInterpreter.cpp at every
> bytecode for invoke. Worse than before, this doesn't print anything.

I am very sceptical of your claim here. Is this really all you have changed.

I say that because (as Gary's post notes) JavaCalls::call is the C++
method which performs a transition into Java from C++. That happens at
least once in a Java thread lifetime when the thread is started (so, for
example, at the transition into your main class's main method). It may
also be called recursively in the same thread, but only if that thread
calls out to a C++ method of the JVM and the JVM then calls back into
Java. However, that is the rare case not the normal case.

For example, it might happen because, say, execution of a Java method
triggers a class load. In that case JVM code may be invoked to create
and resolve the class and the JVM may re-enter Java to run the class
static initializer.

Normal Java to Java calls will *not* go via JavaCalls::call either in
interpreted code or in compiled code. So, logging from this point will
only show you a *very* partial subset of the Java execution tree.

> I have two questions:
> 
> - Have I misinterpreted the cited blog? Shouldn't my first attempt be
> enough to log everything?

No, it should not.

> - Do you have any suggestion for a point where I have better chances
> of accomplishing my goal?

Run in interpreted mode (-Xint) and add tracing to the template
interpreter snippets that handles method invocation and method return.
It's complicated code so expect to spend quite some time understanding
how it works. Also, much of the code is architecture-specific so as well
as looking at the generic code in

  hotspot/src/share/vm/interpreter/*.[ch]pp

you may need to make changes to code in

  hotspot/src/cpu/xxx/vm/*.[ch]pp

where xxx is your preferred cpu (probably x86 but you never know :-).

Start looking at files with the word 'template' in then. The'template'
interpreter is the one currently in use. The alternative 'bytecode'
interpreter is a legacy interpreter written mostly in C++ so changing it
will not help you.

regards,


Andrew Dinn
-----------
Senior Principal Software Engineer
Red Hat UK Ltd
Registered in England and Wales under Company Registration No. 03798903
Directors: Michael Cunningham, Michael ("Mike") O'Neill, Eric Shander