With application sonification, you can listen to your code and tell when it’s hurting.
JFugue is an open-source API for programming music in Java. It redresses the shortcomings of Java’s Sound package for working with Musical Instrument Digital Interface (MIDI) data. For example, the following segment of JFugue code plays a scale:
When music programming gets this simple you can build more advanced musical capabilities on top of it without adding significant complexity to the API. For example, you can place musical segments like the above into Pattern objects, and recombine or alter Patterns in a variety of ways (reversed, inverted, pitches or durations changed, etc.) to experiment with musical phrases. JFugue provides an API for creating rhythmic patterns and for microtonal music as well as an API for sending music to, and receiving music from, external MIDI devices.
In this article, we describe an application of JFugue to—of all things—log file analysis.
Debugging on Your Hands and Knees
The enterprise space is characterized by large, complex systems; multi-threading and multi-vendor configurations are the norm. Debugging in this space is painful. Given the importance of these systems it is generally not an option to debug the live production system, and given the scale and cost there is often no realistic lab system available either. And the complexity of the systems means that even the author can’t predict the behavior of each component.
So you end up scrutinizing huge log files trying to understand why the system fell apart. Most of us are all too familiar with these log files. They are a case study of bad signal-to-noise ratio. Typically very large, they contain only fragments of the information we actually need. One of my first experiences as a developer was trying to track down a memory leak while working for Digital Equipment Corporation. I was toiling at a facility known as The Mill, a converted textile mill with enormously long hallways. To go through a log file, I printed off a 50-foot (yes, fifty!) log file printout and spread it out over the floor. For three hours, I crawled on my hands and knees highlighting interesting parts of the log.
You would think that, 20 years later, our technology would have dramatically improved. Yet today it still seems that grep and awk are our frontline tools for log file analysis.
Application Sonification: Use More of Your Senses
One powerful technique for trying to make apparent the behavior of a system is application visualization, in which we create a visual representation of some aspect of the system, using charts, graphs, animated diagrams, or other techniques. We are visual creatures. Our brains are wired to find patterns and anomalies in the information processed by our visual cortex. So it is natural and fruitful to convert software behavior to the visual realm for analysis. But maybe it’s worthwhile to consider our other senses. After all, in the agile and design communities, a common way to describe poor quality is that is has a bad smell.
One drawback of application visualization is that it requires one’s attention—you have to actively look at the visualization to understand it. This prevents you from focusing your attention elsewhere, and it does not facilitate a general ambience of information. We do experience ambient information when we drive a car: our visual senses are focused on the road, but we will know instantly if the car starts to sound different, or if the engine is revving too high.
Enter application sonification. This is a technique for converting a program’s behavior into an audible pattern. In our application Log4JFugue, we convert a log4j output stream into a JFugue music stream and listen to the program’s behavior.
Log file analysis is time-consuming and boring. This is especially true if you are monitoring a system rather than actively diagnosing an existing problem. Monitoring a system visually requires your full attention, whereas listening to changes can be done without attention. Log4JFugue allows you to listen to a rhythmic music stream in the background, hearing the shifts in the beats and instruments without paying active attention. In the same way that an auto mechanic can listen to your car engine and hear the problem, Log4JFugue lets you experience your application’s changing behavior in a new, audible way.
The primary application where Log4JFugue has been used is a Video On Demand (VOD) system. This system meets all of our enterprise criteria in that it is multi-threaded, multi-vendor, distributed, and mission-critical. If this system fails, users can not watch movies, and providers cannot make money. This system also has the characteristic of failing on nights and weekends because that is when people watch the most movies (and it is hopefully a time when developers are asleep or at least away from the office).
How Log4JFugue Works
Log4JFugue creates a mapping from the system verbs to musical instruments. For example, in the VOD space the major verbs are stream create (stream is the term used to describe a video content being played), stream complete, stream failure, and so on.
Log4JFugue contains a Spring configuration file that maps these various verbs to instruments such as:
Whenever we see a log message containing the string for a particular verb, we increment the count of the associated instrument. More stream creates means more Bass Drum beats, more stream failures means more Cymbal Crashes.
Log4JFugue breaks time into one-second intervals. In each second, it is gathering the counts of the various instruments and log messages for the current second while playing the music stream that was created for the previous second. We use a standard double buffering system, accumulating in one buffer, playing from the other buffer, then swapping buffers. Each second consists of a 16-beat measure. Each instrument comprises one layer of the rhythm.
Count-based music (i.e., rhythm) lends itself nicely to this approach. If one stream create event arrives in a second, we play a Bass Drum whole note. If four stream create events arrive in the next second, we play four Bass Drum quarter notes. JFugue allows the creation of arbitrary notes, so we can for example play seven seventh notes.
The actual code to accomplish this is surprisingly simple, thanks to the JFugue API design. The following code creates a layer that will play one instrument note during the next second:
This code creates another layer that will play another instrument four beats during the next second:
JFugue’s Rhythm API combines these layers into a single piece of music.
Putting It All Together
When we demo Log4JFugue we first show people a real log file, gathered on a real system. We feed this 100,000 line file to the screen and ask people to raise their hands when the ratio of creates to failures falls below 80%. Of course, no one can read a log file printed at full speed but it does tend to get a sympathetic laugh. We then run Log4JFugue against the same log file and ask the audience the same question. At first they hear a few Bass Drum beats, followed by a few Snare Drums. Then the pace of the beat increases with more Bass and Snare beats. People can literally hear the system increasing in speed. After about 15 seconds of our demo we hear a Cymbal crash and everyone puts up their hands. They heard a change in the behavior.
But why just rhythm? Originally, Log4JFugue used tonal music, not rhythms, and it sounded awful!
The problem was that Log4JFugue creates a single dependent variable and tonal music requires at least two variables: pitch and duration. We tried creating music using tonal instruments such as pianos, flutes, and guitars all playing the same pitch such as Middle-C, and the results were jarring. We tried varying the pitch based on the count (higher counts per second gave higher pitches), and that sounded bad, too. While not closing the door on further experiments, we decided to switch to rhythm-based instruments where we could ignore pitch.
While Log4JFugue provides benefit, it also incurs some cost in terms of system resources. Each log message that your program outputs must be analyzed by the system, and each message must be compared against the system verb strings you have configured. This results in processor overhead, which can be mitigated in several ways.
First, you can use Log4JFugue on an existing log file, presumably on a non-production machine. By simply changing a Spring configuration file, you can change from live analysis to post-hoc analysis. You can even change the replay speed if desired.
Second, even when doing live analysis you can use the log4j SocketAppender and send the messages off-box for processing. Log4JFugue can run on any machine with connectivity to your production system.
Third, the number of system verbs that you will configure for analysis is limited by the music string you are willing to listen to. Most people lose the ability to distinguish between instruments after about a dozen.
Finally, the string comparison that Log4JFugue uses is not the stock strcmp that comes with the JDK. Instead, we use a highly optimized precompiling pattern matching system from MIT. So, even though Log4JFugue incurs some overhead, there are a number of ways to successfully mitigate that overhead.
Spring-Based, Loosely Coupled
Log4JFugue is a Spring-based system, which means it is a loosely organized collection of Plain Old Java Objects (POJOs). It ships with a number of alternate classes that can be selected via the Spring configuration file. (See figure for system architecture). It is designed around four primary classes, each of which has a number of derived alternative.
The DataGetter retrieves the raw log messages from a socket or a file.
The MessageReceiver processes the messages and increments the instrument counts.
The SoundBuilder converts the instrument counts into a music string (tonal or atonal).
The Player sends the music string to JFugue or just to a file (for later playing).
Setting up Log4JFugue and Your Application
You can download Log4JFugue from www.jfugue.org.
Using Log4JFugue requires configuring both your application and log4j. The only change to your application is to create a SocketAppender in your log4j configuration file. You should not even need to restart your application, as log4j reprocesses it configuration file upon change.
To configure Log4JFugue, set the dataGetter bean to be the SocketDataGetter.
You need to decide on the key verbs of your system and identify distinctive log strings to look for in the message. You then associate those strings with particular instruments.
JFugue is a wonderfully simple API that lets developers create and experiment with music. By lowering the barrier to entry for music programming, JFugue opens the door for many innovative new applications. Log4JFugue is one such application that uses music in a new and productive way, converting the repetitive and boring task of log file analysis into a musical venture. At one level, Log4JFugue is a thought experiment that presents an alternate way to perform a mundane task. If music can be applied here, where else can it be applied? At another level, Log4JFugue stands on its own as a useful solution to a real problem. More information about JFugue can be found at www.jfugue.org and www.jfugue.org/press and Dave has written a JFugue book.
David Koelle is the author of JFugue. Separately, David is a Senior Software Engineer at Charles River Analytics Inc., where he develops user-centered tools that apply intelligent systems techniques to solve real-world problems.
Brian Tarbox is the author of Log4JFugue. He is also a Principal Staff Engineer at Motorola where he designs server side solutions in the Video On Demand Space. He writes a blog on the intersection of software design, cognition and Tai Chi at briantarbox.blogspot.com.