测试背景

最近公司到一个新客户关系管理项目,为了能够提高开发效率,研发经理尝试了很多种方法,终于在一个Spdycodinghttps://www.spdycoding.com/的网站上找到了可以快速自动生成代码的delicacy生成器,让我研究研究带领小团队学习使用

delicacy框架是一个基础MVC架构的后台框架,提供标准的接口访问,里面封装了DelicacyDao(数据库持久层),无需再使用第三的数据库持久层框架,官网提供delicacy代码生成器,结合delicacy框架,可以通过数据库定义的表结构、自定义写的复杂SQL语句生成相应数据库操作代码(增、删、改、查),同时可以根据用户的需求生成相对应的前端页面代码。

拿到生成器和jar包,先看反编出来的代码,了解开发者逻辑思维。这是一个与常用spring项目不同的思维delicacy生成后的代码与jar包中的基础类契合,构成了以servlet为基础的web项目。万变不离其宗,以servlet为基础则离不开接口业务分发,delicay使用了单一接口地址,按约定参数分发业务的方式。同时使用了内置按线程绑定的数据库连接池,更令人惊讶的是,统一了对象的tojson方法,各对象重写此方法实现自己的行为多态,着实惊艳!更多细节有品味之处便不在这里一一讲述

惊艳过后,我开始探究此结构的便利性与执行性能,并试图与springmvc+mybatis项目作对比,那么第一步是构建项目。最典型的servlet项目pomant等打包,war部署,delicacy的项目同样如此,只要个简单的配置——web.xml、数据源与log4j日志,项目就可以启动了(此处有坑,先卖关子)。当然由于此次是测试性质,我们在项目里写了很多程序起点的main()用来测试单独的一个方面,也把war放入tomcat测试了应用性能。好了,闲言到此为此,请看以下测试数据

测试项目及简析

单表插入

delicacy第一次

单次循环插入

2019-12-07 01:14:32 [TestMain]-[WARN] 插入100条数据使用时间是:206

2019-12-07 01:14:33 [TestMain]-[WARN] 插入1000条数据使用时间是:1588

2019-12-07 01:14:47 [TestMain]-[WARN] 插入10000条数据使用时间是:14073

批量插入

2019-12-07 01:14:48 [TestMain]-[WARN] 插入100条数据使用时间是:168

2019-12-07 01:14:49 [TestMain]-[WARN] 插入1000条数据使用时间是:1389

2019-12-07 01:15:03 [TestMain]-[WARN] 插入10000条数据使用时间是:13736

 

delicacy第二次

单次循环插入

2019-12-07 01:19:16 [TestMain]-[WARN] 插入100条数据使用时间是:201

2019-12-07 01:19:18 [TestMain]-[WARN] 插入1000条数据使用时间是:1508

2019-12-07 01:19:32 [TestMain]-[WARN] 插入10000条数据使用时间是:14254

批量插入

2019-12-07 01:19:32 [TestMain]-[WARN] 插入100条数据使用时间是:169

2019-12-07 01:19:33 [TestMain]-[WARN] 插入1000条数据使用时间是:1394

2019-12-07 01:19:47 [TestMain]-[WARN] 插入10000条数据使用时间是:13840

delicacy第三次

单次循环插入

2019-12-07 01:22:00 [TestMain]-[WARN] 插入100条数据使用时间是:196

2019-12-07 01:22:02 [TestMain]-[WARN] 插入1000条数据使用时间是:1509

2019-12-07 01:22:16 [TestMain]-[WARN] 插入10000条数据使用时间是:14261

批量插入

2019-12-07 01:22:16 [TestMain]-[WARN] 插入100条数据使用时间是:168

2019-12-07 01:22:17 [TestMain]-[WARN] 插入1000条数据使用时间是:1390

2019-12-07 01:22:31 [TestMain]-[WARN] 插入10000条数据使用时间是:13723

 

 

 

mybatis第一次

单次循环插入

2019-12-07 01:16:24 [TestMain]-[WARN] 插入100条数据使用时间是:488

2019-12-07 01:16:26 [TestMain]-[WARN] 插入1000条数据使用时间是:1602

2019-12-07 01:16:41 [TestMain]-[WARN] 插入10000条数据使用时间是:15536

批量插入

