Logging performance in Java

This is a topic that has probably been done to death, but I had some questions around it and decided to answer them for myself for a change. I thought it would be a decent way to restart my blog, which has always been a curious mix of my professional and personal lives.

Right now, I'm being paid to work on the JXTA project by OneDrum, which is a very interesting position to be in (Paid? To work on open source software?). The coding conventions for JXTA state that if you are going to write to a log, you must have code that looks like this:

if (Logging.SHOW_WARNING && LOG.isLoggable(Level.WARNING)) {
  LOG.warning( "This is your final warning." );
}

When I first saw this, I wanted to throw up. It's a lot of code for a relatively simple thing - I just want to write something to a log, if that log level is turned on. When you have a lot of logging in your code (and for a distributed system like JXTA that is virtually impossible to debug you need it), it's a major distraction from the intent of the surrounding code.

Lets break it down, so we're clear on what exactly is happening here. First of all, Logging is a class with a bunch of static finals like SHOW_WARNING, SHOW_INFO, SHOW_FINEST that are initialised based on the value of a java system property. This is done in a static block. So, as soon as you touch the Logging class these are set up and never change again for the lifetime of that class (probably the lifetime of the process). These constants are provided within JXTA as a global, convenient way of changing the logging level of all JXTA code. It can also be done by changing the logging level for "net.jxta" in your logging configuration file.

Secondly, we have the call to LOG.isLoggable, which is typically a static final instance of java.util.logging.Logger for the class which we are currently within. This allows for logging level for specific classes, or package subtrees, to be respected by this code.

Finally, we have the call to LOG.warning() itself. Now, for those unfamiliar with logging, if you call warning() and warning level logs have been disabled, it will do nothing.

So, why do we do all of this? This leads to a number of questions.

How expensive is string concatenation, really?
What is the overhead of a method call?
What is the overhead of an if statement?
What is the cost of checking a static final field?

In order to answer all these questions, I wrote a little test to see the time difference if I


Called the log method directly, string concatenation before call
Called the log method directly, which used String.format() internally, with varargs accepted for parameters
Called a log method directly, which uses String.format() internally, method declared with fixed number of args
Checked only isLoggable() in the condition before logging
Checked both the constant and the condition before logging


Testing with a 2GHz Core 2 Duo Macbook using Java 1.5.0_19_b02-304, the results were:

Direct call, string concatenation: 28739ns (nanoseconds)
Direct call, String.format(), varargs: 57ns
Direct call, String.format(), fixed args: 34ns
Checking LOG.isLoggable first: 3.46ns
Checking constant, then LOG.isLoggable(): 3.18ns

So, allowing the string concatenation to occur is clearly something we want to avoid, given it is 3 orders of magnitude worse than the next-worst result. If you avoid constructing the string by using String.format() inside the log method (as slf4j allows), then the call time is measured in nanoseconds rather than microseconds.

However, a varargs method does not come for free. Presumably those arguments are packaged into a new array, which incurs an object instantiation cost. This is confirmed by doing the same call, but with a version of the log method that takes a fixed number of arguments, shaving 40% off the overall time per call.

But, the big savings occur if you don't even make that method call. If we call a simple accessor method like isLoggable(), things are an order of magnitude faster again.

Finally, if we check a static constant, it is marginally faster again. But now we're talking picoseconds faster, so it's negligible and going to be completely swamped by other factors.

What happens if we run this again, using Java 1.6.0_13-b03-211?

Direct call, string concatenation: 9795ns
Direct call, String.format(), varargs: 39ns
Direct call, String.format(), fixed args: 19ns
Checking LOG.isLoggable(): 0.005ns
Checking constant, then LOG.isLoggable(): 0.003ns

Well, string concatenation is an order of magnitude faster, but still not something we'd like to do lightly. Varargs and fixed method calls are both 40% faster again. But the nice surprise is that if we do the constant check, it's taking picoseconds. In other words, the VM is optimising the code to death, likely removing it.

