选择线程数目时谨慎考虑线程切换开销

最近为了使用更加高效的connection jdbc pool,在网上发现有个叫hikariCP的貌似不错,里面有篇文章讲了关于配置pool size的魔法,不是越多越好,而是应该恰到好处。

https://github.com/brettwooldridge/HikariCP/wiki/About-Pool-Sizing

考虑整体系统性能,考虑线程执行需要的等待时间,设计合理的线程数目。(Connection Pool Size)

我自己也做了一组测试。

测试描述:

对一个spring4+spring security3+hibernate4 (ehcache+hikariCP)+mysql的系统的某个业务方法(save user,insert new user) 性能测试,统计多线程多执行时候save方法的执行时间。


性能收集代码,在spring里面加入aop,统计方法执行时间

package com.elulian.CustomerSecurityManagementSystem.service;

import java.util.Enumeration;
import java.util.concurrent.ConcurrentHashMap;

import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory; 

public class PerfInterceptor implements MethodInterceptor {

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

	private static ConcurrentHashMap<String, MethodStats> methodStats = new ConcurrentHashMap<String, MethodStats>();
	
	public static Enumeration<MethodStats> getMethodStats(){
		return methodStats.elements();
	}
	
	public static void clearMethodStats(){
		methodStats.clear();
	}
	
	public static void printMethodStats(){
		
		Enumeration<MethodStats> e = methodStats.elements();
		
		
		while(e.hasMoreElements()){
			logger.info(e.nextElement().toString());
		}
	}
	
	/* 
	 * performance monitor for service layer
	 * @see org.aopalliance.intercept.MethodInterceptor#invoke(org.aopalliance.intercept.MethodInvocation)
	 */

	public Object invoke(MethodInvocation method) throws Throwable {
		long start = System.nanoTime();
		try {
			return method.proceed();
		} finally {
			updateStats(method.getMethod().getName(),
					(System.nanoTime() - start));
		}
	}

	private void updateStats(String methodName, long elapsedTime) {
		MethodStats stats = methodStats.get(methodName);
		if (stats == null) {
			stats = new MethodStats(methodName);
			methodStats.put(methodName, stats);
		}
		stats.count++;
		stats.totalTime += elapsedTime;
		if (elapsedTime > stats.maxTime) {
			stats.maxTime = elapsedTime;
		}
		
		if(elapsedTime < stats.minTime || 0 == stats.minTime){
			stats.minTime = elapsedTime;
		}

	}
	
	class MethodStats {
		public String methodName;
		public long count;
		public long totalTime;
		public long maxTime;
		public long minTime;

		public MethodStats(String methodName) {
			this.methodName = methodName;
		}

		@Override
		public String toString() {
			StringBuilder sb = new StringBuilder("method: ");
			sb.append(methodName).append("(), cnt = ").append(count)
					.append(", avgTime = ").append(totalTime / count)
					.append(", maxTime = ").append(maxTime).append(", minTime = ")
					.append(minTime);
			return sb.toString();
		}
	}
}

测试代码:统计不同线程数写不同数据量的时间

@Test
	public void testAdd() {
		
		logger.info("-----------begin test add------------------------"); 
		
		monitorAddUser(1, 1);	
		monitorAddUser(1, 10);	
		monitorAddUser(1, 100);	
		monitorAddUser(1, 1000);	
		
		monitorAddUser(5, 1);	
		monitorAddUser(5, 10);	
		monitorAddUser(5, 100);	
		monitorAddUser(5, 1000);	
		
		monitorAddUser(10, 1);			
		monitorAddUser(10, 10);	
		monitorAddUser(10, 100);	
		monitorAddUser(10, 1000);
		
		logger.info("-----------finish test add------------------------");
	}


	/**
	 * @param recordsNumber
	 */
	private void monitorAddUser(final int threads, final int records) {
		
		BlockingQueue<Runnable> queue = new LinkedBlockingQueue<Runnable>();    
	     ThreadPoolExecutor executor = new ThreadPoolExecutor(10, 20, 1, TimeUnit.DAYS, queue, new RejectedExecutionHandler(){

			@Override
			public void rejectedExecution(Runnable arg0, ThreadPoolExecutor arg1) {
				logger.error(arg0.toString());
			}
	    	 
	     });
		
	     List<Future<List<UserInfo>>> list = new LinkedList<Future<List<UserInfo>>>(); 
	     
		for(int i = 0; i < threads; i++){
			list.add(executor.submit(new Callable<List<UserInfo>>(){
						@Override
						public List<UserInfo> call() throws Exception {
							SecurityContextHolder.getContext().setAuthentication(new UsernamePasswordAuthenticationToken("Admin","password"));
							List<UserInfo> list = new ArrayList<UserInfo>(records);
							
							Calendar cl = Calendar.getInstance();
							Date registerTime = cl.getTime();
							cl.add(Calendar.MONTH, 6);
							Date expiredTime = cl.getTime();
							for (int i = 0; i < records; i++){
								String username = "temp" + System.nanoTime() + Thread.currentThread().getName() + i;
								String userId = username;	
								final UserInfo userInfo = new UserInfo();
								buildUser(userInfo, username, userId, registerTime, expiredTime,
										(username + "@gmail.com"),"ALL");
								list.add(userInfoService.save(userInfo));
							}
							return list;
						} 
					})
			);
			
		}
		
		for(Future<List<UserInfo>> future : list){
				try {
					future.get();
				} catch (InterruptedException e) {
					logger.error(e.getMessage(), e);
				} catch (ExecutionException e) {
					logger.error(e.getMessage(), e);
				}
		}
		executor.shutdown();
		PerfInterceptor.printMethodStats();
		PerfInterceptor.clearMethodStats();
	}