2019-12-07 01:16:42 [TestMain]-[WARN] 插入100条数据使用时间是:87

2019-12-07 01:16:42 [TestMain]-[WARN] 插入1000条数据使用时间是:121

2019-12-07 01:16:42 [TestMain]-[WARN] 插入10000条数据使用时间是:507

 

mybatis第二次

单次循环插入

2019-12-07 01:20:33 [TestMain]-[WARN] 插入100条数据使用时间是:480

2019-12-07 01:20:34 [TestMain]-[WARN] 插入1000条数据使用时间是:1618

2019-12-07 01:20:50 [TestMain]-[WARN] 插入10000条数据使用时间是:15252

批量插入

2019-12-07 01:20:50 [TestMain]-[WARN] 插入100条数据使用时间是:89

2019-12-07 01:20:50 [TestMain]-[WARN] 插入1000条数据使用时间是:116

2019-12-07 01:20:50 [TestMain]-[WARN] 插入10000条数据使用时间是:505

mybatis

单次循环

2019-12-07 01:23:51 [TestMain]-[WARN] 插入100条数据使用时间是:469

2019-12-07 01:23:53 [TestMain]-[WARN] 插入1000条数据使用时间是:1620

2019-12-07 01:24:08 [TestMain]-[WARN] 插入10000条数据使用时间是:15043

批量

2019-12-07 01:24:08 [TestMain]-[WARN] 插入100条数据使用时间是:71

2019-12-07 01:24:08 [TestMain]-[WARN] 插入1000条数据使用时间是:120

2019-12-07 01:24:08 [TestMain]-[WARN] 插入10000条数据使用时间是:511

 

测试操作步骤及设置情况

Log4j设置日志为warn,事务自动提交,每次测试后,都清空数据库,再进行下一次测试。delicacymybatis的测试交替进行。

 

简析

delicacy的平均单条插入时候在比mybatis短,连续100条时delicacy的单条平均时间为2msmybatis的单条平均为4.8ms.随着连续条数的增长到10000条,delicacy的单条平均时间为1.4ms,此时mybatis的单条平均为1.5ms.在测试样本内,mybatis始终未能超越delicacy的单条插入能力。delicacy的批量插入时间显著落后于mybatis。小样本数量时delicacymybatis的批量插入时间较单条循环都有显著提升,大样本数量时,delicacy的批量插入时间趋近于单条循环时间。

 

 

父子表插入

Delicacy第一次

2019-12-07 23:09:41 [UnionTableTest]-[WARN] 插入100条数据使用时间是:1090

2019-12-07 23:09:52 [UnionTableTest]-[WARN] 插入1000条数据使用时间是:11048

2019-12-07 23:14:40 [UnionTableTest]-[WARN] 插入10000条数据使用时间是:287114

 

Delicacy第二次

2019-12-07 23:34:37 [UnionTableTest]-[WARN] 插入100条数据使用时间是:1366

2019-12-07 23:34:48 [UnionTableTest]-[WARN] 插入1000条数据使用时间是:11131

2019-12-07 23:39:34 [UnionTableTest]-[WARN] 插入10000条数据使用时间是:286707

Delicacy第三次

2019-12-07 23:47:15 [UnionTableTest]-[WARN] 插入100条数据使用时间是:1085

2019-12-07 23:47:26 [UnionTableTest]-[WARN] 插入1000条数据使用时间是:11096

2019-12-07 23:52:25 [UnionTableTest]-[WARN] 插入10000条数据使用时间是:299705

 

Mybatis第一次

2019-12-09 23:44:45 [UnionTest]-[WARN] 插入100条数据使用时间是:828

2019-12-09 23:44:49 [UnionTest]-[WARN] 插入1000条数据使用时间是:3456

2019-12-09 23:45:22 [UnionTest]-[WARN] 插入10000条数据使用时间是:32876

Mybatis

2019-12-09 23:47:05 [UnionTest]-[WARN] 插入100条数据使用时间是:812

2019-12-09 23:47:08 [UnionTest]-[WARN] 插入1000条数据使用时间是:3524

2019-12-09 23:47:41 [UnionTest]-[WARN] 插入10000条数据使用时间是:32764

Mybatis

2019-12-09 23:48:27 [UnionTest]-[WARN] 插入100条数据使用时间是:809

