This is going to be a fairly short post. Logging vs Memory was about tracking performance in Blindsight, and measuring the stress that logging puts on JVM garbage collection. I've hooked up play-blindsight with all the recommendations, and tried it out with a general load test using Gatling. Will write about that later.
But I also got distracted, so this is about something else.
Keeping track of JVM allocation rates and GC data is kind of a pain. Most of the time you're looking for a general idea of what's going on – I also don't like looking at graphs all that much and didn't to bounce backwards and forwards between different logs.
Then I had an idea.
I have a very odd urge to setup GC behavior as auditory cues using @unlog1c's https://t.co/biXZy47xJV so you hear allocation rate as a hz tone and GC events as record scratches
— Will Sargent (@will_sargent) July 10, 2020
It turns out that there's a project called jSyn that makes this easy. jSyn is used as the sound engine for the incredibly popular Processing project, so it's more than fit for purpose.
I hooked up the allocation rate to a sine wave using jvm-alloc-rate-meter, so that 440 MB/sec produces a 440 Hz tone. This produced some happy burbling noises at around 100 rps, which quickly progressed to protesting warbles under load.
I used GarbageCollectorMXBean to play garbage collection events as percussion. A happy JVM running G1GC has minor GCs every second or so, and sounds like a heartbeat. Put the system under load, and the heartbeat speeds up.
Finally, I added jvm-hiccup-meter and tied it to a hiccup sample. Now, when there's a significant discrepancy between the desired sleep time and the actual sleep time of the application, you hear a hiccup. This told me a bunch about what sort of overhead running a load test in Virtualbox did to the JVM. At high rates, hiccups were very frequent.
I've made the project available on github and bintray. You can listen to some example recordings in MP3.
It's straight Java, and you can run it as a Java agent, although I have not shadowed the dependencies (so you'll need to include them in the classpath). If you want to copy the entire thing, it's one Java file and it's under CC0 license.
This is a fun project, but the more interesting idea is being able to extend the idea of having continuous audio cues providing immediate feedback on the health of the system, especially for underlying "engine" metrics that you may not pick up on consciously. It's relatively simple to hook up sounds to Dropwizard Metrics and JFR events, for example. I've done some previous work with audio markers in Logback, but I haven't seen other Java projects doing this.
The big advantage of having an audio system is that it's audible. It's not "one more thing to look at" and you can ignore it for the most part. The big obstacle in providing audio cues is that… well, it's audible. It can sound quite disagreeable under load, and even in the happy case it's not my favorite noise. It's not going to give you a precise number, and it's very easy to overload the channel with a bunch of noise.
Everything I researched talks about user experience with audio feedback as an "alarm" mechanism, which is not what I'm going for here. If anything, I'd like it to be an ambient pleasant "background water noise" under most circumstances, with any errors and hiccups presenting as distortions and sour notes. This is clearly a feature that requires careful user experience and design to get right, but I think it can be built up over time.
Comments