[FIXED] Getting spring beans initialization times

Issue

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.

Solution

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.

Answered By - Ivan Perales M.
Answer Checked By - Terry (JavaFixing Volunteer)