Performance improvement sample for duplicate SQL (SELECT) issuance in transaction script using Java ThreadLocal

Performance improvement sample for duplicate SQL (SELECT) issuance in transaction script using Java ThreadLocal

Suppose you have an existing system that is implemented in a transaction script. And suppose that there is logic that issues the same SQL (SELECT) many times in a transaction script, which is a bottleneck in terms of performance. (For example, the process of acquiring data from the master appears many times, but basically it is exactly the same including the WHERE clause, and there is no need to issue SQL (SELECT) many times.)

To solve these problems, if you want to issue the exact same SQL (SELECT) a second time or later in a transaction script, This is a sample program that aims to improve performance by retaining the result set issued the first time and improving it so that it can be reused.

Assuming that it is like a Web application, the main thread is started for each Request user, I'm trying to reproduce keeping the result set globally within a thread so that it doesn't conflict with other users' threads.

Configuration image of sample program
Main → SampleCallable [Req A] → SampleAction → SampleBiz → ADao
→ SampleCallable [Req B] → SampleAction → SampleBiz → ADao
→ SampleCallable [Req C] → SampleAction → SampleBiz → ADao

Supplement

The above configuration image shows the following.

Sample program

All sample programs are managed on GitHub. https://github.com/Yu-Yamaguchi/sample-thread-local

Main class

package you_name_is_yu.threadlocal;

import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

import org.apache.log4j.Logger;

/**
 *A processing class that simulates access from multiple clients at almost the same time.
 *Create multiple threads using ExecutorService.
 *
 * @author You_name_is_YU
 *
 */
public class Main {

    private static final Logger logger = Logger.getLogger(Main.class);

    public static void main(String[] args) throws Exception {

        //Flags for enabling performance improvements using ThreadLocal
        boolean enableThreadLocal = true;

        long start = System.currentTimeMillis();

        //Definition of multithread processing assuming that there are requests from three clients at almost the same time
        ExecutorService threadPool = Executors.newFixedThreadPool(3);
        List<Callable<Void>> processes = new ArrayList<>();

        processes.add(new SampleCallable("taro", "101", 700, enableThreadLocal));
        processes.add(new SampleCallable("jiro", "101", 300, enableThreadLocal));
        processes.add(new SampleCallable("saburo", "101", 500, enableThreadLocal));

        //Execute 3 simultaneous requests in multithread
        try {
            threadPool.invokeAll(processes);
        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            threadPool.shutdown();
        }

        long end = System.currentTimeMillis();
        logger.info("■ □ ■ □ ■ □ Total execution time (ms) ■ □ ■ □ ■ □");
        logger.info((end - start) + "ms");
    }
}

SampleCallable class

package you_name_is_yu.threadlocal;

import java.util.concurrent.Callable;

import you_name_is_yu.threadlocal.action.SampleAction;
import you_name_is_yu.threadlocal.dto.ParamDto;
import you_name_is_yu.threadlocal.util.ThreadLocalUtil;

/**
 *A class that actually becomes the starting point of each thread using ExecutorService.
 *This is an image corresponding to one user session (Request).
 *
 * @author You_name_is_YU
 *
 */
public class SampleCallable implements Callable<Void> {

    /**Call execution user name*/
    private String executingUser;
    /**ID condition to narrow down the SELECT target by the parameter from the screen (provisional)*/
    private String id;
    /**Time (milliseconds) indicating how heavy the SELECT statement is * Used to express that SQL is heavy in a pseudo manner*/
    private long sleepTime;
    /**Flag for whether to use ThreadLocal*/
    private boolean enableThreadLocal;

    public SampleCallable(String executingUser, String id, long sleepTime, boolean enableThreadLocal) {
        this.executingUser = executingUser;
        this.id = id;
        this.sleepTime = sleepTime;
        this.enableThreadLocal = enableThreadLocal;
    }

    @Override
    public Void call() throws Exception {

        //When using ThreadLocal, initialize it once.
        if (this.enableThreadLocal) {
            ThreadLocalUtil.initThreadLocalUtil();
        }

        //Execute Action in Struts
        //* Originally, it is generated and executed when the application server receives the Request, but this time it is reproduced in a pseudo manner.
        SampleAction action = new SampleAction();
        action.doAction(new ParamDto(this.executingUser, this.id, this.sleepTime, this.enableThreadLocal));
        return null;
    }

    public String getExecutingUser() {
        return executingUser;
    }

    public void setExecutingUser(String executingUser) {
        this.executingUser = executingUser;
    }

    public String getId() {
        return id;
    }

    public void setId(String id) {
        this.id = id;
    }

    public long getSleepTime() {
        return sleepTime;
    }

    public void setSleepTime(long sleepTime) {
        this.sleepTime = sleepTime;
    }

    public boolean isEnableThreadLocal() {
        return enableThreadLocal;
    }

    public void setEnableThreadLocal(boolean enableThreadLocal) {
        this.enableThreadLocal = enableThreadLocal;
    }
}

