Michael Bien's Weblog

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.

I just wrote JFRLog - a lightweight SLF4J logger implementation which lets you log directly into the Java Flight Recorder. Since SLF4J (Simple Logging Facade for Java) has a binding to basically every logging framework out there, it doesn't even matter how the logging is done or how many frameworks the application or the dependencies use (hopefully not many).

Why? I was mostly curious how practical something like that would be and it turned out it works great. If you are running linux its likely that most of the logging is already centralized and stored in binary form and you need tools like journalctl to read it. If you ever had to correlate log files with events of a JFR recording you probably also asked yourself why isn't everything in the recording in the first place. Having everything in one place simplifies containers too.

JFRLog

The project is available on github under the MIT License. It requires JDK 8+ to run but JDK 14+ to build/test since the JUnit tests rely on the event streaming API. JFRLog's only dependency is the SLF4J API.

quickstart

The basic 2.5 steps to get it working are:

1. replace your SLF4J compatible logging impl with slf4j-jfr-bridge-x.x.x.jar
2. start the JVM with JFR enabled (e.g. -XX:StartFlightRecording:filename=logs/dump.jfr,dumponexit=true) or enable recording later
3. check the flight recorder repository or recording dump for log.* events

update: artifacts of the first release are now available on maven central.

    <dependencies>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.30</version>
        </dependency>
        <!-- depends on slf4j-api -->
        <dependency>
            <groupId>dev.mbien.jfrlog</groupId>
            <artifactId>slf4j-jfr-bridge</artifactId>
            <version>0.1.0</version>
        </dependency>
    </dependencies>

(adding slf4j-api is optional since it is already a dependency of JFRLog but it is a good practice to depend on the interface and makes it also more obvious what is going on)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class HelloJFRLog {
    private final static Logger log = LoggerFactory.getLogger(HelloJFRLog.class);
    public static void main(String[] args) {
        log.info("does it work?");
    }
}

inspect the flight record:

$ jfr print --events "log.*" test_dump.jfr
log.Info {
  startTime = 11:52:15.954
  message = "does it work?"
  origin = "dev.mbien.jfrlogtestproject.HelloJFRLog"
  throwable = N/A
  eventThread = "main" (javaThreadId = 1)
}

Thats it! Log and JFR events all in one place.

configuration

Configuration is straight forward. You can set log levels via java -D arguments or via a jfrlog.properties file and place it into the classpath. Java -D args are treated with higher priority than the configuration file to simplify testing.

# Sets MyKlass to debug, the rest of the package to error and the default log level
# to info (for everything which isn't explicitly configured). 
# The most specific rule wins (order does not matter).
jfrlog.default=info
jfrlog.dev.cool.app=error
jfrlog.dev.cool.app.MyKlass=debug

You can also disable entire log levels by disabling the corresponding events in the JFR recording profile if so desired.

this blog you are reading is using it right now

The Apache Roller blog is a big dusty webapp with many dependencies. Since dependencies use their own favorite logging framework its a nice example of a near-worst-case-scenario a.k.a.: the LoggingHell (extends JarHell). Half of the Apache libs use the old Java Commons Logging layer, struts2 depends on log4j2 for some reason, some webjars use java.util.logging, eclipselink uses its own (!) logging but thankfully with a SLF4J compatibility extension and roller used log4j1 at some point (the version in my WIP branch uses log4j2). Ah, and the web server needs some logging too, but thankfully Jetty uses the SLF4J layer so it doesn't care that much.

So, to see some text in a file, all what is needed is:

• jcl-over-slf4j to connect the JCL abstraction layer to the SLF4J layer for spring etc
• log4j-to-slf4j to make struts happy
• jul-to-slf4j for webjars (i think)
• org.eclipse.persistence.extension to bridge eclipselink's personal logger to SLF4J

Beautiful, all logs lead to SLF4J now. We only forgot about the logging impl itself. Usually you would have a log4j-slf4j-impl or logback-classic there - most likely. But to enable JFRLog all what is needed is to replace it with slf4j-jfr-bridge and that was exactly what I did.

I also wrote some java (single file java program) scripts using the JFR streaming API for easy inspection of the logging repository. (but that is probably a story for another time update: CLI tools blog entry)

How many new logging frameworks or abstraction layers will the current pandemic give us?

Let me know what you think.

fly safe (and keep JFR on)

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