Alternative Log Level Structure

Over the years I have become increasingly dissatisfied with the standard log levels used in Java.  The main problem being that I find with them is that they can be unclear as to where a specific log message belongs: trace, debug, info, warn, error, fatal.

At first glance it appears very straight forward, however after working with many talented teams of developers I have observed that the log levels take effort to standardise across the team and that each team has had their own subtly different guidelines.   Essentially it takes effort to disambiguate edge cases; is a message info or warn? trace or debug? warn or error?  It becomes grey because the level changes based on who the audience is for the message, and typically developers will answer that question from their own view point. 

Previously I posted some guidelines on how we used those log levels; a few years on, I am both older and have less hair.  I have just found it easier to rename each of the log levels and be done with it.  Previously the desire to be a good log4j citizen stopped me, however being somewhat older I am less tolerant of conventions that cause me to loose my hair.  I just don’t have much hair left, and so I need to be more protective of it.   ;)

Here are the log levels that I currently use, I find them to be much more intuitive.

Audit (record of what happened, useful when investigating what the system did and why)

    dev   - diagnostic information useful for developers 

    ops   - diagnostic information useful for people who maintain the system 

    user  - diagnostic information about a user, and if ever seen by a savvy user would be meaningful to them  e.g. ‘CK created account’, and ‘CK logged in'

Alerts (requires action)

    warn - a problem has been detected and mitigated or a potential problem has been detected that does not yet affect users; (action: notify ops/review during office hours to help pre-empt fires/raise awareness of what the state of the system is)

    fatal  - the preverbal has hit the fan, progress can not be made by users (action: wake everybody up)

Alerts are special in two ways, firstly they are raising awareness of an ongoing problem that has a start and hopefully (eventually) an end.  Thus they need to make it clear that yes, we still have a problem or yay the problem has ended.  Secondly, they are a call to action.  Somebody needs to pay attention to alerts, either just by being aware that the system is at reduced capacity (warn) or get out of bed and sound the alarms, round up the troops etc;  the entire system is down (fatal).

Clearly we do not want many alerts.  If there are too many red herrings then people will ignore them, thus the alerts need to be very clear, complete and as rare and accurate as possible.   Thus most messages will be informative/audits and not alerts at all, in which case it must be very clear who the target audience is.  If that audience turn around and say, I do not understand or care then the message comes out entirely.   

I have found that agreeing in a team of developers who a message is for, and whether they need to take action or not to have a lot less grey areas than agreeing what the severity of that message is in relation to another message.  The relative comparison becomes a lot less important.  Thus once a scheme like this is in place, enforcing the rules becomes a lot easier.  The usage is intuitive, so there is little need to keep reminding people (myself included).   

Which is faster in Java, Reflection or MethodHandle?

2014 has been shaping up to be an awesome year so far.  London is a great place to work, especially when it has given me a lot of opportunities to figure out how to make Java run faster.  

For Reflection vs MethodHandles, lets jump straight to some numbers.  The code used to create these benchmark numbers is included at the end.

Direct Method Call	0.1ns
Reflection	4ns
MethodHandle	0.1ns - 110ns

Measurements taken running Java 7 on a shiny OSX laptop

Huh?  Why the huge range of values for MethodHandle?  The reason is that it depends on how the MethodHandle is created and used.  Being a richer API than reflection, it can either run like a farm pig ready for Christmas or become optimised down to being the same as a direct method call.  Awesome.  Thus this post shows how to avoid the costs, and stream line the use of MethodHandle.

Unreflect	87ns
Lookup then bind	105ns
Unreflect then bind	111ns
Invoke exact	11ns
Unreflect invokeExact	6ns
Store MethodHandle in private static final field	0.1ns
Method in private static final field	4ns

These numbers show that some care needs to be taken with MethodHandle, but treat it well and store it in a private static final field and then Hotspot can optimise the reflection out entirely.   Pretty awesome. 

package reports.signals;

import com.softwaremosaic.junit.JUnitMosaicRunner;

import com.softwaremosaic.junit.annotations.Benchmark;

import org.junit.runner.RunWith;

import java.lang.invoke.MethodHandle;

import java.lang.invoke.MethodHandles;

import java.lang.invoke.MethodType;

