//Tracking Apache Roller page views using JFR custom events

The Java Flight Recorder is great for monitoring the JVM but after checking out the new JFR Event Streaming in JDK 14, I was curious how well it would work in practice for basic logging needs. I always wanted to generate some page view statistics for this web blog but never liked the idea of tracking users in their browsers (or at least those few who turned off tracking protection for some reason or used a outdated browser).

So lets take a look if we can record custom page view events using JFR instead of logging or storing stats in a database.

The goal is to record the link the anonymous reader clicked to get to the page (or null) and the actual page on the blog which is visited.

Custom Event

    @Label("Incoming Referrer Event")
    @Description("Reader landed on the Blog.")
    @StackTrace(false)
    private class IncomingReferrerEvent extends Event {

        @Label("Referrer URL")
        private final String referrerUrl;
        
        @Label("Request URL")
        private final String requestUrl;

        private IncomingReferrerEvent(String referrerUrl, String requestUrl) {
            this.referrerUrl = referrerUrl;
            this.requestUrl = requestUrl;
        }

        public String getReferrerUrl() {
            return referrerUrl;
        }

        public String getRequestUrl() {
            return requestUrl;
        }

    }

Defining a custom JFR event is trivial, simply extend jdk.jfr.Event and annotate the fields, the code should be self explanatory.@StackTrace(false) disables the recording of stack traces since we don't need it for this event. Custom events are enabled by default.

    new IncomingReferrerEvent(referrerUrl, requestUrl).commit();

Records the event (placed somewhere in doGet() of Apache Roller's HttpServlet). Events can have a beginning and an end, by simply calling commit() without begin() or end(), only the time stamp at commit and the event values are stored. Due to the design of the JFR you don't really have to worry about concurrency because the events are held in thread-local buffers before they are flushed to disk which should make it fairly performant even in highly parallel settings.

Configuration

The next step is to setup a JFR configuration file.


<?xml version="1.0" encoding="UTF-8"?>
<configuration version="2.0" label="Blog" description="Roller JFR Events" provider="Duke Himself">

    <event name="org.apache.roller.weblogger.jfr.IncomingReferrerEvent">
        <setting name="enabled">true</setting>
    </event>

</configuration>

I could have used the default configuration provided by the jdk but this would lead to much larger file sizes after some uptime. The configuration above only enables our custom event, everything else is turned off. For a larger blueprint see JDK_HOME/lib/jfr/default.jfc.

Once the server is running we can switch the recording on using jcmd. ($1 is the PID)

jcmd $1 JFR.configure repositorypath="/home/server/jfr" samplethreads=false
jcmd $1 JFR.start name="blogstats" settings="/home/server/jfr/blog.jfc"

First Test - 8 MB, not great, not terrible

After a quick test we can plot the summary of the recording file in the repository to check if we see any events.

jfr summary 2020_02_03_04_35_07_519/2020_02_07_16_46_39.jfr 

 Version: 2.1
 Chunks: 1
 Start: 2020-02-07 15:46:39 (UTC)

 Event Type                                             Count  Size (bytes) 
==============================================================================
 jdk.CheckPoint                                        130997      12587784
 org.apache.roller.weblogger.jfr.IncomingReferrerEvent     66          4735
 jdk.Metadata                                               1         81383
 jdk.ThreadEnd                                              0             0
 jdk.TLSHandshake                                           0             0
 jdk.ThreadSleep                                            0             0
 jdk.ThreadPark                                             0             0
 jdk.JavaMonitorEnter                                       0             0
...

There it is, we can see IncomingReferrerEvent in the record. You might be wondering what those jdk.CheckPoint events are. I wasn't sure either since I noticed them the first time with JDK 14 and a websearch resulted in no hits, so I asked on hotspot-jfr-dev. It turns out that they are part of the file format - for more details read the reply or even better the rest of the mail thread too.

The check points will create around 8 MB of data per day (one check point per second), which can be seen as static footprint without recording any actual events. 8 MB, not great, not terrible.

More Events

Having now a good estimate for the footprint, it was time to enable more events. Since the correlation of IncomingReferrerEvents with GC events, network/CPU load or thread count might be interesting given that it all is running on a Raspberry Pi 3b+ with limited resources. I ended up enabling some more events after grep'ing the code base of VisualVM for event Strings (it looks like JFR support is coming soon, the custom build I am using looks fairly complete already) and then adding them to the blog.jfc config file.

jfr summary blog_dump06.jfr 
...
 Event Type                                              Count  Size (bytes) 
==============================================================================
 jdk.CheckPoint                                        1223057     118202307
 jdk.NetworkUtilization                                 264966       4731868
 jdk.CPULoad                                            242765       6198487
 jdk.ActiveSetting                                        3348        123156
 org.apache.roller.weblogger.jfr.IncomingReferrerEvent    6367         89338
 jdk.GCHeapSummary                                         830         35942
 jdk.GarbageCollection                                     415         12577
 jdk.Metadata                                               13       1038982
 jdk.JVMInformation                                         12         27113
 jdk.GCHeapConfiguration                                    12           353
 jdk.ActiveRecording                                        12           727

Even with the added events and another 14 day test run I ended up with a file size of about 130 MB. That is about 9.28 MB per day - mostly CheckPoints ;) - in fact ~118 MB of them. luckily the file compresses nicely.

