Michael Bien's Weblog

The jlink command line tool can be used to create custom java runtimes, which only include the functionality required by the (modular) java application. However, what if the application isn't modular and still uses the classpath? In this case an extra step is needed to determine which JDK modules are required by the application before jlink can be used.

classic classpaths: finding module dependencies with jdeps

jdeps is excellent for porting classic classpath based applications to java modules. It analyzes jars and list all their dependencies, which can be other jars, or modules, with package granularity. Although we don't want to port the dusty application to the module system for this blog post, listing all the module dependencies is exactly what we need for jlink, to be able to create a custom java runtime.

jdeps produces the following output:

# foo.jar depends on bar.jar
foo.jar -> bar.jar
...
# or foo.jar depends on a module
foo.jar -> module.name
...

Since the tool is intended to assist with porting applications to java modules, the default output will be fairly detailed down to package dependencies. The summary (-s) omits all that and only lists jars or modules.

All we have to do is to go recursively through all jars and remember the module names they depend on.

# -s omit detailed package dependencies
# -R analyze recursively through all found dependencies
# --multi-release 16 for the case that there are multi release jars involved
$JDK/bin/jdeps -s -R --multi-release 16 --class-path 'lib/*' dusty-application.jar
jakarta.persistence-2.2.3.jar -> java.base
jakarta.persistence-2.2.3.jar -> java.instrument
jakarta.persistence-2.2.3.jar -> java.logging
jakarta.persistence-2.2.3.jar -> java.sql
foo.jar -> bar.jar
...

Some greping and deduplication and we have a short list of JDK modules our application depends on.

$JDK/bin/jdeps -s -R --multi-release 16 --class-path 'lib/*' dusty-application.jar\
 | grep -Ev '\.jar$' | cut -d " " -f 3 | sort -u
java.base
java.desktop
java.instrument
java.logging
java.naming
java.net.http
java.security.jgss
java.sql
java.xml
jdk.unsupported

Thats it? Not quite. Analyzing an application like that won't show dependencies which are caused via reflection. So you will have to take a good look at the resulting modules and probably add some manually. A good candidate are jdk.crypto.* modules. jlink can assist with that task too by listing service providers.

$JDK/bin/jlink --suggest-providers java.security.Provider
Suggested providers:
  java.naming provides java.security.Provider used by java.base
  java.security.jgss provides java.security.Provider used by java.base
  jdk.crypto.ec provides java.security.Provider used by java.base
...

You might also want to add modules like jdk.jfr, java.management or jdk.localedata even when the application isn't direclty depending on them. You can experiment with options like --compile-time which will usually list more dependencies (default is runtime analysis). jlink adds transitive dependencies automatically.

Any missing modules should be quickly noticed during integration tests.

custom runtimes with jlink

Once we have the module list we can give it to jlink for the actual heavy lifting.

MODS=...
JDK=/home/mbien/dev/java/jdk-16.0.1+9
DIST=custom-$(basename $JDK)

$JDK/bin/jlink -v --add-modules $MODS\
 --compress=2 --no-header-files --no-man-pages\
 --vendor-version="[mbien.dev pod REv1]"\
 --output $DIST

du -s $DIST

jlink is automatically using the modules of the JDK which contains the tool, which means that the example above will create a runtime based on jdk-16.0.1+9. The flag --module-path would set a path to a alternative module folder. If the application is already modular, the path could also include the application modules, if they should be part of the runtime too.

some noteworthy flags:

• --strip-debug this is going to strip debug symbols from both the native binaries and bytecode, you probably don't want to use this since this will remove all line numbers from stack traces. Its likely that the binaries of the JDK distribution you are using have most of their symbols already stripped.
• --strip-native-debug-symbols=objcopy=/usr/bin/objcopy Same as above, but only for native binaries
• --compress=0|1|2 0 for no compression, 1 for string deduplication, 2 for zip compressed modules. This might influence startup time slightly; see CDS section below
• --include-locales=langtag[,langtag]* include only a subset of locales instead of the full module
• --vendor-version="i made this" this looks uninteresting at first glance but it is very useful if you want to recognize your custom runtime again once you have multiple variants in containers. Adding domain name/project name or purpose of the base image helps.
  It will appear on the second line of the output of java -version