SampleAction class

package you_name_is_yu.threadlocal.action;

import you_name_is_yu.threadlocal.biz.SampleBiz;
import you_name_is_yu.threadlocal.dto.ParamDto;

/**
 *Existing system is Struts1.Assuming a legacy system built with X system,
 *The class that corresponds to the Action class.
 *
 * @author You_name_is_YU
 *
 */
public class SampleAction {

    public void doAction(ParamDto param) {
        SampleBiz biz = new SampleBiz();
        biz.doBiz(param);
    }
}

SampleBiz class

package you_name_is_yu.threadlocal.biz;

import java.util.List;

import org.apache.log4j.Logger;

import you_name_is_yu.threadlocal.dao.ADao;
import you_name_is_yu.threadlocal.dto.ADto;
import you_name_is_yu.threadlocal.dto.ParamDto;

/**
 *A class that represents business logic because it is implemented in a transaction script.
 *I simply call Dao and log out a list of SELECT results.
 *
 * @author You_name_is_YU
 *
 */
public class SampleBiz {

    private static final Logger logger = Logger.getLogger(SampleBiz.class);

    /**
     *Business logic.
     *With one business logic, SELECT is called many times under the same conditions, and the acquisition result is used to output the log.
     *I think it's rare to do the same thing over and over again in the same method,
     *For example, from this business logic class, execute the methods of other classes in multiple classes, multiple methods,
     *Forcibly consider the case where there are cases where the same master value is acquired separately but SELECTed separately.
     *
     * @param param parameter
     */
    public void doBiz(ParamDto param) {

        long start = 0;
        long end = 0;

        ADao dao = new ADao();
        try {
            logger.info("=== 1st start ===");
            start = System.currentTimeMillis();
            List<ADto> list = dao.selAList(param);
            for (ADto dto : list) {
                logger.info(dto);
            }
            end = System.currentTimeMillis();
            logger.info((end - start) + "ms");

            logger.info("=== 2nd start ===");
            start = System.currentTimeMillis();
            List<ADto> list2 = dao.selAList(param);
            for (ADto dto : list2) {
                logger.info(dto);
            }
            end = System.currentTimeMillis();
            logger.info((end - start) + "ms");

            logger.info("=== 3rd start ===");
            start = System.currentTimeMillis();
            List<ADto> list3 = dao.selAList(param);
            for (ADto dto : list3) {
                logger.info(dto);
            }
            end = System.currentTimeMillis();
            logger.info((end - start) + "ms");
        } catch (InterruptedException e) {
            e.printStackTrace();
            logger.error(e);
        }
    }
}

ADao class

package you_name_is_yu.threadlocal.dao;

import java.util.ArrayList;
import java.util.List;

import you_name_is_yu.threadlocal.dto.ADto;
import you_name_is_yu.threadlocal.dto.ParamDto;
import you_name_is_yu.threadlocal.util.ThreadLocalUtil;
import you_name_is_yu.threadlocal.vo.where.AWhereVo;

/**
 *Dao performing operations on the A table.
 * @author You_name_is_YU
 *
 */
public class ADao {

    public List<ADto> selAList(ParamDto param) throws InterruptedException {

        //Generate conditional Vo in Where clause
        AWhereVo where = new AWhereVo(param.getId());
        where.setId(param.getId());

        List<ADto> result = null;

        //If an object with the same conditions is already stored in ThreadLocal,
        //As a result, the set is reused and returned as it is.
        if (param.isEnableThreadLocal()) {
            result = ThreadLocalUtil.get(where);

            if (result != null) {
                return result;
            }
        }

        result = new ArrayList<>();
        {
            //A block that executes a SELECT statement and generates an acquisition result
            //The reason for sleeping is that SQL is heavy to some extent and it is a pseudo expression to get the result.
            Thread.sleep(param.getSleepTime());
            result.add(new ADto(param.getId(), "test"));
            result.add(new ADto(param.getId() + "+1", "test1"));
            result.add(new ADto(param.getId() + "+2", "test2"));
        }

        if (param.isEnableThreadLocal()) {
            ThreadLocalUtil.put(where, result);
        }

        return result;
    }
}

ThreadLocalUtil class

package you_name_is_yu.threadlocal.util;

import java.util.HashMap;
import java.util.List;
import java.util.Map;

import org.apache.log4j.Logger;

import you_name_is_yu.threadlocal.dto.ADto;
import you_name_is_yu.threadlocal.vo.where.AWhereVo;

public class ThreadLocalUtil {

    private static final Logger logger = Logger.getLogger(ThreadLocalUtil.class);
    private static final ThreadLocal<HashMap<AWhereVo, List<ADto>>> THREAD_LOCAL = new ThreadLocal<HashMap<AWhereVo, List<ADto>>>();

    private ThreadLocalUtil() {
    }

    public static void initThreadLocalUtil() {
        clear();
        THREAD_LOCAL.set(new HashMap<AWhereVo, List<ADto>>());
    }

