当前使用版本(必填,否则不予处理)
3.5.3.1
该问题是如何引起的？(确定最新版也有问题再提!!!)
对比使用该插件前后的接口执行耗时
重现步骤(如果有就写完整)
1、没有引入mybatis-plus组件前：从Parameters到Total 耗时是 982-940=42毫秒 2023-04-11 19:58:46.939 DEBUG BaseJdbcLogger.java:137]- <== Total: 1 2023-04-11 19:58:46.940 DEBUG [BaseJdbcLogger.java:137]- ==> Preparing: SELECT source FROM product WHERE product_short = ? AND product.project_id = 'b7693573b8904c08b4267ec1e0daccbd' LIMIT 1 2023-04-11 19:58:46.940 DEBUG [BaseJdbcLogger.java:137]- ==> Parameters: ECS(String) 2023-04-11 19:58:46.982 DEBUG [BaseJdbcLogger.java:137]- <== Total: 1
2、引入mybatis-plus组件后：从Parameters到Total 耗时是 947-853=94毫秒 2023-04-11 20:01:19.853 DEBUG [BaseJdbcLogger.java:137]- ==> Preparing: SELECT source FROM product WHERE product_short = ? AND project_id = 'b7693573b8904c08b4267ec1e0daccbd' LIMIT 1 2023-04-11 20:01:19.853 DEBUG [BaseJdbcLogger.java:137]- ==> Parameters: ECS(String) 2023-04-11 20:01:19.947 DEBUG [BaseJdbcLogger.java:137]- <== Total: 1
报错信息
不报错 就是耗时比原来的多了52ms 一个接口如果执行多个sql 性能消耗就很可观 我的疑问是TenantLineInnerInterceptor是用来拼接sql的 在Preparing之前就完成了 为什么会影响到sql的执行耗时 拦截器实现如下 用于多租改造时 自动拼接sql 减少代码改动量 @Bean public MybatisPlusInterceptor mybatisPlusInterceptor() { MybatisPlusInterceptor interceptor = new MybatisPlusInterceptor(); interceptor.addInnerInterceptor(new TenantLineInnerInterceptor(new TenantLineHandler() { @Override public String getTenantIdColumn() { return "project_id"; } @Override public Expression getTenantId() { return new StringValue("b7693573b8904c08b4267ec1e0daccbd"); } @Override public boolean ignoreTable(String tableName) { return false; } })); return interceptor; }
Comment From: miemieYaho
欢迎pr
Comment From: sushuliang113
我的疑问是TenantLineInnerInterceptor是用来拼接sql的 在Preparing之前就完成了 为什么会影响到sql的执行耗时
Comment From: qclucky7
日志打印 1. getConnection -> 返回Connection代理对象ConnectionLogger拦截prepareStatement() 2. prepare -> prepareStatement() -> 返回Statement理对象PreparedStatementLogger代拦截execute等 3. Statement-> getResultSet() 打印
MybatisPlusInterceptor拦截器的都在StatementHandler和Executor, 都在日志之前, 不会影响耗时应该。
Comment From: CHENMING111111
我的疑问是TenantLineInnerInterceptor是用来拼接sql的 在Preparing之前就完成了 为什么会影响到sql的执行耗时
请问下解决了吗，现在300并发，速度很慢
Comment From: caixiaomao
存在同样的问题，并且性能下降快到秒级了，请问有解决办法吗，初步判断问题发生在解析sql拼装租户条件的地方
Comment From: qianying1
- getConnection -> 返回Connection代理对象ConnectionLogger拦截prepareStatement()
- prepare -> prepareStatement() -> 返回Statement理对象PreparedStatementLogger代拦截execute等
- Statement-> getResultSet() 打印
MybatisPlusInterceptor拦截器的都在StatementHandler和Executor, 都在日志之前, 不会影响耗时应该。
貌似会有影响消耗的
Comment From: qclucky7
我本地搭建了个demo, 但是无法复现相差50ms的问题。
我简单模拟了有插件有日志和无插件有日志的情况。
因为我执行的是简单SQL, 不确定复杂SQL会不会是瓶颈。
Arthas执行 trace java.lang.reflect.InvocationHandler invoke -n 5 --skipJDKMethod false
另外可以使用 trace org.apache.ibatis.plugin.Interceptor intercept -n 5 --skipJDKMethod false 查看下拦截器执行耗时情况。
有插件有日志:
`---ts=2023-10-17 14:35:49;thread_name=http-nio-8888-exec-4;id=1b;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@48840594
`---[9.8485ms] com.baomidou.mybatisplus.core.override.MybatisMapperProxy:invoke()
+---[0.06% 0.006ms ] java.lang.reflect.Method:getDeclaringClass() #86
+---[0.08% 0.0082ms ] java.lang.Object:equals() #86
+---[0.16% 0.0153ms ] com.baomidou.mybatisplus.core.override.MybatisMapperProxy:cachedInvoker() #89
`---[98.57% 9.7073ms ] com.baomidou.mybatisplus.core.override.MybatisMapperProxy$MapperMethodInvoker:invoke() #89
`---[99.37% 9.6459ms ] org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor:invoke()
+---[0.06% 0.0062ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #424
+---[0.03% 0.0026ms ] org.mybatis.spring.SqlSessionTemplate:access$200() #425
+---[0.03% 0.0025ms ] org.mybatis.spring.SqlSessionTemplate:access$300() #425
+---[2.34% 0.2259ms ] org.mybatis.spring.SqlSessionUtils:getSqlSession() #424
+---[93.16% 8.9863ms ] java.lang.reflect.Method:invoke() #427
| `---[99.45% 8.9366ms ] org.apache.ibatis.plugin.Plugin:invoke()
| +---[0.03% 0.0026ms ] java.lang.reflect.Method:getDeclaringClass() #60
| +---[0.03% 0.0024ms ] java.util.Map:get() #60
| +---[0.07% 0.0067ms ] java.util.Set:contains() #61
| +---[0.03% 0.0029ms ] org.apache.ibatis.plugin.Invocation:<init>() #62
| `---[99.52% 8.8937ms ] org.apache.ibatis.plugin.Interceptor:intercept() #62
| +---[63.02% min=0.0484ms,max=4.2264ms,total=5.6044ms,count=3] org.apache.ibatis.plugin.Plugin:invoke()
| | +---[0.19% min=0.002ms,max=0.0064ms,total=0.0108ms,count=3] java.lang.reflect.Method:getDeclaringClass() #60
| | +---[0.19% min=0.0027ms,max=0.0042ms,total=0.0109ms,count=3] java.util.Map:get() #60
| | +---[0.29% min=0.0037ms,max=0.0066ms,total=0.0163ms,count=3] java.util.Set:contains() #61
| | +---[0.08% 0.0043ms ] org.apache.ibatis.plugin.Invocation:<init>() #62
| | +---[22.75% 1.275ms ] org.apache.ibatis.plugin.Interceptor:intercept() #62
| | | `---[51.15% 0.6521ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:invoke()
| | | +---[0.48% 0.0031ms ] java.lang.reflect.Method:getDeclaringClass() #48
| | | +---[0.52% 0.0034ms ] java.lang.Object:equals() #48
| | | +---[0.35% 0.0023ms ] java.lang.reflect.Method:getName() #51
| | | +---[0.63% 0.0041ms ] java.lang.String:equals() #51
| | | +---[1.01% 0.0066ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:isDebugEnabled() #52
| | | +---[0.63% 0.0041ms ] java.lang.StringBuilder:<init>() #53
| | | +---[0.83% min=0.0025ms,max=0.0029ms,total=0.0054ms,count=2] java.lang.StringBuilder:append() #53
| | | +---[6.66% 0.0434ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:removeExtraWhitespace() #53
| | | +---[0.55% 0.0036ms ] java.lang.StringBuilder:toString() #53
| | | +---[35.91% 0.2342ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:debug() #53
| | | +---[33.32% 0.2173ms ] java.lang.reflect.Method:invoke() #55
| | | `---[5.70% 0.0372ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:newInstance() #56
| | `---[75.18% min=0.0149ms,max=4.1986ms,total=4.2135ms,count=2] java.lang.reflect.Method:invoke() #64
| | +---[63.41% min=0.076ms,max=2.1919ms,total=2.6717ms,count=5] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:invoke()
| | | +---[0.72% min=0.0024ms,max=0.0088ms,total=0.0193ms,count=5] java.lang.reflect.Method:getDeclaringClass() #47
| | | +---[1.02% min=0.0022ms,max=0.0159ms,total=0.0272ms,count=5] java.lang.Object:equals() #47
| | | +---[0.54% min=0.0019ms,max=0.006ms,total=0.0145ms,count=5] java.lang.reflect.Method:getName() #50
| | | +---[0.88% min=0.0022ms,max=0.0101ms,total=0.0236ms,count=5] java.util.Set:contains() #50
| | | +---[0.25% 0.0068ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:isDebugEnabled() #51
| | | +---[0.07% 0.002ms ] java.lang.StringBuilder:<init>() #52
| | | +---[0.48% min=0.0021ms,max=0.0108ms,total=0.0129ms,count=2] java.lang.StringBuilder:append() #52
| | | +---[0.27% 0.0072ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:getParameterValueString() #52
| | | +---[0.08% 0.0022ms ] java.lang.StringBuilder:toString() #52
| | | +---[6.97% 0.1862ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:debug() #52
| | | +---[0.18% 0.0047ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:clearColumnInfo() #54
| | | +---[0.09% 0.0025ms ] java.lang.reflect.Method:getName() #55
| | | +---[0.10% 0.0026ms ] java.lang.String:equals() #55
| | | +---[70.19% 1.8753ms ] java.lang.reflect.Method:invoke() #59
| | | +---[0.38% min=0.002ms,max=0.0039ms,total=0.0102ms,count=4] java.lang.reflect.Method:getName() #61
| | | +---[0.55% min=0.0023ms,max=0.0052ms,total=0.0148ms,count=4] java.util.Set:contains() #61
| | | +---[0.53% min=0.0021ms,max=0.0062ms,total=0.0142ms,count=4] java.lang.reflect.Method:getName() #68
| | | +---[0.37% min=0.002ms,max=0.0036ms,total=0.0099ms,count=4] java.lang.String:equals() #68
| | | +---[0.94% 0.025ms ] java.lang.reflect.Method:invoke() #69
| | | +---[1.07% 0.0285ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:newInstance() #70
| | | +---[0.32% min=0.002ms,max=0.0042ms,total=0.0085ms,count=3] java.lang.reflect.Method:getName() #71
| | | +---[0.37% min=0.0024ms,max=0.0038ms,total=0.0099ms,count=3] java.lang.String:equals() #71
| | | +---[1.27% min=0.0167ms,max=0.0173ms,total=0.034ms,count=2] java.lang.reflect.Method:invoke() #78
| | | `---[0.46% 0.0124ms ] java.lang.reflect.Method:invoke() #72
| | `---[25.38% min=0.0445ms,max=0.3757ms,total=1.0695ms,count=11] org.apache.ibatis.logging.jdbc.ResultSetLogger:invoke()
| | +---[3.34% min=0.0021ms,max=0.0046ms,total=0.0357ms,count=11] java.lang.reflect.Method:getDeclaringClass() #66
| | +---[3.32% min=0.0019ms,max=0.007ms,total=0.0355ms,count=11] java.lang.Object:equals() #66
| | +---[24.73% min=0.0068ms,max=0.0603ms,total=0.2645ms,count=11] java.lang.reflect.Method:invoke() #69
| | +---[2.86% min=0.0019ms,max=0.0049ms,total=0.0306ms,count=11] java.lang.reflect.Method:getName() #70
| | +---[2.69% min=0.0019ms,max=0.0046ms,total=0.0288ms,count=11] java.lang.String:equals() #70
| | +---[4.04% min=0.0028ms,max=0.0053ms,total=0.0432ms,count=11] org.apache.ibatis.logging.jdbc.ResultSetLogger:clearColumnInfo() #86
| | +---[0.74% 0.0079ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:isTraceEnabled() #73
| | +---[0.27% 0.0029ms ] java.lang.StringBuilder:<init>() #83
| | +---[0.77% min=0.003ms,max=0.0052ms,total=0.0082ms,count=2] java.lang.StringBuilder:append() #83
| | +---[0.22% 0.0024ms ] java.lang.StringBuilder:toString() #83
| | `---[21.93% 0.2345ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:debug() #83
| `---[1.26% 0.1117ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:invoke()
| +---[2.24% 0.0025ms ] java.lang.reflect.Method:getDeclaringClass() #47
| +---[10.38% 0.0116ms ] java.lang.Object:equals() #47
| +---[3.76% 0.0042ms ] java.lang.reflect.Method:getName() #50
| +---[2.15% 0.0024ms ] java.util.Set:contains() #50
| +---[1.88% 0.0021ms ] java.lang.String:equals() #71
| `---[30.35% 0.0339ms ] java.lang.reflect.Method:invoke() #78
+---[0.06% 0.0058ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #428
+---[0.07% 0.0069ms ] org.mybatis.spring.SqlSessionUtils:isSqlSessionTransactional() #428
+---[0.75% 0.0724ms ] org.apache.ibatis.session.SqlSession:commit() #431
| `---[71.27% 0.0516ms ] org.apache.ibatis.plugin.Plugin:invoke()
| +---[4.46% 0.0023ms ] java.lang.reflect.Method:getDeclaringClass() #60
| +---[5.23% 0.0027ms ] java.util.Map:get() #60
| +---[6.59% 0.0034ms ] java.util.Set:contains() #61
| `---[46.90% 0.0242ms ] java.lang.reflect.Method:invoke() #64
+---[0.05% 0.0048ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #449
`---[2.56% 0.2465ms ] org.mybatis.spring.SqlSessionUtils:closeSqlSession() #449
`---[85.31% 0.2103ms ] org.apache.ibatis.plugin.Plugin:invoke()
+---[1.05% 0.0022ms ] java.lang.reflect.Method:getDeclaringClass() #60
+---[52.97% 0.1114ms ] java.util.Map:get() #60
+---[2.52% 0.0053ms ] java.util.Set:contains() #61
`---[21.87% 0.046ms ] java.lang.reflect.Method:invoke() #64
无插件有日志:
`---ts=2023-10-17 14:34:19;thread_name=http-nio-8888-exec-8;id=1f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@23a5818e
`---[9.0863ms] com.baomidou.mybatisplus.core.override.MybatisMapperProxy:invoke()
+---[0.10% 0.0087ms ] java.lang.reflect.Method:getDeclaringClass() #86
+---[0.06% 0.0054ms ] java.lang.Object:equals() #86
+---[0.16% 0.0145ms ] com.baomidou.mybatisplus.core.override.MybatisMapperProxy:cachedInvoker() #89
`---[98.17% 8.9203ms ] com.baomidou.mybatisplus.core.override.MybatisMapperProxy$MapperMethodInvoker:invoke() #89
`---[98.49% 8.7857ms ] org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor:invoke()
+---[0.09% 0.0079ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #424
+---[0.03% 0.0026ms ] org.mybatis.spring.SqlSessionTemplate:access$200() #425
+---[0.03% 0.0027ms ] org.mybatis.spring.SqlSessionTemplate:access$300() #425
+---[2.44% 0.2145ms ] org.mybatis.spring.SqlSessionUtils:getSqlSession() #424
+---[94.58% 8.3093ms ] java.lang.reflect.Method:invoke() #427
| +---[11.33% 0.9412ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:invoke()
| | +---[0.75% 0.0071ms ] java.lang.reflect.Method:getDeclaringClass() #48
| | +---[0.22% 0.0021ms ] java.lang.Object:equals() #48
| | +---[0.37% 0.0035ms ] java.lang.reflect.Method:getName() #51
| | +---[0.22% 0.0021ms ] java.lang.String:equals() #51
| | +---[0.39% 0.0037ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:isDebugEnabled() #52
| | +---[0.20% 0.0019ms ] java.lang.StringBuilder:<init>() #53
| | +---[2.51% min=0.0027ms,max=0.0209ms,total=0.0236ms,count=2] java.lang.StringBuilder:append() #53
| | +---[1.98% 0.0186ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:removeExtraWhitespace() #53
| | +---[0.20% 0.0019ms ] java.lang.StringBuilder:toString() #53
| | +---[51.61% 0.4858ms ] org.apache.ibatis.logging.jdbc.ConnectionLogger:debug() #53
| | +---[29.61% 0.2787ms ] java.lang.reflect.Method:invoke() #55
| | `---[4.30% 0.0405ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:newInstance() #56
| +---[65.44% min=0.0808ms,max=4.6456ms,total=5.4375ms,count=7] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:invoke()
| | +---[0.26% min=0.0013ms,max=0.0028ms,total=0.0139ms,count=7] java.lang.reflect.Method:getDeclaringClass() #47
| | +---[0.48% min=0.0012ms,max=0.0144ms,total=0.0263ms,count=7] java.lang.Object:equals() #47
| | +---[0.28% min=0.0016ms,max=0.0034ms,total=0.0154ms,count=7] java.lang.reflect.Method:getName() #50
| | +---[0.36% min=0.002ms,max=0.0043ms,total=0.0198ms,count=7] java.util.Set:contains() #50
| | +---[0.29% min=0.0015ms,max=0.005ms,total=0.0155ms,count=6] java.lang.reflect.Method:getName() #61
| | +---[0.21% min=0.0014ms,max=0.0025ms,total=0.0112ms,count=6] java.util.Set:contains() #61
| | +---[0.04% 0.0024ms ] java.lang.reflect.Method:getName() #62
| | +---[0.04% 0.0023ms ] java.lang.String:equals() #62
| | +---[0.15% 0.0084ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:setColumn() #65
| | +---[0.61% 0.0333ms ] java.lang.reflect.Method:invoke() #67
| | +---[0.11% 0.0058ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:isDebugEnabled() #51
| | +---[0.02% 0.0013ms ] java.lang.StringBuilder:<init>() #52
| | +---[0.08% min=0.0015ms,max=0.003ms,total=0.0045ms,count=2] java.lang.StringBuilder:append() #52
| | +---[0.40% 0.0217ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:getParameterValueString() #52
| | +---[0.02% 0.0013ms ] java.lang.StringBuilder:toString() #52
| | +---[10.45% 0.568ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:debug() #52
| | +---[7.76% 0.4221ms ] org.apache.ibatis.logging.jdbc.PreparedStatementLogger:clearColumnInfo() #54
| | +---[0.12% 0.0065ms ] java.lang.reflect.Method:getName() #55
| | +---[1.17% 0.0634ms ] java.lang.String:equals() #55
| | +---[59.35% 3.2269ms ] java.lang.reflect.Method:invoke() #59
| | +---[0.31% min=0.0015ms,max=0.0087ms,total=0.0171ms,count=5] java.lang.reflect.Method:getName() #68
| | +---[0.58% min=0.0016ms,max=0.0225ms,total=0.0313ms,count=5] java.lang.String:equals() #68
| | +---[0.57% 0.0312ms ] java.lang.reflect.Method:invoke() #69
| | +---[0.57% 0.0308ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:newInstance() #70
| | +---[0.14% min=0.0017ms,max=0.0026ms,total=0.0077ms,count=4] java.lang.reflect.Method:getName() #71
| | +---[0.17% min=0.0015ms,max=0.0035ms,total=0.0092ms,count=4] java.lang.String:equals() #71
| | +---[1.82% min=0.0109ms,max=0.0758ms,total=0.099ms,count=3] java.lang.reflect.Method:invoke() #78
| | `---[0.26% 0.0143ms ] java.lang.reflect.Method:invoke() #72
| `---[14.06% min=0.0289ms,max=0.3625ms,total=1.1686ms,count=11] org.apache.ibatis.logging.jdbc.ResultSetLogger:invoke()
| +---[2.12% min=0.0015ms,max=0.0034ms,total=0.0248ms,count=11] java.lang.reflect.Method:getDeclaringClass() #66
| +---[1.75% min=0.0011ms,max=0.0043ms,total=0.0205ms,count=11] java.lang.Object:equals() #66
| +---[25.88% min=0.0057ms,max=0.1095ms,total=0.3024ms,count=11] java.lang.reflect.Method:invoke() #69
| +---[1.92% min=0.0011ms,max=0.0037ms,total=0.0224ms,count=11] java.lang.reflect.Method:getName() #70
| +---[7.25% min=0.0015ms,max=0.0673ms,total=0.0847ms,count=11] java.lang.String:equals() #70
| +---[4.22% min=0.002ms,max=0.0207ms,total=0.0493ms,count=11] org.apache.ibatis.logging.jdbc.ResultSetLogger:clearColumnInfo() #86
| +---[0.79% 0.0092ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:isTraceEnabled() #73
| +---[0.14% 0.0016ms ] java.lang.StringBuilder:<init>() #83
| +---[0.34% min=0.0019ms,max=0.0021ms,total=0.004ms,count=2] java.lang.StringBuilder:append() #83
| +---[0.15% 0.0018ms ] java.lang.StringBuilder:toString() #83
| `---[23.69% 0.2768ms ] org.apache.ibatis.logging.jdbc.ResultSetLogger:debug() #83
+---[0.04% 0.0031ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #428
+---[0.09% 0.0075ms ] org.mybatis.spring.SqlSessionUtils:isSqlSessionTransactional() #428
+---[0.18% 0.0158ms ] org.apache.ibatis.session.SqlSession:commit() #431
+---[0.03% 0.0023ms ] org.mybatis.spring.SqlSessionTemplate:access$100() #449
`---[1.66% 0.146ms ] org.mybatis.spring.SqlSessionUtils:closeSqlSession() #449
Comment From: qclucky7
- getConnection -> 返回Connection代理对象ConnectionLogger拦截prepareStatement()
- prepare -> prepareStatement() -> 返回Statement理对象PreparedStatementLogger代拦截execute等
- Statement-> getResultSet() 打印
MybatisPlusInterceptor拦截器的都在StatementHandler和Executor, 都在日志之前, 不会影响耗时应该。
貌似会有影响消耗的
Comment From: caixiaomao
存在同样的问题，并且性能下降快到秒级了，请问有解决办法吗，初步判断问题发生在解析sql拼装租户条件的地方
经过进一步排查，获取租户id的逻辑存在性能问题，优化后问题解决 🥲
Comment From: nieqiurong