1 arthas
1.1. arthas查询方法执行时间
arthas是一款由阿里巴巴开发的Java诊断利器，可以用它来定位不少问题。
官网：https://arthas.aliyun.com/doc/arthas-tutorials?language=cn
1.1.1. arthas原理
- 通过jdk提供的Instrument和Attach API接口，入口为agentmain函数，arthas能够对JVM底层组件进行访问，可参考：https://blog.csdn.net/u010862794/article/details/87773434
- 通过ASM，一种Java字节码操作框架，arthas实现了Enhancer和AdviceWeaver方法，用来动态生成class或增强class
1.1.2. arthas应用场景
例如说，将arthas.jar放在服务端上，启动它之后，可以查看：
- 出现不可预知的bug后，无法在本地复现。无法debug，arthas可以用它来查看正在执行的服务端的具体数据：反编译正在执行的代码，查看入参与出参，定位代码执行的情况。
- 性能优化，查看方法的调用路径，并输出每个节点的执行时间。
- 监控线上JVM的实时运行状态（Thread、GC、Memory、Runtime、堆栈的情况）
- 查看CPU使用率TopN的线程、排查阻塞的线程
1.1.3. arthas查看执行方法的情况
通过arthas，可以查看执行方法链的情况，找到耗时最长的方法：demo.MathGame
$ trace --skipJDKMethod false demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 60 ms.
`---ts=2019-12-04 00:44:41;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
`---[1.357742ms] demo.MathGame:run()
+---[0.028624ms] java.util.Random:nextInt() #23
+---[0.045534ms] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.005372ms] java.lang.StringBuilder:<init>() #28
+---[0.012257ms] java.lang.Integer:valueOf() #28
+---[0.234537ms] java.lang.String:format() #28
+---[min=0.004539ms,max=0.005778ms,total=0.010317ms,count=2] java.lang.StringBuilder:append() #28
+---[0.013777ms] java.lang.Exception:getMessage() #28
+---[0.004935ms] java.lang.StringBuilder:toString() #28
`---[0.06941ms] java.io.PrintStream:println() #28
`---ts=2019-12-04 00:44:42;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
`---[3.030432ms] demo.MathGame:run()
+---[0.010473ms] java.util.Random:nextInt() #23
+---[0.023715ms] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.005198ms] java.lang.StringBuilder:<init>() #28
+---[0.006405ms] java.lang.Integer:valueOf() #28
+---[0.178583ms] java.lang.String:format() #28
+---[min=0.011636ms,max=0.838077ms,total=0.849713ms,count=2] java.lang.StringBuilder:append() #28
+---[0.008747ms] java.lang.Exception:getMessage() #28
+---[0.019768ms] java.lang.StringBuilder:toString() #28
`---[0.076457ms] java.io.PrintStream:println() #28
2. es的profile
可以执行es的profile api，查看执行es的查询语句时，什么节点比较耗时，用于分析，优化es查询效率
2.1. 参考文档
文档入口：https://docs.kilvn.com/elasticsearch/docs/132.html
2.2. 启用方法
ES常见的慢查询优化方案是使用es本身的 profile API，举例如下：
GET /_search
{
"profile": true,
"query" : {
"match" : { "message" : "message number" }
}
}
2.3. 整体结构
其中返回的数据结构如下：
"profile": {
"shards": [
{
"id": "[hWxBcjaPSpqccQtJmN][user_tag][1]",
"searches": [
{
"query": [...],
"rewrite_time": 7861,
"collector": [...]
}
],
"aggregations": [...]
}
]
}
searches：有三个元素，每个元素都有各自的属性与含义:
-
query：分析分块执行生成的查询树的详细时序
-
rewrite_time：查询重写一个或多个组合查询的时间
-
collector：负责协调匹配文档的遍历、得分和集合
aggregations：包含了聚合过程中具体执行信息。
2.3.1 query
-
type：查询类型，常见的有BooleanQuery，TermQuery等
-
time/time_in_nanos：执行该查询所用的时间，包括children的时间
-
breakdown：主要与lucene参数有关，记录Lucene的运转实际上耗费时间的
-
children：具有多个关键字的查询被拆成相应术语的布尔查询
"query": [
{
"type": "BooleanQuery",
"description": "message:message message:number",
"time": "1.873811000ms",
"time_in_nanos": "1873811",
"breakdown": {...},
"children": [
{
"type": "TermQuery",
"description": "message:message",
"time": "0.3919430000ms",
"time_in_nanos": "391943",
"breakdown": {...}
},
{
"type": "TermQuery",
"description": "message:number",
"time": "0.2106820000ms",
"time_in_nanos": "210682",
"breakdown": {...}
}
]
}
]
"breakdown": {
"score": 51306,
"score_count": 4,
"build_scorer": 2935582,
"build_scorer_count": 1,
"match": 0,
"match_count": 0,
"create_weight": 919297,
"create_weight_count": 1,
"next_doc": 53876,
"next_doc_count": 5,
"advance": 0,
"advance_count": 0
}
2.3.2. rewrite_time
"rewrite_time": 12345
2.3.3. collector
-
name：收集器名称
-
reason：详细
-
time_in_nanos：收集执行花费的时间
-
children：收集器(Collector)由SimpleTopScoreDocCollector包装成 CancellableCollector
"collector": [
{
"name": "CancellableCollector",
"reason": "search_cancelled",
"time": "0.3043110000ms",
"time_in_nanos": "304311",
"children": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time": "0.03227300000ms",
"time_in_nanos": "32273"
}
]
}
]
SimpleTopScoreDocCollector是Elasticsearch使用的默认的“评分和排序”的收集器(Collector)
3 junitperf
3.1. junitperf特点
-
适配支持 Junit4、Junit5，入门简单
-
能够提供简单的性能报告支持自定义拓展
3.2. junitperf使用方式
3.2.1. 引入方式
<!--junit的基础上，可用于junit4-->
<dependency>
<groupId>com.github.houbb</groupId>
<artifactId>junitperf</artifactId>
<version>1.0.3</version>
</dependency>
<!--junit的基础上，可用于junit5-->
<dependency>
<groupId>com.github.houbb</groupId>
<artifactId>junitperf</artifactId>
<version>2.0.7/version>
<scope>test</scope>
</dependency>
3.2.2. 代码最简单使用
import com.github.houbb.junitperf.core.annotation.JunitPerfConfig;
import com.github.houbb.junitperf.core.rule.JunitPerfRule;
import com.Application;
import lombok.extern.slf4j.Slf4j;
import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringRunner;
/**
* @Autor lietobrain
* @Date 2022/5/17 13:19
* @Desc: JunitPerf使用
*/
@Slf4j
@RunWith(SpringRunner.class)
@SpringBootTest(classes = {Application.class})
@Rule
public JunitPerfRule junitPerfRule = new JunitPerfRule();
/**
* duration：执行时间（不包含准备时间）300000ms，5min
* threads ：100个线程用户
* warmUp：准备时间（单位：毫秒）
*/
@Test
@JunitPerfConfig(duration = 300000, threads = 100, warmUp = 20)
public void testESCount() {
// ... 测试代码：service.xxxx();
}
}
3.2.3. 坑
- @Before这些前置或者后置方法，在JunitPerf下都会反复执行，并不是说100个线程同时跑，而会每次都调用@Before，这块要注意
网友评论