Now, micro-benchmarks like this are notoriously inaccurate but what I think can be relied upon here are the orders of magnitudes involved. Checking a constant is stupidly fast, passing varargs to defer construction of the string is also good, but we should definitely still avoid direct string concatenation.

Is checking the constant still worthwhile, when calling a varargs style logging method is so fast? I guess this is where the debate lies these days. If you have run-time configurable logging in your code, you probably aren't worrying about losing a handful of nanoseconds to a method call. It's such a small amount you won't notice. It then comes down to whether you can tolerate having that if statement - does it compromise the readability of your code, to the extent that you're losing money for those extra few minutes it takes for someone to understand your method? Or even the time it takes to type that extra line of code?

Time is money, and a developer like me costs $0.01 per second. If your application isn't real-time (and if it were, it wouldn't be using logging), the cost per CPU second is a ridiculous fraction of that.

In conclusion for me, I can tolerate the if statements for now, as the cost of going back and "fixing" all the existing calls is ridiculously higher than the cost of leaving them in, and following the pattern. Ah, software development, it truly is the craft of the lazy pragmatist :)

The Mile High (Programmer) Club

So I was in Dublin this weekend, doing some on-site support for a customer. As I've finally got back into doing some hobby programming completely unrelated to work in the evenings, and I was taking my personal laptop over to Dublin with me (my shiny new black MacBook I bought in Jakarta), I got the chance to do some coding at 20000ft. Not quite as kudos-laden as The Mile High (Fornication) Club, The Mile High (Programmer) Club is nonetheless just as exclusive :)

In other news, we're part way through buying our first house, which means I am now officially old, responsible and will likely start shouting "gerrof me lawn!" to passing innocent children. The slippers have been ordered and I am currently learning what makes a good pipe and what kind of tobacco defines me as a person.

The End of the Road

So, today was my last day in Singapore. It's been good fun, I've been marching around the place and have sore legs to prove it. On the first day I went for a wander around Chinatown, as it was right next to my hotel. Chinatown is pretty cool - the Hindu and Chinese temples were beautifully decorated, and the food from the hawker stalls was delicious (I had sweet and sour battered fish with seafood rice). Not so good was the amount of harassment you get off of the tailors in the region - one of them practically dragged me into his shop and wouldn't listen to any of my polite attempts to disengage, so in the end I just had to march out.

Yesterday, I decided to follow one of the walking tours described in my lonely planet guidebook, to look at some of the older colonial parts of singapore. About half way through, I walked off the beaten track to follow the trail around the promenade - about 2 miles of walking along the riverfront. There were two rowing teams out practising and I got to witness them soaking each other with oars and buckets as distractionary measures while racing. Looked like they were having good fun. There were also a bunch of indian guys just lying around in the shade off the path, sleeping away the hot afternoon. That looked extremely tempting, because I really can't cope with the heat here - marching around in 33 degree heat with 100% humidity really isn't something my european frame is designed for.

Later in the day I got back on the tour route, stopped at IndoChine for some lunch then went for a wander round the Asian Civilisations Museum. As it turns out, the islamic arabs invented algebra, which might explain why George Bush wishes to eradicate them. Stop it at the source, so to speak. Too late Georgie boy, you can't escape the maths. They also had a really cool exhibition showing some artifacts discovered which belonged to an ancient chinese people called the "Shu", who lived around 4000 years ago. Loads of bronze and jade artifacts depicting predatory birds and huge bronze heads very similar in style to what you might find at an aztec temple in South America.

So, after expanding my mind with this cultural experience I decided get stupidly drunk and forget it all. I went to a pub called Molly Malones, an Irish Pub (of course) where I drank a silly amount of Strongbow while chatting away to some of the other expat regulars in the bar.

This led to a stinking hangover the next morning (trying to pack your bag when hung over is a unique form of self-inflicted torture) so I hid myself away in a cinema in the early afternoon then cruised around the shops on Orchard Road for a while - I bought a new watch which makes figuring out time zones a bit easier (you know, jet set lifestyles demand such features). Thoroughly bored of shopping after that, I had some sushi for dinner (expensive but good) then cruised back to the hotel, read New Scientist for a bit then came here to the airport.

