Hello JMX, hello JUL!

Jun 5, 2011

When a TrueZIP application is accessing lots of archive files, maybe of different types, or when accessing recursive archive files like they are used for Java web applications or Java enterprise applications, it would be interesting to figure which archive files are currently mounted and which temporary files are used for this. This post features a general purpose file system driver for instrumenting other file system drivers with JMX and java.util.logging for monitoring and managing TrueZIP applications.

The Challenge

In a previous post, I have shown how to use java.util.logging (JUL) to monitor how TrueZIP figures it’s initial setup. However, the TrueZIP modules do not use JUL for anything else but logging their initial setup. So TrueZIP lacks a feature to log which archive files are mounted and which temporary files are used for this. However, thanks to its extensible architecture, this feature can be added without changing any code in TrueZIP or its client application!

The Approach

In the TrueZIP File* module, all access to archive files is done via the TrueZIP Kernel module. In turn, the TrueZIP Kernel module uses file system driver modules for all I/O, even for accessing the platform file system identified by the file URI scheme. So all you would need to do is to provide a custom file system driver in order to monitor - and manage - TrueZIP with JMX or JUL.

To make this file system driver as reusable as possible, it should be a decorator for any file system driver in order to instrument the decorated file system driver with JMX or JUL. And to make it even more reusable, there should actually be two file system drivers, one for instrumenting the decorated file system driver with JMX and another one for instrumenting the decorated file system driver with JUL. We could then compose these instrumenting file system drivers into an enhanced file system driver service.

Next we would like to be able to integrate this enhanced file system driver service into a TrueZIP application without changing a single line of code. So we would need to make it available to the FsDriverLocator.SINGLETON and have the priority of its instrumenting file system drivers increased when compared with other available file system drivers so that the FsDriverLocator.SINGLETON would install the instrumenting file system drivers.

Finally, we could simply throw a JAR with this enhanced file system driver service onto the run time class path to make the magic happen. This should be beautiful for monitoring and managing a TrueZIP application in the field.

Setting The Stage

Following this approach, I have implemented a file system driver which decorates all file system drivers for the TAR, ZIP and ZIP.RAES file formats as well as the FILE and HTTP(S) file system drivers. To demonstrate it, I simply use the Tree class in the TrueZIP Application Archetype module. As you may know, this class prints an ASCII directory tree of a directory and then terminates. When run with no arguments in the project directory of the generated TrueZIP Application Archetype, it’s output may look like this:

.
|-- logging.properties
|-- nb-configuration.xml
|-- nbactions.xml
|-- pom.xml
|-- src
|   `-- main
|       `-- java
|           `-- com
|               `-- company
|                   `-- project
|                       |-- Application.java
|                       |-- Copy.java
|                       |-- Pickr.java
|                       `-- Tree.java
|-- target
|   |-- classes
|   |   `-- com
|   |       `-- company
|   |           `-- project
|   |               |-- Application.class
|   |               |-- Copy.class
|   |               |-- Pickr$1.class
|   |               |-- Pickr.class
|   |               `-- Tree.class
|   |-- generated-sources
|   |   `-- annotations
|   |-- maven-archiver
|   |   `-- pom.properties
|   |-- project-0.1-SNAPSHOT.jar
|   |   |-- META-INF
|   |   |   |-- MANIFEST.MF
|   |   |   `-- maven
|   |   |       `-- com.company
|   |   |           `-- project
|   |   |               |-- pom.xml
|   |   |               `-- pom.properties
|   |   `-- com
|   |       `-- company
|   |           `-- project
|   |               |-- Application.class
|   |               |-- Copy.class
|   |               |-- Pickr$1.class
|   |               |-- Pickr.class
|   |               `-- Tree.class
|   `-- surefire
`-- test.jar
    |-- archive.tar.gz
    |   `-- pom.xml
    |-- archive.tar
    |   `-- pom.xml
    `-- archive.zip
        `-- pom.xml

Notice that I have added the file logging.properties similar to the one shown in the previous post so that I can see logging output.

Furthermore, I have added the file test.jar which contains the three archive files archive.tar.gz, archive.tar and archive.zip, each of which contains a copy of the file pom.xml.

Now as you see, the Tree class recursively prints the (virtual) directory structure of the archive files project-0.1-SNAPSHOT.jar and test.jar with its enclosed archive files.

I said before that I would like to throw the enhanced file system driver service JAR onto the run time class path without a single line of code. However, the Tree class terminates before I could even have a chance to look at my MXBeans with JConsole. So I had to add the following method to the base class Application:

@Override
protected void sync() {
    try {
        Thread.sleep(Long.MAX_VALUE);
    } catch (InterruptedException ex) {
        Logger  .getLogger(Application.class.getName())
                .log(Level.SEVERE, null, ex);
    }
}

This will not only make the utility run forever, it will also prevent it from unmounting the archive files, so that we have something to monitor and manage in the JConsole.

The JMX MXBeans