2019-12-09 23:48:31 [UnionTest]-[WARN] 插入1000条数据使用时间是:3504

2019-12-09 23:49:03 [UnionTest]-[WARN] 插入10000条数据使用时间是:32259

 

简析

父子表插入时,mybatis的时间稍大于delicacy的时间,单就持久层来看mybatis更强。其主要原因有两点:第一,mybatis没有关心插入时的子表记录的清洗,是纯的持久层,delicacy在插入时,根据入参不同,清理的原来的明细信息。第二,从之前的记录看,mybatis在单表批量插入的时候性能远超delicacy,也以在此次测试时,我们使用1条记录5条明细的插入对mybatis批量插入有优势。

测试后我及时向此框架的开发者反馈了单表批量插入情况,开发者也作出了及时的针对mysql数据库的优化,我们在最后完成测试计划后再做验证。

多线程单表插入

 

Delicacy第一次

2019-12-11 22:00:10 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是26933

Delicacy第二次

2019-12-11 22:00:58 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是26624

Delicacy第三次

2019-12-11 22:06:34 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是27119

Mybatis第一次

2019-12-11 21:49:08 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是28075

Mybatis第二次

2019-12-11 21:50:49 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是27891

Mybatis第三次

2019-12-11 21:51:30 [MultiThreadInsert]-[WARN] 10个线程并发完成100000条插入的时间是27884

 

简析

多线程插入时,delicacy的速度比mybatis快。测试时使用了10线程的固定线程池,都使用了连接池,delicacy是线程绑定的连接池,mybatis是默认连接池,默认连接数是10。此结果从侧面验证了第一项测试的结果:单条插入delicacyMybatis快。

在测试时观查到Wed Dec 11 22:06:07 CST 2019 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.这并不是第一次出现,因为我的数据库默认提示使用账号密码的连接,固jdbc驱动在WARN级别作出提示,但更奇怪的时,在给mybatis做测试的时候,此文本打印次数超过10,348次,但从mysql workbench中监测到确实只有10个连接在工作,而delicacy的打印次数只有10次,workbench中也只有10个连接工作。说明Mybatis连接数据库的次数超过了10次,总连接数正常,其默认连接池工作原理还有待深入检查

 

 

单表查询

Delicacy第一次

2019-12-11 23:48:11 [SingleTableSelect]-[WARN] 执行10000次查询的时间是:3534

Delicacy第二次

2019-12-11 23:48:47 [SingleTableSelect]-[WARN] 执行10000次查询的时间是:3343

Delicacy第三次

2019-12-11 23:49:01 [SingleTableSelect]-[WARN] 执行10000次查询的时间是:3367

 

Mybatis第一次

2019-12-11 23:28:41 [SingleSelectTest]-[WARN] 执行10000次查询的时间是:4043

Mybatis第二次

2019-12-11 23:29:03 [SingleSelectTest]-[WARN] 执行10000次查询的时间是:4099

Mybatis第三次

2019-12-11 23:29:19 [SingleSelectTest]-[WARN] 执行10000次查询的时间是:4027

 

简析

在被邀请做此测试的时候已经预见到此结果,delicay的单表查询比mybatis快。Delicay是生成器的目标代码,在sql结果转换成java Bean的时候使用了直接创造对象new,但是mybatis是通用持久层,只能用反射创建对象。Java反射一直比直接创造对象要慢。

 

 

父子表查询

Delicacy第一次
2019-12-12 22:32:31 [UnionTableSelect]-[WARN] 执行10000父子表查询的时间是:5219

Delicacy第二次

2019-12-12 23:43:59 [UnionTableSelect]-[WARN] 执行10000父子表查询的时间是:4979

Delicacy第三次

2019-12-12 23:44:25 [UnionTableSelect]-[WARN] 执行10000父子表查询的时间是:4950

Mybatis第一次

2019-12-12 01:26:29 [UnionSelectTest]-[WARN] 执行10000父子表查询的时间是:2840

Mybatis

2019-12-12 01:33:57 [UnionSelectTest]-[WARN] 执行10000父子表查询的时间是:2834

Mybatis第三次

2019-12-12 01:34:12 [UnionSelectTest]-[WARN] 执行10000父子表查询的时间是:2866

 

简析