I've really enjoyed myself over here in Asia, but it will be good to be home.

Selamat Tinggal, Jakarta

So, the time has come for me to leave Jakarta. It's been great, ridiculously busy and stressful but I think I will remember my time here fondly in the years to come. I've had so much to talk about over the last week, but I've been working 12 hour days most days so I've had hardly any time at all to write a blog post worthy of it all. It's likely this is going to be another mega-post by the time I finish, so grab a beverage and get comfy.

Where to start? Jakarta has been a massive eye-opener for me as to how it feels to be an ethnic minority - walking amongst the native peoples of Jakarta but most definitely not feeling like one of them. Don't get me wrong, people are VERY polite here and make you feel very comfortable. However, you are one of the few white faces - often I would only see one or two other white people in a whole day, which sounds a bit obvious but when you've only visited countries in the past with a massive white majority, this is a rather strange turn of events.

I was also convinced at one point I was basically the source of amusement amongst some of the security guards that I passed during my daily commute, the pompous "bule" (whitey). Understandable that there would be resentment of white people here after how brutal the dutch where during the colonial rule of Jakarta, but still shocking to come across it first hand. I will definitely have a better understanding of the kind of shit the asian communities of Glasgow have to put up with as a result of this trip.

Another more direct, worrying instance of targeting a "bule" was when I was led into a fake taxi. The taxi seemed legit from the outside and the hotel guard didn't seem too concerned by it, but I knew within under a minute I was about to get screwed. After telling the taxi driver where I wanted to go, he asked me if I spoke any Indonesian. Still a little shaky with my basic Indonesian, I tried "Saya batak bisa bicara bahasa Indonesia". The taxi driver continued to rattle off some more Indonesian I didn't understand then started trying to sign things to me. Eventually I caught the gist - he was demanding 50000 rupiah (2.5 GBP roughly) for the taxi fare instead of what it should have been, around 15000 rupiah. Once I figured it out I started to get a little scared, because typically they take your money then dump you in the middle of fucking nowhere in a Jakartan slum where you will likely end up getting extorted for everything you have (I've heard stories of being taken to mosques in such places and all your possessions taken off you in return for your life). So, I called Irwan and explained the situation, and he asked to speak to the taxi driver. I heard him shouting down the phone to the cab driver for a couple of minutes then the cab driver handed the phone back. Irwan said "just give him the money, he'll take you where you're going". I have to say I have been significantly more wary of the taxis after that.

I've been to a couple of the big shopping malls here in Jakarta at the weekends: Plaza Indonesia, Senayan City and Ratu Plaza. Plaza indonesia is probably the most opulent shopping mall I have ever been in - pretty much the only shops in there are very exclusive designer names for clothes and jewellery (bulgari, tiffany and co, tag heuer, hugo boss, etc). Looking in the window of tiffany and co, they were selling diamond and ruby jewellery at prices of 10000 USD and up. Most of the other shops were the same - easily everything over 100 USD.

Senayan City rivals Plaza Indonesia for similar designer goods but they also have much more reasonable shops. As a comparison, if you take the Braehead shopping mall in Glasgow and were to stack 6 of those, one on top of the other, you have an idea of the size of Senayan City. It's fucking MASSIVE.





On the 5th floor there is a huge electronics shop that has the widest array of plasma and LCD TVs I have ever seen - they also had the world's biggest consumer plasma TV, at a whopping 103in. Seriously, the viewable area of this TV is almost the same height as me (6ft). There isn't even a chance in hell it would fit in my living room back home. For the slightly less insane (the 103in TV wasn't for sale, but if it was my guess is that it would cost over 30000 GBP).



Senayan City also has a Krispy Kreme, which made me a very happy man. I haven't had any Krispy Kreme donuts since I was 16, so this was a big blast from the past.



Ratu Plaza is basically just another shopping mall, but with a high concentration of PC and laptop shops. It also has an awesome pirate emporium, that reminds me of the Barras in Glasgow during the Golden Age of Amiga piracy. DVD9 versions of just-released movies for 7000 rupiah? Even the MPAA execs couldn't say no to that :)

I bought a Black MacBook in Ratu Plaza while I was there, which is what I'm typing this post on. It's awesome, a really nice little laptop and I'm growing to love Mac OS X. It has a few things that are annoying me, but I'm sure there are ways of doing what I want and I just don't know enough about it yet.

While I've been here I've spotted a few examples of "Engrish", which have had me in stitches. Unfortunately I've not been able to photograph them all as some have been on billboards on the faster moving roads. However, here are two I did manage to capture:



Pocari Sweat. Yes, it's an actual drink here, and quite a popular one. I thought it was bottled water at first, but apparently it has a flavour something close to cream soda. I never tried the stuff - I guess I couldn't get the word "sweat" out of my head in relation to a liquid. It's hard to make out from the photo, but it's also an "Ion Supply Drink". Mmmmm, gotta love those ions!



I'll have a generic salad please! This was from the menu in the bar in Le Meridien. I got a few funny looks when I laughed uproariously at that.

Last night, Paul recommended that we go to Tiga Puluh, the club in the basement of the hotel so I could get some experience of the Jakartan Nightlife. For those not in the know, basically all the posh clubs like Tiga Puluh are packed with beautiful Indonesian and Asian women. Thing is, they're all hookers. Really. There is also a very strange etiquette regarding this too - if you are a bule (a whitey) and catch their eye (which is very easy, given you're surrounded by them) this is taken as interest, and they will stare intensely back at you. They will then proceed to walk up to you, do some seductive dancing with other hookers nearby. After doing this for a bit, they will probably walk up behind you and pinch your shirt and say something like "malam" (evening). At that point, if you turn round and talk to them basically you've just signed yourself up for a night of action. If you just ignore them (and they will hang around for at least 5 minutes, staring at the back of your head) they will eventually get the point and walk away.

So, I got some first hand experience of this at Tiga Puluh (the etiquette part, not the action part). Hilariously, after absorbing enough of the atmosphere in Tiga Puluh and starting to get a little worried I was about to be ambushed by 5 ladies of the night dancing to my right (two white guys, one in his 20s and one with grey hair, basically says to them "retirement fund") we retreated to the lounge. We were drinking there for another while, with some other party girls still showing interest and sitting next to us (mirrored walls in the lounge make avoiding eye contact VERY hard). Hilariously at one point I disappeared to the toilet for no more than about 2 minutes to come back and find paul getting chatted up. The look of desperation, followed by relief on his face as I came back to the lounge, was enough to keep me laughing into my beer for the rest of the night.

I'm running out of steam now, so time for a wrap-up. This is an awesome city, they have some real problems with traffic and polution but it is a very vibrant place and is definitely on the way up. I hope to be able to visit again.

My next post will be from SINGAPORE, BABY!

Pihak Tiga

Another early awakening this morning - who would have ever thought I would resent the fact the world is round? My taxi driver took me a weird route to work through some of the back streets today, which let me see just how nuts the traffic REALLY gets off the beaten track. Motorbikes everywhere, people deliberately driving on the wrong sides of roads (in SUVs and on mopeds heading straight into oncoming traffic in the latter case) and through red lights. Probably my favourite thing about watching people drive in indonesia is the totally random stabbing of the horn and indicating in a particular direction for longer than 2 minutes as they drift across lanes as traffic allows.

I'm pretty sure I've been unknowingly on the receiving end of racism courtesy of some of the security guards at work. It could also be paranoia, but they seem to laugh significantly more when I'm sitting about within line of sight of them, like when I was waiting for a taxi today. Of course not that I'll ever know for sure, since I don't speak enough Bahasa Indonesia and they don't speak enough English to insult me in a way I would understand. Still, I think perhaps I'll have a better understanding of what it's like to be of a minority race after a few weeks here.

Today's hilarious revelation about Jakartan culture came courtesy of a colleague in work who had just got back from Holland. He asked with a smirk on his face if I'd had a drink in the hotel bar since I arrived. Not really knowing where this was going, I said no. He then said, "Be careful around the women in that bar. They can be quite... aggressive". I was still slightly confused by this, but I think I knew where he was going. "They are only after your money", he finished.

I had heard this rumour before about some of the foreigner-friendly bars in Jakarta, that the female clientele are predominantly prostitutes who don't inform you of this fact until the deed is done. Still, I was slightly perplexed that the hotel would allow such a thing. Maybe they just like to take care of their guests, in every sense of the word. This led me to think how do you politely ask whether someone is a prostitute or not? It's not inconcievable that people might just talk to you in a hotel because they are feeling just as isolated as you are in a strange country. Another friend advised "just don't have sex with them", which is all well and good but I'd feel guilty for wasting the poor girl's time talking to her if she was just after some cash.

I'm trying to learn some basic Bahasa Indonesia to alleviate my guilt over being an ignorant westerner trampling around Jakarta without even speaking a word of the official language. Simple things like Selamat Pagi (good morning) and Terima kasih (thank you). I'm not going to be winning any prizes for linguistic ability, but it's better than nothing.

Selamat tinggal!

Iain Does Indonesia, Part Deux

Today I was officially made a millionaire. Pity that's measured in Indonesian Rupiah :) I was given a living allowance to cover general expenses of getting taxis to and from the office and food. Both are extremely cheap anyway, roughly 2 quid for a 20min taxi ride and 2 quid for a cooked-to-order lunch and drink. So I don't think I'll be going broke any time soon.

It's been quite a busy day today, so I don't have a lot to say that doesn't concern work, and the work related stuff doesn't really make for interesting reading (not that I could really talk about it on a public site like this anyway). I'm currently musing about where to go for dinner tonight, I'm sorely tempted to go back to the same Thai restuarant because it was so good, but I'm probably better trying something different just to mix it up a bit. The life of an international playboy, it's not easy.

Iain Does Asia, Part 1

This is my first day in Jakarta, after a grueling 28 hours in total travelling from Glasgow. The journey yesterday was very hard going - a 7.5hr flight from Glasgow to Dubai, with a 3 hour stop-over before the final stage of the journey which consisted of dubai to Colombo (4.5hrs), Colombo to Singapore(3.5hrs), Singapore to Jakarta(1.5hrs) with stop-overs of around 1 hour between each. Watching India and the islands of Myanmar and Indonesia flow past on the plane was interesting, though by that point I was very tired and drifting in an out of very light sleep. I can never seem to sleep on planes, even when I've been up for nearly a full day.

I arrived last night around 7pm. I see what people mean now about the city having a pungent smell - it is similar to the smell on bonfire night in Glasgow. The traffic wasn't quite as bad as some had said, though the cab driver did comment that it was a particularly quiet evening on the roads. The cab driver was very friendly, and despite him not speaking much English and me not speaking much Bahase we managed to establish a simple rappor by laughing at simple things like the number of toll roads on the way from the airport ("jakarta roads, all money money money!") and how hot it was.

The hotel, complete with turban wearing Sikh doorman, is ridiculously extravagant. I never realised this upon arrival but the ground floor contains 4 restuarants, a posh wine bar complete with pianist and scantily clad vocal siren, and a nightclub of all things in the basement. The place is absolutely immaculate with floor-to-ceiling marble and impossibly smiley staff wherever you turn. Obviously, to match this classy decor the dulcit tones of "Who Let the Dogs Out" was playing full blast from the bar - who DID let the dogs out? We may never know.

All major buildings in Jakarta are guarded by armed security forces who check under the bonnet, under the car using mirrors and in the trunk for any suspicious devices. This is a standard precaution after the bombings a few years back which are a constant threat, especially for buildings host to filthy engleesh ka-niggits like my hotel.

As for my hotel room, it's bigger than the living room in my house complete with king size bed (which i used about 10% of while sleeping, star shaped sleeping may be required so I don't feel like I'm squandering all that room), floor-to-ceiling marble bathroom with a walk-in shower, separate bath, and a telephone next to the toilet (yes, really). In front of my bed I have a desk, a couch, an office desk (where I am as I type this) and an LCD TV. So yeah, the room is a let down after seeing the lobby :P

I was pretty shagged after all that travelling so after a quick phone call and quick test of the internet connection (the sign of an addict?) I went to bed at around 9:30pm. I was woken up by the prayer calls emanating from the minarets of the local mosques this morning - the sounds carries very well at 4:30am. I had been waking up about once an hour anyway, I can just tell it's going to take a fair bit of time for my body to adjust to this timezone properly and allow me to sleep for any reasonable duration. I couldn't sleep much past 5:30am , so I sat about watching the traffic through my window for most of the morning while ironing clothes for today's work. The first thing that struck me as totally different about the traffic here is the ratio of motorbikes to cars - it's easily 1 to 1.

Also visible outside my window is what appears to be a totally derelict construction site for another hotel - the steel columns are rusting and various tropical foliage is starting to grow around the base. The rest of the vista is a mix of tropical plants interspersed with traditional asian houses and modern skyscrapers. One thing that struck me last night when flying in was that the city is actually quite dark at night, at least from the air. Glasgow looks like an orange pool of lava from the sky, whereas here I could only see the occasional strip of white lights. I think now that this was because of the trees covering or absorbing most of the reflected lights off of the road.

Bastian, my main contact here in Jakarta, came to meet me in the lobby at 9am and we took a cab over to the building where I will be working for the next two weeks. At that time in the morning it was already around 24 degrees centigradea and humid as fuck - Bastian laughed at my discomfort and said it was only going to get much, much worse. I had been watching the traffic steadily build all morning through the window all morning but the roads just got increasingly busy the further I went. Some roads were a lot quieter than others, and Bastian explained that many of the roads operate a car pool policy where you can only drive on them if there are more than 3 people in the car. This is rigorously enforced with police guarding the starts and the ends of the roads. Amusingly, as we exited one car pool road and headed towards another Bastian pointed out a whole bunch of people standing at the side of the road holding their arms out as if flagging down a bus. "They're jockeys", he said, much to my confusion. "You can hire them to sit in your car with you so you can drive on the car pool roads" he explained. I burst out laughing, and asked how much they cost. "Around 10000 rupia", meaning around 60p. I'd heard of selling your body, but not quite like that...

The motor bike drivers here are total nutters. You have to understand that in Jakarta, the lines on the road are mere decoration rather than meaning anything like lane divisions or directions - people drive wherever the hell they want, and weave their way between and around cars with alarming indifference. The bikers are the worst, and have to constantly toot their horns to warn drivers of their crazy maneouvering, or for the suave have a little noise generator like you might remember from BMX's as a kid - siren noises and descending bombs. I don't think I stopped giggling for most of the journey.

The office was smaller than my hotel room and host to about 20 people. It's not air conditioned as such, but fans positioned in every spare square inch of flooring (and there isn't much of that) and a single portable AC unit working full tilt to try (and fail) to keep the room temperature under 25 degrees. It wasn't so bad in the morning, but after the clouds burned off in the late afternoon and the computers (especially those nuclear reactors that are dell laptops) had been on all day it was ridiculously hot.

Getting back to the hotel, I decided to sample the thai restuarant ("Lemon Grass") which was totally empty as it had just opened. Table for one, complete with a copy of the Jakarta Post and "Girl from Ipanema" being played and sung very skillfully across the way in the wine bar - nothing like making my life a cheap imitation of "Lost in Translation". The food - fuck me, it was good. Hands down the best thai food I've ever had. 3 courses and a bottle of beer all for the exorbitant fee of 10 pounds. I think I like it here.