Now, when running the tweaked utility, I see the output above and then the utility halts. Next, I start JConsole and connect it to the JVM running the Tree class. When changing to the MBeans tab, I can now see some nice MXBeans for TrueZIP. Each of the MXBean classes provide attributes with descriptions so you can figure what’s going on:

The FsManager MXBean represents the file system manager singleton which has been given an artificial MBean ObjectName:

The FsModel MXBeans represent federated file systems alias archive file systems. Because the Tree class has found five archive files in the directory tree, we see five MXBeans, one for each mounted archive file:

Last but not least, the IOPool$Entry MXBeans represent temporary files. It may be hard to follow, but one temporary file is required for each enclosed archive file - so in this case one temporary file for archive.tar.gz, archive.tar and archive.zip within test.jar.

Furthermore, because the TAR file format does not have a central directory, the TAR drivers unroll each TAR file when mounting them - so in this case two temporary files for the file pom.xml in archive.tar.gz and archive.tar are added:

Finally, I promised you there is something to manage: Notice the umount operation on the FsManager and FsModel MXBeans:

If called on an FsModel MXBean with TrueZIP 7.1.3 or later, this unmounts the federated file system for the respective archive file and all enclosed federated file systems. So if called on test.jar, then archive.tar.gz, archive.tar and archive.zip get unmounted, too. With earlier TrueZIP versions, the filtering doesn’t work correctly and accidentally all archive files may get unmounted.
If called on the FsManager MXBean, then all federated file systems get unmounted.
In any case, this will only work if the federated file systems are idle! If any file system is busy doing I/O, then you will get a FsSyncException. So calling this operation is safe.

Once you unmount a federated file system, its respective FsModel and IOPool$Entry MXBeans vanish automatically. So you only see the stuff which keeps TrueZIP busy.

The Log Records

While the MXBeans feature is nice for monitoring and managing mounted federated file systems, JUL can maintain a log of all I/O activities for post-mortem analysis. The enhanced file system drivers instrument their decorated file system drivers to record a stack trace each time a temporary buffer (i.e. temporary file) is allocated or released and each time any file is opened or closed. This is beautiful for post-mortem analysis of left-over-temporary-file, out-of-file-descriptor issues or reducing the need to create temporary files. Actually, I have used the driver successfully to resolve some issues in TrueZIP (#TRUEZIP-49, #TRUEZIP-92 and #TRUEZIP-106).

Here are the log records for the Tree class with TrueZIP 7.1.4. For brevity, I have shortened the stack traces:

Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController
FINEST: Randomly reading de.schlichtherle.truezip.fs.file.nio.FileEntry[name=project-0.1-SNAPSHOT.jar,types=FILE,size(DATA)=7631,size(STORAGE)=7631,time(WRITE)=1307290092285,time(READ)=1307290092261,time(CREATE)=1307290092261,members=null]
de.schlichtherle.truezip.fs.inst.log.NeverThrowable: Relax, this throwable has just been created for the following stack trace and is never thrown.
```...
	at de.schlichtherle.truezip.file.TFile.isDirectory(TFile.java:2014)
	at com.company.project.Tree.graph(Tree.java:63)
	at com.company.project.Tree.graph(Tree.java:74)
	at com.company.project.Tree.graph(Tree.java:74)
	at com.company.project.Tree.work(Tree.java:52)
	at de.schlichtherle.truezip.file.TApplication.run(TApplication.java:74)
	at com.company.project.Tree.main(Tree.java:44)
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController
FINEST: Randomly reading de.schlichtherle.truezip.fs.file.nio.FileEntry[name=test.jar,types=FILE,size(DATA)=4744,size(STORAGE)=4744,time(WRITE)=1307131816805,time(READ)=1307131816801,time(CREATE)=1307131816801,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogInputStreamController
FINEST: Stream reading de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.tar.gz,type=FILE,size(DATA)=1475,size(STORAGE)=1475,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController
FINE: Allocated de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp7665130242097270929.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853144,time(READ)=1307300853144,time(CREATE)=1307300853144,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController
FINER: Stream writing de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp7665130242097270929.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853150,time(READ)=1307300853144,time(CREATE)=1307300853144,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController close
FINER: Closed de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp7665130242097270929.tmp,types=FILE,size(DATA)=5986,size(STORAGE)=5986,time(WRITE)=1307300853159,time(READ)=1307300853144,time(CREATE)=1307300853144,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogInputStreamController close
FINEST: Closed de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.tar.gz,type=FILE,size(DATA)=1475,size(STORAGE)=1475,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogInputStreamController
FINEST: Stream reading de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.tar,type=FILE,size(DATA)=10240,size(STORAGE)=1457,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController
FINE: Allocated de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2086110507762540519.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853165,time(READ)=1307300853165,time(CREATE)=1307300853165,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController
FINER: Stream writing de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2086110507762540519.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853167,time(READ)=1307300853165,time(CREATE)=1307300853165,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController close
FINER: Closed de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2086110507762540519.tmp,types=FILE,size(DATA)=5986,size(STORAGE)=5986,time(WRITE)=1307300853169,time(READ)=1307300853165,time(CREATE)=1307300853165,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogInputStreamController close
FINEST: Closed de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.tar,type=FILE,size(DATA)=10240,size(STORAGE)=1457,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController
FINE: Allocated de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853178,time(READ)=1307300853178,time(CREATE)=1307300853178,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController
FINER: Stream writing de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=FILE,size(DATA)=0,size(STORAGE)=0,time(WRITE)=1307300853181,time(READ)=1307300853178,time(CREATE)=1307300853178,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogOutputSocketController$LogOutputStreamController close
FINER: Closed de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=FILE,size(DATA)=1474,size(STORAGE)=1474,time(WRITE)=1307300853183,time(READ)=1307300853178,time(CREATE)=1307300853178,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController
FINER: Randomly reading de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=FILE,size(DATA)=1474,size(STORAGE)=1474,time(WRITE)=1307300853183,time(READ)=1307300853178,time(CREATE)=1307300853178,members=null]
```...
Jun 05, 2011 9:07:33 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController
FINEST: Randomly reading de.schlichtherle.truezip.socket.IOCache$CacheEntry[delegate=de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.zip,type=FILE,size(DATA)=1474,size(STORAGE)=1474,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController close
FINER: Closed de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=FILE,size(DATA)=1474,size(STORAGE)=1474,time(WRITE)=1307300853183,time(READ)=1307300853178,time(CREATE)=1307300853178,members=null]
de.schlichtherle.truezip.fs.inst.log.NeverThrowable: Relax, this throwable has just been created for the following stack trace and is never thrown.
```...
	at de.schlichtherle.truezip.fs.FsManager.sync(FsManager.java:112)
```...
	at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:791)