The undocumented Flag

If you take a look at the JDK sources you notice a flag with the description: "flush-interval, Minimum time before flushing buffers, measured in (s)econds..." - sounds exactly what we need.
jcmd $1 JFR.start name="blogstats" flush-interval=10s settings="/home/server/jfr/blog.jfc"

Results look promising: as expected around 10x reduction in CheckPoint events. (I don't have more data to show since I literally just added the flag and rebooted the server as I am typing this)

update: size of the record dump file after ~14.3 days (343h) is 25.13 MB which is about 1.8 MB per day - much better.

I can't recommend relying on undocumented or hidden flags since they can change or go away without notice (@see hotspot-jfr-dev discussion). The realtime nature of event streaming is also gone with a buffer delay of 10s, so keep that in mind.

The File Format

The file format for the JFR repository and record dumps isn't standardized and can change. So another thing to keep in mind if JFR is used for logging is that it might not be possible to read old JDK 14 dumps with JDK 20 in future (although reading JDK 11 dumps with 14 works just fine). But this doesn't sound like a big issue to me since JDKs don't just disappear, it will always be possible to open JDK 14 dumps with JDK 14 (and maybe even with JDK 20 from the future if backwards compatibility can be maintained).

Conclusion

Although the static footprint of the JFR in JDK 14 came as a surprise I am not too concerned of it. Storage is cheap and I am sure the issue will be solved or reduced to a minimum in one way or another.

The benefit of tracking my blog stats with JFR is that I can inspect them with the same tools I would use for JVM performance monitoring (VisualVM, JDK Mission Control, etc). JFR Event Streaming and the OpenJDK command line tools make it also easy to access the data in a structured manner.

JFR can not only be used for JVM monitoring but certainly also for structured logging in some scenarios. Log files will probably never disappear completely and I am sure JFR (or the original JRockit Flight Recorder implementation) was never intended to fully replace a logging framework but maybe one day logs will mostly contain lines produced by Event#toString() running dual stacks where it is still required :).

fly safe


//JFR Event Streaming with Java 14

The Java Flight Recorder has a long history. It used to be part of the BEA JRockit JVM, became a commercial feature of the Oracle JDK (7+) after Oracle acquired BEA and Sun and was finally fully open sourced with the release of OpenJDK 11 (backports exist for 8) (JEP328). OpenJDK 14 will add some improvements to the JFR.

JEP 349 will allow the continuous consumption of java flight recorder events in-memory from within the same JVM, or out-of-process from a different JVM via its JFR repository file.

JEP 349 made it already into the early access builds and can be experimented with since OpenJDK 14 build 22+. Lets check it out.

In-Process Streaming

The base JFR configuration files (XML) can be found in JDK_HOME/lib/jfr. The default configuration (default.jfc) is relatively low overhead, while profile.jfc will provide more data. Java Mission Control can create custom settings based on templates if needed. I am using the default config for the examples.

The first example will start JFR on the local JVM using the default recorder settings and register a few event handlers to check if it is working.

import java.io.IOException;
import java.text.ParseException;
import jdk.jfr.Configuration;
import jdk.jfr.consumer.EventStream;
import jdk.jfr.consumer.RecordingStream;

public class JFRStreamTest {
    
    public static void main(String[] args) throws IOException, ParseException  {
        
        Configuration config = Configuration.getConfiguration("default");
        System.out.println(config.getDescription());
        System.out.println("settings:");
        config.getSettings().forEach((key, value) -> System.out.println(key+": "+value));
        
        // open a stream and start local recording
        try (EventStream es = new RecordingStream(config)) {
            
            // register event handlers
            es.onEvent("jdk.GarbageCollection", System.out::println);
            es.onEvent("jdk.CPULoad", System.out::println);
            es.onEvent("jdk.JVMInformation", System.out::println);
            
            // start and block
            es.start();
        }
    
    }
    
}

The above example should print information about the running JVM once, CPU load periodically and GC events when they occur.

Out-of-Process Streaming

Simply start the flight recorder as usual via jcmd <PID> JFR.start or via the JVM flag -XX:+FlightRecorder at startup. The repository location will be stored in the jdk.jfr.repository system property as soon JFR is running (new in Java 14). It can also be set at startup via a comma separated list of flight recorder options: -XX:FlightRecorderOptions=repository=./blackbox

Update thanks to Erik from Oracle in the comments section: The repository location can be also set using jcmd <PID> JFR.configure repositorypath=<directory>. If you set it after a recording has started, new data will be written in the new location.

$ jcmd -l | grep netbeans
8492 org.netbeans.Main ... --branding nb

$ jcmd 8492 JFR.start name=streamtest
Started recording 1. No limit specified, using maxsize=250MB as default.
Use jcmd 8492 JFR.dump name=streamtest filename=FILEPATH to copy recording data to file.

$ jinfo -sysprops 8492 | grep jfr
jdk.jfr.repository=/tmp/2019_11_18_02_19_59_8492

Now that the recording is running and we know where the repository is, a second JVM can open a stream to the live JFR repository and monitor the application. Note that we did not dump any JFR records to a file, we connect to the live repository directly.

import java.io.IOException;
import java.nio.file.Path;
import jdk.jfr.consumer.EventStream;

public class JFRStreamTest {
    
    public static void main(String[] args) throws IOException  {
        // connect to JFR repository
        try (EventStream es = EventStream.openRepository(Path.of("/tmp/2019_11_18_02_19_59_8492"))) {
            
            // register some event handlers
            //es.onEvent("jdk.CPULoad", System.out::println);
            es.onEvent("jdk.SocketRead", System.out::println);
            es.onEvent("jdk.SocketWrite", System.out::println);
            
            // start and block
            es.start();
        }
    
    }
    
}

As a quick test i monitored with the example above a NetBeans instance running on Java 14 and let the IDE check for updates. Since we watch for SocketRead and Write events the output looked like:

jdk.SocketRead {
  startTime = 04:34:09.571
  duration = 117.764 ms
  host = "netbeans.apache.org"
  address = "40.79.78.1"
  port = 443
  timeout = 30.000 s
  bytesRead = 5 bytes
  endOfStream = false
  eventThread = "pool-5-thread-1" (javaThreadId = 163)
  stackTrace = [
    java.net.Socket$SocketInputStream.read(byte[], int, int) line: 68
    sun.security.ssl.SSLSocketInputRecord.read(InputStream, byte[], int, int) line: 457
    sun.security.ssl.SSLSocketInputRecord.decode(ByteBuffer[], int, int) line: 165
    sun.security.ssl.SSLTransport.decode(TransportContext, ByteBuffer[], int, int, ...
    sun.security.ssl.SSLSocketImpl.decode(ByteBuffer) line: 1460
    ...
  ]
}
...

Streaming Dumped Records

Opening streams (EventStream.openFile(path)) to JFR record dumps (jcmd <PID> JFR.dump filename=foo.jfr) is also possible of course - works as expected.

Conclusion

Pretty cool new feature! It is currently not possible to do in-memory but out-of-process steaming without syncing on repository files. But since a ramdisk can workaround this issue so easily I am not even sure if this capability would be worth it.

fly safe


//Converting from CVS to GIT

This post is a short description how to convert a CVS repository into GIT. I used the tool cvs2svn from Tigris.org for this task. As an example I will use the project jake2.

0. Install cvs2svn and cvs

('cvs2svn' not only does cvs2svn conversion it also contains the shell commands cvs2git and cvs2bzr)
sudo apt-get install cvs
sudo apt-get install cvs2svn

1. Download the CVS repository

This is mandatory. In contrary to SVN you can't just read out the complete versioning history just by using the CVS protocol. To convert from CVS you will need direct file access to the repository.

Sourceforge for example supports repository synchronization via rsync to allow backups. Thats what I used to get a copy of the jake2 repository.

rsync -av rsync://jake2.cvs.sourceforge.net/cvsroot/jake2/* .

2. Convert into GIT fast-import format

Take a look at /usr/share/doc/cvs2svn/examples/cvs2git-example.options.gz and extract the example configuration file. The file is very good documented so I won't repeat things here. But the most important step is to provide an author mapping from cvs to git authors (search for 'author_transforms').
cvs2git --options=cvs2git.options

This will produce a dump and blob file for step 3.

3. Create GIT repository and import CVS history

mkdir gitrepo
cd gitrepo
git init
cat ../repo-tmp/git-blob.dat ../repo-tmp/git-dump.dat | git fast-import

4. Manual cleanup

cvs2git will do its best to convert tags and branches into git tags and branches and usually add an artificial commit do document that. Now you will probably want to take a look at the repository with a history browser like gitk or giggle... and clean it up a bit. E.g remove branches which could be tags etc. If this is to much work you might consider to tweak the configuration of step 2 and convert again with different strategies.

- - - -

btw you can find the jake2 git repo here.


//You have won the Jackpot 3.0

You probably remember the project called Jackpot which James Gosling was initially involved with. It was basically a way to migrate client code between incompatible third party libraries by specifying refactoring rules. The project was that good integrated into NetBeans that it looked dead from the outside for a long time, since it was only used internally. NetBeans 6.9 uses Jackpot for most of the in-code hints for instance.

There where various ways to specify the transformation rules, e.g. via a special declarative language or even in Annotations directly in the library-code which would cause incompatibilities (or e.g in conjunction with @Deprecated).

Jan Lahoda recently started with the efforts to make the project usable as standalone tool again. Jackpot 3.0 is available via bitbucket for early adopters.

Back to the Future

I used this opportunity to test jackpotc (the jackpot compiler) with JOGL. What I tired is to provide transformations which transform old JOGL 1.1.1 code into latest JOGL 2 compatible client code. So firstly thanks to Jan for fixing all the bugs we run into while testing the experimental commandline compiler.

The first thing I did was to transform the code to properly use OpenGL profiles. As testcode i will use the famous Gears OpenGL demo (but those kind of automatic transformations will only pay of if you use them on large codebases). Since it was written against JOGL 1.1.1 it can only use OpenGL up to version 2.x, which means we can simply use the GL2 profile.

Transformation Rules

'JOGL2 API change: javax.media.opengl.GL -> javax.media.opengl.GL2':
javax.media.opengl.GL=>javax.media.opengl.GL2;;

'JOGL2 API change: new javax.media.opengl.GLCapabilities(javax.media.opengl.GLProfile)':
new javax.media.opengl.GLCapabilities()=>
new javax.media.opengl.GLCapabilities(javax.media.opengl.GLProfile.get(javax.media.opengl.GLProfile.GL2));;

'JOGL2 API change: GL gl = drawable.getGL() -> GL2 gl = drawable.getGL().getGL2()':
$d.getGL() :: $d instanceof javax.media.opengl.GLAutoDrawable=>
$d.getGL().getGL2();; 

Just by looking at the transformation rules you can easily see that it is far more powerfull as any simple text replacement could be. Jackpot uses javac and can therefore work with full qualified names, instanceof and more. It will also correctly fix imports for you (there is currently a open bug in this area). The quotes are used as description string which will be printed when jackpotc runs on every code occurrence which applies.

Invoking Jackpot

jackpotc -sourcepath $SRC -cp $LIBS -d $OUTPUT\
         -Ajackpot30_extra_hints=./jogl1Tojogl2.hint $FILESET

$LIBS must contain both library versions, JOGL 1.1.1 and JOGL 2. This is not optimal but it will probably work in most situations to just use both without thinking about an particular ordering or the need to do multiple iterations.

Results

If everything runs fine the console output should look like the sample below for each transformation which applies for the given $FILESET:
./test/oldgears/src/jogl111/gears/Gears.java:54: warning: JOGL2 API change: GL gl = drawable.getGL() -> GL2 gl = drawable.getGL().getGL2()
    GL gl = drawable.getGL();
...
The final result is a diff patch located in $OUTPUT/META_INF/upgrade called upgrade.diff containing the complete changeset for the transformation. Now the only thing you have to do is to review the changes and apply them.
@@ -51,7 +51,7 @@
     // Use debug pipeline
     // drawable.setGL(new DebugGL(drawable.getGL()));
 
-    GL gl = drawable.getGL();
+    GL2 gl = drawable.getGL().getGL2();
...

You can find the complete demo and all ready-to-run shellscripts in the tools/jackpotc folder inside JOGL's git repository. The classic JOGL 2 Gears demo can be found in form of an applet here (uses latest hudson builds... can be unstable).

happy coding!


- - - -
The JOGL repositories are open for contributions. If you would like to add some rules or fix other things... feel free to fork the repos on github and commit to them. (same rule applies for all JogAmp Projects like JOCL, JOAL, GlueGen... etc)