JavaのThreadLocalを使ってトランザクションスクリプト内における重複したSQL（SELECT）発行に対する性能改善サンプル
既存のシステムが存在し、そのシステムがトランザクションスクリプトで実装されているとします。
そして、トランザクションスクリプト内における何度も同じSQL（SELECT）を発行しているロジックがあり、性能面でボトルネックになっているとします。
（例えば、マスタからデータを取得する処理が何度も登場するが、基本的にはWHERE句含めて全く同じで、何度もSQL（SELECT）を発行する必要が無いケースなど）
こういった問題を解消するため、トランザクションスクリプト内で完全に同じSQL（SELECT）を2回目以降発行する場合は、
1回目に発行した結果セットを保持しておき、それを使いまわすように改良することで、性能改善を図ることを目的としたサンプルプログラムです。
想定としてはWebアプリケーションのようなものをイメージしていて、Requestユーザごとにメインスレッドが起動し、
他のユーザのスレッドと競合しないように、スレッド内でグローバルに結果セットを保持することを再現しようとしています。
サンプルプログラムの構成イメージ
| Main | → | SampleCallable [Req A] | → | SampleAction | → | SampleBiz | → | ADao |
| → | SampleCallable [Req B] | → | SampleAction | → | SampleBiz | → | ADao | |
| → | SampleCallable [Req C] | → | SampleAction | → | SampleBiz | → | ADao |
補足
上記構成イメージは、以下のようなことを表しています。
- Main
- 複数のクライアントからほぼ同時にアクセスされたことを疑似的に再現するための処理クラス
- ExecutorServiceを使って複数スレッドを生成
- SampleCallable
- ExecutorServiceを利用して実際に各スレッドの開始ポイントとなるクラス
- これが１ユーザーセッション（Request）に相当するイメージ。
- SampleAction
- 既存システムがStruts1.X系で構築されたレガシーなシステムを想定
- Requestを受け付けるActionクラス
- SampleBiz
- トランザクションスクリプトでの実装であるため、ビジネスロジックを表すクラス
- 単純にDaoを呼んで、SELECTした結果のリストをログ出力している。
- ADao
- Aテーブルに対する操作を行うDao
サンプルプログラム
サンプルプログラムは、GitHubに全て管理しております。
https://github.com/Yu-Yamaguchi/sample-thread-local
Mainクラス
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;
/**
* 複数のクライアントからほぼ同時にアクセスされたことを疑似的に再現するための処理クラス。
* 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 {
// ThreadLocalを使った性能改善を有効化するかどうかのフラグ
boolean enableThreadLocal = true;
long start = System.currentTimeMillis();
// ほぼ同時に３台のクライアントからRequestがあったと仮定したマルチスレッド処理の定義
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));
// マルチスレッドでの３台同時リクエストを実行
try {
threadPool.invokeAll(processes);
} catch (Exception e) {
e.printStackTrace();
} finally {
threadPool.shutdown();
}
long end = System.currentTimeMillis();
logger.info("■□■□■□合計実行時間（ms）■□■□■□");
logger.info((end - start) + "ms");
}
}
SampleCallableクラス
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;
/**
* ExecutorServiceを利用して実際に各スレッドの開始ポイントとなるクラス。
* これが１ユーザーセッション（Request）に相当するイメージ。
*
* @author You_name_is_YU
*
*/
public class SampleCallable implements Callable<Void> {
/** 呼び出し実行ユーザ名 */
private String executingUser;
/** 画面からのパラメータで、SELECT対象を絞り込むIDの条件（仮） */
private String id;
/** SELECT文がどの程度重いかを表す時間（ミリ秒）※疑似的にSQLが重いことを表現するために利用 */
private long sleepTime;
/** 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 {
// ThreadLocalを利用する場合、いったん初期化。
if (this.enableThreadLocal) {
ThreadLocalUtil.initThreadLocalUtil();
}
// StrutsでいうところのActionを実行
// ※本来はアプリケーションサーバがRequestを受け付けた際に生成して実行するが、今回はそれを疑似的に再現。
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クラス
package you_name_is_yu.threadlocal.action;
import you_name_is_yu.threadlocal.biz.SampleBiz;
import you_name_is_yu.threadlocal.dto.ParamDto;
/**
* 既存システムがStruts1.X系で構築されたレガシーなシステムを想定した、
* Actionクラスに該当するクラス。
*
* @author You_name_is_YU
*
*/
public class SampleAction {
public void doAction(ParamDto param) {
SampleBiz biz = new SampleBiz();
biz.doBiz(param);
}
}
SampleBizクラス
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;
/**
* トランザクションスクリプトでの実装であるため、ビジネスロジックを表すクラス。
* 単純にDaoを呼んで、SELECTした結果のリストをログ出力している。
*
* @author You_name_is_YU
*
*/
public class SampleBiz {
private static final Logger logger = Logger.getLogger(SampleBiz.class);
/**
* ビジネスロジック。
* １つのビジネスロジックで、何回も同じ条件でSELECTを呼び、その取得結果を利用してログ出力を行っている。
* 同一メソッド内でこのように何度も同じことをすることは少ないと思いますが、
* 例えばこのビジネスロジッククラスから他のクラスのメソッドを複数クラス、複数メソッド実行し、
* それぞれの中で、同じマスタの値を取得するのに、別々にSELECTしているようなケースがあったとした場合などを無理やり考えてください。
*
* @param param パラメータ
*/
public void doBiz(ParamDto param) {
long start = 0;
long end = 0;
ADao dao = new ADao();
try {
logger.info("＝＝＝1回目 開始＝＝＝");
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("＝＝＝2回目 開始＝＝＝");
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("＝＝＝3回目 開始＝＝＝");
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クラス
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;
/**
* Aテーブルに対する操作を行うDao。
* @author You_name_is_YU
*
*/
public class ADao {
public List<ADto> selAList(ParamDto param) throws InterruptedException {
// Where句の条件用Voの生成
AWhereVo where = new AWhereVo(param.getId());
where.setId(param.getId());
List<ADto> result = null;
// ThreadLocalに同一条件のオブジェクトが既に格納されている場合、
// その結果セットを再利用してそのまま返却する。
if (param.isEnableThreadLocal()) {
result = ThreadLocalUtil.get(where);
if (result != null) {
return result;
}
}
result = new ArrayList<>();
{
// SELECT文を実行して取得結果を生成するブロック
// sleepしているのは、SQLがある程度重くて、その結果を取得することを疑似的に表現するため。
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クラス
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("あったよ");
result = map.get(key);
}
return result;
}
public static void clear() {
THREAD_LOCAL.remove();
}
}
実行結果のログ
ThreadLocalを利用しない場合
ThreadLocalを利用しない場合、つまり既存システムの状態での性能はどのような感じか確認します。
Mainクラスのmainメソッド内ローカル変数boolean enableThreadLocalの部分をfalseに指定して実行した結果です。
※本来はマルチスレッド処理してるので、以下のような順番ではログは出ません。
見やすいようにしてます。
2018-15-29 08:15:00,145 [pool-1-thread-1] INFO you_name_is_yu.threadlocal.biz.SampleBiz :＝＝＝1回目 開始＝＝＝
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 :＝＝＝2回目 開始＝＝＝
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 :＝＝＝3回目 開始＝＝＝
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 :＝＝＝1回目 開始＝＝＝
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 :＝＝＝2回目 開始＝＝＝
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 :＝＝＝3回目 開始＝＝＝
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 :＝＝＝1回目 開始＝＝＝
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 :＝＝＝2回目 開始＝＝＝
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 :＝＝＝3回目 開始＝＝＝
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 :■□■□■□合計実行時間（ms）■□■□■□
2018-15-29 08:15:02,255 [main] INFO you_name_is_yu.threadlocal.Main :2167ms
ThreadLocalを利用した場合
ThreadLocalを利用した場合の性能を確認します。
Mainクラスのmainメソッド内ローカル変数boolean enableThreadLocalの部分をtrueに指定して実行した結果です。
この結果を確認すると、しっかり性能改善できていることがわかります。
（無駄に発行するSQLの数を減らしているので当然ですが。。。）
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.biz.SampleBiz :＝＝＝1回目 開始＝＝＝
[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 :＝＝＝2回目 開始＝＝＝
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1] 同じ！！
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1] 同じ！！
[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 :＝＝＝3回目 開始＝＝＝
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1] 同じ！！
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-1] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-1] 同じ！！
[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 :＝＝＝1回目 開始＝＝＝
[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 :＝＝＝2回目 開始＝＝＝
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2] 同じ！！
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2] 同じ！！
[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 :＝＝＝3回目 開始＝＝＝
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2] 同じ！！
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-2] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-2] 同じ！！
[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 :＝＝＝1回目 開始＝＝＝
[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 :＝＝＝2回目 開始＝＝＝
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3] 同じ！！
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3] 同じ！！
[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 :＝＝＝3回目 開始＝＝＝
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3] 同じ！！
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.util.ThreadLocalUtil :あったよ
[pool-1-thread-3] INFO you_name_is_yu.threadlocal.vo.where.AWhereVo :[pool-1-thread-3] 同じ！！
[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 :■□■□■□合計実行時間（ms）■□■□■□
2018-19-29 08:19:12,476 [main] INFO you_name_is_yu.threadlocal.Main :757ms