Getting spring beans initialization times

Question

I have an application with a large spring context which loads lots of beans written by lots of developers.
Some of the beans may do some significant processing on their initialization code which may take a long time.
I'm looking for a simple way to get the loading time of each bean.
Since the software is running on a large number of customers' machines I need a way to find the bottlenecks beans easily in the log.
If I could register to events such as "Before loading bean" and after it would be great.
So if I can get this data problematically I can write something like:

if (beanLoadingTime > 2 seconds) 
    print bean details and loading time to log file

That's why enabling the logging or profilng isn't enough.

Answer 1

Dont know if my solution will help you, but this is what i did because i needed something similar.

First, we need to log two things, instantiation time and initialization time. For the first thing i enable logging just for the package "org.springframework.beans.factory", using %d{mm:ss,SSS} %m%n as a pattern (time and message only). Spring logs messages like: Creating instance of bean... and Finished creating instance of bean... For the second thing i created a LoggerBeanPostProcessor as recommended in this answer . The code is:

public class LoggerBeanPostProcessor implements BeanPostProcessor, Ordered {

    protected Log logger = LogFactory.getLog("org.springframework.beans.factory.LoggerBeanPostProcessor");
    private Map<String, Long> start;
    private Map<String, Long> end;

    public LoggerBeanPostProcessor() {
        start = new HashMap<>();
        end = new HashMap<>();
    }

    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        start.put(beanName, System.currentTimeMillis());
        return bean;
    }

    @Override
    public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        end.put(beanName, System.currentTimeMillis());
        logger.debug("Init time for " + beanName + ": " + initializationTime(beanName));
        return bean;
    }

    @Override
    public int getOrder() {
        return Integer.MAX_VALUE;
    }

    // this method returns initialization time of the bean.
    public long initializationTime(String beanName) {
        return end.get(beanName) - start.get(beanName);
    }
}

I use a file appender in the log4j config. Then i wrote a simple code to parse that info and gets milisecond of each thing and sum them:

public static void main(String[] argumentos) throws Exception{
        File file = new File("C:\\app\\daily.log");
        List<String> lines = FileUtils.readLines(file);

        Map<String,Long> start = new HashMap();
        Map<String,Long> end = new HashMap();
        Map<String,Long> init = new HashMap();
        List<String> beans = new ArrayList();
        int max = 0;

        for(String line :  lines) {
            String time = StringUtils.substring(line, 0, 9);
            String msg = StringUtils.substring(line, 10);

            if(msg.startsWith("Creating instance")) {
                int fi = StringUtils.indexOf(msg, '\'') + 1;
                int li = StringUtils.lastIndexOf(msg, '\'');
                String bean = StringUtils.substring(msg, fi, li);
                if(start.containsKey(bean)) {
                    continue;
                }
                start.put(bean, parseTime(time));
                beans.add(bean);
                max = Math.max(max, bean.length());

            } else if(msg.startsWith("Finished creating")) {
                int fi = StringUtils.indexOf(msg, '\'') + 1;
                int li = StringUtils.lastIndexOf(msg, '\'');
                String bean = StringUtils.substring(msg, fi, li);
                if(end.containsKey(bean)) {
                    continue;
                }
                end.put(bean, parseTime(time));

            } else if(msg.startsWith("Init time for")) {
                int li = StringUtils.lastIndexOf(msg, ':');
                String bean = StringUtils.substring(msg, 14, li);
                if(init.containsKey(bean)) {
                    continue;
                }
                init.put(bean, Long.parseLong(StringUtils.substring(msg, li+2)));
            }
        }

        for(String bean : beans) {
            long s = start.get(bean);
            long e = end.get(bean);
            long i = init.containsKey(bean) ? init.get(bean) : -1;
            System.out.println(StringUtils.leftPad(bean, max) + ": " + StringUtils.leftPad(Long.toString((e-s)+i), 6, ' '));
        }
    }

Resulting in this:

                                           splashScreen:    172
org.springframework.aop.config.internalAutoProxyCreator:     31
                                loggerBeanPostProcessor:   1137
                                             appContext:   1122

Hope this helps you as much as it helped me.

Answer 2

To find performance bottlenecks in your Java code, use a profiler.

A profiler will measure the time spent in every method being profiled, both in the method itself, and the total of the method plus every call it makes. Usually, profiling it enabled at the class or package level, e.g. if your code is in the com.example package or subpackages, you specify that, and the profiler will monitor your code, without wasting time monitoring Spring code and the Java runtime library.

Depending on your IDE, that may already be built in, or may be available as an extension/plugin.

Update

To hook into the Spring containers bean instantiation process, a BeanPostProcessor may be the solution. The referenced description include the following:

[...] for each bean instance that is created by the container, the post-processor gets a callback from the container both before container initialization methods (such as InitializingBean’s afterPropertiesSet() and any declared init method) are called as well as after any bean initialization callbacks. The post-processor can take any action with the bean instance, including ignoring the callback completely.