    public static void put(AWhereVo key, List<ADto> val) {
        Map<AWhereVo, List<ADto>> map = THREAD_LOCAL.get();
        map.put(key, val);
    }

    public static List<ADto> get(AWhereVo key) {
        List<ADto> result = null;
        Map<AWhereVo, List<ADto>> map = THREAD_LOCAL.get();
        if (map.containsKey(key)) {
            logger.info("There was");
            result = map.get(key);
        }

        return result;
    }

    public static void clear() {
        THREAD_LOCAL.remove();
    }
}

Execution result log

When ThreadLocal is ** not used **

Check what the performance looks like when ThreadLocal is not used, that is, in the state of the existing system. This is the result of executing by specifying the part of the local variable boolean enableThreadLocal in the main method of the Main class to false.

2018-15-29 08:15:00,145 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
2018-15-29 08:15:00,846 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
2018-15-29 08:15:00,846 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
2018-15-29 08:15:00,846 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
2018-15-29 08:15:00,847 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :701ms
2018-15-29 08:15:00,847 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
2018-15-29 08:15:01,547 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
2018-15-29 08:15:01,548 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
2018-15-29 08:15:01,548 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
2018-15-29 08:15:01,549 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :702ms
2018-15-29 08:15:01,550 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
2018-15-29 08:15:02,251 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
2018-15-29 08:15:02,252 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
2018-15-29 08:15:02,252 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
2018-15-29 08:15:02,253 [pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :702ms

2018-15-29 08:15:00,151 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
2018-15-29 08:15:00,455 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
2018-15-29 08:15:00,456 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
2018-15-29 08:15:00,457 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
2018-15-29 08:15:00,459 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :307ms
2018-15-29 08:15:00,460 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
2018-15-29 08:15:00,761 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
2018-15-29 08:15:00,762 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
2018-15-29 08:15:00,763 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
2018-15-29 08:15:00,764 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :304ms
2018-15-29 08:15:00,764 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
2018-15-29 08:15:01,065 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
2018-15-29 08:15:01,065 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
2018-15-29 08:15:01,066 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
2018-15-29 08:15:01,066 [pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :302ms

2018-15-29 08:15:00,135 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
2018-15-29 08:15:00,645 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
2018-15-29 08:15:00,646 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
2018-15-29 08:15:00,647 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
2018-15-29 08:15:00,647 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :505ms
2018-15-29 08:15:00,647 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
2018-15-29 08:15:01,156 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
2018-15-29 08:15:01,156 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
2018-15-29 08:15:01,157 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
2018-15-29 08:15:01,158 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :510ms
2018-15-29 08:15:01,159 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
2018-15-29 08:15:01,661 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
2018-15-29 08:15:01,662 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
2018-15-29 08:15:01,663 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
2018-15-29 08:15:01,663 [pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :503ms

2018-15-29 08:15:02,254 [main] INFO  you_name_is_yu.threadlocal.Main :■ □ ■ □ ■ □ Total execution time (ms) ■ □ ■ □ ■ □
2018-15-29 08:15:02,255 [main] INFO  you_name_is_yu.threadlocal.Main :2167ms

When using ThreadLocal **

Check the performance when using ThreadLocal. This is the result of executing by specifying the part of the local variable boolean enableThreadLocal in the main method of the Main class to true.

If you check this result, you can see that the performance has been improved. (Of course, because we are reducing the number of SQL to be issued in vain ...)

[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :705ms
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1]the same! !!
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1]the same! !!
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :4ms
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1]the same! !!
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1]the same! !!
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101, name=test]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+1, name=test1]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-1]ADto [id=101+2, name=test2]
[pool-1-thread-1] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :5ms

[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :310ms
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2]the same! !!
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2]the same! !!
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :2ms
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2]the same! !!
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2]the same! !!
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101, name=test]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+1, name=test1]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-2]ADto [id=101+2, name=test2]
[pool-1-thread-2] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :2ms

[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 1st start ===
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :503ms
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 2nd start ===
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3]the same! !!
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3]the same! !!
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :3ms
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :=== 3rd start ===
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3]the same! !!
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.util.ThreadLocalUtil :There was
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3]the same! !!
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101, name=test]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+1, name=test1]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :[pool-1-thread-3]ADto [id=101+2, name=test2]
[pool-1-thread-3] INFO  you_name_is_yu.threadlocal.biz.SampleBiz :3ms

2018-19-29 08:19:12,474 [main] INFO  you_name_is_yu.threadlocal.Main :■ □ ■ □ ■ □ Total execution time (ms) ■ □ ■ □ ■ □
2018-19-29 08:19:12,476 [main] INFO  you_name_is_yu.threadlocal.Main :757ms

Recommended Posts

Performance improvement sample for duplicate SQL (SELECT) issuance in transaction script using Java ThreadLocal
ChatWork4j for using the ChatWork API in Java
[For beginners] Minimum sample to display RecyclerView in Java
I tried using an extended for statement in Java