```...
	at java.lang.Thread.run(Thread.java:722)

Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController close
FINEST: Closed de.schlichtherle.truezip.socket.IOCache$CacheEntry[delegate=de.schlichtherle.truezip.fs.archive.zip.JarArchiveEntry[name=archive.zip,type=FILE,size(DATA)=1474,size(STORAGE)=1474,time(WRITE)=1306838088000,time(READ)=-1,time(CREATE)=-1]]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController release
FINE: Released de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp7665130242097270929.tmp,types=,size(DATA)=-1,size(STORAGE)=-1,time(WRITE)=-1,time(READ)=-1,time(CREATE)=-1,members=null]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController release
FINE: Released de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2086110507762540519.tmp,types=,size(DATA)=-1,size(STORAGE)=-1,time(WRITE)=-1,time(READ)=-1,time(CREATE)=-1,members=null]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogIOPoolController$LogEntryController release
FINE: Released de.schlichtherle.truezip.fs.file.nio.TempFilePool$TempEntry[name=C:/Users/CHRIST~1/AppData/Local/Temp/.tzp2777101681099613840.tmp,types=,size(DATA)=-1,size(STORAGE)=-1,time(WRITE)=-1,time(READ)=-1,time(CREATE)=-1,members=null]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController close
FINEST: Closed de.schlichtherle.truezip.fs.file.nio.FileEntry[name=test.jar,types=FILE,size(DATA)=4744,size(STORAGE)=4744,time(WRITE)=1307131816805,time(READ)=1307131816801,time(CREATE)=1307131816801,members=null]
```...
Jun 05, 2011 9:07:56 PM de.schlichtherle.truezip.fs.inst.log.LogInputSocketController$LogReadOnlyFileController close
FINEST: Closed de.schlichtherle.truezip.fs.file.nio.FileEntry[name=project-0.1-SNAPSHOT.jar,types=FILE,size(DATA)=7631,size(STORAGE)=7631,time(WRITE)=1307290092285,time(READ)=1307290092261,time(CREATE)=1307290092261,members=null]
```...

As you can see from the first stack trace, the record comes from a call to TFile.isDirectory() by the Tree class. As you can also see, the last records come from the JmxMBeanServer via the JConsole.

Note the use of different logging levels to support filtering interesting log records:

Level.FINE is used for allocating and releasing temporary buffers.
Level.FINER is used for opening and closing temporary buffers.
Level.FINEST is used for opening and closing any other file system entries.

Performance

A final note about performance: Of course there is some impact on the runtime performance of the application by this enhanced file system driver service because all MXBean and logging instrumentation is done synchronously. So this enhanced file system driver service should really only get used for special purposes such as monitoring, managing and analyzing a TrueZIP application. It should not be used on a regular base in a production environment.

Some of the performance impact could be lowered by doing the JMX instrumentation asynchronously, but still the impact of the stack trace logging would be huge, so I think it’s not worth going this route.

Availability

As you have seen, the enhanced file system driver service is very useful for monitoring, managing and analyzing TrueZIP applications. However, it’s not an official part of the TrueZIP open source software, but available as a commercial offering. If you are interested to use the enhanced file system driver service for monitoring, managing and analyzing your own TrueZIP application, please contact me at christian AT schlichtherle DOT de.

Enjoy TrueZIP!