首先,当我看到父子表查询消耗的时间少于单表查询时,立即让我以为测试出了问题。检查后发现是数据库中的数据量变少了,单表查询时User表中数据是60万,现在user表中数据是5.5万,Customer表中数据是1.1.并且user表中的customer_id字段做了索引(没做索引时很慢,explan后发现user表被全表扫描)。

其次,Delicacy在做父子表查询时对子表的查询是独立的查询,然后把子表数据装进返回对象的list中,所以在本次测试中10000次查询,则delicacy实际进行了20000次查询数据库的操作,因而速度变慢。从具体的时间消息上也可以证实此过程。

 

 

Web项目应用感受

 

delicacy程序搭建:

Ssm 这个结构在国内网上有大把的样板代码,配置可整套复制然后修改即可,maven依赖各大仓库都有。但值得说的是:ssm本人也很久没有用过了,加上idea 社区版不能直接调试,在这个项目搭建上也折腾了好一会。再说delicacy,除数据连接和日志外没有配置,这个很爽。但是在启动项目过程中遇到两次运行时异常,一次为缺少commons-fileupload,一次为缺少表column_domains。特意把这两个提出来说的原因是,我并没有用到文件上传,也并没有用到column_domains表,这是delicacy的两个隐藏依赖,成功满足后,项目顺利运行。

运行:

1在程序中写了一个用随机id查询用户并返回json的接口,两者的简易程序相当。Jmeter配置10线程测试得ssmqps13945.1,而delicacy的为7846.2。分析发现delicacy框架在warn级别打出了日志

2019-12-16 23:01:44 [delicacy.servlet.DelicacyServlet]-[WARN]

2019-12-16 23:01:44 [delicacy.servlet.DelicacyServlet]-[WARN] "id":13780,"account":"n","password":"h","userName":"z","customerId":2756,"a":"f","b":"f","c":"f","d":"i","e":"e","f":"z","g":"m"

此日志为详细输入参数与输出结果,ssm没有日志。我认为输入输出日志是调试日志,框架应用在warn级别打印此日志略有不妥,其它开源框架一般打印在debugtrace级别。

尽最大努力排除日志因素影响,delicacy的日志级别调到error级别后测得QPS12810.7。这个结果让我惊讶,前面的测试,单表查询,与结果集解析,都是delicacy10-20%的优势胜出 ,为什么输出到客户端的吞吐量要比ssh的小呢?

 

2delicay生成一个父子关系的表查询,很容易就能查询并返回父子结构的数据,这个是很不错的功能。也是在开发中常用到的。但是在前期我们知道delicacy的子表信息是多次查询得到的,为非最佳效率的方法。就此我考虑专门写一个sql语句给生成器,专门执行这个查询任务。

 

