Logging all method calls by modifying OpenJDK

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Logging all method calls by modifying OpenJDK

Stefano Cristalli
Hello everyone,

please pardon the duplicated request
(https://stackoverflow.com/questions/47267178/logging-all-method-calls-by-modifying-openjdk)
from StackOverflow, but I thought I'd also post here considering how
specific the questions are.

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.

At first I was relying on the new JDK 9 logging feature, but then I
decided to append directly to file to exclude the possibility that the
log was disabled at some point.

I have two questions:

- Have I misinterpreted the cited blog? Shouldn't my first attempt be
enough to log everything?
- Do you have any suggestion for a point where I have better chances
of accomplishing my goal?

Am I missing something?
Thank you in advance for your time.

Best regards.

Stefano Cristalli
Reply | Threaded
Open this post in threaded view
|

Re: Logging all method calls by modifying OpenJDK

David Holmes
Hi Stefano,

It sounds like javaCalls::call is used primarily on interpreted code
paths, so once code has been running long enough and gets compiled you
no longer go through your logging code. If you run with -Xint you should
see all logging; if you run with -Xcomp you should see much less.

Modifying the JIT compiler to include the additional logging is probably
quite complicated - and that's not even taking inlining into account.

David

On 14/11/2017 1:37 AM, Stefano Cristalli wrote:

> Hello everyone,
>
> please pardon the duplicated request
> (https://stackoverflow.com/questions/47267178/logging-all-method-calls-by-modifying-openjdk)
> from StackOverflow, but I thought I'd also post here considering how
> specific the questions are.
>
> 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.
>
> At first I was relying on the new JDK 9 logging feature, but then I
> decided to append directly to file to exclude the possibility that the
> log was disabled at some point.
>
> I have two questions:
>
> - Have I misinterpreted the cited blog? Shouldn't my first attempt be
> enough to log everything?
> - Do you have any suggestion for a point where I have better chances
> of accomplishing my goal?
>
> Am I missing something?
> Thank you in advance for your time.
>
> Best regards.
>
> Stefano Cristalli
>
Reply | Threaded
Open this post in threaded view
|

Re: Logging all method calls by modifying OpenJDK

Andrew Dinn
In reply to this post by Stefano Cristalli
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