full JDK as baseline

MODS=ALL-MODULE-PATH

# --compress=1
138372 (151812 with CDS)

# --compress=2
102988 (116428 with CDS)

# --compress=2 --strip-debug
90848 (102904 with CDS)

custom runtime example

MODS=java.base,java.instrument,java.logging,java.naming,java.net.http,\
java.security.jgss,java.sql,java.xml,jdk.jfr,jdk.unsupported,java.rmi,\
java.management,java.datatransfer,java.transaction.xa,\
jdk.crypto.cryptoki,jdk.crypto.ec

# --compress=1
55996 (69036 with CDS)

# --compress=2
45304 (58344 with CDS)

# --compress=2 --strip-debug
40592 (52240 with CDS)

(this a aarch64 build of OpenJDK, x64 binaries are slightly larger)

Most modules are actually fairly small, the 5 largest modules are java.base, java.desktop, jdk.localedata, jdk.compiler and jdk.internal.vm.compiler. Since java.base is mandatory anyway, adding more modules won't significantly influence the runtime size unless you can't avoid some of the big ones.

Once you are happy with the custom runtime you should add it to your test environment of the project and IDE.

CDS - to share or not to share?

I wrote about class data sharing before so I keep this short. A CDS archive is a file which is mapped into memory by the JVM on startup and is shared between JVM instances. This even works for co-located containers, sharing the same image layer which includes the CDS archive.

Although it adds to the image size, zip compression + CDS seems to be always smaller than uncompressed without CDS. The CDS file should also eliminate the need to decompress modules during startup since it should contain the most important classes already. So the decision seems to be made easy: compact size + improved startup time and potential (small) memory footprint savings as bonus.

Leaving the CDS out frees up ~10 MB of image size. If this matters to your project, benchmark it to see if it makes a difference. It is also possible to put application classes into the shared archive or create a separate archive for the application which extends the runtime archive (dynamic class data sharing). Or go a step further and bundle the application and runtime in a single, AOT compiled, compact, native image with GraalVM (although this might reduce peak throughput due to lack of JIT and have a smaller choice of GCs beside other restrictions) - but this probably won't happen for dusty applications.

# create CDS archive for the custom runtime
$DIST/bin/java -Xshare:dump

# check if it worked, this will fail if it can't map the archive
$DIST/bin/java -Xshare:on -version

# list all modules included in the custom java runtime
$DIST/bin/java --list-modules

summary

Only a single extra step is needed to determine most of the dependencies of an application, even if it hasn't been ported to java modules yet. Maintaining a module list won't be difficult since it should be fairly static (backend services won't suddenly start using swing packages when they are updated). Make sure that the custom runtime is used in your automated tests and IDE.

Stop using java 8, time to move on - even without a modular application :)

- - - sidenotes - - -

If you want to create a runtime which can compile and run single-file-sourcode-programs adding just jdk.compiler isn't enough. This will result in a a little bit misleading "IllegalArgumentException: error: release version 16 not supported" exception. Solution is to add jdk.zipfs too - I haven't investigated it any further.

If jlink has to be run from within a container (can be useful for building for foreign archs, e.g aarch64 on x64), you might have to change the process fork mechanism if you run into trouble (java.io.IOException: Cannot run program "objcopy": error=0, Failed to exec spawn helper: pid: 934, exit value: 1). (export JAVA_TOOL_OPTIONS="-Djdk.lang.Process.launchMechanism=vfork" worked for me)

I needed a toy project to experiment with JEP 389 of Project Panama (modern JNI) but wanted to take a better look at CRIU (Checkpoint/Restore In Userspace) too. So I thought, lets try to combine both and created JCRIU. The immediate questions I had were: how fast can it defrost a warmed up JVM and can it make a program time travel.

Lets attempt to investigate the first question with this blog entry.

CRIU Crash Course

CRIU can dump process trees to disk (checkpoint) and restore them any time later (implemented in user space) - its all in the name.

Lets run a minimal test first.

#!/bin/bash
echo my pid: $$
i=0
while true
do
    echo $i && ((i=i+1)) && sleep 1