3.写了一个查询,使用到四张表,客户,联系人,客户联系人关系,用户(各表中都有Create_user_id,连上用户表以把id转换为名字,一次性获得该客户的所有详细的可显示的信息。生成器为我们生成了符合sql返回列的数据,条件查询部分很轻松实现了。实际操作中较难序列化父子关系的json,这里我并没有使用用开源的第三方json序列化工具,而是试图像框架的代码一样让对象自己实现自己的tojson(),但手写代码太痛苦了。参见类中注释uroaming.processor.ThreeTableProc

 

至此delicay的体验就写完了,基于我是一个平时使用mybatis用户情形,以上点评较多存在主观感受。我相信较为熟悉delicay的用户可能有更好的实践方案,以至于更好的应用delicacy.

 

mybatis程序搭建:

 

为了与delicay一样使用放在tomcat中的war运行项目,我特意使用的srping mvcmybatis赋能,而不是springbootMvcxml配置还是需要花很多时间,特别是贸然使用了5版本的mvc一个坑是classPath:字符串的写法,以前是纯小写,现在有的地方要与大写,有的要写小写classpath。然后配置mybatisspring bean窗口,直接在网上抄来了。

 

运行:

1.写一个用随机id查询用户并返回json的接口,也正是上文中的例子。Spring运行时报错,无法转换为json。加入jacksonjar后解决。 这里需要说明一下,在delicacy中的缺少包的情况:缺少commons-fileupload包的时候,我并没有需要上传文件的功能。而缺少jackson包时,我正在使用@ResponseBody要求spring将对象转换为json

 

2.对于mybatis来说,delicay 第二项和第三项应用几乎雷同,直接执行delicacy的第三项业务,写xml动态sql的时候,每个字母都是键盘敲击出来,大量看上去有规律重复的条件让人发狂。还要每一个属性去核对出入参的属性,太伤人了。

 

 

附加测试

在测试的途中,很有幸与delicacy开发者建立联系,开发者了解到mysqlinsert批量插入语句有特殊的支持时,更改了代码针对mysql优化,帮再此测一遍delicacy批量单线程插入性能;

Delicacy优化前:

2019-12-07 01:14:48 [TestMain]-[WARN] 插入100条数据使用时间是:168

2019-12-07 01:14:49 [TestMain]-[WARN] 插入1000条数据使用时间是:1389

2019-12-07 01:15:03 [TestMain]-[WARN] 插入10000条数据使用时间是:13736

优化后第一次

2019-12-19 22:22:09 [SingleTableInsert]-[WARN] 插入100条数据使用时间是:34

2019-12-19 22:22:10 [SingleTableInsert]-[WARN] 插入1000条数据使用时间是:60

2019-12-19 22:22:10 [SingleTableInsert]-[WARN] 插入10000条数据使用时间是:268

优化后第

2019-12-19 22:24:09 [SingleTableInsert]-[WARN] 插入100条数据使用时间是:34

2019-12-19 22:24:09 [SingleTableInsert]-[WARN] 插入1000条数据使用时间是:61

2019-12-19 22:24:10 [SingleTableInsert]-[WARN] 插入10000条数据使用时间是:258

优化后第三次

2019-12-19 22:24:22 [SingleTableInsert]-[WARN] 插入100条数据使用时间是:32

2019-12-19 22:24:22 [SingleTableInsert]-[WARN] 插入1000条数据使用时间是:60

2019-12-19 22:24:22 [SingleTableInsert]-[WARN] 插入10000条数据使用时间是:264

 

分析:

优化后的性能发生质的飞跃,同时超过了mybatis的性能。

 

 

Delicaysql解析与mybatis的动态sql测试

 

由于sql解析后查数据库的性能在之前的测试中已经有了较为详细的比较,并且我认为sql解析的时间会远小于数据库的查询执行时间,所以为了避免数据库的查询时间抖动让解析性能测不出,我在这项测试中用动态修改字节码的技术,把程序解析完成之后,准备发送到jdbc驱动以查询数据库之前的时间计算出来,把真实查询数据库的过程祛除。测试sql15个条件全部设置查询值

Delicacy第一次

2019-12-21 00:00:36 [uroaming.SqlParseTest]-[WARN] delicacy解析10000次条件查询sql的时间是:1163

Delicacy第二次

2019-12-21 00:00:51 [uroaming.SqlParseTest]-[WARN] delicacy解析10000次条件查询sql的时间是:1170

Delicacy第三次

2019-12-21 00:01:03 [uroaming.SqlParseTest]-[WARN] delicacy解析10000次条件查询sql的时间是:1148

 

Mybatis第一次

2019-12-21 01:42:32 [fu.dan.qi.testmybatis.SqlParseTest]-[WARN] mybatis 解析10000次条件查询sql的时间是:1551

Mybatis第二次

2019-12-21 01:42:53 [fu.dan.qi.testmybatis.SqlParseTest]-[WARN] mybatis 解析10000次条件查询sql的时间是:1544

Mybatis第三次

2019-12-21 01:43:03 [fu.dan.qi.testmybatis.SqlParseTest]-[WARN] mybatis 解析10000次条件查询sql的时间是:1553

 

分析:mybatis解析sql的速度慢于delicacy,这当中已经祛除了真实的查数据库的影响。只有查询,固定返回空结果,封装java对象。我认为原因是mybatis使用反射,加载插件(这次没有插件)等因素导致代码调用链复杂所致。而生成器后成的delicacy代码是已知类型操作,代码调用链较短。

 

 

写在最后

本人水平有限,这次对比结果到这里就告一段落,总体的感觉是delicay用了不同于国内流行的常规开发方法,不同的设计结构,利用了生成器对特定项目的优势,巧妙的提升了不少的性能,而对新工具,方法的熟练需要项目来锻炼,如能精通则开发效率的提高还有更大的空间。