Want to receive a weekly email containing
the scoop on our new titles along with the
occasional special offer? Just click the button.
(You can always unsubscribe later by editing your
account information).

Give us an email and a password (you can use the password later to log in and
change your preferences). We'll send you a newsletter roughly once a week.

...And Your Bugs Can Sing

I can name that bug in five notes.

by David Koelle, Brian Tarbox

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:

Player player = new Player();

player.play("C D E F G A B");

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:

stream create - Bass Drum

stream complete - Snare Drum

stream failure - Cymbal Crash

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:

rhythm.setLayer(1, ".......O........");

This code creates another layer that will play another instrument four beats during the next second:

rhythm.setLayer(2, "..X...X...X...X.");

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.

Performance Considerations

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

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.

log4j.appender.SOCKET=org.apache.log4j.net.SocketAppender

log4j.appender.SOCKET.Port=4445

log4j.appender.SOCKET.RemoteHost=192.168.1.3

To configure Log4JFugue, set the dataGetter bean to be the SocketDataGetter.

<bean id="dataGetter" class="org.log4jfugue.SocketDataGetter">

</bean>

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.

<prop key="OPEN_HI_HAT">sendTrap</prop>

<prop key="MARACAS">stream create</prop>

<prop key="HI_WOOD_BLOCK">destroyImpl</prop>

Conclusion

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.