done

The script above will print its PID initially and then continue to print and increment a number. It isn't important that this is a bash script, it could be any process.

shell 1:

$ sh test.sh 
my pid: 14255
0
1
...
9
Killed

shell 2:

$ criu dump -t 14255 --shell-job -v -D dump/
...
(00.021161) Dumping finished successfully

This command will let CRIU dump (checkpoint) the process with the specified PID and store its image in ./dump (overwriting any older image on the same path). The flag --shell-job tells CRIU that the process is attached to a console. Dumping a process will automatically kill it, like in this example, unless -R is specified.

shell 2:

$ criu restore --shell-job -D dump/
10
11
12
...

To restore, simply replace "dump" with "restore", without specifying the PID. As expected the program continues counting in shell 2, right where it was stopped in shell 1.

Rootless CRIU

As of now (Nov. 2020) the CRIU commands above still require root permissions. But this might change soon. Linux 5.9 received cap_checkpoint_restore (patch) and CRIU is also already being prepared. To test rootless CRIU, simply build the non-root branch and set cap_checkpoint_restore to the resulting binary (no need to install, you can use criu directly).

sudo setcap cap_checkpoint_restore=eip /path/to/criu/binary

Note: Dependent on your linux distribution you might have to set cap_sys_ptrace too. Some features might not work yet, for example restoring as --shell-job or using the CRIU API. Use a recent Kernel (at least 5.9.8) before trying to restore a JVM.

CRIU + Java + Panama = JCRIU

JCRIU uses Panama's jextract tool during build time to generate a low level (1:1) binding directly from the header of the CRIU API. The low level binding isn't exposed through the public API however, its just a implementation detail. Both jextract and the foreign function module are part of project Panama, early access builds are available here. JEP 389: Foreign Linker API has been (today) accepted for inclusion as JDK 16 incubator module - it might appear in mainline builds soon.

The main entry point is CRIUContext which implements AutoCloseable to cleanly dispose resources after use. Potential errors are mapped to CRIUExceptions. Checkpointing should be fairly robust since the communication is done over RPC with the actual CRIU process. Crashing CRIU most likely won't take the JVM down too.

    public static void main(String[] args) throws IOException, InterruptedException {
        
        // create empty dir for images
        Path image = Paths.get("checkpoint_test_image");

        if (!Files.exists(image))
            Files.createDirectory(image);
        
        // checkpoint the JVM every second
        try (CRIUContext criu = CRIUContext.create()
                .logLevel(WARNING).leaveRunning(true).shellJob(true)) {
            
            int n = 0;
            
            while(true) {
                Thread.sleep(1000);

                criu.checkpoint(image); // checkpoint and entry point for a restore

                long pid = ProcessHandle.current().pid()
                System.out.println("my PID: "+pid+" checkpont# "+n++);
            }
        }
    }

The above example is somewhat similar to the simple bash script. The main difference is that the Java program is checkpointing itself every second. This allows us to CTRL+C any time - the program will keep counting and checkpointing where it left of, if restored.

[mbien@longbow JCRIUTest]$ sudo sh start-demo.sh 
WARNING: Using incubator modules: jdk.incubator.foreign
my PID: 16195 checkpont# 0
my PID: 16195 checkpont# 1
my PID: 16195 checkpont# 2
my PID: 16195 checkpont# 3
my PID: 16195 checkpont# 4
my PID: 16195 checkpont# 5
CTRL+C
[mbien@longbow JCRIUTest]$ sudo criu restore --shell-job -D checkpoint_test_image/
my PID: 16195 checkpont# 5
my PID: 16195 checkpont# 6
my PID: 16195 checkpont# 7
my PID: 16195 checkpont# 8
my PID: 16195 checkpont# 9
CTRL+C
[mbien@longbow JCRIUTest]$ sudo criu restore --shell-job -D checkpoint_test_image/
my PID: 16195 checkpont# 9
my PID: 16195 checkpont# 10
my PID: 16195 checkpont# 11
my PID: 16195 checkpont# 12
my PID: 16195 checkpont# 13
my PID: 16195 checkpont# 14
CTRL+C