本次测试包括了1个线程同时写入不同量的数据,5个线程同时写入不同量的数据和10个线程同时写入不同量的数据,在本机小跑了2次:

INFO - -----------begin test add------------------------
INFO - method: save(), cnt = 1, avgTime = 609820325, maxTime = 609820325, minTime = 609820325 
INFO - method: save(), cnt = 10, avgTime = 164609600, maxTime = 294096906, minTime = 134606570
INFO - method: save(), cnt = 100, avgTime = 151708086, maxTime = 346537459, minTime = 134017872
INFO - method: save(), cnt = 1000, avgTime = 154990550, maxTime = 502604064, minTime = 137988348
INFO - method: save(), cnt = 5, avgTime = 643401202, maxTime = 826286288, minTime = 469981973
INFO - method: save(), cnt = 50, avgTime = 333072749, maxTime = 1205599371, minTime = 148682659
INFO - method: save(), cnt = 500, avgTime = 329581392, maxTime = 1191434464, minTime = 140381524
INFO - method: save(), cnt = 5000, avgTime = 320060021, maxTime = 2038866575, minTime = 137353679
INFO - method: save(), cnt = 10, avgTime = 1229729703, maxTime = 1433571059, minTime = 897245616
INFO - method: save(), cnt = 100, avgTime = 645747340, maxTime = 2502894618, minTime = 140583262
INFO - method: save(), cnt = 951, avgTime = 630759070, maxTime = 3539171189, minTime = 140115070
INFO - method: save(), cnt = 10000, avgTime = 651280533, maxTime = 4336544319, minTime = 137962908

线程数 记录数 平均时间 最大时间 最小时间
1 1 0.60982 0.60982 0.60982
1 10 0.16461 0.294097 0.134607
1 100 0.151708 0.346537 0.134018
1 1000 0.154991 0.502604 0.137988
5 1 0.643401 0.826286 0.469982
5 10 0.333073 1.205599 0.148683
5 100 0.329581 1.191434 0.140382
5 1000 0.32006 2.038867 0.137354
10 1 1.22973 1.433571 0.897246
10 10 0.645747 2.502895 0.140583
10 100 0.630759 3.539171 0.140115
10 1000 0.651281 4.336544 0.137963

INFO - -----------begin test add------------------------
INFO - method: save(), cnt = 1, avgTime = 1134227197, maxTime = 1134227197, minTime = 1134227197
INFO - method: save(), cnt = 10, avgTime = 181221421, maxTime = 280446161, minTime = 148497436
INFO - method: save(), cnt = 100, avgTime = 167396030, maxTime = 336451038, minTime = 142955461
INFO - method: save(), cnt = 1000, avgTime = 158428404, maxTime = 451007058, minTime = 139375516
INFO - method: save(), cnt = 5, avgTime = 671908207, maxTime = 772010460, minTime = 565322956
INFO - method: save(), cnt = 50, avgTime = 337210775, maxTime = 1123061570, minTime = 148056024
INFO - method: save(), cnt = 500, avgTime = 333817014, maxTime = 844627873, minTime = 137880338
INFO - method: save(), cnt = 5000, avgTime = 340500268, maxTime = 1900762183, minTime = 135334967
INFO - method: save(), cnt = 10, avgTime = 1195048106, maxTime = 1576752359, minTime = 606659475
INFO - method: save(), cnt = 100, avgTime = 712619854, maxTime = 3173834220, minTime = 156229511
INFO - method: save(), cnt = 1000, avgTime = 668881282, maxTime = 3553853384, minTime = 140232453
INFO - method: save(), cnt = 10000, avgTime = 658712070, maxTime = 3953375463, minTime = 134411528
INFO - -----------finish test add------------------------
线程数 记录数 平均时间 最大时间 最小时间
1 1 1.134227 1.134227 1.134227
1 10 0.181221 0.280446 0.148497
1 100 0.167396 0.336451 0.142955
1 1000 0.158428 0.451007 0.139376
5 1 0.671908 0.77201 0.565323
5 10 0.337211 1.123062 0.148056
5 100 0.333817 0.844628 0.13788
5 1000 0.3405 1.900762 0.135335
10 1 1.195048 1.576752 0.606659
10 10 0.71262 3.173834 0.15623
10 100 0.668881 3.553853 0.140232
10 1000 0.658712 3.953375 0.134412

从测试结果我们可以知道:

1个线程比5个线程快,(1个线程写10条记录平均时间是5个线程写10条记录平均时间的1/2)5个线程比10个线程快(1/2)。(除去线程数1,记录1是第一次启动,有lazy load之外)

1个线程写10个记录比10个线程各写1个记录快。

使用jvisualvm监控程序运行时,也可以看出来thread等待切换非常多:



设计多线程是为了尽可能利用CPU空闲等待时间(等IO,等交互。。。),它的代价就是要增加部分CPU时间来实现线程切换。假如CPU空闲等待时间已经比线程切换更短,(线程越多,切换消耗越大)那么线程切换会非常影响性能,成为系统瓶颈。


至于如何设计合理的线程数目,要考虑线程的执行时间和等待时间以及切换开销,对于connection pool,hikaricp里面给出一个非常有经验的解答

connections = ((core_count * 2) + effective_spindle_count)

我的电脑真的老了:

mysql> delete from userinfo where name like 'temp%';
Query OK, 17815 rows affected (7.25 sec)






展开阅读全文

没有更多推荐了,返回首页