import java.lang.reflect.InvocationTargetException;

import java.lang.reflect.Method;

/**

 *

 */

@RunWith(JUnitMosaicRunner.class)

public class SignalManagerExperimentalTest {

    private int i=0;

    public void m() {

        i += 1;

    }

    private static final int NUMITS = 10000;

/*

    6.61ns per call

    4.95ns per call

    4.08ns per call

    3.95ns per call

    3.93ns per call

    3.88ns per call

     */

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int fooRef() throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {

        Method f = this.getClass().getMethod( "m" );

        for ( int i=0;i

            f.invoke( this );

        }

        return i;

    }

    private static final Method pf = getF();

    private static Method getF() {

        try {

            return SignalManagerExperimentalTest.class.getMethod( "m" );

        } catch ( NoSuchMethodException e ) {

            e.printStackTrace();

        }

        return null;

    }

/*

    7.27ns per call

    4.75ns per call

    3.79ns per call

    3.72ns per call

    3.71ns per call

    4.29ns per call

     */

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int fooRefPF() throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {

        for ( int i=0;i

            pf.invoke( this );

        }

        return i;

    }

/*

    0.09ns per call

    0.12ns per call

    0.10ns per call

    0.11ns per call

    0.10ns per call

    0.10ns per call

     */

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int fooDirect() throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {

        for ( int i=0;i

            m();

        }

        return i;

    }

/*

unreflect

    87.07ns per call

    87.38ns per call

    87.39ns per call

    87.98ns per call

    86.89ns per call

    88.20ns per call

*/

@Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

public int unreflect() throws Throwable {

    Method f = this.getClass().getMethod( "m" );

    MethodHandle h = MethodHandles.lookup().unreflect( f );

    for ( int i=0;i

        h.invoke(this);

    }

    return i;

}

/*

lookup then bind

    110.45ns per call

    106.48ns per call

    106.04ns per call

    106.15ns per call

    105.20ns per call

    105.13ns per call

*/

@Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

public int lookupBind() throws Throwable {

    MethodHandle h = MethodHandles.lookup().bind( this, "m", MethodType.methodType(Void.TYPE) );

    for ( int i=0;i

        h.invoke();

    }

    return i;

}

/*

unreflect then bind

    112.95ns per call

    110.62ns per call

    112.70ns per call

    112.77ns per call

    111.10ns per call

    111.64ns per call

*/

@Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

public int unreflectBind() throws Throwable {

    Method f = this.getClass().getMethod( "m" );

    MethodHandle h = MethodHandles.lookup().unreflect( f ).bindTo( this );

    for ( int i=0;i

        h.invoke();

    }

    return i;

}

    /*

    invoke exact

        12.65ns per call

        12.03ns per call

        11.17ns per call

        10.46ns per call

        10.36ns per call

        10.18ns per call

*/

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int invokeExact() throws Throwable {

        MethodHandle h = MethodHandles.lookup().bind( this, "m", MethodType.methodType(Void.TYPE) );

        for ( int i=0;i

            h.invokeExact();

        }

        return i;

    }

    /*

        unreflect invokeExact

            7.49ns per call

            7.12ns per call

            6.75ns per call

            6.72ns per call

            6.22ns per call

            5.92ns per call

             */

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int unreflectInvokeExact() throws Throwable {

        Method f = this.getClass().getMethod( "m" );

        MethodHandle h = MethodHandles.lookup().unreflect( f );

        for ( int i=0;i

            h.invokeExact(this);

        }

        return i;

    }

    private static final MethodHandle mh = lookupViaFindVirtual();

    private static MethodHandle lookupViaFindVirtual() {

        try {

            return MethodHandles.lookup().findVirtual( SignalManagerExperimentalTest.class, "m" , MethodType.methodType(Void.TYPE));

        } catch ( Throwable e ) {

            e.printStackTrace();

            return null;

        }

    }

/*

    0.12ns per call

    0.09ns per call

    0.12ns per call

    0.11ns per call

    0.10ns per call

    0.10ns per call

     */

    @Benchmark( value=1000, durationResultMultiplier = 1.0/NUMITS )

    public int fooHandleSF() throws Throwable {

        for ( int i=0;i

            mh.invokeExact( this );

        }

        return i;

    }

}