Note: start-demo.sh is just setting env variables to an early access JDK 16 panama build, enables jdk.incubator.foreign etc. The project README has the details.

Important Details and Considerations

• CRIU restores images with the same PIDs the processes had during checkpoint. This won't cause much trouble in containers since the namespace should be quite empty, but might conflict from time to time on a workstation. If the same image should be restored multiple times concurrently, it will have to run in its own PID namespace. This can be achieved with sudo unshare -p -m -f [restore command]. See man unshare for details.
• Opened files are not allowed to change (in size) between checkpoint and restore. If they do, the restore operation will fail. (watch out for log files, JFR repos, JVM perf data or temporary files)
• If the application established TCP connections you have to tell CRIU that via the --tcp-established flag (or similar named method in CRIUContext). CRIU will try to restore all connections in their correct states. wiki link to more options
• The first checkpoint or restore after system boot can take a few seconds because CRIU has to gather information about the system configuration first; this information is cached for subsequent uses
• Some application dependent post-restore tasks might be required, for example keystore/cert replacement or RNG re-initialization (...)
• CRIU can't checkpoint resources it can't reach. A X Window or state stored on a GPU can't be dumped
• Migration should probably only be attempted between (very) similar systems and hardware

Instant Defrosting of Warmed-up JVMs

Lets take a look what you can do with super luminal, absolute zero, instant defrosting JCRIU (ok I'll stop ;)) when applied to my favorite dusty java web monolith: Apache Roller. I stopped the time this blog here would require to start on my workstation when loaded from a NVMe on JDK 16 + Jetty 9.4.34. (I consider it started when the website has loaded in the browser, not when the app server reports it started)

classic start: ~6.5 s

(for comparison: it takes about a minute to start on a Raspberry Pi 3b+, which is serving this page you are reading right now)

Now lets try this again. But this time Roller will warm itself up, generate RSS feeds, populate the in-memory cache, give the JIT a chance to compile hot paths, compact the heap by calling System.gc() and finally shock frost itself via criu.checkpoint(...).

        warmup();    // generates/caches landing page/RSS feeds and first 20 blog entries
        System.gc(); // give the GC a chance to clean up unused objects before checkpoint

        try (CRIUContext criu = CRIUContext.create()
                .logLevel(WARNING).leaveRunning(false).tcpEstablished(true)) {

            criu.checkpoint(imagePath);  // checkpoint + exit

        } catch (CRIUException ex) {
            jfrlog.warn("post warmup checkpoint failed", ex);
        }

(The uncompressed image size was between 500-600 MB during my tests, heap was set to 1 GB with ParallelGC active)

restore:

$ sudo time criu restore --shell-job --tcp-established -d -D blog_image/

real 0m0,204s
user 0m0,015s
sys  0m0,022s

instant defrosting: 204 ms

Note: -d detaches the shell after the restore operation completed. Alternative way to measure defrosting time is by enabling verbose logging with -v and comparing the last timestamp, this is slightly slower (+20ms) since CRIU tends to log a lot on lower log levels. Let me know if there is a better way of measuring this, but I double checked everything and the image loading speed would be well below the average read speed of my M.2 NVMe.

The blog is immediately reachable in the browser, served by a warmed-up JVM.

Conclusion && Discussion

CRIU is quite interesting for use cases where Java startup time matters. Quarkus for example moves slow framework initialization from startup to build time, native images with GraalVM further improve initialization by AOT compiling the application into a single binary, but this also sacrifices a little bit throughput. CRIU can be another tool in the toolbox to quickly map a running JVM with application into memory (no noteworthy code changes required).

The Foreign Linker API (JEP 389) is currently proposed as preview feature for OpenJDK 16, which is a major part of project Panama. However, to use JCRIU on older JDKs, another implementation for CRIUContext would be needed. A implementation which communicates via google protocol buffers with CRIU would completely avoid binding to the CRIU C-API for example.

The JVM would be in an excellent position to aid CRIU in many ways. It already is an operating system for Java/Bytecode based programs (soon even with its own implementation for threads) and knows how to drive itself to safe points (checkpointing an application which is under load is probably a bad idea), how to compact or resize the heap, invalidate code cache etc - I see great potential there.

Let me know what you think.

Thanks a lot to Adrian Reber (@adrian__reber) who patiently answered all my questions about CRIU.

Once JFRLog stored all logs as events in JFR records, you might want to read them out again for inspection and maybe even in an easy readable format which resembles classic log files a bit more.

For this I wrote the JFRPrint utility which was originally a single-file java program (SFJP) but can now be used as jbang script. The utility can format any JFR event, not only log messages.

setup and example

# add the catalog to jbang
$ jbang catalog add jfrlog https://github.com/mbien/JFRLog/blob/master/cli/jbang-catalog.json

# define a log pattern
$ MSG_PATTERN="{eventName,0d,C} {startTime,dt:yyyy-MM-dd HH:mm:ss.SSS}\
 [{eventThread.javaName}] {origin,1d}: {message} {throwable,o,n}"

# print jfr records using the pattern
$ jbang jfrprint 10h log.* "$MSG_PATTERN" dump.jfr
INFO 2020-09-30 16:12:42.458 [main] jfrlogtest.LogTest: Hello There!
INFO 2020-09-30 16:12:42.460 [main] jfrlogtest.LogTest: 1 2 3 test 
WARN 2020-09-30 16:12:42.461 [main] jfrlogtest.LogTest: don't panic 
java.lang.IllegalArgumentException: test, please ignore
	at dev.mbien.jfrlogtest.LogTest.main(LogTest.java:12)
...

Usage is as follows:

jfrprint timespan event_name pattern [jfr_record_file | jfr_repository_folder]

timespan can be set to only print events which happened after now-timespan. The util will print all events matching event_name (supports * wildcard as postfix) if a JFR record is passed as an argument. If it is a repository folder however, it is going to behave similar to tail -f and will stream all upcoming events from the live JFR repository.

To print the usage and more examples simply type:

jbang jfrprint help

message pattern

{fieldName, option1, option2, ..}

The message pattern format fairly simple. The curly brace blocks are replaced with the event field defined by fieldName. Printing the name of the event thread for example becomes {eventThread.javaName}.

Options can be appended in a coma separated list after fieldName.

• dt: prefix defines a date-time format and supports everything what DateTimeFormatter.ofPattern() is able to parse
• c sets the String to lower case, C to upper case
• [0-n]d defines how many dots you want to see. 0d would format "log.Warn" to "Warn". 1d formats "foo.bar.Bazz" to "bar.Bazz"
• o stands for optional and won't print anything if the field is null. This can be useful for printing exceptions when combined with n which adds a new line before the field
• for more options check the source

{...} is a special token which will print all fields which haven't been printed yet. This is especially useful for events which aren't log messages which might have unknown fields.

The following pattern will print all events with all their fields which happened in the last hour:

jfrprint 1h * "{eventName} {startTime} {...}" record.jfr

Note: if no pattern is provided the output will match the multi-line output of OpenJDK's jfr print CLI tool which is also the same format as used in jdk.jfr.Event::toString().

it is still very basic

I wrote it originally as SFJP and tried to keep everything as simple and concise as possible. But since it is now set up as as jbang "script", it would allow to make the CLI experience a bit nicer - which i might do in future ;)

Let me know if you find it useful or want to see a particular feature.

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)
    public class IncomingReferrerEvent extends Event {

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

        public IncomingReferrerEvent(String referrerUrl, String requestUrl) {
            this.referrerUrl = referrerUrl;
            this.requestUrl = 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. The event name is the fully qualified class name by default, but can be overwritten with @Name("dev.foo.NewName").

    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

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

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

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

sudo apt-get install cvs
sudo apt-get install cvs2svn

1. Download the CVS 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

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

btw you can find the jake2 git repo here.

You might remember the project called Jackpot which came out of SunLabs and had James Gosling involved with. It was basically a way to declaratively define refactoring rules, allowing for example, to migrate client code between incompatible third party libraries. The project has been integrated into NetBeans as the IDE's refactoring engine since then. NetBeans 6.9 uses Jackpot for most of the in-code hints and code inspections for instance.

There were 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 ran into while testing the experimental command line 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 as example (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 powerful than 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 to that rule.

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

./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();
...

@@ -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!