mirror of
https://github.com/cheetahlou/CategoryResourceRepost.git
synced 2025-11-19 07:33:47 +08:00
mod
This commit is contained in:
louzefeng
@@ -0,0 +1,415 @@
|
||||
<audio id="audio" title="16丨案例：性能监控工具之Grafana+Prometheus+Exporters" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/95/79/953457c8660169380e1d736b6c2c3979.mp3"></audio>
|
||||
|
||||
在本模块中，我将把几个常用的监控部分给梳理一下。前面我们提到过，在性能监控图谱中，有操作系统、应用服务器、中间件、队列、缓存、数据库、网络、前端、负载均衡、Web服务器、存储、代码等很多需要监控的点。
|
||||
|
||||
显然这些监控点不能在一个专栏中全部覆盖并一一细化，我只能找最常用的几个，做些逻辑思路的说明，同时也把具体的实现描述出来。如果你遇到了其他的组件，也需要一一实现这些监控。
|
||||
|
||||
在本篇中，主要想说明白下图的这个监控逻辑。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e0/39/e0aa269a7f528f393b859cc8ed69ac39.jpg" alt="">
|
||||
|
||||
这应该是现在最流行的一套监控逻辑了吧。
|
||||
|
||||
我今天把常见的使用Grafana、Prometheus、InfluxDB、Exporters的数据展示方式说一下，如果你刚进入性能测试领域，也能有一个感性的认识。
|
||||
|
||||
有测试工具，有监控工具，才能做后续的性能分析和瓶颈定位，所以有必要把这些工具的逻辑跟你摆一摆。
|
||||
|
||||
所有做性能的人都应该知道一点，不管数据以什么样的形式展示，最要紧的还是看数据的来源和含义，以便做出正确的判断。
|
||||
|
||||
我先说明一下JMeter和node_exporter到Grafana的数据展示逻辑。至于其他的Exporter，我就不再解释这个逻辑了，只说监控分析的部分。
|
||||
|
||||
## JMeter+InfluxDB+Grafana的数据展示逻辑
|
||||
|
||||
一般情况下，我们用JMeter做压力测试时，都是使用JMeter的控制台来查看结果。如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/60/75/60469fd6df4eff032fe0ce161963f675.png" alt="">
|
||||
|
||||
或者装个插件来看结果：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/bd/32/bdcaa07b1ce26ffe504a7fde931b1d32.png" alt="">
|
||||
|
||||
或者用JMeter来生成HTML：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/98/f2/98d050b5df8554a7109e3e532e0781f2.png" alt="">
|
||||
|
||||
这样看都没有问题，我们在前面也强调过，对于压力工具来说，我们最多只关心三条曲线的数据：TPS（T由测试目标定义）、响应时间、错误率。这里的错误率还只是辅助排查问题的曲线，没有问题时，只看TPS和响应时间即可。
|
||||
|
||||
不过采取以上三种方式有几个方面的问题。
|
||||
|
||||
1. 整理结果时比较浪费时间。
|
||||
1. 在GUI用插件看曲线，做高并发时并不现实。
|
||||
1. 在场景运行时间比较长的时候，采用生成HTML的方式，会出现消耗内存过大的情况，而实际上，在生成的结果图中，有很多生成的图我们并不是那么关注。
|
||||
1. 生成的结果保存之后再查看比较麻烦，还要一个个去找。
|
||||
|
||||
那么如何解决这几个问题呢？
|
||||
|
||||
用JMeter的Backend Listener帮我们实时发送数据到InfluxDB或Graphite可以解决这样的问题。Graphite Backend Listener的支持是在JMeter 2.13版本，InfluxdDB Backend Listener的支持是在JMeter 3.3的版本，它们都是用异步的方式把数据发送出来，以便查看。
|
||||
|
||||
其实有这个JMeter发送给InfluxDB的数据之后，我们不需要看上面的那些HTML数据，也可以直观地看到系统性能的性能趋势。并且这样保存下来的数据，在测试结束后想再次查看也比较方便比对。
|
||||
|
||||
JMeter+InfluxDB+Grafana的结构如下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/60/d6/60e7006b3baf95393080b302ccab9fd6.jpg" alt="">
|
||||
|
||||
在这个结构中，JMeter发送压力到服务器的同时，统计下TPS、响应时间、线程数、错误率等信息。默认每30秒在控制台输出一次结果（在jmeter.properties中有一个参数#summariser.interval=30可以控制）。配置了Backend Listener之后，将统计出的结果异步发送到InfluxDB中。最后在Grafana中配置InfluxDB数据源和JMeter显示模板。
|
||||
|
||||
然后就可以实时查看JMeter的测试结果了，这里看到的数据和控制台的数据是一样。
|
||||
|
||||
但如果这么简单就说完了，这篇文章也就没价值了。下面我们来说一下，数据的传输和展示逻辑。
|
||||
|
||||
### JMeter中Backend Listener的配置
|
||||
|
||||
下面我们就InfluxDB的Backend Listener做个说明。它的配置比较简单，在脚本中加上即可。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b1/38/b1da92bbdf07f81f80c17a863a1ae238.png" alt="">
|
||||
|
||||
我们先配置好influxdb Url、application等信息，application这个配置可以看成是场景名。
|
||||
|
||||
那么JMeter如何将数据发给InfluxDB呢？请看源码中的关键代码，如下所示：
|
||||
|
||||
```
|
||||
private void addMetrics(String transaction, SamplerMetric metric) {
|
||||
// FOR ALL STATUS
|
||||
addMetric(transaction, metric.getTotal(), metric.getSentBytes(), metric.getReceivedBytes(), TAG_ALL, metric.getAllMean(), metric.getAllMinTime(),
|
||||
metric.getAllMaxTime(), allPercentiles.values(), metric::getAllPercentile);
|
||||
// FOR OK STATUS
|
||||
addMetric(transaction, metric.getSuccesses(), null, null, TAG_OK, metric.getOkMean(), metric.getOkMinTime(),
|
||||
metric.getOkMaxTime(), okPercentiles.values(), metric::getOkPercentile);
|
||||
// FOR KO STATUS
|
||||
addMetric(transaction, metric.getFailures(), null, null, TAG_KO, metric.getKoMean(), metric.getKoMinTime(),
|
||||
metric.getKoMaxTime(), koPercentiles.values(), metric::getKoPercentile);
|
||||
|
||||
|
||||
metric.getErrors().forEach((error, count) -> addErrorMetric(transaction, error.getResponseCode(),
|
||||
error.getResponseMessage(), count));
|
||||
}
|
||||
|
||||
|
||||
```
|
||||
|
||||
从这段代码可以看出，站在全局统计的视角来看，这里把JMeter运行的统计结果，比如事务的Total请求、发送接收字节、平均值、最大值、最小值等，都加到metric中，同时也会把成功和失败的事务信息添加到metric中去。
|
||||
|
||||
在源码中，还有更多的添加metric的步骤，你有兴趣的话，也可以看一下JMeter源码中的`InfluxdbBackendListenerClient.java`。
|
||||
|
||||
保存了metric之后，再使用InfluxdbMetricsSender发送到Influxdb中去。发送关键代码如下：
|
||||
|
||||
```
|
||||
@Override
|
||||
public void writeAndSendMetrics() {
|
||||
........
|
||||
if (!copyMetrics.isEmpty()) {
|
||||
try {
|
||||
if(httpRequest == null) {
|
||||
httpRequest = createRequest(url);
|
||||
}
|
||||
StringBuilder sb = new StringBuilder(copyMetrics.size()*35);
|
||||
for (MetricTuple metric : copyMetrics) {
|
||||
// Add TimeStamp in nanosecond from epoch ( default in InfluxDB )
|
||||
sb.append(metric.measurement)
|
||||
.append(metric.tag)
|
||||
.append(" ") //$NON-NLS-1$
|
||||
.append(metric.field)
|
||||
.append(" ")
|
||||
.append(metric.timestamp+"000000")
|
||||
.append("\n"); //$NON-NLS-1$
|
||||
}
|
||||
|
||||
|
||||
StringEntity entity = new StringEntity(sb.toString(), StandardCharsets.UTF_8);
|
||||
|
||||
httpRequest.setEntity(entity);
|
||||
lastRequest = httpClient.execute(httpRequest, new FutureCallback<HttpResponse>() {
|
||||
@Override
|
||||
public void completed(final HttpResponse response) {
|
||||
int code = response.getStatusLine().getStatusCode();
|
||||
/*
|
||||
* HTTP response summary 2xx: If your write request received
|
||||
* HTTP 204 No Content, it was a success! 4xx: InfluxDB
|
||||
* could not understand the request. 5xx: The system is
|
||||
* overloaded or significantly impaired.
|
||||
*/
|
||||
if (MetricUtils.isSuccessCode(code)) {
|
||||
if(log.isDebugEnabled()) {
|
||||
log.debug("Success, number of metrics written: {}", copyMetrics.size());
|
||||
}
|
||||
} else {
|
||||
log.error("Error writing metrics to influxDB Url: {}, responseCode: {}, responseBody: {}", url, code, getBody(response));
|
||||
}
|
||||
}
|
||||
@Override
|
||||
public void failed(final Exception ex) {
|
||||
log.error("failed to send data to influxDB server : {}", ex.getMessage());
|
||||
}
|
||||
@Override
|
||||
public void cancelled() {
|
||||
log.warn("Request to influxDB server was cancelled");
|
||||
}
|
||||
});
|
||||
........
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
```
|
||||
|
||||
通过writeAndSendMetrics，就将所有保存的metrics都发给了InfluxDB。
|
||||
|
||||
### InfluxDB中的存储结构
|
||||
|
||||
然后我们再来看下InfluxDB中如何存储：
|
||||
|
||||
```
|
||||
> show databases
|
||||
name: databases
|
||||
name
|
||||
----
|
||||
_internal
|
||||
jmeter
|
||||
> use jmeter
|
||||
Using database jmeter
|
||||
>
|
||||
> show MEASUREMENTS
|
||||
name: measurements
|
||||
name
|
||||
----
|
||||
events
|
||||
jmeter
|
||||
> select * from events where application='7ddemo'
|
||||
name: events
|
||||
time application text title
|
||||
---- ----------- ---- -----
|
||||
1575255462806000000 7ddemo Test Cycle1 started ApacheJMeter
|
||||
1575256463820000000 7ddemo Test Cycle1 ended ApacheJMeter
|
||||
..............
|
||||
n> select * from jmeter where application='7ddemo' limit 10
|
||||
name: jmeter
|
||||
time application avg count countError endedT hit max maxAT meanAT min minAT pct90.0 pct95.0 pct99.0 rb responseCode responseMessage sb startedT statut transaction
|
||||
---- ----------- --- ----- ---------- ------ --- --- ----- ------ --- ----- ------- ------- ------- -- ------------ --------------- -- -------- ------ -----------
|
||||
1575255462821000000 7ddemo 0 0 0 0 0 internal
|
||||
1575255467818000000 7ddemo 232.82352941176472 17 0 17 849 122 384.9999999999996 849 849 0 0 all all
|
||||
1575255467824000000 7ddemo 232.82352941176472 17 849 122 384.9999999999996 849 849 0 0 all 0_openIndexPage
|
||||
1575255467826000000 7ddemo 232.82352941176472 17 849 122 384.9999999999996 849 849 ok 0_openIndexPage
|
||||
1575255467829000000 7ddemo 0 1 1 1 1 internal
|
||||
1575255472811000000 7ddemo 205.4418604651163 26 0 26 849 122 252.6 271.4 849 0 0 all all
|
||||
1575255472812000000 7ddemo 0 1 1 1 1 internal
|
||||
1575255472812000000 7ddemo 205.4418604651163 26 849 122 252.6 271.4 849 ok 0_openIndexPage
|
||||
1575255472812000000 7ddemo 205.4418604651163 26 849 122 252.6 271.4 849 0 0 all 0_openIndexPage
|
||||
1575255477811000000 7ddemo 198.2142857142857 27 0 27 849 117 263.79999999999995 292.3500000000001 849 0 0 all all
|
||||
|
||||
|
||||
```
|
||||
|
||||
这段代码也就是说，在InfluxDB中，创建了两个MEASUREMENTS，分别是events和jmeter。这两个各自存了数据，我们在界面中配置的testtile和eventTags放在了events这个MEASUREMENTS中。在模板中这两个值暂时都是不用的。
|
||||
|
||||
在jmeter这个MEASUREMENTS中，我们可以看到application和事务的统计信息，这些值和控制台一致。
|
||||
|
||||
在Grafana中显示的时候，就是从这个表中取出的数据，根据时序做的曲线。
|
||||
|
||||
### Grafana中的配置
|
||||
|
||||
有了JMeter发送到InfluxDB中的数据，下面就来配置一下Grafana中的展示。首先，要配置一个InfluxDB数据源。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/88/c8/880584ed313336eac49fe7fe6f82a3c8.png" alt="">
|
||||
|
||||
在这里配置好URL、Database、User、Password之后，直接点击保存即可。
|
||||
|
||||
然后添加一个JMeter dashboard，我们常用的dashboard是Grafana官方ID为5496的模板。导入进来后，选择好对应的数据源。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f7/82/f7291868468ec639efda5b24b2555182.png" alt="">
|
||||
|
||||
然后就看到界面了。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/97/f3/97095aac53edf2d164e25de3db3221f3.png" alt="">
|
||||
|
||||
这时还没有数据，我们稍后做个示例，看下JMeter中的数据怎么和这个界面的数据对应起来。
|
||||
|
||||
我们先看下图中两个重要的数据查询语句吧。
|
||||
|
||||
TPS曲线：
|
||||
|
||||
```
|
||||
SELECT last("count") / $send_interval FROM "$measurement_name" WHERE ("transaction" =~ /^$transaction$/ AND "statut" = 'ok') AND $timeFilter GROUP BY time($__interval)
|
||||
|
||||
```
|
||||
|
||||
上面这个就是Total TPS了，在这里称为throughput。关于这个概念，我在第一篇中就已经有了说明，这里再次提醒，概念的使用在团队中要有统一的认识，不要受行业内一些传统信息的误导。
|
||||
|
||||
这里取的数据来自MEASUREMENTS中成功状态的所有事务。
|
||||
|
||||
响应时间曲线：
|
||||
|
||||
```
|
||||
SELECT mean("pct95.0") FROM "$measurement_name" WHERE ("application" =~ /^$application$/) AND $timeFilter GROUP BY "transaction", time($__interval) fill(null)
|
||||
|
||||
```
|
||||
|
||||
这里是用95 pct内的响应时间画出来的曲线。
|
||||
|
||||
整体展示出来的效果如下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ff/3d/ffac987c827b103fef240916f7cb233d.png" alt="">
|
||||
|
||||
### 数据比对
|
||||
|
||||
首先，我们在JMeter中配置一个简单的场景。10个线程，每个线程迭代10次，以及两个HTTP请求。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/55/dc/5546c4449baf0e59d477095a93d717dc.png" alt="">
|
||||
|
||||
也就是说，这时会产生10x10x2=200次请求。我们用JMeter跑起来看一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/92/b9/92d1144a5e8d9ebb7fec246777431bb9.png" alt="">
|
||||
|
||||
看到了吧，这个请求数和我们预想的一样。下面我们看一下Grafana中展示出来的结果。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ff/55/ffb38e433239eeb4712887f7d9723155.png" alt="">
|
||||
|
||||
还有针对每个事务的统计情况。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/3b/47/3b921720759c06ea39673ec5c84a8047.png" alt="">
|
||||
|
||||
至此，JMeter到Grafana的展示过程就完成了。以后我们就不用再保存JMeter的执行结果了，也不用等着JMeter输出HTML了。
|
||||
|
||||
## node_exporter+Prometheus+Grafana的数据展示逻辑
|
||||
|
||||
对性能测试来说，在常用的Grafana+Prometheus+Exporter的逻辑中，第一步要看的就是操作系统资源了。所以在这一篇中，我们将以node_exporter为例来说明一下操作系统抽取数据的逻辑，以便知道监控数据的来源，至于数据的含义，我们将在后续的文章中继续描述。
|
||||
|
||||
首先，我们还是要画一个图。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/39/6b/39a970eea119124245e2318779ec7c6b.jpg" alt="">
|
||||
|
||||
现在node_exporter可以支持很多个操作系统了。官方列表如下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/76/e9/76c6d768b427dd0e3003f9c78a57b3e9.png" alt="">
|
||||
|
||||
当然不是说只支持这些，你也可以扩展自己的Exporter。
|
||||
|
||||
### 配置node_exporter
|
||||
|
||||
node_exporter目录如下：
|
||||
|
||||
```
|
||||
[root@7dgroup2 node_exporter-0.18.1.linux-amd64]# ll
|
||||
total 16524
|
||||
-rw-r--r-- 1 3434 3434 11357 Jun 5 00:50 LICENSE
|
||||
-rwxr-xr-x 1 3434 3434 16878582 Jun 5 00:41 node_exporter
|
||||
-rw-r--r-- 1 3434 3434 463 Jun 5 00:50 NOTICE
|
||||
|
||||
```
|
||||
|
||||
启动：
|
||||
|
||||
```
|
||||
[root@7dgroup2 node_exporter-0.18.1.linux-amd64]#./node_exporter --web.listen-address=:9200 &
|
||||
|
||||
```
|
||||
|
||||
是不是很简洁？如果想看更多的功能 ，可以查看下它的帮助。
|
||||
|
||||
### 配置Prometheus
|
||||
|
||||
先下载Prometheus：
|
||||
|
||||
```
|
||||
[root@7dgroup2 data]# wget -c https://github.com/prometheus/prometheus/releases/download/v2.14.0/prometheus-2.14.0.linux-amd64.tar.gz
|
||||
..........
|
||||
100%[=============================================================================================>] 58,625,125 465KB/s in 6m 4s
|
||||
|
||||
|
||||
2019-11-29 15:40:16 (157 KB/s) - ‘prometheus-2.14.0.linux-amd64.tar.gz’ saved [58625125/58625125]
|
||||
|
||||
|
||||
[root@7dgroup2 data]
|
||||
|
||||
|
||||
```
|
||||
|
||||
解压之后，我们可以看到目录结构如下：
|
||||
|
||||
```
|
||||
[root@7dgroup2 prometheus-2.11.1.linux-amd64]# ll
|
||||
total 120288
|
||||
drwxr-xr-x. 2 3434 3434 4096 Jul 10 23:26 console_libraries
|
||||
drwxr-xr-x. 2 3434 3434 4096 Jul 10 23:26 consoles
|
||||
drwxr-xr-x. 3 root root 4096 Nov 30 12:55 data
|
||||
-rw-r--r--. 1 3434 3434 11357 Jul 10 23:26 LICENSE
|
||||
-rw-r--r--. 1 root root 35 Aug 7 23:19 node.yml
|
||||
-rw-r--r--. 1 3434 3434 2770 Jul 10 23:26 NOTICE
|
||||
-rwxr-xr-x. 1 3434 3434 76328852 Jul 10 21:53 prometheus
|
||||
-rw-r--r-- 1 3434 3434 1864 Sep 21 09:36 prometheus.yml
|
||||
-rwxr-xr-x. 1 3434 3434 46672881 Jul 10 21:54 promtool
|
||||
[root@7dgroup2 prometheus-2.11.1.linux-amd64]#
|
||||
|
||||
```
|
||||
|
||||
在`prometheus.yml`中添加如下配置，以取数据：
|
||||
|
||||
```
|
||||
- job_name: 's1'
|
||||
static_configs:
|
||||
- targets: ['172.17.211.143:9200']
|
||||
|
||||
```
|
||||
|
||||
启动：
|
||||
|
||||
```
|
||||
[root@7dgroup2 data]# ./prometheus --config.file=prometheus.yml &
|
||||
|
||||
|
||||
```
|
||||
|
||||
这样就行了吗？当然不是。根据上面的流程图，我们还需要配置Grafana。
|
||||
|
||||
### 配置Grafana
|
||||
|
||||
首先配置一个数据源，非常简单。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/7f/04/7fdde673c4aabe7d2b0293384237dc04.png" alt="">
|
||||
|
||||
再配置一个node_exporter的模板，比如我这里选择了官方模板（ID：11074），展示如下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/33/00/33c880ff5ba645285f6e6dfbd32aed00.png" alt="">
|
||||
|
||||
### 数据逻辑说明
|
||||
|
||||
说明完上面的过程之后，对我们做性能测试和分析的人来说，最重要的，就是要知道数据的来源和含义了。
|
||||
|
||||
拿上面图中的CPU使用率来说吧（因为CPU使用率是非常重要的一个计数器，所以我们今天先拿它来开刀）。
|
||||
|
||||
我们先点一下title上的edit，看一下它的query语句。
|
||||
|
||||
```
|
||||
avg(irate(node_cpu_seconds_total{instance=~"$node",mode="system"}[30m])) by (instance)
|
||||
avg(irate(node_cpu_seconds_total{instance=~"$node",mode="user"}[30m])) by (instance)
|
||||
avg(irate(node_cpu_seconds_total{instance=~"$node",mode="iowait"}[30m])) by (instance)
|
||||
1 - avg(irate(node_cpu_seconds_total{instance=~"$node",mode="idle"}[30m])) by (instance)
|
||||
|
||||
```
|
||||
|
||||
这些都是从Prometheus中取出来的数据，查询语句读了Prometheus中`node_cpu_seconds_total`的不同的模块数据。
|
||||
|
||||
下面我们来看一下，`node_exporter`暴露出来的计数器。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a6/b0/a6a96e9ead348d8d206c8f10e1890db0.png" alt="">
|
||||
|
||||
这些值和top一样，都来自于`/proc/`目录。下面这张图是top数据，我们可以比对一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/2d/50/2d62f76de8535a92caa3c0e140cba250.png" alt="">
|
||||
|
||||
到此，我们就了解到了操作系统中监控数据的取值逻辑了，也就是从操作系统本身的计数器中取出值来，然后传给Prometheus，再由Grafana中的query语句查出相应的数据，最后由Grafana展示在界面上。
|
||||
|
||||
## 总结
|
||||
|
||||
为什么要解释数据的逻辑呢？
|
||||
|
||||
因为最近在工作中遇到一些情况，有人觉得有了Prometheus+Grafana+Exportor这样的组合工具之后，基本上都不再用手工执行什么命令了。但我们要了解的是，对于监控平台来说，它取的所有的数据必然是被监控者可以提供的数据，像node_exporter这样小巧的监控收集器，它可以获取的监控数据，并不是整个系统全部的性能数据，只是取到了常见的计数器而已。
|
||||
|
||||
这些计数器不管是用命令查看，还是用这样炫酷的工具查看，它的值本身都不会变。所以不管是在监控平台上看到的数据，还是在命令行中看到的数据，我们最重要的是要知道含义以及这些值的变化对性能测试和分析的下一步骤的影响。
|
||||
|
||||
后面我们将着重来解释这些细节。
|
||||
|
||||
## 问题
|
||||
|
||||
最后我个问题吧，你可以自己去验证下。JMeter是如何把数据推送到Grafana中呢？另外，同样是监控操作系统的计数器，监控平台中的数据和监控命令中的数据有什么区别？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
241
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/17丨CentOS：操作系统级监控及常用计数器解析（上）.md
Normal file
241
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/17丨CentOS：操作系统级监控及常用计数器解析（上）.md
Normal file
@@ -0,0 +1,241 @@
|
||||
<audio id="audio" title="17丨CentOS：操作系统级监控及常用计数器解析（上）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/0b/d0/0b37f1284815a0e1b5cedcecfa9a2ed0.mp3"></audio>
|
||||
|
||||
我相信有一些人看到这篇文章的标题肯定有种不想看的感觉，因为这样的内容实在被写得太多太多了。操作系统分析嘛，无非就是CPU使用率、I/O使用率、内存使用率、网络使用率等各种使用率的描述。
|
||||
|
||||
然而因为视角的不同，在性能测试和分析中，这始终是我们绕不过去的分析点。我们得知道什么时候才需要去分析操作系统，以及要分析操作系统的什么内容。
|
||||
|
||||
首先，我们前面在性能分析方法中提到，性能分析要有起点，通常情况下，这个起点就是响应时间、TPS等压力工具给出来的信息。
|
||||
|
||||
我们判断了有瓶颈之后，通过拆分响应时间就可以知道在哪个环节上出了问题，再去详细分析这个操作系统。这就需要用到我们的分析决策树了。
|
||||
|
||||
你还记得我们[在第6篇文章](https://time.geekbang.org/column/article/182912)中提到的分析决策大树吗？今天我们单独把操作系统的这一环节给提出来，并加上前面说的细化过程，就可以得到下面的这个分析决策树。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a1/f7/a130dc74013b8760dfca23a58fef1af7.jpg" alt="">
|
||||
|
||||
在分段分层确定了这个系统所运行的应用有问题之后，还要记起另一件事情，就是前面提到的“全局—定向”的监控思路。
|
||||
|
||||
既然说到了全局，我们得先知道操作系统中，都有哪些大的模块。这里就到了几乎所有性能测试人员看到就想吐的模块了，CPU、I/O、Memory、Network…
|
||||
|
||||
没办法，谁让操作系统就这么点东西呢。我先画一个思维导图给你看一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/15/e8/151cc299bf73d012fb89ad659dbabde8.jpg" alt="">
|
||||
|
||||
我很努力地把一些常见指标的相应关系都画到了图中，你是不是已经看晕了？看晕就对了，别着急。
|
||||
|
||||
我们先要知道的是，面对这些大的模块，到底要用什么的监控手段来实现对它们的监控呢？要知道，在一篇文章中不可能详尽地描述操作系统，我会尽量把我工作中经常使用到的一些和性能分析相关的、使用频度高的知识点整理给你。
|
||||
|
||||
## 监控命令
|
||||
|
||||
我们经常用到的Linux监控命令大概有这些：`top`、`atop`、`vmstat`、`iostat`、`iotop`、`dstat`、`sar`等……请你注意我这里列的监控命令是指可以监控到相应模块的计数器，而不是说只能监控这个模块，因为大部分命令都是综合的工具集。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e5/4a/e5331e0ad62421d9f09e1280734d884a.png" alt="">
|
||||
|
||||
像这样的监控工具还能列上一堆，但这并不是关键，关键的是我们在什么时候能想起来用这些工具，以及知道这些工具的局限性。
|
||||
|
||||
比如说top，它能看CPU、内存、Swap、线程列表等信息，也可以把I/O算进去，因为它有CPU的wa计数器，但是它看不了Disk和Network，这就是明显的局限性。之后出现的`atop`对很多内容做了整理，有了Disk和Net信息，但是呢，在一些Linux发行版中又不是默认安装的。`vmstat`呢？它能看CPU、内存、队列、Disk、System、Swap等信息，但是它又看不了线程列表和网络信息。
|
||||
|
||||
像这样的局限，我还能说上两千字。
|
||||
|
||||
当工具让你眼花缭乱的时候，不要忘记最初的目标，我们要监控的是这几大模块：CPU、I/O、Memory、Network、System、Swap。
|
||||
|
||||
然后，我们再来对应前面提到的“全局—定向”监控的思路。如果你现在仅用命令来监控这个系统，你要执行哪几个呢？
|
||||
|
||||
对应文章前面的思维导图，我们做一个细致的表格。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/77/d6/77f5ccf100207f0d3c8e36f7a63da2d6.jpg" alt="">
|
||||
|
||||
你会发现，`vmstat`可以看Swap，但它能看的是`si`和`so`，看不到其他的计数器，但是`top`可以看到这些计数器……像这样的细节还有很多。
|
||||
|
||||
因为计数器非常多，又不是每个都常用。但是万一某个时候就需要用了呢？这个时候如果你不知道的话，就无法继续分析下去。
|
||||
|
||||
这里我主要想告诉你什么呢？就是用命令的时候，你要知道这个命令能干什么，不能干什么。你可能会说，有这些么多的计数器，还有这么多的命令，光学个OS我得学到啥时候去？
|
||||
|
||||
我要告诉你的是监控的思考逻辑。你要知道的是，正是因为你要监控CPU的某个计数器才执行了这个命令，而不是因为自己知道这个命令才去执行。这个关系我们一定要搞清楚。
|
||||
|
||||
那么逻辑就是这样的：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d3/58/d37b87454b4928190062e7b30abb2258.jpg" alt="">
|
||||
|
||||
比如说，我想看下OS各模块的性能表现，所以执行top这个命令看了一些计数器，同时我又知道，网络的信息在`top`中是看不到的，所以我要把OS大模块看完，还要用`netstat`看网络，以此类推。
|
||||
|
||||
如果你还是觉得这样不能直接刺激到你的神经，懵懂不知道看哪些命令。那么在这里，我用上面的工具给你做一个表格。
|
||||
|
||||
命令模块对照表：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/71/8e/71161027f0729d2d2cbbd9152eb0518e.jpg" alt="">
|
||||
|
||||
我虽然给出了这张表，但要想融会贯通，还需要你亲手画几遍，每个命令都练习很多遍。好，这个时候，我们就已经把全局监控的第一层的计数器基本看完了。
|
||||
|
||||
如果你站起来说：“高老师！你忽悠我，我这还有个想看的，你这里还没有！”
|
||||
|
||||
那你就在上面的表格中加上你想看的计数器和相关的命令就可以了，你的这个表格就会越来越丰富，丰富的过程中，也就慢慢厘清了自己的思路。
|
||||
|
||||
有了这些命令垫底之后，下面我们来看常用的监控平台。
|
||||
|
||||
## 监控平台Grafana+Prometheus+node_exporter
|
||||
|
||||
这是现在用得比较多的监控平台了。在微服务时代，再加上Kubernetes+Docker的盛行，这个监控套装几乎是干IT的都知道。
|
||||
|
||||
我们来看一下常用的Dashboard。为了理解上的通用性，我这里都用默认的信息，不用自己定制的。
|
||||
|
||||
Grafana.com官方ID：8919的模板内容如下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f5/1c/f52641e8564288d5b05788fbfce37d1c.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/4b/b3/4b7affcab03d6efa63220972da2f84b3.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/45/42/45647dbefa9f47896e218d4c4470f642.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a1/c2/a1aa19f218376f566dc8dd82ec25b2c2.png" alt="">
|
||||
|
||||
还记得我们要看系统的模块是哪几个吗？
|
||||
|
||||
- CPU
|
||||
- Memory
|
||||
- I/O
|
||||
- Network
|
||||
- System
|
||||
- Swap
|
||||
|
||||
你可以自己对一下，是不是大模块都没有漏掉？确实没有。但是！上面的计数器你得理解。
|
||||
|
||||
我们先来看一下CPU。
|
||||
|
||||
上图中有了System、User、I/O Wait、Total，还记得我们上面说top里有8个CPU计数器吧，这里就4个怎么办？
|
||||
|
||||
Total这个值的计算方式是这样的：
|
||||
|
||||
```
|
||||
1 - avg(irate(node_cpu_seconds_total{instance=~"$node",mode="idle"}[30m])) by (instance)
|
||||
|
||||
```
|
||||
|
||||
也就是说，它包括除了空闲CPU的其他所有CPU使用率，这其实就有ni、hi、si、st、guest、gnice的值。当我们在这个图中看到System、User、I/O Wait都不高时，如果Total很高，那就是ni、hi、si、st、guest、gnice计数器中的某个值大了。这时你要想找问题，就得自己执行命令查看了。
|
||||
|
||||
看完CPU之后，再看一下Network。
|
||||
|
||||
上图中有网络流量图。可以看到只有“上传下载”，这个值似乎容易理解，但是不够细致。node_exportor还提供了一个“网络连接信息”图。可以看到Sockets_used、CurrEstab、TCP_alloc、TCP_tw、UDP_inuse这些值，它们所代表的含义如下：
|
||||
|
||||
- Sockets_used：已使用的所有协议套接字总量
|
||||
- CurrEstab：当前状态为 ESTABLISHED 或 CLOSE-WAIT 的 TCP 连接数
|
||||
- TCP_alloc：已分配（已建立、已申请到sk_buff）的TCP套接字数量
|
||||
- TCP_tw：等待关闭的TCP连接数
|
||||
- UDP_inuse：正在使用的 UDP 套接字数量
|
||||
|
||||
这些值也可以通过查看“cat /proc/net/sockstat”知道。这是监控工具套装给我们提供的便利，
|
||||
|
||||
然后我们再来看下Memory。
|
||||
|
||||
上图中有总内存、可用内存、已用内存这三个值。如果从应用的角度来看，我们现在对内存的分析，就要和语言相关了。像Java语言，一般会去分析JVM。我们对操作系统的物理内存的使用并不关注，在大部分场景下物理内存并没有成为我们的瓶颈点，但这并不是说在内存上就没有调优的空间了。
|
||||
|
||||
关于内存这一块，我不想展开太多。因为展开之后内容太多了，如果你有兴趣的话，可以找内存管理的资料来看看。
|
||||
|
||||
其他几个模块我就不再一一列了，I/O、System、Swap也都是有监控数据的。
|
||||
|
||||
从全局监控的角度上看，这些计数器也基本够看。但是对于做性能分析、定位瓶颈来说，这些值显然是不够的。
|
||||
|
||||
还记得我在前面提到的“先全局监控再定向监控”找证据链的理念吧。像node_exporter这样的监控套装给我们提供的就是全局监控的数据，就是大面上覆盖了，细节上仍然不够。
|
||||
|
||||
那怎么办呢？下面我就来一一拆解一下。
|
||||
|
||||
## CPU
|
||||
|
||||
关于CPU的计数器，已经有很多的信息了。这里我再啰嗦一下。CPU常见的计数器是top中的8个值，也就是下面这些：
|
||||
|
||||
```
|
||||
%Cpu(s): 0.7 us, 0.5 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.2 si, 0.0 st
|
||||
|
||||
|
||||
```
|
||||
|
||||
含义我就不写了，你搜一下就会知道。
|
||||
|
||||
在mpstat（Multi-Processor Statistics）中看到的是10个计数器：
|
||||
|
||||
```
|
||||
[root@7dgroup3 ~]# mpstat -P ALL 3
|
||||
Linux 3.10.0-957.21.3.el7.x86_64 (7dgroup3) 12/27/2019 _x86_64_ (2 CPU)
|
||||
|
||||
|
||||
03:46:25 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
|
||||
03:46:28 PM all 0.17 0.00 0.17 0.00 0.00 0.00 0.00 0.00 0.00 99.66
|
||||
03:46:28 PM 0 0.33 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 99.67
|
||||
03:46:28 PM 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
|
||||
|
||||
|
||||
```
|
||||
|
||||
这里多出来`%guest`、`%gnice`两个值。他们的含义在Linux man page中有详细的说明。
|
||||
|
||||
>
|
||||
%guest ：Show the percentage of time spent by the CPU or CPUs to run a virtual processor.
|
||||
|
||||
|
||||
>
|
||||
%gnice：Show the percentage of time spent by the CPU or CPUs to run a niced guest.
|
||||
|
||||
|
||||
你可以看到计数器的名字稍有不同，像`top`中的`wa`在`mpstat`中是`%iowait`，`si`是mpstat中的`%soft`。
|
||||
|
||||
在Linux中，这就是我们经常查看的CPU计数器了。在我的性能生涯中，常见的问题大部分都是体现在这么几个计数器上（排名有先后）：
|
||||
|
||||
1. us
|
||||
1. wa
|
||||
1. sy
|
||||
1. si
|
||||
|
||||
首先，为了确定看到CPU高之后，接着往下分析的方向是绝对没有错的，建议你用`Perf top -g`先看一下CPU热点。`perf`默认用的是`cpu-clock`事件。这一步只是为了确定方向对不对。
|
||||
|
||||
那么如何从这几个计数器找到后续的证据链呢？下面就是我们定向监控分析的过程了。**我要狂敲黑板了！！！**
|
||||
|
||||
us CPU是用户态进程消耗的CPU百分比。大家都知道怎么往下落。这个链就是下面这样的：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f7/fe/f77487a2ec038f3be19cdc1581851afe.jpg" alt="">
|
||||
|
||||
当然不是只有这几个命令可以用，你可以找到大把的工具用，我只是列出来常用的。你要是想炫技，可以自己写些脚本来做。这个过程几乎被写烂了，所以，我就不多余举例子了。
|
||||
|
||||
`wa cpu`是I/O读写等待消耗的CPU百分比。这个证据链怎么往下落呢？来看一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d9/4c/d9663c2f1682ebe85626578043e2bf4c.jpg" alt="">
|
||||
|
||||
你看中间有一步跳跃，这就是wa CPU直接跳到线程了。为什么没有进程了呢？那是因为iotop有直接到线程的能力。如果你想先看进程也可以，记得执行iotop -P。
|
||||
|
||||
sy CPU是内核消耗的CPU百分比。这个问题就有点复杂了，因为它并没有一个固定的套路。但是它的分析链路仍然和us CPU高的分析链路差不多，只是这个进程可能不是应用的，而是系统自己的。但是，是什么导致内核进程占用CPU高呢。这可能和应用有关，当然也可能和配置有关。那么现在我们画一个它的分析链路。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0f/6a/0f33a14c4ff683ee7f056c9fbada4d6a.jpg" alt="">
|
||||
|
||||
其实在实际的分析过程中，也是这样的。如果我们看到一个系统的进程消耗了更多的资源，那就要去查一下这个进程是干吗的，看它的运行逻辑和配置文件。不一定所有情况都是配置的问题，但绝大多数情况是这个原因，只能说，在系统级别，我们遇到的内核进程本身有性能问题的情况还是很少的。大部分时候都只是配置问题。
|
||||
|
||||
si CPU是软中断消耗的CPU百分比。什么是软中断呢？在wikipedia.org中有这样的描述：
|
||||
|
||||
>
|
||||
In digital computers, an interrupt is an input signal to the processor indicating an event that needs immediate attention. An interrupt signal alerts the processor and serves as a request for the processor to interrupt the currently executing code, so that the event can be processed in a timely manner. If the request is accepted, the processor responds by suspending its current activities, saving its state, and executing a function called an interrupt handler (or an interrupt service routine, ISR) to deal with the event. This interruption is temporary, and, unless the interrupt indicates a fatal error, the processor resumes normal activities after the interrupt handler finishes.
|
||||
|
||||
|
||||
简单点来说，当出现异常或资源争用时，它是用来管理秩序的。CPU正在吭哧吭哧着干活呢，突然来了一个优先级高的，needs immediate attention，这时就会发一个中断信号给CPU。作为一个干活的，CPU谁的话都得听，这时候就把手头的工作现场保存一下，干这个优先级高的活。除非这个中断是致命的，不然CPU会在干完这个活之后再回去干之前的活，这就是一次软中断。
|
||||
|
||||
这个值，越多就越有问题，关键是它有多少才是有问题呢？这一点你从来没有看过有人给建议值对不对？因为它根本没有可以参考的值，在不同的应用和硬件环境中，si CPU都会有很大差别。我见过软中断每秒几万多就有问题的，也见过软中断每秒20万都没有问题的。
|
||||
|
||||
下面我来照例画个分析的图看一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/20/c9/20470196892d0d199021f4da1021a8c9.jpg" alt="">
|
||||
|
||||
在这个判断的链路中，就是要把si的中断模块找出来，然后再分析这个模块的功能和配置。比如我们看网卡的中断，这是常见的一种性能问题。我们要知道网络是带宽不够？还是配置得不对？还是防火墙？还是啥啥啥别的原因？
|
||||
|
||||
如果是其他的模块也是一样的逻辑。
|
||||
|
||||
好，在知道了上面这几个常见的CPU计数器的分析证据链逻辑之后，我就不再详细画其他的CPU的计数器了。
|
||||
|
||||
ni呢，在我职业生涯中就没见过它高过；hi倒是见过，不过是因为硬件坏了；st呢，只有无良商家不断超卖虚拟服务器才会出现。如果你在一个企业内部搭建的虚拟化基础平台上也经常看见这种情况，那就是公司太穷了，硬件都不够用。
|
||||
|
||||
## 总结
|
||||
|
||||
在操作系统的分析过程中，CPU绝对是一个重点分析的对象，它的一举一动都牵动着性能分析的人，所以我们需要在CPU的高低上花很多的时间去分析判断。
|
||||
|
||||
幸运的是，当CPU使用率高的时候，我们可以有很多的手段来找到对应的根本原因。这个过程不仅分析思路完整，而且工具繁多。它不像网络那么绕，也不像内存那么复杂，逻辑上还是很清楚的。
|
||||
|
||||
## 思考题
|
||||
|
||||
看完了今天的内容，你不妨说一下为什么CPU是很多性能问题分析的方向性指标？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
289
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/18丨CentOS：操作系统级监控及常用计数器解析（下）.md
Normal file
289
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/18丨CentOS：操作系统级监控及常用计数器解析（下）.md
Normal file
@@ -0,0 +1,289 @@
|
||||
<audio id="audio" title="18丨CentOS：操作系统级监控及常用计数器解析（下）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/b0/1d/b00e975efce7535ffb15dde93190eb1d.mp3"></audio>
|
||||
|
||||
在上一篇文章中，我们已经讲了监控系统层面的分析思路以及CPU分析，今天我们分析一下操作系统中其他的层面。
|
||||
|
||||
首先是I/O。
|
||||
|
||||
## I/O
|
||||
|
||||
I/O其实是挺复杂的一个逻辑，但我们今天只说在做性能分析的时候，应该如何定位问题。
|
||||
|
||||
对性能优化比较有经验的人（或者说见过世面比较多的人）都会知道，当一个系统调到非常精致的程度时，基本上会卡在两个环节上，对计算密集型的应用来说，会卡在CPU上；对I/O密集型的应用来说，瓶颈会卡在I/O上。
|
||||
|
||||
我们对I/O的判断逻辑关系是什么呢？
|
||||
|
||||
我们先画一个I/O基本的逻辑过程。我们很多人嘴上说I/O，其实脑子里想的都是Disk I/O，但实际上一个数据要想写到磁盘当中，没那么容易，步骤并不简单。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0b/0c/0b8dd1fa8ddda518e666546205d9170c.jpg" alt="">
|
||||
|
||||
这个简化的图是思虑再三的结果。
|
||||
|
||||
I/O有很多原理细节，那我们如何能快速地做出相应的判断呢？首先要祭出的一个工具就是`iostat`。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b8/31/b8de645585fa5804e26929c88c579031.png" alt="">
|
||||
|
||||
在这张图中，我们取出一条数据来做详细看下：
|
||||
|
||||
```
|
||||
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
|
||||
vda 0.00 0.67 18.33 114.33 540.00 54073.33 823.32
|
||||
avgqu-sz await r_await w_await svctm %util
|
||||
127.01 776.75 1.76 901.01 7.54 100.00
|
||||
|
||||
```
|
||||
|
||||
我解释一下其中几个关键计数器的含义。
|
||||
|
||||
`svctm`代表I/O平均响应时间。请注意，这个计数器，有很多人还把它当个宝一样，实际上在man手册中已经明确说了：“Warning! Do not trust this field any more. This field will be removed in a future sysstat version.” 也就是说，这个数据你爱看就爱，不一定准。
|
||||
|
||||
`w_await`表示写入的平均响应时间；`r_await`表示读取的平均响应时间；`r/s`表示每秒读取次数；`w/s`表示每秒写入次数。
|
||||
|
||||
而IO/s的关键计算是这样的：
|
||||
|
||||
```
|
||||
IO/s = r/s + w/s = 18.33+114.33 = 132.66
|
||||
%util = ( (IO/s * svctm) /1000) * 100% = 100.02564%
|
||||
|
||||
```
|
||||
|
||||
这个`%util`是用`svctm`算来的，既然`svctm`都不一定准了，那这个值也只能参考了。还好我们还有其他工具可以接着往深了去定位，那就是`iotop`。
|
||||
|
||||
```
|
||||
Total DISK READ : 2.27 M/s | Total DISK WRITE : 574.86 M/s
|
||||
Actual DISK READ: 3.86 M/s | Actual DISK WRITE: 34.13 M/s
|
||||
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
|
||||
394 be/3 root 0.00 B/s 441.15 M/s 0.00 % 85.47 % [jbd2/vda1-8]
|
||||
32616 be/4 root 1984.69 K/s 3.40 K/s 0.00 % 42.89 % kube-controllers
|
||||
13787 be/4 root 0.00 B/s 0.00 B/s 0.00 % 35.41 % [kworker/u4:1]
|
||||
...............................
|
||||
|
||||
```
|
||||
|
||||
从上面的`Total DISK WRITE/READ`就可以知道当前的读写到底有多少了，默认是按照`I/O`列来排序的，这里有`Total`，也有`Actual`，并且这两个并不相等，为什么呢？
|
||||
|
||||
因为Total的值显示的是用户态进程与内核态进程之间的速度，而Actual显示的是内核块设备子系统与硬件之间的速度。
|
||||
|
||||
而在`I/O`交互中，由于存在`cache`和在内核中会做`I/O`排序，因此这两个值并不会相同。那如果你要说磁盘的读写能力怎么样，我们应该看的是`Actual`。这个没啥好说的，因为`Total`再大，不能真实写到硬盘上也是没用的。
|
||||
|
||||
在下面的线程列表中，通过排序，就可以知道是哪个线程（注意在第一列是TID哦）占的`I/O`高了。
|
||||
|
||||
## Memory
|
||||
|
||||
关于内存，要说操作系统的内存管理，那大概开一个新专栏也不为过。但是在性能测试的项目中，如果不做底层的测试，基本上在上层语言开发的系统中，比如说Java、Go、C++等，在分析过程中都直接看业务系统就好了。
|
||||
|
||||
在操作系统中，分析业务应用的时候，我们会关注的内存内容如下面的命令所示：
|
||||
|
||||
```
|
||||
[root@7dgroup ~]# free -m
|
||||
total used free shared buff/cache available
|
||||
Mem: 3791 1873 421 174 1495 1512
|
||||
Swap: 0 0 0
|
||||
[root@7dgroup ~]#
|
||||
|
||||
|
||||
```
|
||||
|
||||
`total`肯定是要优先看的，其次是`available`，这个值才是系统真正可用的内存，而不是`free`。
|
||||
|
||||
因为Linux通常都会把用的内存给`cache`，但是不一定会用，所以`free`肯定会越来越少，但是`available`是计算了`buff`和`cache`中不用的内存的，所以只要`available`多，就表示内存够用。
|
||||
|
||||
当出现内存泄露或因其他原因导致物理内存不够用的时候，操作系统就会调用`OOM Killer`，这个进程会强制杀死消耗内存大的应用。这个过程是不商量的，然后你在“`dmesg`”中就会看到如下信息。
|
||||
|
||||
```
|
||||
[12766211.187745] Out of memory: Kill process 32188 (java) score 177 or sacrifice child
|
||||
[12766211.190964] Killed process 32188 (java) total-vm:5861784kB, anon-rss:1416044kB, file-rss:0kB, shmem-rss:0kB
|
||||
|
||||
```
|
||||
|
||||
这种情况只要出现，TPS肯定会掉下来，如果你有负载均衡的话，压力工具中的事务还是可能有成功的。但如果你只有一个应用节点，或者所有应用节点都被`OOM Killer`给干掉了，那TPS就会是这样的结果。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/38/83/38825aee9c3d56819c3e242382bbb483.png" alt="">
|
||||
|
||||
对内存监控，可以看到这样的趋势：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/7b/3a/7b2cf887b969f5684b266ee82869663a.png" alt="">
|
||||
|
||||
内存慢慢被耗光，但是杀掉应用进程之后，`free`内存立即就有了。你看上面这个图，就是一个机器上有两个节点，先被杀了一个，另一个接着泄露，又把内存耗光了，于是又被杀掉，最后内存全都空闲了。
|
||||
|
||||
在我的性能工作生涯中，这样的例子还挺常见。当然对这种情况的分析定位，只看物理内存已经没有意义了，更重要的是看应用的内存是如何被消耗光的。
|
||||
|
||||
对于内存的分析，你还可以用`nmon`和`cat/proc/meminfo`看到更多信息。如果你的应用是需要大页处理的，特别是大数据类的应用，需要关注下`HugePages`相关的计数器。
|
||||
|
||||
内存我们就说到这里，总之，要关注`available`内存的值。
|
||||
|
||||
## NetWork
|
||||
|
||||
这里我们就来到了网络分析的部分了，在说握手之前，我们先看网络的分析决策链。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ed/2c/ed8a7d9ca55cc58d25db9f07bc57b42c.jpg" alt="">
|
||||
|
||||
请看上图中，在判断了瓶颈在网络上之后，如果知道某个进程的网络流量大，首先肯定是要考虑减少流量，当然要在保证业务正常运行，TPS也不降低的情况下。
|
||||
|
||||
### Recv_Q和Send_Q
|
||||
|
||||
当然我们还要干一件事，就是可能你并不知道是在哪个具体的环节上出了问题，那就要学会判断了。网络`I/O`栈也并不简单，看下图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/58/0f/5837c5a68264aaf8b5a870281cf8060f.png" alt="">
|
||||
|
||||
数据发送过程是这样的。
|
||||
|
||||
应用把数据给到`tcp_wmem`就结束它的工作了，由内核接过来之后，经过传输层，再经过队列、环形缓冲区，最后通过网卡发出去。
|
||||
|
||||
数据接收过程则是这样的。
|
||||
|
||||
网卡把数据接过来，经过队列、环形缓冲区，再经过传输层，最后通过`tcp_rmem`给到应用。
|
||||
|
||||
你似乎懂了对不对？那么在这个过程中，我们有什么需要关注的呢？
|
||||
|
||||
首先肯定是看队列，通过`netstat`或其他命令可以看到`Recv_Q`和`Send_Q`，这两项至少可以告诉你瓶颈会在哪一端。如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/6f/13/6f2fbd3c7299a64a8a28ace03bf84613.jpg" alt="">
|
||||
|
||||
我画个表清晰地判断一下瓶颈点。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/be/d1/bef88cefe67796c856f29dc89f4510d1.png" alt="">
|
||||
|
||||
其实这个过程中，我还没有把防火墙加进去，甚至我都没说`NAT`的逻辑，这些基础知识你需要自己先做足功课。
|
||||
|
||||
在我们做性能分析的过程中，基本上，基于上面这个表格就够通过接收和发送判断瓶颈点发生在谁身上了。
|
||||
|
||||
但是，要是这些队列都没有值，是不是网络就算好了呢？还不是。
|
||||
|
||||
### 三次握手和四次挥手
|
||||
|
||||
我们先看握手图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a6/45/a68fb795457f127bb0c24a065bf11945.jpg" alt="">
|
||||
|
||||
我发现一点，很多人以为三次握手是非常容易理解的，但是没几个人能判断出和它相关的问题。
|
||||
|
||||
握手的过程，我就不说了，主要看这里面的两个队列：半连接队列和全连接队列。
|
||||
|
||||
在B只接到第一个`syn`包的时候，把这个连接放到半连接队列中，当接到`ack`的时候才放到全连接队列中。这两个队列如果有问题，都到不了发送接收数据的时候，你就看到报错了。
|
||||
|
||||
查看半连接全连接溢出的手段也很简单，像下面这种情况就是半连接没建立起来，半连接队列满了，`syn`包都被扔掉了。
|
||||
|
||||
```
|
||||
[root@7dgroup ~]# netstat -s |grep -i listen
|
||||
8866 SYNs to LISTEN sockets dropped
|
||||
|
||||
```
|
||||
|
||||
那么半连接队列和什么参数有关呢？
|
||||
|
||||
1. 代码中的`backlog`：你是不是想起来了`ServerSocket(int port, int backlog)中的backlog`？是的，它就是半连接的队列长度，如果它不够了，就会丢掉`syn`包了。
|
||||
1. 还有操作系统的内核参数`net.ipv4.tcp_max_syn_backlog`。
|
||||
|
||||
而像下面这样的情况呢，就是全连接队列已经满了，但是还有连接要进来，已经超过负荷了。
|
||||
|
||||
```
|
||||
[root@7dgroup2 ~]# netstat -s |grep overflow
|
||||
154864 times the listen queue of a socket overflowed
|
||||
|
||||
```
|
||||
|
||||
这是在性能分析过程中经常遇到的连接出各种错的原因之一，它和哪些参数有关呢？我列在这里。
|
||||
|
||||
1. `net.core.somaxconn`：系统中每一个端口最大的监听队列的长度。
|
||||
1. `net.core.netdev_max_backlog`：每个网络接口接收数据包的速率比内核处理这些包的速率快时，允许送到队列的数据包的最大数目。
|
||||
1. `open_file`：文件句柄数。
|
||||
|
||||
我们再来看下四次挥手。我遇到性能测试过程中的挥手问题，有很多都是做性能分析的人在不了解的情况下就去做各种优化动作而产生的。
|
||||
|
||||
先看一下TCP挥手图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/69/88/69a6fc7664ae937d13d241a255989988.jpg" alt="">
|
||||
|
||||
在挥手的逻辑中，和性能相关的问题真的非常少。
|
||||
|
||||
但有一个点是经常会问到的，那就是`TIME_WAIT`。不知道为什么，很多人看到`TIME_WAIT`就紧张，就想去处理掉，于是搜索一圈，哦，要改`recycle/reuse`的TCP参数，要改`fin_time_out`值。
|
||||
|
||||
至于为什么要处理`TIME_WAIT`，却没几个人能回答得上来。
|
||||
|
||||
在我的性能工作经验中，只有一种情况要处理`TIME_WAIT`，那就是**端口不够用**的时候。
|
||||
|
||||
`TCP/IPv4`的标准中，端口最大是65535，还有一些被用了的，所以当我们做压力测试的时候，有些应用由于响应时间非常快，端口就会不够用，这时我们去处理`TIME_WAIT`的端口，让它复用或尽快释放掉，以支持更多的压力。
|
||||
|
||||
所以处理`TIME_WAIT`的端口要先判断清楚，如果是其他原因导致的，即使你处理了`TIME_WAIT`，也没有提升性能的希望。
|
||||
|
||||
如果还有人说，还有一种情况，就是内存不够用。我必须得说，那是我没见过世面了，我至今没见过因为`TIME_WAIT`的连接数把内存耗光了的。
|
||||
|
||||
一个TCP连接大概占3KB，创建10万个连接，才`100000x3KB≈300M`左右，何况最多才65535呢？服务器有那么穷吗？
|
||||
|
||||
## System
|
||||
|
||||
确切地说，在性能测试分析的领域里，System似乎实在是没有什么可写的地方。
|
||||
|
||||
我们最常见的System的计数器是`in(interrupts:中断)`和`cs(context switch：上下文切换)`。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c4/06/c4b16ca370a2ffa1482915cf3ad57206.png" alt="">
|
||||
|
||||
因为这是我能找得到的最疯狂的System计数器了。
|
||||
|
||||
中断的逻辑在前面跟你说过了。
|
||||
|
||||
`cs`也比较容易理解，就是CPU不得不转到另一件事情上，听这一句你就会知道，中断时肯定会有`cs`。但是不止中断会引起cs，还有多任务处理也会导致`cs`。
|
||||
|
||||
因为`cs`是被动的，这个值的高和低都不会是问题的原因，只会是一种表现，所以它只能用来做性能分析中的证据数据。
|
||||
|
||||
在我们的这个图中，显然是由于`in`引起的`cs`，CPU队列那么高也是由`in`导致的。像这样的问题，你可以去看我们在上篇文章中提到的`si CPU`高的那个分析链了。
|
||||
|
||||
## Swap
|
||||
|
||||
Swap的逻辑是什么呢？它是在磁盘上创建的一个空间，当物理内存不够的时候，可以保存物理内存里的数据。如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/18/6b/1805402973701416c23c16003af5c06b.jpg" alt="">
|
||||
|
||||
先看和它相关的几个参数。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e2/7f/e29ec84d980fb9e667e41010b209427f.png" alt="">
|
||||
|
||||
在操作系统中，vm.swappiness是用来定义使用swap的倾向性。官方说明如下：
|
||||
|
||||
>
|
||||
<p>swappiness<br>
|
||||
This control is used to define how aggressive the kernel will swap memory pages. Higher values will increase agressiveness, lower values decrease the amount of swap.<br>
|
||||
A value of 0 instructs the kernel not to initiate swap until the amount of free and file-backed pages is less than the high water mark in a zone.<br>
|
||||
The default value is 60.</p>
|
||||
|
||||
|
||||
1. 值越高，则使用swap的倾向性越大。
|
||||
1. 值越低，则使用swap的倾向性越小。
|
||||
|
||||
但这个倾向性是谁跟谁比呢？简单地说，在内存中有anon内存(匿名而链表，分为：inactive/active)和file内存(映射页链表，也分为：inactive/active)，而swappiness是定义了对anon页链表扫描的倾向性。在Linux源码vmscan.c中有这样的定义：
|
||||
|
||||
```
|
||||
/*
|
||||
* With swappiness at 100, anonymous and file have the same priority.
|
||||
* This scanning priority is essentially the inverse of IO cost.
|
||||
*/
|
||||
anon_prio = swappiness;
|
||||
file_prio = 200 - anon_prio;
|
||||
|
||||
```
|
||||
|
||||
也就是说如果swappiness设置为100时，则anon和file内存会同等的扫描；如果设置为0时，则file内存扫描的优先级会高。但是这并不是说设置为了0就没有swap了，在操作系统中还有其他的逻辑使用swap。
|
||||
|
||||
`swapiness`默认是60%。注意，下面还有一个参数叫`vm.min_free_kbytes`。即使把`vm.swappiness`改为0，当内存用到小于`vm.min_free_kbytes`时照样会发生Swap。
|
||||
|
||||
想关掉Swap就`swapoff -a`。
|
||||
|
||||
和Swap相关的计数器有：`top`中的`Total`、`free`、`used`和`vmstat`里的`si`、`so`。
|
||||
|
||||
说到Swap，在性能测试和分析中，我的建议是直接把它关了。
|
||||
|
||||
为什么呢？因为当物理内存不足的时候，不管怎么交换性能都是会下降的，不管是Swap还是磁盘上的其他空间，都是从磁盘上取数据，性能肯定会刷刷往下掉。
|
||||
|
||||
## 总结
|
||||
|
||||
对操作系统的监控及常用计数器的分析会涉及到很多的内容，所以两篇文章可能也是覆盖不全的，我只把在性能测试分析工作中经常见到的计数器解析了一遍。总体来说，你需要记住以下三点：
|
||||
|
||||
1. 监控平台再花哨，都只是提供数据来给你分析的。只要知道了数据的来源、原理、含义，用什么工具都不重要。
|
||||
1. 性能分析的时候，不会只看操作系统一个模块或哪几个固定计数器的。这些动态的数据，需要有分析链把它们串起来。
|
||||
1. 操作系统提供的监控数据是分析链路中不可缺少的一环，除非你能绕过操作系统，又能很确切地定位出根本原因。
|
||||
|
||||
## 思考题
|
||||
|
||||
我为什么说用什么监控平台并不重要呢？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流进步。
|
||||
@@ -0,0 +1,207 @@
|
||||
<audio id="audio" title="19丨Java & C ++：代码级监控及常用计数器解析（上）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/ca/0e/caf8262ffe95731d5f4fef1f05ca2d0e.mp3"></audio>
|
||||
|
||||
在性能测试分析中，有一部分人存在着一个思路上的误解，那就是一开始就一头扎进代码里，折腾代码性能。这是我非常反对的一种做法。
|
||||
|
||||
事实上，要想这么做，有一个前提，那就是架构中的其他组件都经过了千锤百炼，出现问题的可能性极低。
|
||||
|
||||
实际上，我凭着十几年的经验来看，大部分时候，代码出现严重性能瓶颈的情况还真是不多。再加上现在成熟的框架那么多，程序员们很多情况下只写业务实现。在这种情况下，代码出现性能瓶颈的可能性就更低了。
|
||||
|
||||
但我们今天终归要说代码级的监控及常用的计数器。如何去评估一个业务系统的代码性能呢？在我看来，分析的思路是下面这个样子的。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ee/e3/eebce7bd7cab91685baf4a9a526be9e3.jpg" alt="">
|
||||
|
||||
从上图可以看到，分析的时候有两个关键点：执行时间和执行空间。我相信很多人都清楚，我们要很快找到执行时间耗在哪一段和空间耗在哪里。
|
||||
|
||||
现在我们来实际操作一下，看如何判断。
|
||||
|
||||
## Java类应用查找方法执行时间
|
||||
|
||||
首先你得选择一个合适的监控工具。Java方法类的监控工具有很多，这里我选择JDK里自带的jvisualvm。
|
||||
|
||||
顺便说一下，我的Java版本号是这个：
|
||||
|
||||
```
|
||||
(base) GaoLouMac:~ Zee$ java -version
|
||||
java version "1.8.0_111"
|
||||
Java(TM) SE Runtime Environment (build 1.8.0_111-b14)
|
||||
Java HotSpot(TM) 64-Bit Server VM (build 25.111-b14, mixed mode)
|
||||
|
||||
```
|
||||
|
||||
打开应用服务器上的JMX之后，连上jvisualvm，你会看到这样的视图。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/76/36/76e17407985e427e832c0de988cc8f36.png" alt="">
|
||||
|
||||
这里再啰嗦一下我们的目标，这时我们要找到消耗CPU的方法，所以要先点`Sampler - CPU`，你可以看到如下视图。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d3/63/d3a21195b1b8bcb1838df3d7ec76ef63.png" alt="">
|
||||
|
||||
从上图可以看到方法执行的累积时间，分别为自用时间百分比、自用时间、自用时间中消耗CPU的时间、总时间、总时间中消耗CPU的时间、样本数。
|
||||
|
||||
从这些数据中就可以看到方法的执行效率了。
|
||||
|
||||
但是，这里面Method这么多，我怎么知道哪个跟我的方法执行时间有关呢？比如说上面这个应用中，最消耗CPU的是JDBC的一个方法fill。这合理吗？
|
||||
|
||||
先来看一下我的脚本。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ad/b8/ad1e7b5f712dcbb7e7b35af084f01db8.png" alt="">
|
||||
|
||||
从结构上你就能看出来，我做了登录，然后就做了创建的动作，接着就退出了。
|
||||
|
||||
这几个操作和数据库都有交互。拿create这个步骤来说，它的脚本非常直接，就是一个POST接口。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/7d/dd/7dadcb5071e391a7c97f9ae91e00c9dd.png" alt="">
|
||||
|
||||
还记得前面我们怎么说查看后端的运行逻辑的吗？后端接收这个POST的代码如下：
|
||||
|
||||
```
|
||||
@RequestMapping("/save")
|
||||
@ResponseBody
|
||||
public Object save(Blog blog, HttpSession session){
|
||||
try{
|
||||
Long id = blog.getId();
|
||||
if(id==null){
|
||||
User user = (User)session.getAttribute("user");
|
||||
blog.setAuthor(user.getName());
|
||||
blog.setUserId(user.getId());
|
||||
blog.setCreateTime(new Date());
|
||||
blog.setLastModifyTime(new Date());
|
||||
blogWriteService.create(blog);
|
||||
}else {
|
||||
blog.setLastModifyTime(new Date());
|
||||
blogWriteService.update(blog);
|
||||
}
|
||||
}catch (Exception e){
|
||||
throw new JsonResponseException(e.getMessage());
|
||||
}
|
||||
return true;
|
||||
}
|
||||
|
||||
```
|
||||
|
||||
这段代码的功能就是讲前端内容接收过来放到实体中，然后通过create方法写到数据库中。那么create是怎么实现的呢？
|
||||
|
||||
```
|
||||
public void create(Blog blog) {
|
||||
mapper.insert(blog);
|
||||
BlogStatistics blogStatistics = new BlogStatistics(blog.getId());
|
||||
blogStatisticsMapper.insert(blogStatistics);
|
||||
|
||||
```
|
||||
|
||||
它就是一个mapper.insert，显然这个create是我们自己实现的代码，里面其实没有什么逻辑。而ReadAheadInputStream.fill是create中的MyBatis调用的JDBC中的方法。 从压力工具到数据库的调用逻辑就是：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e2/a6/e23bec9dd1d7712ff541c86479433ba6.jpg" alt="">
|
||||
|
||||
而我们看到的最耗时的方法是最后一个，也就是fill。实际上，我们应该关心的是save接口到底怎么样。我们来过滤下看看。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/53/af/535a53ffb59aa005830e5f30159c2faf.png" alt="">
|
||||
|
||||
从save的结果上来看，它本身并没有耗什么时间，都是后面的调用在消耗时间。
|
||||
|
||||
我们再来看看cerate。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/36/b6/36e52d8b3f346aa6b66ece606aa6e6b6.png" alt="">
|
||||
|
||||
它本身也没消耗什么时间。
|
||||
|
||||
顺着逻辑图，我们再接着看MyBatis中的insert方法。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c7/8a/c780aa816eb132eea8acc0bb06cc0e8a.png" alt="">
|
||||
|
||||
就这样一层层找下去，最后肯定就找到了fill这个方法了。但是你怎么知道整个调用逻辑中有哪些层级呢？你说我可以看源码。当然不是不可以。但要是没有源码呢？做性能分析的人经常没有源码呀。
|
||||
|
||||
这个时候，我们就要来看栈了。这里我打印了一个调用栈，我们来看下这个逻辑。
|
||||
|
||||
```
|
||||
"http-nio-8080-exec-1" - Thread t@42
|
||||
java.lang.Thread.State: RUNNABLE
|
||||
...............
|
||||
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
|
||||
...............
|
||||
...............
|
||||
at com.sun.proxy.$Proxy87.create(Unknown Source)
|
||||
...............
|
||||
at com.blog.controller.BackBlogController.save(BackBlogController.java:85)
|
||||
...............
|
||||
at java.lang.Thread.run(Thread.java:745)
|
||||
|
||||
|
||||
Locked ownable synchronizers:
|
||||
- locked <4b6968c3> (a java.util.concurrent.ThreadPoolExecutor$Worker)
|
||||
|
||||
```
|
||||
|
||||
我把其他的都给清掉了，我们只看最简单的栈逻辑，其中UnknownSource的部分是因为反射实现的insert没有把源码反编译出来。
|
||||
|
||||
其实这个栈有117行，我怕你看晕。
|
||||
|
||||
从这一层一层的关系中，我们就可以知道调用逻辑了。知道调用逻辑的方法有很多，看源码也行，看编译后运行的代码也行，关键在于知道谁调了谁，这样就行了。
|
||||
|
||||
我这个还算是清晰的调用逻辑，要是代码调用关系再复杂一些，分分钟有想死有没有？
|
||||
|
||||
不过比较好的是，像jvisualvm这样的工具给我们提供了很多便利。这时可能有人会跳起来了，为什么不用Arthas、BTrace之类的工具呢？如果你喜欢的话，可以把Athas弄上，像下面这样。
|
||||
|
||||
```
|
||||
[arthas@1]$ trace com.blog.controller.BackBlogController save
|
||||
Press Q or Ctrl+C to abort.
|
||||
Affect(class-cnt:2 , method-cnt:2) cost in 320 ms.
|
||||
`---ts=2020-01-06 10:38:37;thread_name=http-nio-8080-exec-2;id=2b;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
|
||||
`---[29.048684ms] com.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$586fe45c:save()
|
||||
`---[28.914387ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
|
||||
`---[27.897315ms] com.blog.controller.BackBlogController:save()
|
||||
...............
|
||||
`---[24.192784ms] com.blog.service.BlogWriteService:create() #85
|
||||
|
||||
```
|
||||
|
||||
这也能看出来creat是消耗了时间的。如果你接着跟踪create方法。如下所示：
|
||||
|
||||
```
|
||||
[arthas@1]$ trace com.blog.service.BlogWriteService create //这一行是arthas中跟踪class中的某个具体方法的语句。
|
||||
Press Q or Ctrl+C to abort.
|
||||
Affect(class-cnt:2 , method-cnt:2) cost in 199 ms. //被跟踪方法的处理次数和时长
|
||||
`---ts=2020-01-06 10:41:51;thread_name=http-nio-8080-exec-4;id=2f;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
|
||||
`---[6.939189ms] com.sun.proxy.$Proxy87:create()
|
||||
`---ts=2020-01-06 10:41:51;thread_name=http-nio-8080-exec-10;id=38;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
|
||||
`---[4.144799ms] com.blog.service.BlogWriteServiceImpl:create() //写接口中create方法耗时
|
||||
+---[2.131934ms] tk.mybatis.mapper.common.Mapper:insert() #24 //mybatis中insert方法耗时
|
||||
...............
|
||||
`---[1.95441ms] com.blog.mapper.BlogStatisticsMapper:insert() #26 //insert方法调用了上面的create方法耗时
|
||||
|
||||
```
|
||||
|
||||
要是接着往下跟踪，就可以看到反射这一块了。
|
||||
|
||||
```
|
||||
[arthas@1]$ trace tk.mybatis.mapper.common.Mapper insert
|
||||
Press Q or Ctrl+C to abort.
|
||||
Affect(class-cnt:5 , method-cnt:5) cost in 397 ms.
|
||||
`---ts=2020-01-06 10:44:01;thread_name=http-nio-8080-exec-5;id=33;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@4f2895f8
|
||||
`---[3.800107ms] com.sun.proxy.$Proxy80:insert()
|
||||
|
||||
```
|
||||
|
||||
类似的，你还可以玩JDK自带的工具jdb，它也可以直接attach到一个进程上，调试能力也是不弱的。
|
||||
|
||||
在我看来，这些工具、手段都是为了实现从`响应时间长<->代码行`的分析过程。思路是最重要的。
|
||||
|
||||
另外也要说一下，现在有的APM工具也可以实现这样的功能，但是呢，我并不建议一开始就上这么细致的工具，因为不管APM产品吹得有多牛逼，它都是要消耗10%左右的CPU的。并且，你觉得直接在生产上装一个APM工具的agent到业务系统中是合理的吗？如果是自己实现的metrics方法，输出性能数据尚可接受，如果是别人的这类工具，还是算了。
|
||||
|
||||
在大部分时候，我都不建议在生产上用APM工具。万一生产上真的有极端的情况，需要看细致的性能问题，再临时attach上去，也可以做到。何必为了可能出现的问题而长时间地消耗资源呢。
|
||||
|
||||
## 总结
|
||||
|
||||
大部分时间里，性能测试和分析都在和时间打交道，而在时间的拆分逻辑中，我们在前面也提到过思路，如何一步步把时间拆解到应用当中，那就是**分段**。
|
||||
|
||||
当拆解到应用当中之后，就是抓函数方法的执行时间了。这是保证我们从前到后分析逻辑的关键一环，请你注意，是关键一环，而不是最初的一环。
|
||||
|
||||
通过这篇文章我想告诉你，在大部分的开发语言中，都有手段直接将方法的执行时间消耗抓出来，你可能现在还不知道是什么方法，没关系，因为跟踪的手段有很多，你可以临时去学习如何操作。
|
||||
|
||||
我只要在你的脑子里种下这样的一种印象，那就是，有办法抓到函数方法的执行时间消耗在哪里！
|
||||
|
||||
## 思考题
|
||||
|
||||
最后给你留两道思考题吧。我为什么不建议在生产环境中一开始就上APM类工具来抓取方法的执行时间呢？你有什么方法可以抓取到Java语言中的方法执行时间？如果你擅长其他语言，也可以描述其他语言中的方法执行时间抓取工具。
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
@@ -0,0 +1,322 @@
|
||||
<audio id="audio" title="20丨Java & C ++：代码级监控及常用计数器解析（下）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/fb/4b/fb780be17fb483d22f45b32a3f905e4b.mp3"></audio>
|
||||
|
||||
在上一篇文章中，我们描述了在Java开发语言中如何抓取方法的执行时间，其中描述的操作也是我们在分析时经常使用的。
|
||||
|
||||
今天我们将接着描述如下几点内容：
|
||||
|
||||
1. Java语言中如何查找有问题的内存对象。
|
||||
1. 简单介绍一下在C/C++语言中如何查找方法执行时间和对象的内存消耗。
|
||||
|
||||
之所以要描述C/C++语言的相关内容，就是为了告诉你，几乎在任何一语言中都有相应的工具，都有办法捕获到相应的内容。
|
||||
|
||||
下面我们来看看如何抓取Java应用中对象占用多大内存，以及如何分辨占用是合理的和不合理的。
|
||||
|
||||
## Java类应用查找对象内存消耗
|
||||
|
||||
对Java的内存分析通常都落在对JVM的使用上（不要认为我这句话说得片面），再具体一点，说的就是内存泄露和内存溢出。由于现在对象都是可变长的，内存溢出就不常见了；而由于底层框架的慢慢成熟，内存泄露现在也不常见了。
|
||||
|
||||
有人说了，那你还啰嗦个什么劲呢？别捉急呀，不常见不等于没有。只是说它不再是No.1级的问题，但是排在No.2级还是没问题的。
|
||||
|
||||
如果你的应用有了问题，看到了像这样的图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c1/19/c12c874e2048b88e71510ad5fb3af319.png" alt=""><br>
|
||||
这是我在一个项目中遇到的问题，图片不够清晰，我们只要关注黄线的趋势就好。
|
||||
|
||||
之所以把它拿出来说事，是因为这个问题太极端了。上图是近20天的JVM使用率，从曲线的趋势上就可以看出来，它存在明显的内存泄露，但是又泄露得非常非常慢。这个系统要求24x365运行。
|
||||
|
||||
做过运维的人会知道，如此长时间的运行，运维时间长了之后，只会对这样的系统做常规的健康检查，因为前期天天关注它，又不出问题，眼睛都看瞎了，也不值得，于是后期就放松了警惕，慢慢懈怠。
|
||||
|
||||
而这个系统在生产上出现事故是在正常运行快到一年的时候，这个系统的业务量不大，十几个TPS的业务量级。这是一个外贸的系统，业务量虽然不大，但每个业务涉及的金额很大。其实出故障时间倒也不长，才几个小时，但是也干掉了几个总监级职位及相关人员。
|
||||
|
||||
如何对内存进行分析，仍然是性能测试分析的从业人员应该知道的知识点。
|
||||
|
||||
我们从技术的角度来说一下内存问题的排查思路。
|
||||
|
||||
这下我换个实例程序。我们照样用jvisualvm，记住哦，这时候Arthas之类的工具就没得玩了，因为Arthas只会操作栈，有很多在Java方面做性能分析的工具都是只分析栈的。在Java中动态操作对象，其实资源消耗非常高。打个比方，你可以想像一下，在一个课间休息的校园，像寻找一个特定的孩子有多难。
|
||||
|
||||
其实操作一个对象还有迹可循，但是内存中那么多对象，要想全都控制，那几乎是不理智的。所以，我们首先要看内存整体的健康状态。
|
||||
|
||||
### 内存趋势判断
|
||||
|
||||
**场景一：典型的正常内存的场景**
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e3/38/e3b1d3c0eb74914f3f3e04d4483f4d38.png" alt="">
|
||||
|
||||
看了这个图后，要有如下几个反应：
|
||||
|
||||
1. 内存使用很正常，回收健康。
|
||||
1. 内存从目前的压力级别上来看，够用，无需再增加。
|
||||
1. 无内存泄露的情况，因为回收之后基本回到了同一水位上。
|
||||
1. 基本也能看得出来GC够快。为什么说基本呢？因为最好还是看一下这张图。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b8/4b/b8f84cf6e690b84b98ded381e8e0ba4b.png" alt="">
|
||||
|
||||
从这张图可以看到，当应用在压力场景之后，GC并没有消耗过多的CPU。
|
||||
|
||||
**场景二：典型的内存分配过多的场景**
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/2d/d5/2ddbc9cf8f99e5d13c8d2b65b26dbcd5.png" alt="">
|
||||
|
||||
从这张图我们可以看出来：
|
||||
|
||||
1. 内存使用很正常，回收健康。
|
||||
1. 从目前的压力级别上来看，内存不仅够用，而且过多。
|
||||
1. 无内存泄露的情况。
|
||||
|
||||
**场景三：典型的内存不够用的场景**
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/7f/72/7f3c24cf57f51588fdb0657ee8983572.png" alt="">
|
||||
|
||||
从这张图我们可以看出来：
|
||||
|
||||
1. 内存使用很正常，回收健康。
|
||||
1. 从目前的压力级别上来看，**内存不够用，需再增加。**
|
||||
1. CPU可看可不看，因为现在看似乎没多大意义，先加了内存再说。
|
||||
1. 无内存泄露的情况，因为回收之后基本回到了同一水位上。
|
||||
|
||||
**场景四：典型的内存泄露到爆的场景**
|
||||
|
||||
为了显示我能力的多样性，我换个工具的监控结果。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0c/c6/0cd248b5d32fa7c6b2bb34f3c1332dc6.png" alt="">
|
||||
|
||||
看到上面这张图，你可能觉得人生面对着挑战：“啥玩意？”
|
||||
|
||||
实际上，这张图说明以下四点：
|
||||
|
||||
1. 年轻代（第三列）、年老代（第四列）全满了，持久代在不断增加，并且也没有释放过。
|
||||
1. 两个保留区（第一列、第二列）都是空的。
|
||||
1. Yonug GC（第六列）已经不做了。
|
||||
1. Full GC（第八列）一直都在尝试做回收的动作，但是一直也没成功，因为年轻代、年老代都没回收下来，持久代也在不停涨。
|
||||
|
||||
如果出现了1和2的话，不用看什么具体对象内存的消耗，只要像网上那些只玩JVM参数的人一样，调调参数就行了。
|
||||
|
||||
但是如果出现3和4，对于3还要再判断一下，之前的内存是不是设置得太小了？如果是，就调大，看能不能到场景一的状态。如果不是，那就得像场景四一样，查一下内存到底消耗在哪个对象上了。
|
||||
|
||||
### 查找增加的内存
|
||||
|
||||
**逻辑一**
|
||||
|
||||
下面我们来说说如何判断性能测试过程中内存的变化。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/50/8e/502a6ed2d254820ce92ab6bd22b2928e.png" alt="">
|
||||
|
||||
我们在内存中经常看到的对象是这样的。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ed/9e/ed0fbdbfa94a97380a86c7730b2db49e.png" alt="">
|
||||
|
||||
如果你用jmap的话，会看到如下信息。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/fe/2b/fec55fa1419b3e87be9e1d9adf06982b.png" alt="">
|
||||
|
||||
你可能会问，这么多的内容，我到底要看什么呢？这也是性能测试人员经常遇到的问题，明明数据都在眼前，就是不知道从哪下嘴。
|
||||
|
||||
我建议你不要看这些底层的对象类型，因为实在是有点多哇。在这里我们最好是看自己代码调用的对象的内存占用大小增量。
|
||||
|
||||
1. 先过滤下我们自己的包。
|
||||
1. 点击一下Deltas，就能看到下面的截图。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b1/70/b1373d88b3799c573d618545141dca70.png" alt="">
|
||||
|
||||
在刚开始点击Deltas之后，会看到全是零的对象。
|
||||
|
||||
下面我们来做下压力，观察一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ee/40/eebbb6e45916a8f3f4fb4f5c43538c40.png" alt="">
|
||||
|
||||
你看现在对象的实体都在往上增加对吧？但是当压力停止之后，该回收的都回收了，而有些必须长久使用的对象，在架构设计上也应该清晰地判断增量，不然就有可能导致内存不够。出现这种情况一般是架构师的失职。像这类东西应该写到公司的代码规范里。
|
||||
|
||||
当内存正常回收之后，再观察Deltas，应该会看到大部分对象都回收了的状态。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/74/cc/7438e6e9df188a85edc5906a22852fcc.png" alt="">
|
||||
|
||||
临时的对象也都清理了。 这就是正常的结果。
|
||||
|
||||
如果停止压力之后，又做了正常的FullGC回收了之后，还是像下面这样。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/73/6e/73e145ffcad24c4b72bb5c33b92e8b6e.png" alt="">
|
||||
|
||||
那就显然有问题了。回收不了的对象就是典型的内存泄露了。
|
||||
|
||||
**逻辑二**
|
||||
|
||||
我们看下面这个图。这是jmap做出来的heapdump，然后用MAT打开的。
|
||||
|
||||
1.第一个可疑的内存泄露点占了466.4MB的内存。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ac/21/ac38b7a41afa0b4eef5ea8282494a421.png" alt="">
|
||||
|
||||
2.找到内存消耗点的多的内容。如下所示。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c7/ec/c77ccf1e96b1794987354fac146cc6ec.png" alt="">
|
||||
|
||||
这是一个实体bean。每个倒是不大，但是架不住有79万个。
|
||||
|
||||
3.看它对应的栈。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0e/1f/0e7914173204f8609c45c24944655f1f.png" alt="">
|
||||
|
||||
就是一个数据库操作。
|
||||
|
||||
4.取出SQL，查看执行计划如下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/fd/8d/fd1c9859d61fb9bc531b3a10449b318d.png" alt="">
|
||||
|
||||
这是曲线的SQL查询数据过多，导致内存不够用。这个不叫泄露，这是溢出。因为要是一个人查询，就可能没事嘛，但是多个人一起查了，才会出问题。从业务的代码实现的角度上说，这绝对是个有问题的设计逻辑。如果真是必须全表扫描的，你得规定这个功能怎么用呀。如果不用全表扫描，干嘛不做过滤呢？
|
||||
|
||||
其实在Java中查找内存消耗的手段还有很多。你喜欢怎么玩就怎么玩，只要找得到就好。我只是给两种我觉得常用又易用的方式。
|
||||
|
||||
## C/C++类应用查找方法执行时间
|
||||
|
||||
对C/C++的应用来说，我们可以用google-perftools查找方法执行时间。当然，在这之时，你需要先安装配置好google-perftools和libunwind。
|
||||
|
||||
google-perftools是针对C/C++程序的性能分析工具。使用它，可以对CPU时间片、内存等系统资源的分配和使用进行分析。
|
||||
|
||||
使用步骤如下：
|
||||
|
||||
1. 编译目标程序，加入对 google-perftools 库的依赖。
|
||||
1. 运行目标程序，在代码中加入启动/终止剖析的开关。
|
||||
1. 将生成的结果通过剖析工具生成相应的调用图。
|
||||
|
||||
你可以在代码中加入固定输出剖析数据的开关，当运行到某段代码时就会执行。当然你也可以在代码中只加入接收信号的功能，然后在运行的过程中，通过kill命令给正在运行的程序发送指令，从而控制开关。
|
||||
|
||||
我来举个例子。如果我们有一个函数f，我想知道它的执行效率。硬编码的方式就是在调用这个函数的前后加上剖析开关。
|
||||
|
||||
```
|
||||
ProfilerStart("test.prof");//开启性能分析
|
||||
f();
|
||||
ProfilerStop();//停止性能分析
|
||||
|
||||
|
||||
```
|
||||
|
||||
在程序编译之后，会在同目录生成一个叫a.out的可执行文件。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/54/c4/54f34188238d4dad62f9fd1ed5fdf5c4.png" alt="">
|
||||
|
||||
执行这个文件，就会生成test.prof文件。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/42/7d/42fa660a548ffdaf7a9f84e92a2bef7d.png" alt="">
|
||||
|
||||
然后执行命令：
|
||||
|
||||
```
|
||||
pprof --pdf a.out test.prof >test.pdf
|
||||
|
||||
```
|
||||
|
||||
打开这个PDF就可以看到如下图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f6/58/f69e0653da960428fb4f308578508758.png" alt="">
|
||||
|
||||
你看到上面有很多只有地址而没有函数名的调用吗？那是没有符号表。这里我们不分析那些不是我们自己的函数，我们只看自己的函数f。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d3/11/d3728112e6b6eb636aea729c0a5b9211.png" alt="">
|
||||
|
||||
看这一段，它有三行。
|
||||
|
||||
- 第一行：函数名；
|
||||
- 第二行：不包含内部函数调用的样本数 (百分比) ；
|
||||
- 第三行：of 包含内部函数调用的样本数 (百分比)。
|
||||
|
||||
是不是和Java中self time/total time有异曲同工之妙？它也可以实现从CPU使用率高到具体函数的定位。
|
||||
|
||||
你也许会说，这个有点复杂，还要在代码里加这么多，编译还要加上动态库啥的。当然了，你还可以用perf工具来跟踪CPU clock，在代码编译时加上调试参数，就可以直接用perf top -g看调用过程由每个函数所消耗的CPU时钟。你还可以用systemtap来自己写代码进行动态跟踪。
|
||||
|
||||
## C/C++类应用查找对象内存消耗
|
||||
|
||||
其实googler perftools也可以分析内存，但是我觉得它没有Valgrind好使。所以在这一部分，我用valgrind来告诉你如何查找到C/C++的内存消耗。
|
||||
|
||||
valgrind能实现这些功能：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/60/f8/6098d8b66b331a1791cc8daaeaa186f8.png" alt="">
|
||||
|
||||
这里举一个内存泄露的小例子。这是一段再无聊不过的代码：
|
||||
|
||||
```
|
||||
#include <stdlib.h>
|
||||
|
||||
|
||||
void f(void)
|
||||
{
|
||||
int* x = malloc(10 * sizeof(int));
|
||||
x[10] = 0; // problem 1: heap block overrun
|
||||
} // problem 2: memory leak -- x not freed
|
||||
|
||||
|
||||
int main(void)
|
||||
{
|
||||
f();
|
||||
return 0;
|
||||
|
||||
```
|
||||
|
||||
我们不断分配，而不释放。
|
||||
|
||||
编译运行之后，我们可以看到如下结果。
|
||||
|
||||
```
|
||||
[root@7dgroup Sample10]# gcc -Wall -o test5 test5.c
|
||||
[root@7dgroup Sample10]# valgrind --tool=memcheck --leak-check=full ./test5
|
||||
==318== Memcheck, a memory error detector
|
||||
==318== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.
|
||||
==318== Using Valgrind-3.10.0 and LibVEX; rerun with -h for copyright info
|
||||
==318== Command: ./test5
|
||||
==318==
|
||||
==318== Invalid write of size 4
|
||||
==318== at 0x40054E: f (in /root/GDB/Sample10/test5)
|
||||
==318== by 0x40055E: main (in /root/GDB/Sample10/test5)
|
||||
==318== Address 0x51f7068 is 0 bytes after a block of size 40 alloc'd
|
||||
==318== at 0x4C29BFD: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
|
||||
==318== by 0x400541: f (in /root/GDB/Sample10/test5)
|
||||
==318== by 0x40055E: main (in /root/GDB/Sample10/test5)
|
||||
==318==
|
||||
==318==
|
||||
==318== HEAP SUMMARY:
|
||||
==318== in use at exit: 40 bytes in 1 blocks
|
||||
==318== total heap usage: 1 allocs, 0 frees, 40 bytes allocated
|
||||
==318==
|
||||
==318== 40 bytes in 1 blocks are definitely lost in loss record 1 of 1
|
||||
==318== at 0x4C29BFD: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
|
||||
==318== by 0x400541: f (in /root/GDB/Sample10/test5)
|
||||
==318== by 0x40055E: main (in /root/GDB/Sample10/test5)
|
||||
==318==
|
||||
==318== LEAK SUMMARY:
|
||||
==318== definitely lost: 40 bytes in 1 blocks
|
||||
==318== indirectly lost: 0 bytes in 0 blocks
|
||||
==318== possibly lost: 0 bytes in 0 blocks
|
||||
==318== still reachable: 0 bytes in 0 blocks
|
||||
==318== suppressed: 0 bytes in 0 blocks
|
||||
==318==
|
||||
==318== For counts of detected and suppressed errors, rerun with: -v
|
||||
==318== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 1 from 1)
|
||||
[root@7dgroup Sample10]#
|
||||
|
||||
```
|
||||
|
||||
主要看一下这行。
|
||||
|
||||
```
|
||||
==318== total heap usage: 1 allocs, 0 frees, 40 bytes allocated
|
||||
|
||||
|
||||
```
|
||||
|
||||
这里分配了40个字节的一块内存，但是0释放，所以就泄露了。
|
||||
|
||||
请你注意，在调试自己的程序时，要像Java一样，分析内存的泄露，在压力前和压力后做内存的比对。在压力中则不用做。
|
||||
|
||||
## 总结
|
||||
|
||||
不管是什么语言的应用，在性能分析的过程中，都是分析两个方法。
|
||||
|
||||
1. 执行速度够不够快。只有够快才能满足更高的TPS。
|
||||
1. 执行过程中内存用得多不多。内存用得少，才可以同时支持更多的请求。
|
||||
|
||||
我觉得对性能测试过程中的分析来说，这两点足够你解决代码上的问题了。有人说，为什么不说I/O的事情呢。其实I/O仍然是读写量的多少，也会反应用内存中。至于磁盘本身性能跟不上，那是另一个话题。
|
||||
|
||||
## 思考题
|
||||
|
||||
最后给你留两个思考题吧。对代码的性能分析过程中，主要是哪两点呢？针对代码分析的这两点，有什么样的分析链路？
|
||||
|
||||
欢迎你在评论区写下自己的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
729
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/21丨Tomcat：中间件监控及常用计数器解析.md
Normal file
729
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/21丨Tomcat：中间件监控及常用计数器解析.md
Normal file
@@ -0,0 +1,729 @@
|
||||
<audio id="audio" title="21丨Tomcat：中间件监控及常用计数器解析" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/fc/2b/fcf2545ce0e0cdb37bf9df6b7fb2852b.mp3"></audio>
|
||||
|
||||
在当今Spring Cloud微服务架构盛行的时代，Tomcat仍然作为应用最广的应用服务器而存在着，所以我们不得不说一说对它的性能分析。
|
||||
|
||||
很多时候，我们做性能测试分析时，都会把Tomcat这类的应用弄混淆。对它的监控和分析，总是会和JDK、框架代码、业务代码混合来看，这就导致了分析上的混乱。我们应该把这些分析内容分隔开来，哪些是tomcat，哪些是JDK等。
|
||||
|
||||
在我看来，Tomcat、WebLogic、WebSphere、JBoss等，它们都具有同样的分析思路。因为Tomcat的市场范围更大，所以，今天，我们以它为例来说明这类应用应该如何分析。
|
||||
|
||||
首先我们得知道它的架构是什么样的。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/bb/10/bb22a5bea7abe133a8db73e2fe311f10.jpg" alt="">
|
||||
|
||||
这是一个在网上随处可见的架构图，它能告诉我们Tomcat内部如何运作。如果你有兴趣，还可以看一下官方对它的架构描述。
|
||||
|
||||
然而，我们做性能分析的人真的要完全掌握这些细节吗？当然不是。从经验上来说，基本上有几大方面，是Tomcat优化时需要关注的。
|
||||
|
||||
如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c1/90/c1c6e4a479c53a3365cbffe476ab6090.png" alt="">
|
||||
|
||||
最上面，我放了两个框，分别是操作系统和JDK。因为要调优Tomcat，和这两者非常相关，但是操作系统和JDK又各自有独立的分析逻辑，而在本篇中，我专门讲Tomcat类型的组件，所以上面两块的内容我将尽量不涉及，以免混乱。
|
||||
|
||||
在Tomcat的性能分析中，我将我认为重要的几个技术点列在了思维导图中，同时也对它们做了重要程度的标识。在我分析经验中，这些内容已经包括了大部分的优化场景。
|
||||
|
||||
## 运行模式之争
|
||||
|
||||
有很多人对运行模式非常敏感，大家也看到经常有文章说：“对于性能来说，显然是BIO<NIO<APR的。”然而也有人做过测试说，其实不见得BIO性能就最差，这取决于应用场景；也有人说在压力低的情况下，显然BIO的性能更高。
|
||||
|
||||
从我的经验上来说，真的没必要纠结这一点。本着对Tomcat官方的信任，我觉得最好就是用官方给的默认运行模式，它肯定是经过了更严格的测试才被选择的。这就跟相信世上好人多是一样的道理。
|
||||
|
||||
现在新的Tomcat版本中默认的是NIO了，你可以在启动日志中看到相应的信息，如下所示：
|
||||
|
||||
```
|
||||
21-Jan-2020 16:50:57.989 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-jsse-nio-443"]
|
||||
|
||||
```
|
||||
|
||||
简单地说BIO和NIO的区别如下面两张图所示。
|
||||
|
||||
BIO图示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/60/74/60199e42afcd7283eb19616506aa5874.jpg" alt="">
|
||||
|
||||
NIO图示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/28/44/286d1ba0019496abcb5f545d40b3c844.jpg" alt=""><br>
|
||||
要理解这个区别，首先得知道几个知识点：
|
||||
|
||||
1. Acceptor是TCP层面的东西，它负责完成TCP握手的过程，放入全连接队列，然后将数据生成request，调用servlet容器处理。
|
||||
1. 而Worker干的就是接到request数据，处理后给出response。
|
||||
1. Poller是一个队列，属于典型的生产者-消费者模式。
|
||||
|
||||
知道了这些，你就会明白其实对于Acceptor和Worker本身来说，仍然是阻塞的。而这个Poller只能是在大并发的时候，可以hold住更多的请求而已，看起来Tomcat处理请求的容量增加了，但是我们还是要在具体的应用中去测试，来比对响应时间的差异。
|
||||
|
||||
但是还有一点区别我们得知道，Tomcat的keepAliveTimeout参数默认使用的是connectionTimeout的值。这样一来，由于使用BIO时，Acceptor读取socket中的数据并传递给Worker这个过程是阻塞的，意味着当代码执行到Worker中时，这个socket仍然被占着；而使用NIO时，Acceptor读取socket数据后交给了Poller了，Worker从Poller中得到请求内容并处理，这个过程就分开了，这样Worker在处理时就不会阻塞socket，所以Tomcat可以处理更多的socket，这才是NIO性能提升的关键点。
|
||||
|
||||
而APR是个啥呢？它是利用了OS中的能力来进行高并发地文件读取或者网络传输，来提高对静态文件的处理。有很多网上的实验结果都可以证明，在具体的应用中它并没有比NIO的性能高到哪里去，并且配置起来还麻烦，所以这个模式现在并没有很广泛的使用。
|
||||
|
||||
所以在Tomcat中，运行模式之争应该说已经不存在了。
|
||||
|
||||
## 请求量、请求时间、响应时间
|
||||
|
||||
这是我希望你能在分析Tomcat时关注的内容。我们有很多种方式可以看这些信息，最简单的就是访问日志了。通过在conf/server.xml中做如下配置：
|
||||
|
||||
```
|
||||
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
|
||||
prefix="localhost_access_log" suffix=".txt"
|
||||
pattern="%h %l %u %t &quot;%r&quot; %s %b %D %F" />
|
||||
|
||||
```
|
||||
|
||||
其中%D就是请求时间，%F是响应时间。配置了之后，在日志中就会看到如下内容：
|
||||
|
||||
```
|
||||
172.17.211.144 - - [21/Jan/2020:18:06:57 +0800] "POST /back/save HTTP/1.1" 200 14 29 29
|
||||
172.17.211.144 - - [21/Jan/2020:18:06:57 +0800] "GET /validate/code/pic HTTP/1.1" 200 541 5 0
|
||||
|
||||
```
|
||||
|
||||
最后两列就是请求时间和响应时间。通过这两个时间的比对，你就可以知道，Tomcat本身消耗了多少时间以及Tomcat之后的操作又消耗了多少时间。
|
||||
|
||||
当然，如果你喜欢的话，也可以看这样的监控图表。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/18/9b/18ceb1d636507f8a11f039f54054c59b.png" alt="">
|
||||
|
||||
这是一个小工具Probe的监控数据，从这里，你可以知道Tomcat这段时间处理了多少请求，以及处理这些请求的时间、最大时间、最小时间和平均时间。
|
||||
|
||||
但是！我不建议用这个工具来监控Tomcat，因为它性能差。你可能会问，那你还说它干吗？因为其他的性能监控工具中，很少有见到这个角度的图表展示，在这里只是为了告诉你，分析Tomcat全局性能状态时，可以通过总请求数，以及平均响应时间来看Tomcat的全局处理能力如何。
|
||||
|
||||
当然这些数据你同样可以通过分析访问日志获取。
|
||||
|
||||
显然有了这些数据，我们就可以做一个大体的判断了。在服务节点多的时候，只要看这里的平均响应时间，你就能知道在这个Tomcat上有没有消耗掉你在压力工具中看到的响应时间。
|
||||
|
||||
下面我通过测试结果来说明几个Tomcat中常用的优化动作。
|
||||
|
||||
在展示优化动作之前，先看一下connector基本配置：
|
||||
|
||||
```
|
||||
<Connector
|
||||
SSLEnabled="true"
|
||||
acceptCount="100"
|
||||
clientAuth="false"
|
||||
disableUploadTimeout="true"
|
||||
enableLookups="false"
|
||||
maxThreads="25"
|
||||
port="443"
|
||||
connectionTimeout="20000"
|
||||
keystoreFile="/PathToTomcat/bin/server.keystore"
|
||||
keystorePass="12345678"
|
||||
protocol="org.apache.coyote.http11.Http11NioProtocol"
|
||||
scheme="https"
|
||||
secure="true"
|
||||
sslProtocol="TLS" />
|
||||
|
||||
```
|
||||
|
||||
这只是一个基本配置。至于是不是最优的配置，我们需要在针对一个应用测试的过程中慢慢来看。
|
||||
|
||||
比如有人会说，你这里为什么不配置minSpareThreads和maxSpareThreads之类的参数？首先，我们要知道，为什么要配置这两个参数？对于一个线程数超高的应用来说，长期维护大量的线程肯定会导致操作系统中context switch的增加，在一个应用的波峰波谷差别较大的时候，我们用这两个参数其实是为了减少在波谷时产生的维护成本。但是同时你也要知道，在线程不够用的时候，开新的线程也同样需要成本，所以这两个值需不需要配置，完全取决于应用场景的具体测试结果。
|
||||
|
||||
总之，所有的配置都需要在具体的应用场景测试了之后，再下定论，别凭感觉。
|
||||
|
||||
## 协议 HTTP、HTTPS
|
||||
|
||||
我们知道在HTTPS的协议中，因为加入了SSL证书会导致性能下降，但是对有些应用来说，又不得不用SSL证书。在这里我自己配置了一个证书，来给你看看证书对性能产生的影响。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a7/9a/a7c39bf9d167036fe1373f2d729f7b9a.png" alt="">
|
||||
|
||||
我的证书配置是这样的：
|
||||
|
||||
- 根证书：RSA证书、sha256，8192位
|
||||
- 中级证书：RSA，sha256、4096位
|
||||
- 终端证书：RSA，sha256、4096位
|
||||
|
||||
一般情况下，SSL证书都是分为三层的。在这个例子中，我生成的时候还特意用了高位数，位数越高，对性能影响越大，因为计算成本增加了。现在我们在市场上买的证书，根据价值的不同，加密方式和位数都会不一样，请稍微注意一下。
|
||||
|
||||
下面来看看测试结果。
|
||||
|
||||
Tomcat with SSL：
|
||||
|
||||
```
|
||||
summary + 588 in 00:00:13 = 46.0/s Avg: 10 Min: 1 Max: 804 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 4403 in 00:00:30 = 146.8/s Avg: 4 Min: 0 Max: 87 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 4991 in 00:00:43 = 116.7/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 7107 in 00:00:30 = 237.1/s Avg: 4 Min: 0 Max: 77 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 12098 in 00:01:13 = 166.3/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 11121 in 00:00:30 = 370.7/s Avg: 4 Min: 0 Max: 72 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 23219 in 00:01:43 = 226.0/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 12709 in 00:00:30 = 423.6/s Avg: 4 Min: 0 Max: 87 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 35928 in 00:02:13 = 270.6/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 14548 in 00:00:30 = 485.0/s Avg: 4 Min: 0 Max: 69 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 50476 in 00:02:43 = 310.1/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 15810 in 00:00:30 = 527.0/s Avg: 5 Min: 0 Max: 83 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 66286 in 00:03:13 = 343.9/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 15242 in 00:00:30 = 508.0/s Avg: 5 Min: 0 Max: 77 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 81528 in 00:03:43 = 366.0/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 16709 in 00:00:30 = 557.1/s Avg: 5 Min: 0 Max: 75 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 98237 in 00:04:13 = 388.7/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 17099 in 00:00:30 = 570.0/s Avg: 6 Min: 0 Max: 161 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 115336 in 00:04:43 = 407.9/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
Tomcat without SSL：
|
||||
|
||||
```
|
||||
summary + 12 in 00:00:03 = 4.2/s Avg: 148 Min: 4 Max: 937 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 3531 in 00:00:30 = 117.8/s Avg: 4 Min: 0 Max: 63 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 3543 in 00:00:33 = 107.8/s Avg: 4 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 7283 in 00:00:30 = 242.8/s Avg: 4 Min: 0 Max: 90 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 10826 in 00:01:03 = 172.2/s Avg: 4 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 9554 in 00:00:30 = 318.5/s Avg: 3 Min: 0 Max: 35 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 20380 in 00:01:33 = 219.5/s Avg: 4 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 14747 in 00:00:30 = 491.6/s Avg: 3 Min: 0 Max: 49 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 35127 in 00:02:03 = 285.9/s Avg: 3 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 16844 in 00:00:30 = 561.4/s Avg: 3 Min: 0 Max: 47 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 51971 in 00:02:33 = 340.0/s Avg: 3 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 17547 in 00:00:30 = 585.0/s Avg: 3 Min: 0 Max: 47 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 69518 in 00:03:03 = 380.2/s Avg: 3 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 18798 in 00:00:30 = 626.6/s Avg: 4 Min: 0 Max: 213 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 88316 in 00:03:33 = 414.9/s Avg: 3 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 18529 in 00:00:30 = 617.6/s Avg: 4 Min: 0 Max: 204 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 106845 in 00:04:03 = 439.9/s Avg: 3 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
summary + 18837 in 00:00:30 = 627.9/s Avg: 4 Min: 0 Max: 53 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 125682 in 00:04:33 = 460.6/s Avg: 4 Min: 0 Max: 937 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
这里稍微啰嗦一下，我们以这种终端直接输出的数据看JMeter的结果时，主要关注下"summary +"的数据，因为"summary ="的数据是整个场景执行的平均数据。另外，第一行的数据会不准确，可以忽略，如果你把粒度调低一些，可以看到更细的数据。
|
||||
|
||||
通过上面的数据可以看到，没有SSL比有SSL证书是要高出一些TPS的。如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a0/4e/a0c999ecb1f005daa4da51880753c34e.jpg" alt="">
|
||||
|
||||
显然SSL证书对性能有明显的影响了，最大的影响到18.93%，是在8个线程时，而在五六个线程时，TPS损耗有13%左右。
|
||||
|
||||
这和加密位数、应用场景等都有关系，所以这一段可以给你的结论就是：SSL证书对性能会有损耗。但具体损耗是多少，在你的应用场景中需要具体测试。
|
||||
|
||||
### 线程池
|
||||
|
||||
Tomcat的线程池，一直是调优Tomcat的重点对象。在我的工作经验中，我发现经常有人不太清楚对Tomcat应该配置多大的线程池。
|
||||
|
||||
之前，我见过有一个人在一个4C8G的机器上把一个Tomcat节点的线程池配置到了4000。我问他为什么要这么配置，他说想支持4000的并发用户。
|
||||
|
||||
我们先不说他有没有理解在线用户、并发用户和TPS之间的逻辑关系，只说把Tomcat配置为4000这个事情。就算Tomcat能支撑得住4000，但机器能撑得住吗？结果还没跑多少压力线程，操作系统的CS就不断走高，消耗了大量的sy CPU，只有少量的us CPU能处理正常的业务。
|
||||
|
||||
然后我告诉他把Tomcat线程数调到默认的200先看看，结果TPS上升了好几倍。
|
||||
|
||||
这就是对线程在系统中运行的逻辑不理解导致的情况。
|
||||
|
||||
我们在测试的时候，先得学会判断：线程数到底够不够用。要是不够用，但又有足够的硬件资源，那你可以增加线程。
|
||||
|
||||
但是在增加线程之前，先要判断，代码是不是运行得足够快，如果代码本身就慢，那就先优化代码，再调整线程。
|
||||
|
||||
这里就有一个小的分析链路了。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/72/8a/7200322d770436e0007d56eaaab5508a.png" alt="">
|
||||
|
||||
怎么来判断代码运行得足够快呢？
|
||||
|
||||
下面我们来看几个例子，然后我会说一下如何判断代码快不快（当然这个具体的应用也有关，你还需要在具体的应用中做详细地分析哦）。
|
||||
|
||||
### 场景一：当压力线程远远小于服务端线程数时
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/8d/ca/8d0aa1603e1ab8325234ef35f445e4ca.png" alt="">
|
||||
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 930 in 00:00:16 = 59.7/s Avg: 7 Min: 0 Max: 922 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 4546 in 00:00:30 = 151.6/s Avg: 3 Min: 0 Max: 46 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary = 5476 in 00:00:46 = 120.2/s Avg: 3 Min: 0 Max: 922 Err: 0 (0.00%)
|
||||
summary + 5822 in 00:00:30 = 194.0/s Avg: 2 Min: 0 Max: 32 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary = 11298 in 00:01:16 = 149.5/s Avg: 3 Min: 0 Max: 922 Err: 0 (0.00%)
|
||||
summary + 5295 in 00:00:24 = 216.5/s Avg: 2 Min: 0 Max: 26 Err: 0 (0.00%) Active: 0 Started: 1 Finished: 1
|
||||
summary = 16593 in 00:01:40 = 165.9/s Avg: 2 Min: 0 Max: 922 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
线程监控结果：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/45/91/4555aa52c4ad29ca58875b43d32d5591.png" alt="">
|
||||
|
||||
jvisuavlvm的thread监控图是每秒刷新一次，其中橙色代表TIMED_WAITING状态，没活干；绿色代表RUNNABLE状态，在干活。
|
||||
|
||||
通过这个测试结果，你可以看到，在只有一个压力线程的情况下，这10个Worker是轮流提供响应的。
|
||||
|
||||
这就是**典型的线程足够用的状态**。
|
||||
|
||||
### 场景二：当压力线程数通过递增，慢慢超过服务端线程数时
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e5/4b/e5420d0a3eccb3fbef84c57dd322a64b.png" alt=""><br>
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 4529 in 00:00:22 = 203.6/s Avg: 2 Min: 0 Max: 464 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary + 11023 in 00:00:30 = 367.7/s Avg: 2 Min: 0 Max: 71 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 15552 in 00:00:52 = 297.8/s Avg: 2 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 15131 in 00:00:30 = 504.4/s Avg: 2 Min: 0 Max: 166 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 30683 in 00:01:22 = 373.2/s Avg: 2 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 17420 in 00:00:30 = 580.7/s Avg: 3 Min: 0 Max: 68 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 48103 in 00:01:52 = 428.6/s Avg: 3 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 17416 in 00:00:30 = 580.5/s Avg: 3 Min: 0 Max: 72 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 65519 in 00:02:22 = 460.7/s Avg: 3 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 17389 in 00:00:30 = 579.6/s Avg: 4 Min: 0 Max: 71 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 82908 in 00:02:52 = 481.4/s Avg: 3 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18591 in 00:00:30 = 619.8/s Avg: 4 Min: 0 Max: 82 Err: 0 (0.00%) Active: 11 Started: 11 Finished: 0
|
||||
summary = 101499 in 00:03:22 = 501.9/s Avg: 3 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18692 in 00:00:30 = 623.1/s Avg: 5 Min: 0 Max: 72 Err: 0 (0.00%) Active: 12 Started: 12 Finished: 0
|
||||
summary = 120191 in 00:03:52 = 517.6/s Avg: 4 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18577 in 00:00:30 = 619.2/s Avg: 6 Min: 0 Max: 83 Err: 0 (0.00%) Active: 14 Started: 14 Finished: 0
|
||||
summary = 138768 in 00:04:22 = 529.2/s Avg: 4 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 19371 in 00:00:30 = 645.7/s Avg: 6 Min: 0 Max: 113 Err: 0 (0.00%) Active: 15 Started: 15 Finished: 0
|
||||
summary = 158139 in 00:04:52 = 541.2/s Avg: 4 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18891 in 00:00:30 = 629.7/s Avg: 7 Min: 0 Max: 146 Err: 0 (0.00%) Active: 17 Started: 17 Finished: 0
|
||||
summary = 177030 in 00:05:22 = 549.4/s Avg: 4 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 19075 in 00:00:30 = 635.6/s Avg: 7 Min: 0 Max: 99 Err: 0 (0.00%) Active: 18 Started: 18 Finished: 0
|
||||
summary = 196105 in 00:05:52 = 556.7/s Avg: 5 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18782 in 00:00:30 = 625.4/s Avg: 8 Min: 0 Max: 122 Err: 0 (0.00%) Active: 20 Started: 20 Finished: 0
|
||||
summary = 214887 in 00:06:22 = 562.1/s Avg: 5 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18911 in 00:00:30 = 631.3/s Avg: 8 Min: 0 Max: 146 Err: 0 (0.00%) Active: 21 Started: 21 Finished: 0
|
||||
summary = 233798 in 00:06:52 = 567.2/s Avg: 5 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18153 in 00:00:30 = 605.1/s Avg: 9 Min: 0 Max: 147 Err: 0 (0.00%) Active: 23 Started: 23 Finished: 0
|
||||
summary = 251951 in 00:07:22 = 569.7/s Avg: 5 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 14704 in 00:00:30 = 490.1/s Avg: 10 Min: 0 Max: 175 Err: 0 (0.00%) Active: 24 Started: 24 Finished: 0
|
||||
summary = 266655 in 00:07:52 = 564.7/s Avg: 6 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 18196 in 00:00:30 = 606.6/s Avg: 10 Min: 0 Max: 147 Err: 0 (0.00%) Active: 26 Started: 26 Finished: 0
|
||||
summary = 284851 in 00:08:22 = 567.2/s Avg: 6 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 17768 in 00:00:30 = 592.3/s Avg: 10 Min: 0 Max: 227 Err: 0 (0.00%) Active: 27 Started: 27 Finished: 0
|
||||
summary = 302619 in 00:08:52 = 568.6/s Avg: 6 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 16754 in 00:00:30 = 558.2/s Avg: 12 Min: 0 Max: 218 Err: 0 (0.00%) Active: 29 Started: 29 Finished: 0
|
||||
summary = 319373 in 00:09:22 = 568.0/s Avg: 7 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
summary + 17216 in 00:00:30 = 574.0/s Avg: 12 Min: 0 Max: 249 Err: 0 (0.00%) Active: 30 Started: 30 Finished: 0
|
||||
summary = 336589 in 00:09:52 = 568.3/s Avg: 7 Min: 0 Max: 464 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
线程监控结果：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/15/0e/15df234451fadf3d3ab9106bb985c80e.png" alt="">
|
||||
|
||||
在这个场景中，我特意把压力工具中的线程数设置得高于Tomcat线程数，并且通过递增的方式加压。
|
||||
|
||||
一开始线程数是足够用的，还有挺多的时间处于空闲状态。但随着压力的增加，Tomcat的线程越来越忙，直到不够用，于是Tomcat就自己调整了线程数，直到maxThreads的值。然后线程的空闲状态就越来越少，到最后几乎没有空闲状态了。
|
||||
|
||||
你也可以看到响应时间随着线程数的不够用而不断的增加。
|
||||
|
||||
这就是**典型的线程配置不够的状态**。
|
||||
|
||||
### 场景三：当压力线程数远高于服务端线程数时
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/88/38/88b477ca0e28afdf5d2502f2f58faa38.png" alt=""><br>
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 1 in 00:00:02 = 0.5/s Avg: 1724 Min: 1724 Max: 1724 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary + 5821 in 00:00:28 = 204.3/s Avg: 128 Min: 1 Max: 1798 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 5822 in 00:00:31 = 190.8/s Avg: 129 Min: 1 Max: 1798 Err: 0 (0.00%)
|
||||
summary + 10881 in 00:00:30 = 362.7/s Avg: 57 Min: 1 Max: 405 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 16703 in 00:01:01 = 276.0/s Avg: 82 Min: 1 Max: 1798 Err: 0 (0.00%)
|
||||
summary + 11548 in 00:00:30 = 384.9/s Avg: 52 Min: 1 Max: 308 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 28251 in 00:01:31 = 312.1/s Avg: 70 Min: 1 Max: 1798 Err: 0 (0.00%)
|
||||
summary + 3747 in 00:00:10 = 387.8/s Avg: 51 Min: 1 Max: 328 Err: 0 (0.00%) Active: 0 Started: 50 Finished: 50
|
||||
summary = 31998 in 00:01:40 = 319.4/s Avg: 67 Min: 1 Max: 1798 Err: 0 (0.00%)
|
||||
|
||||
|
||||
```
|
||||
|
||||
线程监控结果：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/a8/fe/a84094c875c823e1aec552f244529bfe.png" alt="">
|
||||
|
||||
在这个压力场景中，我直接把压力线程加上来，并且高于Tomcat的处理线程，Tomcat一下就上到了maxThreads的上限，然后就几乎没再闲过。同时你也可以看到响应时间远远大于场景二中的响应时间。
|
||||
|
||||
这就是**典型的压力过高的状态**。
|
||||
|
||||
对比前面三个场景，我们再比对之前专栏中的文章内容，就可以理解几个关键的知识点了。
|
||||
|
||||
首先，压力工具中的线程数到底应不应该在没有报错的情况下无休止地增加？
|
||||
|
||||
显然即使你增加，对服务端能处理的请求来说，并没有什么意义，只会导致响应时间的变长。
|
||||
|
||||
其次，把压力线程理解为并发用户数到底对不对？
|
||||
|
||||
如果你把压力线程理解为并发用户，通过这几个示例就可以看到，服务端能处理的压力线程必然不会超过自身的线程上限，也就是说，把压力线程理解为并发用户，并发用户的上限是固定的。你都不用测试，直接看服务端的线程数配置为多大就够了。这也是为什么我一再强调并发用户数不能用压力线程来描述，不能用压力线程来承载服务端性能指标的关键点。
|
||||
|
||||
而用TPS来描述的时候，因为有了“秒”的概念，就有了时间段，而在这个时间段内得到的响应都认为是被支持了的，所以用TPS来描述会更为合理。<br>
|
||||
而T的定义具有业务含义时，也就对应起了技术和业务之间的关系，这个逻辑也就完整了。
|
||||
|
||||
从这里你也可以看到，我在整个专栏中所描述的概念在具体的落地时，都会秉承它的连贯性，要不然一个飞在空中的概念就没有意义了。
|
||||
|
||||
### 场景四：设置最大最小空闲线程数
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f2/f1/f285ace2441abd42c09785ae69fb95f1.png" alt=""><br>
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 1 in 00:00:01 = 0.9/s Avg: 730 Min: 730 Max: 730 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 2915 in 00:00:30 = 97.5/s Avg: 5 Min: 0 Max: 1126 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 2916 in 00:00:31 = 94.1/s Avg: 5 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 6690 in 00:00:30 = 222.9/s Avg: 4 Min: 0 Max: 81 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 9606 in 00:01:01 = 157.5/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 9968 in 00:00:30 = 332.4/s Avg: 4 Min: 0 Max: 88 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 19574 in 00:01:31 = 215.2/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 14140 in 00:00:30 = 471.1/s Avg: 3 Min: 0 Max: 87 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 33714 in 00:02:01 = 278.6/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 14985 in 00:00:30 = 499.8/s Avg: 4 Min: 0 Max: 84 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 48699 in 00:02:31 = 322.6/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 16446 in 00:00:30 = 548.1/s Avg: 4 Min: 0 Max: 76 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 65145 in 00:03:01 = 360.0/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 16171 in 00:00:30 = 539.2/s Avg: 5 Min: 0 Max: 410 Err: 0 (0.00%) Active: 11 Started: 11 Finished: 0
|
||||
summary = 81316 in 00:03:31 = 385.4/s Avg: 4 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 16419 in 00:00:30 = 547.2/s Avg: 7 Min: 0 Max: 646 Err: 0 (0.00%) Active: 13 Started: 13 Finished: 0
|
||||
summary = 97735 in 00:04:01 = 405.6/s Avg: 5 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 15981 in 00:00:30 = 532.7/s Avg: 9 Min: 0 Max: 832 Err: 0 (0.00%) Active: 14 Started: 14 Finished: 0
|
||||
summary = 113716 in 00:04:31 = 419.7/s Avg: 5 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 16064 in 00:00:30 = 535.6/s Avg: 11 Min: 0 Max: 888 Err: 0 (0.00%) Active: 16 Started: 16 Finished: 0
|
||||
summary = 129780 in 00:05:01 = 431.2/s Avg: 6 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 15446 in 00:00:30 = 514.8/s Avg: 10 Min: 0 Max: 1022 Err: 0 (0.00%) Active: 17 Started: 17 Finished: 0
|
||||
summary = 145226 in 00:05:31 = 438.8/s Avg: 6 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 14643 in 00:00:30 = 488.1/s Avg: 12 Min: 0 Max: 1114 Err: 0 (0.00%) Active: 19 Started: 19 Finished: 0
|
||||
summary = 159869 in 00:06:01 = 442.9/s Avg: 7 Min: 0 Max: 1126 Err: 0 (0.00%)
|
||||
summary + 14805 in 00:00:30 = 493.5/s Avg: 13 Min: 0 Max: 1250 Err: 0 (0.00%) Active: 20 Started: 20 Finished: 0
|
||||
summary = 174674 in 00:06:31 = 446.8/s Avg: 7 Min: 0 Max: 1250 Err: 0 (0.00%)
|
||||
summary + 14446 in 00:00:30 = 481.5/s Avg: 15 Min: 0 Max: 1385 Err: 0 (0.00%) Active: 22 Started: 22 Finished: 0
|
||||
summary = 189120 in 00:07:01 = 449.2/s Avg: 8 Min: 0 Max: 1385 Err: 0 (0.00%)
|
||||
summary + 14310 in 00:00:30 = 477.1/s Avg: 17 Min: 0 Max: 1454 Err: 0 (0.00%) Active: 23 Started: 23 Finished: 0
|
||||
summary = 203430 in 00:07:31 = 451.1/s Avg: 9 Min: 0 Max: 1454 Err: 0 (0.00%)
|
||||
summary + 13856 in 00:00:30 = 461.8/s Avg: 18 Min: 0 Max: 1454 Err: 0 (0.00%) Active: 25 Started: 25 Finished: 0
|
||||
summary = 217286 in 00:08:01 = 451.8/s Avg: 9 Min: 0 Max: 1454 Err: 0 (0.00%)
|
||||
summary + 13643 in 00:00:30 = 454.8/s Avg: 18 Min: 0 Max: 1591 Err: 0 (0.00%) Active: 26 Started: 26 Finished: 0
|
||||
summary = 230929 in 00:08:31 = 451.9/s Avg: 10 Min: 0 Max: 1591 Err: 0 (0.00%)
|
||||
summary + 13605 in 00:00:30 = 453.5/s Avg: 21 Min: 0 Max: 1593 Err: 0 (0.00%) Active: 28 Started: 28 Finished: 0
|
||||
summary = 244534 in 00:09:01 = 452.0/s Avg: 10 Min: 0 Max: 1593 Err: 0 (0.00%)
|
||||
summary + 13316 in 00:00:30 = 443.7/s Avg: 23 Min: 0 Max: 1598 Err: 0 (0.00%) Active: 29 Started: 29 Finished: 0
|
||||
summary = 257850 in 00:09:31 = 451.6/s Avg: 11 Min: 0 Max: 1598 Err: 0 (0.00%)
|
||||
summary + 12538 in 00:00:30 = 418.1/s Avg: 24 Min: 0 Max: 1599 Err: 0 (0.00%) Active: 30 Started: 30 Finished: 0
|
||||
summary = 270388 in 00:10:01 = 449.9/s Avg: 12 Min: 0 Max: 1599 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
线程监控结果：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b8/e2/b8cd1f7109a47c04a163091fcd1b73e2.png" alt="">
|
||||
|
||||
这个场景是为了描述minSpareThreads和maxSpareThreads的能力，我们可以看到场景结束了之后，线程确实被回收了。
|
||||
|
||||
记住，这个回收的价值在于，当再次有少量请求进来时不会导致过多的维护线程的成本，从而导致TPS的下降。如果你的应用中，本身线程数就不是非常大，即使长时间维护着固定的线程池也不会有大的成本，那么不配置这两个参数也是可以的。
|
||||
|
||||
### 禁用AJP
|
||||
|
||||
什么是AJP呢？你可以点击[这里](https://Tomcat.apache.org/connectors-doc/ajp/ajpv13a.html)看一下。
|
||||
|
||||
AJP是个二进制的TCP传输协议，相比HTTP来说有更高的性能和效率，只是支持AJP的代理服务器不多。在我们常用的应用场景中，用Nginx来连接Tomcat较多，AJP协议是用不上的，因为Nginx官方根本就没有支持AJP协议的模块。当然也有人提供过AJP的Nginx代理模块，只是实际应用的也不多。
|
||||
|
||||
下面我们看禁用AJP和启用AJP产生的效果。
|
||||
|
||||
首先看下启用AJP的测试结果。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ca/f0/ca10bcddc4e459abf3e486f2f10a2ff0.png" alt="">
|
||||
|
||||
启动AJP（在Tomcat的conf/server.xml中配置）：
|
||||
|
||||
```
|
||||
<Connector port="8009" protocol="AJP/1.3" redirectPort="8443" />
|
||||
|
||||
```
|
||||
|
||||
启动日志：
|
||||
|
||||
```
|
||||
21-Jan-2020 01:14:58.404 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [ajp-nio-8009]
|
||||
|
||||
```
|
||||
|
||||
测试结果为下面这样：
|
||||
|
||||
```
|
||||
summary + 4 in 00:00:02 = 1.8/s Avg: 482 Min: 188 Max: 903 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 2704 in 00:00:29 = 92.8/s Avg: 5 Min: 0 Max: 83 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 2708 in 00:00:31 = 86.4/s Avg: 5 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 6154 in 00:00:30 = 205.1/s Avg: 4 Min: 0 Max: 89 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 8862 in 00:01:01 = 144.5/s Avg: 5 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 8818 in 00:00:30 = 293.9/s Avg: 4 Min: 0 Max: 71 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 17680 in 00:01:31 = 193.6/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 13267 in 00:00:30 = 442.3/s Avg: 4 Min: 0 Max: 66 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 30947 in 00:02:01 = 255.0/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 13004 in 00:00:30 = 433.4/s Avg: 4 Min: 0 Max: 59 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 43951 in 00:02:31 = 290.4/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 15800 in 00:00:30 = 526.6/s Avg: 4 Min: 0 Max: 88 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 59751 in 00:03:01 = 329.5/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 16766 in 00:00:30 = 559.0/s Avg: 5 Min: 0 Max: 90 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 76517 in 00:03:31 = 362.1/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 16760 in 00:00:30 = 558.6/s Avg: 5 Min: 0 Max: 67 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 93277 in 00:04:01 = 386.5/s Avg: 4 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
summary + 16991 in 00:00:30 = 566.4/s Avg: 6 Min: 0 Max: 148 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 110268 in 00:04:31 = 406.4/s Avg: 5 Min: 0 Max: 903 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
然后我们再看下禁用AJP的测试结果。
|
||||
|
||||
禁用AJP：
|
||||
|
||||
```
|
||||
<!-- Connector port="8009" protocol="AJP/1.3" redirectPort="8443" -->
|
||||
|
||||
```
|
||||
|
||||
无启动日志。
|
||||
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 90 in 00:00:05 = 16.9/s Avg: 33 Min: 2 Max: 812 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 3443 in 00:00:30 = 115.0/s Avg: 4 Min: 0 Max: 93 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 3533 in 00:00:35 = 100.2/s Avg: 5 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 7245 in 00:00:30 = 241.5/s Avg: 4 Min: 0 Max: 75 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 10778 in 00:01:05 = 165.2/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 11029 in 00:00:30 = 367.6/s Avg: 4 Min: 0 Max: 335 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 21807 in 00:01:35 = 228.9/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 12227 in 00:00:30 = 407.5/s Avg: 4 Min: 0 Max: 67 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 34034 in 00:02:05 = 271.7/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 14735 in 00:00:30 = 491.4/s Avg: 4 Min: 0 Max: 72 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 48769 in 00:02:35 = 314.1/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 16574 in 00:00:30 = 552.5/s Avg: 4 Min: 0 Max: 65 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 65343 in 00:03:05 = 352.7/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 17488 in 00:00:30 = 582.9/s Avg: 4 Min: 0 Max: 70 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 82831 in 00:03:35 = 384.8/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 16933 in 00:00:30 = 564.5/s Avg: 5 Min: 0 Max: 87 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 99764 in 00:04:05 = 406.8/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
summary + 17363 in 00:00:30 = 578.8/s Avg: 6 Min: 0 Max: 76 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 117127 in 00:04:35 = 425.5/s Avg: 4 Min: 0 Max: 812 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
通过比对，如下图所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/30/71/30114785a6e692a14f9b17f27fbf0a71.jpg" alt="">
|
||||
|
||||
禁用AJP确实性能会高一点，在这个场景中最高的时候，同压力线程下，性能高出近20%。
|
||||
|
||||
### 压缩
|
||||
|
||||
在很多的压力测试中，我们说压缩这个功能都是基于两个目标：
|
||||
|
||||
1. 减少带宽的消耗；
|
||||
1. 减少传输的时间；
|
||||
|
||||
但是这必然会导致服务端CPU消耗的增加，这是个必然的过程。所以它的配置前提就是CPU足够用，带宽不够用。如果你带宽足够用，CPU不够用时，显然这样做是不理智的。
|
||||
|
||||
下面我们来看一下Tomcat中压缩和不压缩产生的结果。
|
||||
|
||||
首先是不压缩。
|
||||
|
||||
```
|
||||
summary + 588 in 00:00:13 = 46.0/s Avg: 10 Min: 1 Max: 804 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 4403 in 00:00:30 = 146.8/s Avg: 4 Min: 0 Max: 87 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 4991 in 00:00:43 = 116.7/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 7107 in 00:00:30 = 237.1/s Avg: 4 Min: 0 Max: 77 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 12098 in 00:01:13 = 166.3/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 11121 in 00:00:30 = 370.7/s Avg: 4 Min: 0 Max: 72 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 23219 in 00:01:43 = 226.0/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 12709 in 00:00:30 = 423.6/s Avg: 4 Min: 0 Max: 87 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 35928 in 00:02:13 = 270.6/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 14548 in 00:00:30 = 485.0/s Avg: 4 Min: 0 Max: 69 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 50476 in 00:02:43 = 310.1/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 15810 in 00:00:30 = 527.0/s Avg: 5 Min: 0 Max: 83 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 66286 in 00:03:13 = 343.9/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 15242 in 00:00:30 = 508.0/s Avg: 5 Min: 0 Max: 77 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 81528 in 00:03:43 = 366.0/s Avg: 4 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 16709 in 00:00:30 = 557.1/s Avg: 5 Min: 0 Max: 75 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 98237 in 00:04:13 = 388.7/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
summary + 17099 in 00:00:30 = 570.0/s Avg: 6 Min: 0 Max: 161 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 115336 in 00:04:43 = 407.9/s Avg: 5 Min: 0 Max: 804 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
网络流量：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/8d/5c/8dd475b263132ef93c3221246c32455c.png" alt="">
|
||||
|
||||
然后是压缩。
|
||||
|
||||
在这里，我为了让压缩生效的范围更大，把最小值设置为了10bytes。
|
||||
|
||||
```
|
||||
compression="on" compressionMinSize="10" noCompressionUserAgents="gozilla,traviata" compressableMimeType="text/html,text/xml,application/javascript,text/javascript,text/css,text/plain,text/json"
|
||||
|
||||
summary + 1037 in 00:00:09 = 117.5/s Avg: 4 Min: 0 Max: 418 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 5832 in 00:00:30 = 194.2/s Avg: 3 Min: 0 Max: 74 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 6869 in 00:00:39 = 176.8/s Avg: 3 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 10378 in 00:00:30 = 346.3/s Avg: 3 Min: 0 Max: 71 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 17247 in 00:01:09 = 250.6/s Avg: 3 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 12670 in 00:00:30 = 422.2/s Avg: 3 Min: 0 Max: 64 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 29917 in 00:01:39 = 302.7/s Avg: 3 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 13917 in 00:00:30 = 464.0/s Avg: 4 Min: 0 Max: 78 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 43834 in 00:02:09 = 340.3/s Avg: 3 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 14815 in 00:00:30 = 493.9/s Avg: 4 Min: 0 Max: 79 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 58649 in 00:02:39 = 369.3/s Avg: 3 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 15710 in 00:00:30 = 523.6/s Avg: 5 Min: 0 Max: 89 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 74359 in 00:03:09 = 393.8/s Avg: 4 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 16059 in 00:00:30 = 535.3/s Avg: 5 Min: 0 Max: 70 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 90418 in 00:03:39 = 413.2/s Avg: 4 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 15909 in 00:00:30 = 530.2/s Avg: 6 Min: 0 Max: 96 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 106327 in 00:04:09 = 427.3/s Avg: 4 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
summary + 16011 in 00:00:30 = 533.8/s Avg: 6 Min: 0 Max: 75 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 122338 in 00:04:39 = 438.8/s Avg: 4 Min: 0 Max: 418 Err: 0 (0.00%)
|
||||
|
||||
|
||||
```
|
||||
|
||||
网络流量：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/9c/2c/9c9b4f5a564ce9f142ff1a4a42caca2c.png" alt="">
|
||||
|
||||
通过上面的测试比对结果可以看到：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/40/d0/400a23da7e7fe4d93d3bdbcb8e3291d0.jpg" alt="">
|
||||
|
||||
确实在CPU资源足够用的时候，采用压缩，TPS要大一些，但随着压力的增加，CPU资源不够了之后，压缩就没啥用了。
|
||||
|
||||
从带宽传输上可以看到，不压缩时最大带宽达到40M，而压缩时最大带宽只有14M，可见压缩对带宽的作用还是很显著的。
|
||||
|
||||
### acceptCount
|
||||
|
||||
在上面的思维导图中，线程池最后一个参数就是acceptCount，这个值就比较容易理解，就是TCP的接收队列长度。
|
||||
|
||||
这次我直接用一个大压力的场景说明它的值大小的区别。我直接上50个线程。为什么要这么做呢，就是为了让队列产生得多一些。
|
||||
|
||||
下面我们直接来看结果吧。
|
||||
|
||||
### acceptCount=“10000”
|
||||
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 2400 in 00:00:11 = 217.6/s Avg: 108 Min: 3 Max: 1176 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary + 10322 in 00:00:30 = 344.1/s Avg: 62 Min: 1 Max: 470 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 12722 in 00:00:41 = 310.1/s Avg: 71 Min: 1 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 12660 in 00:00:30 = 422.0/s Avg: 49 Min: 0 Max: 331 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 25382 in 00:01:11 = 357.4/s Avg: 60 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 13337 in 00:00:30 = 444.6/s Avg: 46 Min: 1 Max: 410 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 38719 in 00:01:41 = 383.3/s Avg: 55 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 14176 in 00:00:30 = 472.4/s Avg: 43 Min: 0 Max: 302 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 52895 in 00:02:11 = 403.7/s Avg: 52 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 14696 in 00:00:30 = 489.7/s Avg: 42 Min: 1 Max: 261 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 67591 in 00:02:41 = 419.7/s Avg: 50 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 16191 in 00:00:30 = 539.9/s Avg: 38 Min: 0 Max: 320 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 83782 in 00:03:11 = 438.6/s Avg: 47 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 5299 in 00:00:09 = 580.1/s Avg: 36 Min: 1 Max: 201 Err: 0 (0.00%) Active: 0 Started: 50 Finished: 50
|
||||
summary = 89081 in 00:03:20 = 445.0/s Avg: 47 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
### acceptCount=“100”
|
||||
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 1115 in 00:00:11 = 100.1/s Avg: 306 Min: 11 Max: 1936 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary + 7923 in 00:00:30 = 264.1/s Avg: 87 Min: 1 Max: 521 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 9038 in 00:00:41 = 219.7/s Avg: 114 Min: 1 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 11414 in 00:00:30 = 380.5/s Avg: 56 Min: 1 Max: 381 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 20452 in 00:01:11 = 287.5/s Avg: 81 Min: 1 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 11949 in 00:00:30 = 398.4/s Avg: 51 Min: 0 Max: 390 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 32401 in 00:01:41 = 320.4/s Avg: 70 Min: 0 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 13403 in 00:00:30 = 446.7/s Avg: 46 Min: 0 Max: 326 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 45804 in 00:02:11 = 349.3/s Avg: 63 Min: 0 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 13271 in 00:00:30 = 442.4/s Avg: 45 Min: 0 Max: 295 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 59075 in 00:02:41 = 366.6/s Avg: 59 Min: 0 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 14307 in 00:00:30 = 476.9/s Avg: 43 Min: 1 Max: 288 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 73382 in 00:03:11 = 383.9/s Avg: 56 Min: 0 Max: 1936 Err: 0 (0.00%)
|
||||
summary + 4292 in 00:00:09 = 476.3/s Avg: 42 Min: 1 Max: 226 Err: 0 (0.00%) Active: 0 Started: 50 Finished: 50
|
||||
summary = 77674 in 00:03:20 = 388.1/s Avg: 55 Min: 0 Max: 1936 Err: 0 (0.00%)
|
||||
|
||||
```
|
||||
|
||||
通过上面的结果，可以得到下图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/50/0a/50b80dc97fa05ed1571380e913a9ba0a.jpg" alt="">
|
||||
|
||||
可见当acceptCount大时，对TPS还是有明显帮助的。
|
||||
|
||||
接下来，我们再看下connectionTimeout。
|
||||
|
||||
### connectionTimeout
|
||||
|
||||
我需要说明的是，以下场景均基于以下配置：acceptCount=“10000”。
|
||||
|
||||
这个值对我们来说，也是非常关键的数据，因为它影响着KeepAlive的超时和connection的超时。
|
||||
|
||||
我们在性能分析的时候，会遇到一种情况是，很多应用都用默认超时，而在压力大的时候，会有少量的报错是因为前端的超时已经到了，而后端还没到，因为毕竟后端是后接收到的请求。这就导致了大压力下少量的错误是因为超时配置导致的。
|
||||
|
||||
所以我们通常都会画一个图如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d9/61/d935ee8b317bada3264fc9e640a2c261.jpg" alt="">
|
||||
|
||||
而在真实的应用场景中，应该配置多长时间的超时一定是经过严格的测试的。
|
||||
|
||||
下面我们来看看结果。
|
||||
|
||||
当`connectionTimeout="20000"`时，这个结果直接拿上面的测试结果复用。
|
||||
|
||||
测试结果：
|
||||
|
||||
```
|
||||
summary + 2400 in 00:00:11 = 217.6/s Avg: 108 Min: 3 Max: 1176 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary + 10322 in 00:00:30 = 344.1/s Avg: 62 Min: 1 Max: 470 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 12722 in 00:00:41 = 310.1/s Avg: 71 Min: 1 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 12660 in 00:00:30 = 422.0/s Avg: 49 Min: 0 Max: 331 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 25382 in 00:01:11 = 357.4/s Avg: 60 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 13337 in 00:00:30 = 444.6/s Avg: 46 Min: 1 Max: 410 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 38719 in 00:01:41 = 383.3/s Avg: 55 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 14176 in 00:00:30 = 472.4/s Avg: 43 Min: 0 Max: 302 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 52895 in 00:02:11 = 403.7/s Avg: 52 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 14696 in 00:00:30 = 489.7/s Avg: 42 Min: 1 Max: 261 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 67591 in 00:02:41 = 419.7/s Avg: 50 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 16191 in 00:00:30 = 539.9/s Avg: 38 Min: 0 Max: 320 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 83782 in 00:03:11 = 438.6/s Avg: 47 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
summary + 5299 in 00:00:09 = 580.1/s Avg: 36 Min: 1 Max: 201 Err: 0 (0.00%) Active: 0 Started: 50 Finished: 50
|
||||
summary = 89081 in 00:03:20 = 445.0/s Avg: 47 Min: 0 Max: 1176 Err: 0 (0.00%)
|
||||
|
||||
|
||||
```
|
||||
|
||||
当connectionTimeout="200"时，测试结果为：
|
||||
|
||||
```
|
||||
summary + 1540 in 00:00:13 = 117.5/s Avg: 258 Min: 7 Max: 2150 Err: 15 (0.97%) Active: 50 Started: 50 Finished: 0
|
||||
summary + 10080 in 00:00:30 = 336.4/s Avg: 65 Min: 1 Max: 465 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 11620 in 00:00:43 = 269.8/s Avg: 90 Min: 1 Max: 2150 Err: 15 (0.13%)
|
||||
summary + 12691 in 00:00:30 = 422.8/s Avg: 49 Min: 0 Max: 317 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 24311 in 00:01:13 = 332.6/s Avg: 69 Min: 0 Max: 2150 Err: 15 (0.06%)
|
||||
summary + 12707 in 00:00:30 = 423.8/s Avg: 48 Min: 1 Max: 312 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 37018 in 00:01:43 = 359.2/s Avg: 62 Min: 0 Max: 2150 Err: 15 (0.04%)
|
||||
summary + 13530 in 00:00:30 = 450.7/s Avg: 45 Min: 0 Max: 306 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 50548 in 00:02:13 = 379.8/s Avg: 57 Min: 0 Max: 2150 Err: 15 (0.03%)
|
||||
summary + 13791 in 00:00:30 = 460.0/s Avg: 44 Min: 1 Max: 344 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 64339 in 00:02:43 = 394.5/s Avg: 55 Min: 0 Max: 2150 Err: 15 (0.02%)
|
||||
summary + 14840 in 00:00:30 = 494.6/s Avg: 41 Min: 0 Max: 319 Err: 0 (0.00%) Active: 50 Started: 50 Finished: 0
|
||||
summary = 79179 in 00:03:13 = 410.1/s Avg: 52 Min: 0 Max: 2150 Err: 15 (0.02%)
|
||||
summary + 3734 in 00:00:07 = 530.5/s Avg: 39 Min: 1 Max: 282 Err: 0 (0.00%) Active: 0 Started: 50 Finished: 50
|
||||
summary = 82913 in 00:03:20 = 414.3/s Avg: 51 Min: 0 Max: 2150 Err: 15 (0.02%)
|
||||
|
||||
|
||||
```
|
||||
|
||||
看到没有，一开始就有少量的报错产生了，但一些我没加断言的报错应该没有在这里没显示出来。
|
||||
|
||||
所以根据应用的重要性，超时长度在具体的应用场景中，一定要做严格的测试。把完整的业务链路图画出来之后，一个个环节分析超时应该设置为多大，才是合理的做法。
|
||||
|
||||
## 总结
|
||||
|
||||
至于其他的Tomcat调优参数，你可以在自己的场景中实际操作一下。
|
||||
|
||||
总之，Tomcat的优化就是这么几个关键环节：协议、运行模式（尽管现在我认为它已经不再有争议了，但是当你用老版本的Tomcat时还是要注意一下）、线程池（关键中的关键）等。
|
||||
|
||||
不止是Tomcat这样，其他类似的应用服务器也是一样。尽管这些应用服务器在架构设计上会不同，但是在我的调优生涯中，针对这样的应用服务器，可调优的关键点真的就这么几个。
|
||||
|
||||
可见这样的应用服务器本身可调优的点并不多。如果你要调的是SpringBoot中的Tomcat组件，也可以用同样的思路。
|
||||
|
||||
最后我还是要说，在你的具体工作中，一定要拿实际测试结果来分析判断，以免产生偏差。在任何时候，都要知道，性能测试的计数器中，没有哪个计数器的值可以直接告诉你性能问题的原因，只有通过自己的分析判断才能找得到。
|
||||
|
||||
## 思考题
|
||||
|
||||
最后给你留两道思考题吧。类似Tomcat的应用服务器，应该如何拆解监控计数器呢？我们应该如何判断应用服务器的线程是否够用？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流进步一下。
|
||||
322
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/22丨MySQL：数据库级监控及常用计数器解析（上）.md
Normal file
322
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/22丨MySQL：数据库级监控及常用计数器解析（上）.md
Normal file
@@ -0,0 +1,322 @@
|
||||
<audio id="audio" title="22丨MySQL：数据库级监控及常用计数器解析（上）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/b1/55/b1f0d98f9fbf80831ab2bdc41fec7455.mp3"></audio>
|
||||
|
||||
数据库是一个非常大的话题，我们在很多地方，都会看到对数据库的性能分析会包括以下部分。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/17/40/178e637e4723e37abb7eb9d477d20f40.png" alt="">
|
||||
|
||||
但其实呢，以上这些内容都是我们应该具备的基础知识，所以我今天要讲的就是，具备了这些基础知识之后我们应该干什么事情。
|
||||
|
||||
也就是说，从性能瓶颈判断分析的角度入手，才是性能从业人员该有的逻辑。每次我分析一个性能问题时，逻辑总是这样的：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/62/ab/625d1ec2717f84cb2dc9119d8c7e43ab.jpg" alt="">
|
||||
|
||||
1. 先画出整个系统的架构图。
|
||||
1. 列出整个系统中用到了哪些组件。这一步要确定用哪些监控工具来收集数据，具体的内容你可以看下之前讲到的监控设计相关的内容。
|
||||
1. 掌握每个组件的架构图。在这一步中需要列出它们的关键性能配置参数。
|
||||
1. 在压力场景执行的过程中收集状态计数器。
|
||||
1. 通过分析思路画出性能瓶颈的分析决策树。
|
||||
1. 找到问题的根本原因。
|
||||
1. 提出解决方案并评估每个方案的优缺点和成本。
|
||||
|
||||
这是我一直强调的分析决策树的创建逻辑。有了这些步骤之后，即使不熟悉一个系统，你也可以进行性能分析。
|
||||
|
||||
对于MySQL数据库来说，我们想对它进行分析，同样也需要看它的架构图。如下图所示（这是MySQL5版本的架构示意图）：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/34/42/34c20915477740cac9cfa18aa7114542.png" alt="">
|
||||
|
||||
这里就有一个问题了：看架构图是看什么？这个图够细吗？
|
||||
|
||||
首先，看架构图，一开始肯定是看大而全的架构。比如说上图，我们知道了，MySQL中有Connection Pool、SQL Interface、Parser等这些大的模块。
|
||||
|
||||
其次，我们得知道这些模块的功能及运行逻辑。比如说，我们看到了这些模块之后，需要知道，当一个SQL通过Connection Pool进到系统之后，需要先进入SQL Interface模块判断这个语句，知道它是一个什么样的SQL，涉及到了什么内容；然后通过Parser模块进行语法语义检查，并生成相应的执行计划；接着到Optimizer模块进行优化，判断走什么索引，执行顺序之类的；然后就到Caches中找数据，如果在Caches中找不到数据的话，就得通过文件系统到磁盘中找。
|
||||
|
||||
这就是一个大体的逻辑。但是知道了这个逻辑还不够。还记得前面我们说的对一个组件进行“全局—定向”的监控思路吧。
|
||||
|
||||
这里我们也得找工具实现对MySQL的监控，还好MySQL的监控工具非常多。
|
||||
|
||||
在讲MySQL的监控工具之前，我们先来了解下MySQL中的两个Schema，分别是`information_schema`和`performance_schema` 。
|
||||
|
||||
为什么呢？
|
||||
|
||||
`information_schema`保存了数据库中的所有表、列、索引、权限、配置参数、状态参数等信息。像我们常执行的`show processlist;`就来自于这个schema中的processlist表。
|
||||
|
||||
`performance_schema`提供了数据库运行时的资源消耗情况，它以较低的代价收集信息，可以提供不少性能数据。
|
||||
|
||||
所以这两个Schema对我们来说就非常重要了。
|
||||
|
||||
你没事的时候，也可以查一下它们相关的各个表，一个个看着玩。监控工具中的很多数据来自于它们。
|
||||
|
||||
还有两个命令是你在分析MySQL时一定要学会的：`SHOW GLOBAL VARIABLES;`和`SHOW GLOBAL status;`。前一个用来查看配置的参数值，后一个用来查询状态值。当你没有其他工具可用的时候，就可以用这两个命令的输出结果来分析。对于全局监控来说，这两个命令绝对够用。
|
||||
|
||||
对于MySQL的监控工具有很多，但我主要讲的是以下几个工具：<br>
|
||||
mysqlreport、pt-query-digest、mysql_exportor+Prometheus+Grafana。
|
||||
|
||||
今天我们先来说一下mysqlreport。
|
||||
|
||||
## 全局分析：mysqlreport
|
||||
|
||||
这个工具执行之后会生成一个文本文件，在这个文本文件中包括了如下这些内容。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/fb/65/fba573a14508771dd20d78379b704665.png" alt="">
|
||||
|
||||
我觉得这个工具是属于既不浪费资源，又能全局监控MySQL的很好的工具。
|
||||
|
||||
在我们执行性能场景时，如果想让mysqlreport抓取到的数据更为准确，可以先重启一下数据库。如果你觉得重启数据库这个动作实在是有点大，可以先把状态计数器、打开表、查询缓存等数据给刷新一下。
|
||||
|
||||
我认为mysqlreport有一些重要的知识点需要你知道，在这里我找一个例子给你解释一下。
|
||||
|
||||
### 索引报表
|
||||
|
||||
```
|
||||
_ Key _________________________________________________________________
|
||||
Buffer used 5.00k of 8.00M %Used: 0.06
|
||||
Current 1.46M %Usage: 18.24
|
||||
|
||||
```
|
||||
|
||||
请注意，这里所指的Key Buffer是指MyISAM引擎使用的`Shared Key Buffer`，InnoDB所使用的`Key Buffer`不在这里统计。
|
||||
|
||||
从上面的数据来看，MySQL每次分配的`Key Buffer`最大是5K，占8M的0.06%，还是很小的。下一行中的数据可以看到的是当前只用了1.46M，占8M的18.24%。
|
||||
|
||||
显然这个Key Buffer是够用的，如果这个使用率高，你就得增加`key_buffer_size`的值了。
|
||||
|
||||
### 操作报表
|
||||
|
||||
```
|
||||
__ Questions ___________________________________________________________
|
||||
Total 126.82M 32.5/s
|
||||
+Unknown 72.29M 18.5/s %Total: 57.00
|
||||
Com_ 27.63M 7.1/s 21.79
|
||||
DMS 26.81M 6.9/s 21.14
|
||||
COM_QUIT 45.30k 0.0/s 0.04
|
||||
QC Hits 38.18k 0.0/s 0.03
|
||||
Slow 2 s 6.21M 1.6/s 4.90 %DMS: 23.17 Log:
|
||||
DMS 26.81M 6.9/s 21.14
|
||||
SELECT 20.73M 5.3/s 16.34 77.30
|
||||
INSERT 3.68M 0.9/s 2.90 13.71
|
||||
UPDATE 1.43M 0.4/s 1.13 5.33
|
||||
DELETE 983.11k 0.3/s 0.78 3.67
|
||||
REPLACE 0 0/s 0.00 0.00
|
||||
Com_ 27.63M 7.1/s 21.79
|
||||
admin_comma 11.86M 3.0/s 9.35
|
||||
set_option 10.40M 2.7/s 8.20
|
||||
commit 5.15M 1.3/s 4.06
|
||||
|
||||
```
|
||||
|
||||
从这个数据可以看到的信息量就有点大了，它可以反应出来这个数据库现在忙不忙。
|
||||
|
||||
从32.5每秒的操作量上来说，还是有点忙的。你还可以看到下面有操作数的细分，其实我不太愿意看下面的这些细分，描述上除了`QC Hits`和`DMS`的意思比较清晰之外，其他的几个值理解起来比较费劲。我也不建议你看下面那几个，因为它们对性能分析来说没起到什么正向的作用。
|
||||
|
||||
而Slow 那这一行就很重要了，从这行可以看出`slow log`的时间是设置为2秒的，并且每秒还出现1.6个的慢日志，可见这个系统的SQL的慢日志实在是有点多。
|
||||
|
||||
`DMS`部分可以告诉我们这个数据库中各种SQL所占的比例。其实它是具有指向性的，像我们的这个例子中，显然是`SELECT`多，那如果要做SQL优化的话，肯定优先考虑`SELECT`的语句，才会起到立竿见影的效果。
|
||||
|
||||
### 查询和排序报表
|
||||
|
||||
```
|
||||
__ SELECT and Sort _____________________________________________________
|
||||
Scan 7.88M 2.0/s %SELECT: 38.04
|
||||
Range 237.84k 0.1/s 1.15
|
||||
Full join 5.97M 1.5/s 28.81
|
||||
Range check 913.25k 0.2/s 4.41
|
||||
Full rng join 18.47k 0.0/s 0.09
|
||||
Sort scan 737.86k 0.2/s
|
||||
Sort range 56.13k 0.0/s
|
||||
Sort mrg pass 282.65k 0.1/s
|
||||
|
||||
```
|
||||
|
||||
这个报表具有着绝对的问题指向性。这里的`Scan`（全表扫描）和`Full join`（联合全表扫描）在场景执行过程中实在是太多了，这显然是SQL写得有问题。
|
||||
|
||||
Range范围查询很正常，本来就应该多。
|
||||
|
||||
### 查询缓存报表
|
||||
|
||||
```
|
||||
__ Query Cache _________________________________________________________
|
||||
Memory usage 646.11k of 1.00M %Used: 63.10
|
||||
Block Fragmnt 14.95%
|
||||
Hits 38.18k 0.0/s
|
||||
Inserts 1.53k 0.0/s
|
||||
Insrt:Prune 2.25:1 0.0/s
|
||||
Hit:Insert 24.94:1
|
||||
|
||||
```
|
||||
|
||||
在这部分中，我们看的关键点是，`Query Cache`没用！因为各种`query`都没有缓存下来。同时这里我们还要看一个关键值，那就是`Block Fragment`，它是表明`Query Cache`碎片的，值越高，则说明问题越大。
|
||||
|
||||
如果你看到下面这样的数据，就明显没有任何问题。
|
||||
|
||||
```
|
||||
__ Query Cache ______________________________________________________
|
||||
Memory usage 38.05M of 256.00M %Used: 14.86
|
||||
Block Fragmnt 4.29%
|
||||
Hits 12.74k 33.3/s
|
||||
Inserts 58.21k 152.4/s
|
||||
Insrt:Prune 58.21k:1 152.4/s
|
||||
Hit:Insert 0.22:1
|
||||
|
||||
```
|
||||
|
||||
这个数据明显看到缓存了挺多的数据。Hits这一行指的是每秒有多少个SELECT语句从`Query Cache`中取到了数据，这个值是越大越好。
|
||||
|
||||
而通过`Insrt:Prune`的比值数据，我们可以看到Insert远远大于Prune（每秒删除的`Query Cache`碎片)，这个比值越大就说明`Query Cache`越稳定。如果这个值接近1：1那才有问题，这个时候就要加大`Query Cache`或修改你的SQL了。
|
||||
|
||||
而通过下面的`Hit:Insert`的值，我们可以看出命中要少于插入数，说明插入的比查询的还要多，这时就要去看这个性能场景中是不是全是插入了。如果我们查看了，发现SELECT语句还是很多的，而这个比值又是Hit少，那么我们的场景中使用的数据应该并不是插入的数据。其实在性能场景的执行过程中经常这样。所以在性能分析的过程中，我们只要知道这个值就可以了，并不能说明`Query Cache`就是无效的了。
|
||||
|
||||
### 表信息报表
|
||||
|
||||
```
|
||||
__ Table Locks _________________________________________________________
|
||||
Waited 0 0/s %Total: 0.00
|
||||
Immediate 996 0.0/s
|
||||
|
||||
|
||||
__ Tables ______________________________________________________________
|
||||
Open 2000 of 2000 %Cache: 100.00
|
||||
Opened 15.99M 4.1/s
|
||||
|
||||
|
||||
```
|
||||
|
||||
这个很明显了，表锁倒是不存在。但是你看现在`table_open_cache`已经达到上限了，设置为2000，而现在已经达到了2000，同时每秒打开表4.1个。
|
||||
|
||||
这些数据说明了什么呢？首先打开的表肯定是挺多的了，因为达到上限了嘛。这时候你会自然而然地想到去调`table_open_cache`参数。但是我建议你调之前先分析下其他的部分，如果在这个性能场景中，MySQL的整体负载就会比较高，同时也并没有报错，那么我不建议你调这个值。如果负载不高，那再去调它。
|
||||
|
||||
### 连接报表和临时表
|
||||
|
||||
```
|
||||
__ Connections _________________________________________________________
|
||||
Max used 521 of 2000 %Max: 26.05
|
||||
Total 45.30k 0.0/s
|
||||
|
||||
|
||||
__ Created Temp ________________________________________________________
|
||||
Disk table 399.77k 0.1/s
|
||||
Table 5.81M 1.5/s Size: 16.0M
|
||||
File 2.13k 0.0/s
|
||||
|
||||
```
|
||||
|
||||
这个数据连接还完全够用，但是从临时表创建在磁盘（Disk table）和临时文件（File)上的量级来说，还是有点偏大了，所以，可以增大`tmp_table_size`。
|
||||
|
||||
### 线程报表
|
||||
|
||||
```
|
||||
__ Threads _____________________________________________________________
|
||||
Running 45 of 79
|
||||
Cached 9 of 28 %Hit: 72.35
|
||||
Created 12.53k 0.0/s
|
||||
Slow 0 0/s
|
||||
|
||||
|
||||
__ Aborted _____________________________________________________________
|
||||
Clients 0 0/s
|
||||
Connects 7 0.0/s
|
||||
|
||||
|
||||
__ Bytes _______________________________________________________________
|
||||
Sent 143.98G 36.9k/s
|
||||
Received 21.03G 5.4k/
|
||||
|
||||
```
|
||||
|
||||
当Running的线程数超过配置值时，就需要增加`thread_cache_size`。但是从这里来看，并没有超过，当前配置了79，只用到了45。而这里Cached的命中`%Hit`是越大越好，我们通常都希望在99%以上。
|
||||
|
||||
### InnoDB缓存池报表
|
||||
|
||||
```
|
||||
__ InnoDB Buffer Pool __________________________________________________
|
||||
Usage 1.87G of 4.00G %Used: 46.76
|
||||
Read hit 100.00%
|
||||
Pages
|
||||
Free 139.55k %Total: 53.24
|
||||
Data 122.16k 46.60 %Drty: 0.00
|
||||
Misc 403 0.15
|
||||
Latched 0.00
|
||||
Reads 179.59G 46.0k/s
|
||||
From file 21.11k 0.0/s 0.00
|
||||
Ahead Rnd 0 0/s
|
||||
Ahead Sql 0/s
|
||||
Writes 54.00M 13.8/s
|
||||
Flushes 3.16M 0.8/s
|
||||
Wait Free 0 0/s
|
||||
|
||||
```
|
||||
|
||||
这个部分对MySQL来说是很重要的，`innodb_buffer_pool_size`为4G，它会存储表数据、索引数据等。通常在网上或书籍里，你能看到有人建议将这个值设置为物理内存的50%，当然这个值没有绝对的，还要在具体的应用场景中测试才能知道。
|
||||
|
||||
这里的`Read hit`达到100%，这很好。
|
||||
|
||||
下面还有些其他的读写数据，这部分的数据将和我们在操作系统上看到的I/O有很大关系。有些时候，由于写入的过多，导致操作系统的`I/O wait`很高的时候，我们不得不设置`innodb_flush_log_at_trx_commit`参数（0：延迟写，实时刷；1：实时写，实时刷；2：实时写，延迟刷）和`sync_binlog` 参数（0：写入系统缓存，而不刷到磁盘；1：同步写入磁盘；N：写N次系统缓存后执行一次刷新操作）来降低写入磁盘的频率，但是这样做的风险就是当系统崩溃时会有数据的丢失。
|
||||
|
||||
这其实是我们做测试时，存储性能不高的时候常用的一种手段，为了让TPS更高一些。但是，你一定要知道生产环境中的存储是什么样的能力，以确定在生产环境中应该如何配置这个参数。
|
||||
|
||||
### InnoDB锁报表
|
||||
|
||||
```
|
||||
__ InnoDB Lock _________________________________________________________
|
||||
Waits 227829 0.1/s
|
||||
Current 1
|
||||
Time acquiring
|
||||
Total 171855224 ms
|
||||
Average 754 ms
|
||||
Max 6143 ms
|
||||
|
||||
```
|
||||
|
||||
这个信息就有意思了。显然在这个例子中，锁的次数太多了，并且锁的时间都还不短，平均时间都能达到754ms，这显然是不能接受的。
|
||||
|
||||
那就会有人问了，锁次数和锁的平均时间多少才是正常呢？在我的经验中，锁平均时间最好接近零。锁次数可以有，这个值是累加的，所以数据库启动时间长，用得多，锁次数就会增加。
|
||||
|
||||
### InnoDB其他信息
|
||||
|
||||
```
|
||||
__ InnoDB Data, Pages, Rows ____________________________________________
|
||||
Data
|
||||
Reads 35.74k 0.0/s
|
||||
Writes 6.35M 1.6/s
|
||||
fsync 4.05M 1.0/s
|
||||
Pending
|
||||
Reads 0
|
||||
Writes 0
|
||||
fsync 0
|
||||
|
||||
|
||||
Pages
|
||||
Created 87.55k 0.0/s
|
||||
Read 34.61k 0.0/s
|
||||
Written 3.19M 0.8/s
|
||||
|
||||
|
||||
Rows
|
||||
Deleted 707.46k 0.2/s
|
||||
Inserted 257.12M 65.9/s
|
||||
Read 137.86G 35.3k/s
|
||||
Updated 1.13M 0.3/
|
||||
|
||||
```
|
||||
|
||||
这里的数据可以明确告诉你的一点是，在这个性能场景中，插入占有着绝对的量级。
|
||||
|
||||
## 总结
|
||||
|
||||
好了，我们拿一个mysqlreport报表从上到下看了一遍之后，你是不是觉得对MySQL有点感觉了？这里我给一个结论性的描述吧：
|
||||
|
||||
1. 在这个性能场景中，慢日志太多了，需要定向监控看慢SQL，找到慢SQL的执行计划。
|
||||
1. 在这个插入多的场景中，锁等待太多，并且等待的时候又太长，解决慢SQL之后，这里可能会解决，但还是要分析具体的原因的，所以这里也是指向了SQL。
|
||||
|
||||
这里为什么要描述得这么细致呢？主要是因为当你看其他一些工具的监控数据时，分析思路是可以共用的。
|
||||
|
||||
但是有人说这里还有一个问题：SQL怎么看？
|
||||
|
||||
其实对于我们分析的逻辑来说，在数据库中看SQL就是在做定向的分析了。请你不要相信一些人所吹嘘的那样，一开始就把所有的SQL执行时间统计出来，这真的是完全没有必要的做法。因为成本太高了。
|
||||
|
||||
在下一篇文章里，我们换个工具来看看SQL的执行时间到底应该怎么分析。
|
||||
|
||||
## 思考题
|
||||
|
||||
最后给你留两道思考题吧，MySQL中全局监控工具可以给我们提供哪些信息？以及，如何判断MySQL状态值和配置值之间的关系呢？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事。
|
||||
455
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/23丨MySQL：数据库级监控及常用计数器解析（下）.md
Normal file
455
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/23丨MySQL：数据库级监控及常用计数器解析（下）.md
Normal file
@@ -0,0 +1,455 @@
|
||||
<audio id="audio" title="23丨MySQL：数据库级监控及常用计数器解析（下）" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/2c/c7/2cf56c9da1999966de8bbb128e61e3c7.mp3"></audio>
|
||||
|
||||
上一篇文章中，我们讲了有关数据库的全局分析，那么在今天的文章中，我们继续看看在数据库中，如何做定向分析。
|
||||
|
||||
还记得我在上篇文章中提到的工具吗？mysqlreport、pt-query-digest和mysql_exportor+Prometheus+Grafana。我们在上一篇中已经讲完了mysqlreport，今天我们来看看剩下的这几个。
|
||||
|
||||
## 定向抓取SQL：pt-query-digest
|
||||
|
||||
`pt-query-digest`是个挺好的工具，它可以分析`slow log`、`general log`、`binary log`，还能分析tcpdump抓取的MySQL协议数据，可见这个工具有多强大。`pt-query-digest`属于Percona-tool工具集，这个Percona公司还出了好几个特别好使的监控MySQL的工具。
|
||||
|
||||
`pt-query-digest`分析slow log时产生的报告逻辑非常清晰，并且数据也比较完整。执行命令后就会生成一个报告。
|
||||
|
||||
我来稍微解释一下这个报告。我们先看这个报告的第一个部分：
|
||||
|
||||
```
|
||||
# 88.3s user time, 2.5s system time, 18.73M rss, 2.35G vsz
|
||||
# Current date: Thu Jun 22 11:30:02 2017
|
||||
# Hostname: localhost
|
||||
# Files: /Users/Zee/Downloads/log/10.21.0.30/4001/TENCENT64-slow.log.last
|
||||
# Overall: 210.18k total, 43 unique, 0.26 QPS, 0.14x concurrency _________
|
||||
# Time range: 2017-06-12 21:20:51 to 2017-06-22 09:26:38
|
||||
# Attribute total min max avg 95% stddev median
|
||||
# ============ ======= ======= ======= ======= ======= ======= =======
|
||||
# Exec time 118079s 100ms 9s 562ms 2s 612ms 293ms
|
||||
# Lock time 15s 0 7ms 71us 119us 38us 69us
|
||||
# Rows sent 1.91M 0 48.42k 9.53 23.65 140.48 2.90
|
||||
# Rows examine 13.99G 0 3.76M 69.79k 101.89k 33.28k 68.96k
|
||||
# Rows affecte 3.36M 0 1.98M 16.76 0.99 4.90k 0
|
||||
# Query size 102.82M 6 10.96k 512.99 719.66 265.43 719.66
|
||||
|
||||
```
|
||||
|
||||
从上表中可以看得出来，在这个慢日志中，总执行时间达到了118079s，平均执行时间为562ms，最长执行时间为9s，标准方差为612ms。
|
||||
|
||||
可见在此示例中，SQL执行还是有点慢的。
|
||||
|
||||
这时也许会有人问，SQL执行多长时间才是慢呢？之前在一个金融机构，我跟一个做核心系统的团队讨论他们的SQL执行时间指标。他们判断之后说，希望SQL平均执行时间指标定在500ms。我说，你们要500ms，那前面还有一连串的节点才能到达最终的用户，如果每个环节都这样要求自己，那最终的用户不就明显感觉到很慢了吗？
|
||||
|
||||
经过一轮轮的讨论，最后定在了100ms以内。
|
||||
|
||||
其实从我的经验上来看，对于大部分实时的业务，一个SQL执行的平均时间指标定在100ms都多了。但是对性能来说就是这样，在所有的环节中都没有固定的标准，只有经验数据和不断演化的系统性能能力。
|
||||
|
||||
我们再接着分析上面的数据。再来看`pt-query-digest`给出的负载报表：
|
||||
|
||||
```
|
||||
# Profile
|
||||
# Rank Query ID Response time Calls R/Call V/M Item
|
||||
# ==== ================== ================ ====== ====== ===== ===========
|
||||
# 1 0x6A516B681113449F 73081.7989 61.9% 76338 0.9573 0.71 UPDATE mb_trans
|
||||
# 2 0x90194A5C40980DA7 38014.5008 32.2% 105778 0.3594 0.20 SELECT mb_trans mb_trans_finan
|
||||
# 3 0x9B56065EE2D0A5C8 3893.9757 3.3% 9709 0.4011 0.11 UPDATE mb_finan
|
||||
# MISC 0xMISC 3088.5453 2.6% 18353 0.1683 0.0 <40 ITEMS>
|
||||
|
||||
```
|
||||
|
||||
从这个表中可以看到，有两个SQL的执行时间占了总执行时间的94%，显然这两个SQL是要接下来要分析的重点。
|
||||
|
||||
我们再接着看这个工具给出的第一个SQL的性能报表：
|
||||
|
||||
```
|
||||
# Query 1: 0.30 QPS, 0.29x concurrency, ID 0x6A516B681113449F at byte 127303589
|
||||
# This item is included in the report because it matches --limit.
|
||||
# Scores: V/M = 0.71
|
||||
# Time range: 2017-06-16 21:12:05 to 2017-06-19 18:50:59
|
||||
# Attribute pct total min max avg 95% stddev median
|
||||
# ============ === ======= ======= ======= ======= ======= ======= =======
|
||||
# Count 36 76338
|
||||
# Exec time 61 73082s 100ms 5s 957ms 2s 823ms 672ms
|
||||
# Lock time 19 3s 20us 7ms 38us 66us 29us 33us
|
||||
# Rows sent 0 0 0 0 0 0 0 0
|
||||
# Rows examine 36 5.06G 3.82k 108.02k 69.57k 101.89k 22.70k 68.96k
|
||||
# Rows affecte 2 74.55k 1 1 1 1 0 1
|
||||
# Query size 12 12.36M 161 263 169.75 192.76 11.55 158.58
|
||||
# String:
|
||||
# Databases db_bank
|
||||
# Hosts 10.21.16.50 (38297/50%)... 1 more
|
||||
# Users user1
|
||||
# Query_time distribution
|
||||
# 1us
|
||||
# 10us
|
||||
# 100us
|
||||
# 1ms
|
||||
# 10ms
|
||||
# 100ms ################################################################
|
||||
# 1s #########################################
|
||||
# 10s+
|
||||
# Tables
|
||||
# SHOW TABLE STATUS FROM `db_bank` LIKE 'mb_trans'\G
|
||||
# SHOW CREATE TABLE `db_bank`.`mb_trans`\G
|
||||
UPDATE mb_trans
|
||||
SET
|
||||
resCode='PCX00000',resultMes='交易成功',payTranStatus='P03',payRouteCode='CMA'
|
||||
WHERE
|
||||
seqNo='20170619PM010394356875'\G
|
||||
# Converted for EXPLAIN
|
||||
# EXPLAIN /*!50100 PARTITIONS*/
|
||||
select
|
||||
resCode='PCX00000',resultMes='交易成功',payTranStatus='P03',payRouteCode='CMA' from mb_trans where
|
||||
seqNo='20170619PM010394356875'\G
|
||||
|
||||
```
|
||||
|
||||
从查询时间分布图上来看，这个语句的执行时间在100ms~1s之间居多，95%的执行时间在2s以下。那么这个SQL就是我们接下来要调优的重点了。
|
||||
|
||||
第二个SQL我就不赘述了，因为逻辑是完全一样的。
|
||||
|
||||
通过对慢日志的分析，我们可以很快知道哪个SQL是慢的了。当然你用`mysqldumpslow`分析，也会得到一样的结果。
|
||||
|
||||
## SQL剖析：profiling
|
||||
|
||||
在分析数据库的性能时，显然对SQL的分析是绕不过去的一个环节。但是我之前也说过了，上来就对SQL进行全面剖析也是不合逻辑的，因为SQL那么多，如果对每个SQL都进行详细的执行步骤解析，显然会拖慢整个系统，而且，对一些执行快的SQL进行分析也没有什么必要，徒增资源消耗。
|
||||
|
||||
通过上面的分析过程，我们已经定位到了具体是哪个SQL执行得慢，那么下面就是要知道SQL的执行细节。无论是在Oracle还是在MySQL中，我们都要去看执行计划。
|
||||
|
||||
比如说下面这样的：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0d/e6/0dc186fdc3757e4804030a9e19b5a0e6.png" alt="">
|
||||
|
||||
上图中`select_type`是子句类型的意思，有简单有复杂，但是它不能说明什么成本的问题。在这里，最重要的内容是type，因为type可以告诉你访问这个表的时候，是通过什么样的方式访问的。上图中的ALL是全表扫描的意思。type还有如下几个值：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ba/ba/ba8d198f6dc35389a615c8e64b5c6dba.png" alt="">
|
||||
|
||||
执行计划中的`possible_keys`会列出可能使用到的索引值。key这一列会列出执行时使用到的索引值。
|
||||
|
||||
以上信息就是MySQL的执行计划中比较重要的部分了。这些信息可以帮助我们做SQL的分析，为优化提供证据。
|
||||
|
||||
除了执行计划外，MySQL还提供了`profiling`，这个有什么用呢？它可以把SQL执行的每一个步骤详细列出来，从一个SQL进入到数据库中，到执行完这整个生命周期。
|
||||
|
||||
MySQL的`profiling`在`session`级生效，所以当你用了慢日志，知道哪个SQL有问题之后，再用这个功能是最见成效的。如果想一开始就把所有`session`的`SQL profiling`功能打开，那成本就太高了。
|
||||
|
||||
下面我来详细解释一下profiling的用法和功能。
|
||||
|
||||
### profiling操作步骤
|
||||
|
||||
profiling的操作步骤比较简单，如下所示：
|
||||
|
||||
```
|
||||
步骤一 ：set profiling=1; //这一步是为了打开profiling功能
|
||||
步骤二 ：执行语句 //执行你从慢日志中看到的语句
|
||||
步骤三 ：show profiles; //这一步是为了查找步骤二中执行的语句的ID
|
||||
步骤四 ：show profile all for query id; //这一步是为了显示出profiling的结果
|
||||
|
||||
```
|
||||
|
||||
我们实际执行一下上面的步骤：
|
||||
|
||||
```
|
||||
// 步骤一：打开profiling功能
|
||||
mysql> set profiling=1;
|
||||
Query OK, 0 rows affected, 1 warning (0.00 sec)
|
||||
// 这一步只是为了确认一下profiles列表有没有值，可以不用执行。
|
||||
mysql> show profiles;
|
||||
Empty set, 1 warning (0.00 sec)
|
||||
// 步骤二：执行语句
|
||||
mysql> select * from t_user where user_name='Zee0355916';
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| id | user_number | user_name | org_id | email | mobile | create_time |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:19:32 |
|
||||
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:08:34 |
|
||||
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 13:42:31 |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
3 rows in set (14.33 sec)
|
||||
// 步骤三：查看profiles列表中，有了我们刚才执行的语句
|
||||
mysql> show profiles;
|
||||
+----------+-------------+---------------------------------------------------+
|
||||
| Query_ID | Duration | Query |
|
||||
+----------+-------------+---------------------------------------------------+
|
||||
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
|
||||
+----------+-------------+---------------------------------------------------+
|
||||
1 row in set, 1 warning (0.00 sec)
|
||||
// 步骤四：看这个语句的profile信息
|
||||
mysql> show profile all for query 1;
|
||||
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
|
||||
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
| starting | 0.000024 | 0.000012 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
|
||||
| Waiting for query cache lock | 0.000004 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| init | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| checking query cache for query | 0.000052 | 0.000036 | 0.000015 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
|
||||
| checking permissions | 0.000007 | 0.000005 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
|
||||
| Opening tables | 0.000032 | 0.000023 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5095 |
|
||||
| init | 0.000042 | 0.000029 | 0.000013 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_prepare_select | sql_select.cc | 1051 |
|
||||
| System lock | 0.000016 | 0.000011 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 304 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| System lock | 0.000020 | 0.000014 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| optimizing | 0.000012 | 0.000009 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 139 |
|
||||
| statistics | 0.000019 | 0.000013 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 365 |
|
||||
| preparing | 0.000015 | 0.000010 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 488 |
|
||||
| executing | 0.000004 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 110 |
|
||||
| Sending data | 14.324781 | 4.676869 | 0.762349 | 1316 | 132 | 2499624 | 288 | 0 | 0 | 8 | 30862 | 0 | exec | sql_executor.cc | 190 |
|
||||
| end | 0.000015 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_select | sql_select.cc | 1106 |
|
||||
| query end | 0.000006 | 0.000005 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5015 |
|
||||
| closing tables | 0.000016 | 0.000013 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5063 |
|
||||
| freeing items | 0.000013 | 0.000010 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2 | 0 | mysql_parse | sql_parse.cc | 6490 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| freeing items | 0.000014 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| freeing items | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| storing result in query cache | 0.000004 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | end_of_result | sql_cache.cc | 1034 |
|
||||
| logging slow query | 0.015645 | 0.000084 | 0.000020 | 2 | 0 | 16 | 8 | 0 | 0 | 0 | 2 | 0 | log_slow_do | sql_parse.cc | 1935 |
|
||||
| cleaning up | 0.000034 | 0.000024 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
|
||||
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
26 rows in set, 1 warning (0.02 sec)
|
||||
|
||||
```
|
||||
|
||||
非常长，从这样的数据中，我们就看到了一个语句在数据库中从开始到结束的整个生命周期。
|
||||
|
||||
对生命周期中的每个步骤进行统计之后，我们就可以看到每个步骤所消耗的时间。不仅如此，还能看到如下这些信息：
|
||||
|
||||
- BLOCK IO
|
||||
- Context Switches
|
||||
- CPU
|
||||
- IPC
|
||||
- MEMORY
|
||||
- Page Fault
|
||||
- SOURCE
|
||||
- SWAPS
|
||||
|
||||
有了这些信息，我们基本上就可以判断语句哪里有问题了。
|
||||
|
||||
从上面这个示例语句中，你可以看到`Sending data`这一步消耗了14秒的时间，并且从后面的数据中，也可以看到主动上下文切换有1316次，被动的有132次，块操作的量也非常大。
|
||||
|
||||
碰到这样的情况，我们就得先知道这个`Sending data`到底是什么东西。下面我们结合之前说的到的执行计划，一起看一下：
|
||||
|
||||
```
|
||||
mysql> explain select * from t_user where user_name='Zee0355916';
|
||||
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
|
||||
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
||||
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
|
||||
| 1 | SIMPLE | t_user | ALL | NULL | NULL | NULL | NULL | 3868195 | Using where |
|
||||
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
|
||||
1 row in set (0.00 sec)
|
||||
|
||||
```
|
||||
|
||||
这就是个典型的全表扫描，所以下一步就是检查有没有创建索引。
|
||||
|
||||
```
|
||||
mysql> show indexes from t_user;
|
||||
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
|
||||
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
|
||||
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
|
||||
| t_user | 0 | PRIMARY | 1 | id | A | 3868195 | NULL | NULL | | BTREE | | |
|
||||
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
|
||||
1 row in set (0.00 sec)
|
||||
|
||||
|
||||
mysql>
|
||||
|
||||
```
|
||||
|
||||
还是有一个主键索引的，但由于我们没用主键来查，所以用不到。
|
||||
|
||||
有些性能测试工程师面对这种情况可能会有这种想法：第一次没有查索引，但是把所有数据都调到缓存里了呀，所以第二次就快了嘛，于是有些人可能想尽快“完成”工作，就用重复的数据。
|
||||
|
||||
这里我再执行一遍，你可以看看是什么结果：
|
||||
|
||||
```
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| Query_ID | Duration | Query |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
|
||||
| 2 | 0.00006675 | show profile all for 1 |
|
||||
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|
||||
| 4 | 0.00040025 | show indexes from t_user |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
6 rows in set, 1 warning (0.00 sec)
|
||||
|
||||
|
||||
mysql> select * from t_user where user_name='Zee0355916';
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| id | user_number | user_name | org_id | email | mobile | create_time |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:19:32 |
|
||||
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:08:34 |
|
||||
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 13:42:31 |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
3 rows in set (0.00 sec)
|
||||
|
||||
|
||||
mysql> show profiles;
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| Query_ID | Duration | Query |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
|
||||
| 2 | 0.00006675 | show profile all for 1 |
|
||||
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|
||||
| 4 | 0.00040025 | show indexes from t_user |
|
||||
| 5 | 0.00027325 | select * from t_user where user_name='Zee0355916' |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
7 rows in set, 1 warning (0.00 sec)
|
||||
|
||||
|
||||
mysql> show profile all for query 5;
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
|
||||
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
|
||||
| starting | 0.000029 | 0.000018 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
|
||||
| Waiting for query cache lock | 0.000006 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| init | 0.000003 | 0.000003 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| checking query cache for query | 0.000008 | 0.000006 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
|
||||
| checking privileges on cached | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1692 |
|
||||
| checking permissions | 0.000010 | 0.000192 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
|
||||
| sending cached result to clien | 0.000210 | 0.000028 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | send_result_to_client | sql_cache.cc | 1803 |
|
||||
| cleaning up | 0.000006 | 0.000006 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
|
||||
8 rows in set, 1 warning (0.00 sec)
|
||||
|
||||
|
||||
mys
|
||||
|
||||
|
||||
```
|
||||
|
||||
看到没有，在用重复数据的时候确实会让响应时间快很多，因为数据直接从`cache`中发给`client`了。
|
||||
|
||||
但是，这种作法请你坚决制止，因为它不符合真实生产的样子。当你再换一个数据的时候，就会歇菜，还要再经过14秒的时间做全表扫描。
|
||||
|
||||
所以正确的做法是创建合适的索引，让语句在执行任何一条数据时都能快起来，那么，我们现在就创建一个索引，再看执行结果。
|
||||
|
||||
```
|
||||
// 创建索引
|
||||
mysql> ALTER TABLE t_user ADD INDEX username_idx (user_name);
|
||||
Query OK, 0 rows affected (44.69 sec)
|
||||
Records: 0 Duplicates: 0 Warnings: 0
|
||||
// 分析表
|
||||
mysql> analyze table t_user;
|
||||
+-----------+---------+----------+----------+
|
||||
| Table | Op | Msg_type | Msg_text |
|
||||
+-----------+---------+----------+----------+
|
||||
| pa.t_user | analyze | status | OK |
|
||||
+-----------+---------+----------+----------+
|
||||
1 row in set (0.08 sec)
|
||||
// 执行语句
|
||||
mysql> select * from t_user where user_name='Zee0046948';
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| id | user_number | user_name | org_id | email | mobile | create_time |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
| 000061a2-31c2-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-08 10:53:08 |
|
||||
| 047d7ae1-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 13:36:42 |
|
||||
| 1abfa543-318f-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-08 04:48:48 |
|
||||
| 671c4014-3222-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-08 22:23:12 |
|
||||
| 9de16dd3-32a5-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:02:28 |
|
||||
| dd4ab182-32a4-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 13:57:05 |
|
||||
| f507067e-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-09 14:12:04 |
|
||||
| f7b82744-3185-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | test9495@dunshan.com | 17600009498 | 2020-01-08 03:43:24 |
|
||||
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
|
||||
8 rows in set (0.02 sec)
|
||||
// 查看Query_ID
|
||||
mysql> show profiles;
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| Query_ID | Duration | Query |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
|
||||
| 2 | 0.00006675 | show profile all for 1 |
|
||||
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
|
||||
| 4 | 0.00005875 | show indexes for table t_user |
|
||||
| 5 | 0.00005850 | show indexes for t_user |
|
||||
| 6 | 0.00040025 | show indexes from t_user |
|
||||
| 7 | 0.00027325 | select * from t_user where user_name='Zee0355916' |
|
||||
| 8 | 0.00032100 | explain select * from t_user where user_name='Zee0355916' |
|
||||
| 9 | 12.22490550 | select * from t_user where user_name='Zee0046945' |
|
||||
| 10 | 0.00112450 | select * from t_user limit 20 |
|
||||
| 11 | 44.68370500 | ALTER TABLE t_user ADD INDEX username_idx (user_name) |
|
||||
| 12 | 0.07385150 | analyze table t_user |
|
||||
| 13 | 0.01516450 | select * from t_user where user_name='Zee0046948' |
|
||||
+----------+-------------+-----------------------------------------------------------+
|
||||
13 rows in set, 1 warning (0.00 sec)
|
||||
// 查看profile信息
|
||||
mysql> show profile all for query 13;
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
| starting | 0.000030 | 0.000017 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
|
||||
| Waiting for query cache lock | 0.000005 | 0.000004 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| init | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| checking query cache for query | 0.000060 | 0.000050 | 0.000011 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
|
||||
| checking permissions | 0.000009 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
|
||||
| Opening tables | 0.000671 | 0.000412 | 0.000000 | 1 | 0 | 8 | 0 | 0 | 0 | 0 | 1 | 0 | open_tables | sql_base.cc | 5095 |
|
||||
| init | 0.006018 | 0.000082 | 0.000899 | 1 | 0 | 5408 | 0 | 0 | 0 | 1 | 0 | 0 | mysql_prepare_select | sql_select.cc | 1051 |
|
||||
| System lock | 0.000017 | 0.000011 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 304 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000003 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| System lock | 0.000019 | 0.000015 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| optimizing | 0.000012 | 0.000010 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 139 |
|
||||
| statistics | 0.001432 | 0.000167 | 0.000037 | 1 | 0 | 32 | 0 | 0 | 0 | 0 | 4 | 0 | optimize | sql_optimizer.cc | 365 |
|
||||
| preparing | 0.000026 | 0.000043 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | optimize | sql_optimizer.cc | 488 |
|
||||
| executing | 0.000034 | 0.000005 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 110 |
|
||||
| Sending data | 0.006727 | 0.000439 | 0.001111 | 13 | 0 | 1536 | 0 | 0 | 0 | 0 | 1 | 0 | exec | sql_executor.cc | 190 |
|
||||
| end | 0.000014 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_select | sql_select.cc | 1106 |
|
||||
| query end | 0.000009 | 0.000008 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5015 |
|
||||
| closing tables | 0.000015 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5063 |
|
||||
| freeing items | 0.000010 | 0.000008 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 6490 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| freeing items | 0.000027 | 0.000022 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| freeing items | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
|
||||
| storing result in query cache | 0.000004 | 0.000004 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | end_of_result | sql_cache.cc | 1034 |
|
||||
| cleaning up | 0.000015 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
|
||||
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|
||||
25 rows in set, 1 warning (0.01 sec)
|
||||
|
||||
|
||||
mysql>
|
||||
|
||||
```
|
||||
|
||||
从上面最后的profile信息你可以看出来，步骤一点没少，但是速度快了很多，这才是正确的优化思路。
|
||||
|
||||
在上一篇文章中，我描述了在一个数据库中，如何从全局监控的角度查看数据，今天讲的是如何找到具体慢的SQL，以及如何定位这个SQL的问题。
|
||||
|
||||
当然不是所有的情况下，都是SQL的问题，也有可能是配置的问题，也有可能是硬件的问题。不管什么样的问题，其分析思路都是这样的，也就是我总是在强调的：全局监控-定向监控。
|
||||
|
||||
当然，在这里我也应该给出MySQL分析决策树的思路。从`mysqlreport`的划分上，给出几个具体的分析决策树的树枝。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/5b/27/5b9c8e2f05ee467ffc834dad86dcb927.png" alt="">
|
||||
|
||||
这是常见的问题，如果你有兴趣，可以自己完善这棵完整的树，因为你可能会有不一样的划分计数器的工具或思路，所以这个树是可以灵活变化的。
|
||||
|
||||
你一定要记得，别人给你的东西，永远变不成自己的东西，它们只能引导你。如果你自己动手去做一遍，哪怕只画出一个分枝来，都会是很大的进步。
|
||||
|
||||
如果你想用其他的全局监控工具，也可以考虑如下的组合，也就是mysql_exportor+Prometheus+Grafana。
|
||||
|
||||
## mysql_exportor+Prometheus+Grafana
|
||||
|
||||
我在前面也屡次提到过这类组合，不同的exportors结合Prometheus+Grafana，可以实现实时监控及数据的保存。
|
||||
|
||||
在这里我们看一下`mysql_exportor`可以给我们提供什么样的监控数据。这里截几个图，给你大概看一下这个套装工具能看什么内容，有兴趣的话，你也可以自己搭建一下。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d9/ac/d96a58c12ab279375d976f27ff17acac.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/29/a1/292761d3463870e0fe3a0b05a502d6a1.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/95/73/959feaeacefe12129a9337eee5e1c073.png" alt="">
|
||||
|
||||
## 总结
|
||||
|
||||
有关数据库的知识实在是太多了，在这两篇文章中，我重点想告诉你的，就是分析数据库应该具有的思路。至于其他的知识点，我想应该是你打开文章之前就应该储备的东西。
|
||||
|
||||
我们再来总结一下，在数据库的分析中，最有可能在三个方面出现问题：
|
||||
|
||||
1. 硬件配置
|
||||
1. 数据库配置
|
||||
1. SQL语句
|
||||
|
||||
对于硬件配置来说，我们只能在解决了2和3的问题之后，再来评估到底多少硬件够用的。而面对数据库配置问题，这个实在没什么好招，只能去了解数据库架构等一系列的知识之后，再学着解决。而SQL的问题呢，应该说是我们在性能测试和分析中最常见的了。SQL性能问题的分析思路也比较清晰，那就是判断出具体的SQL瓶颈点，进而做相应的优化，切记不要蒙！
|
||||
|
||||
现在的数据库类别比之前多太多了，每种数据库都有自己的架构和使用场景，我们要在充分了解了之后，才能下手去调。
|
||||
|
||||
## 思考题
|
||||
|
||||
我在这里照例留两个问题。你能说一下数据库分析的大体思路是什么吗？如何在数据库中迅速找到一个慢SQL的根本原因呢？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
245
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/24丨Kafka：性能监控工具之队列级监控及常用计数器解析.md
Normal file
245
极客时间专栏/性能测试实战30讲/第三模块：性能监控分析工具篇/24丨Kafka：性能监控工具之队列级监控及常用计数器解析.md
Normal file
@@ -0,0 +1,245 @@
|
||||
<audio id="audio" title="24丨Kafka：性能监控工具之队列级监控及常用计数器解析" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/a8/86/a8c27f0ac42253f1b1fbbedda3675b86.mp3"></audio>
|
||||
|
||||
在我看来队列服务器是最简单的一种组件了。因为队列给我们下手的机会实在是并不多。我们只是用它，如果想改变它就只能去改代码，其他的都只是配置问题。
|
||||
|
||||
在当前的市场中，Kafka算是用得非常火的一个队列服务器了，所以今天，我选择它来做一些解读。
|
||||
|
||||
虽然我在前面一直在强调分析的思路，但在这一篇中，我打算换个思路，不是像以前那样，直接给你一个结论型的思维导图，而是一起来分析一个组件，让我们看看从哪里下手，来观察一个被分析对象的相关配置。
|
||||
|
||||
## 了解Kafka的基本知识
|
||||
|
||||
我们先看一下这张图，以便更好地了解一个队列服务器。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/65/87/659043d7a680bd0cb5df070e0ecec687.jpg" alt="">
|
||||
|
||||
这是Kafka官网上的一个图。从这个图中可以看到，对Kafka来说，这就像一个典型的集线器。那它里面的结构是什么样子的呢？根据我的理解，我画了一个如下的示意图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d5/30/d59231449717009067723332de568130.png" alt="">
|
||||
|
||||
在这个图中，有三个Broker，也就是三个集群节点。每个消息有一个leader partition，还有两个follower partition。我没有画更多的Producer和Consumer、Consumer Group，是觉得线太多了容易乱。
|
||||
|
||||
因为Producer和Consumer肯定会从leader partition中读写数据，而Kafka也保证了leader在不同broker上的均衡，所以Kafka的集群能力很好。
|
||||
|
||||
我们再看一下消息是如何在Kafka中被存储的。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/20/72/2047c0b11c63407a8ebfb696398b0272.png" alt="">
|
||||
|
||||
上图是Kafka数据的存储方式，也就是每个分区都是一直往后面加的。
|
||||
|
||||
我们再来看一下它的数据存储方式。
|
||||
|
||||
首先是目录：
|
||||
|
||||
```
|
||||
drwxr-xr-x 2 root root 4096 Feb 7 23:39 test-0
|
||||
drwxr-xr-x 2 root root 4096 Feb 7 01:34 test_perf-1
|
||||
drwxr-xr-x 2 root root 4096 Feb 7 01:34 test_perf-4
|
||||
|
||||
```
|
||||
|
||||
Kafka的目录是根据topic创建的，每个目录名中也包括一个partition。比如上面名字中的test_perf-1就是topic名是test_perf，partition就是1。
|
||||
|
||||
接着再来看下文件：
|
||||
|
||||
```
|
||||
[root@node-2 test-2]# ll
|
||||
total 10850656
|
||||
-rw-r--r-- 1 root root 493128 Feb 9 14:14 00000000000000000000.index
|
||||
-rw-r--r-- 1 root root 1073739646 Feb 9 14:14 00000000000000000000.log
|
||||
-rw-r--r-- 1 root root 630504 Feb 9 14:14 00000000000000000000.timeindex
|
||||
-rw-r--r-- 1 root root 443520 Feb 9 14:16 00000000000000240212.index
|
||||
-rw-r--r-- 1 root root 1073727327 Feb 9 14:16 00000000000000240212.log
|
||||
-rw-r--r-- 1 root root 551052 Feb 9 14:16 00000000000000240212.timeindex
|
||||
-rw-r--r-- 1 root root 448840 Feb 9 14:18 00000000000000453584.index
|
||||
-rw-r--r-- 1 root root 1073729759 Feb 9 14:18 00000000000000453584.log
|
||||
-rw-r--r-- 1 root root 556920 Feb 9 14:18 00000000000000453584.timeindex
|
||||
.........................
|
||||
-rw-r--r-- 1 root root 12 Feb 9 13:14 leader-epoch-checkpoint
|
||||
[root@node-2 test-2]#
|
||||
|
||||
```
|
||||
|
||||
有索引文件，有数据文件，也有时间索引文件，非常明显的三个后缀名。索引文件显然就是指向message在数据文件中的什么位置，而这些数据文件就是一个个的Segment，也就是一段一段的。这些文件的大小受server.properties文件中的log.segment.bytes参数限制，默认为1G。
|
||||
|
||||
要查到相应的message就要先查索引文件，找到message的位置；然后从log文件中找到具体的message。
|
||||
|
||||
在这个逻辑中，Segment的大小就很有讲究了，太细就会导致索引文件过大，查找索引费时间；太粗了就会导致查找得不够精准。那么该如何配置呢？也要通过性能测试才能知道。
|
||||
|
||||
有了这些信息之后，我们再看下Kafka高效的原因：
|
||||
|
||||
1. Kafka直接使用Linux文件系统的Cache来高效缓存数据。
|
||||
1. Kafka采用Linux Zero-Copy技术提高发送性能（不懂Linux Zero-copy的请自行补课）。
|
||||
1. Kafka服务端采用的是selector多线程模式（从逻辑上理解，它和Tomcat的NIO类似，我就不单独画图了，以免占篇幅）。
|
||||
1. Kafka采用二分法找数据。
|
||||
|
||||
总体来说，就是一个Java的应用，直接使用文件系统和操作系统的特性实现了队列的高效应用场景。
|
||||
|
||||
## 配置文件
|
||||
|
||||
我们先来查看一下Kafka的配置文件中都有什么，为了简洁，在这里，我把一些注释以及和性能无关的配置删除了。当然如果你有兴趣的话，可以到Kafka的config目录中找到server.properties中，以查看这些内容。
|
||||
|
||||
```
|
||||
############################# Socket Server Settings #############################
|
||||
num.network.threads=3
|
||||
num.io.threads=8
|
||||
socket.send.buffer.bytes=102400
|
||||
socket.receive.buffer.bytes=102400
|
||||
socket.request.max.bytes=104857600
|
||||
|
||||
|
||||
############################# Log Basics #############################
|
||||
num.partitions=10
|
||||
num.recovery.threads.per.data.dir=1
|
||||
|
||||
|
||||
############################# Internal Topic Settings #############################
|
||||
offsets.topic.replication.factor=1
|
||||
transaction.state.log.replication.factor=1
|
||||
transaction.state.log.min.isr=1
|
||||
|
||||
|
||||
############################# Log Flush Policy #############################
|
||||
log.flush.interval.messages=10000
|
||||
log.flush.interval.ms=1000
|
||||
|
||||
|
||||
############################# Log Retention Policy #############################
|
||||
log.retention.check.interval.ms=300000
|
||||
|
||||
|
||||
############################# Zookeeper #############################
|
||||
zookeeper.connection.timeout.ms=6000
|
||||
|
||||
|
||||
############################# Group Coordinator Settings #############################
|
||||
group.initial.rebalance.delay
|
||||
|
||||
|
||||
```
|
||||
|
||||
其实配置文件并不多，对不对？从配置名称上也很容易知道它们和什么相关。这里比较重要的参数就是Socket Server相关的，以及和log相关的。
|
||||
|
||||
我觉得到了这里，这个逻辑就基本清楚了，对Kafka的性能优化也就有了大体的判断。
|
||||
|
||||
## 构建Kafka的性能优化思维导图
|
||||
|
||||
我们可以根据以上的知识画出如下所示的，Kafka的基本优化点：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/b2/db/b2b0ad6f744035d26d5efab25d4ec9db.png" alt="">
|
||||
|
||||
同样的，我把操作系统和JDK方面的优化当成独立的部分，在上图中只把Kafka相关的内容列出来。
|
||||
|
||||
有了上面的知识，也有了这个思维逻辑，那么就可以理出针对一个Kafka应用要干的事情：
|
||||
|
||||
1. 先分析一下具体的应用场景，关键是topic、partition数量、message大小。
|
||||
1. 确定要支撑的业务容量和时间长度。
|
||||
1. 分析架构中需要的broker量级、partition、Segment等配置。这些配置应该是架构师给出的准确预估，如果不能给出，那只能靠我们，也就是做性能测试的人给出具体的结论了。
|
||||
|
||||
## 对组件的性能分析思路
|
||||
|
||||
我想告诉你的是对一个组件的性能分析思路。如果你有了下面这张图所示的思路，那至少可以覆盖大部分的性能问题了。这个思路就是：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/62/ab/625d1ec2717f84cb2dc9119d8c7e43ab.jpg" alt="">
|
||||
|
||||
对于Kafka这样的队列服务器来说，状态计数器是啥子呢？让我们看一下Kafka的一个Grafana Dashboard。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f0/d7/f0025246911a11e34d0608e607669ad7.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f9/1d/f9cefe3ff768fe06662a3ab26aca6c1d.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/35/37/35319958007c7fbcb2332cc920af7837.png" alt="">
|
||||
|
||||
从这几个图就能看得出来，最重要的是每秒产生了多少message，以及消费时间间隔。这两个对我们来说是最重要的队列计数器了。
|
||||
|
||||
但是它们能不能告诉我们现在的队列服务器有没有瓶颈呢？显然是不能的。
|
||||
|
||||
对于队列来说，消息都是异步被消费者取走的。所以队列中要有保存消息的能力，但是保存多久呢？永远保存吗？显然不现实。但是如果保存得太短了，正常的业务都可能做不下去，所以，我们要制定策略，哪些topic是实时处理的，处理不完怎么办？内存多大，能保存多少消息，积压了怎么办？
|
||||
|
||||
所以对于队列服务器，只看上面的那几个计数器，我觉得过于片面。
|
||||
|
||||
我们前面提到的grafana+prometheus监控操作系统、MySQL的DashBoard都有非常完整的数据，但是Kafka的DashBoard显然信息不够，不能判断它自己有没有问题。
|
||||
|
||||
操作系统的监控指标对Kafka来说，也是异常的重要。就像之前我说过的那样，操作系统是不可绕过的分析节点。所以所有要做性能测试和性能分析的人，首先要学的就是操作系统方面的知识。
|
||||
|
||||
## 示例
|
||||
|
||||
下面我们来看一个简单测试示例。
|
||||
|
||||
### 生产10W消息
|
||||
|
||||
在这个示例中，共生产10W的消息，每个消息大小是2000字节，每秒产生5000个消息。
|
||||
|
||||
```
|
||||
[root@node-1 Kafka_2.13-2.4.0]# /home/zee/Kafka/Kafka_2.13-2.4.0/bin/Kafka-producer-perf-test.sh --topic test --num-records 100000 --record-size 2000 --throughput 5000 --producer-props bootstrap.servers=172.18.0.2:9092,172.19.0.14:9092,172.20.0.7:9092
|
||||
24997 records sent, 4999.4 records/sec (9.54 MB/sec), 15.8 ms avg latency, 398.0 ms max latency.
|
||||
25010 records sent, 5001.0 records/sec (9.54 MB/sec), 26.0 ms avg latency, 514.0 ms max latency.
|
||||
25000 records sent, 5000.0 records/sec (9.54 MB/sec), 1.1 ms avg latency, 24.0 ms max latency.
|
||||
100000 records sent, 4998.000800 records/sec (9.53 MB/sec), 11.03 ms avg latency, 514.00 ms max latency, 1 ms 50th, 52 ms 95th, 305 ms 99th, 501 ms 99.9th.
|
||||
|
||||
```
|
||||
|
||||
可以看到每秒有9.53MB的消息产生，平均响应时延是11.03ms，最大时延是514ms。
|
||||
|
||||
### 生产100W消息
|
||||
|
||||
在这个示例中，共生产100W的消息，每个消息大小是2000字节，每秒产生5000个消息。
|
||||
|
||||
```
|
||||
[root@node-4 bin]# /home/zee/Kafka/Kafka_2.13-2.4.0/bin/Kafka-producer-perf-test.sh --topic test_perf --num-records 1000000 --record-size 2000 --throughput 5000 --producer-props bootstrap.servers=172.17.0.11:9092,172.19.0.14:9092,172.20.0.7:9092
|
||||
24992 records sent, 4996.4 records/sec (9.53 MB/sec), 21.7 ms avg latency, 482.0 ms max latency.
|
||||
25025 records sent, 5004.0 records/sec (9.54 MB/sec), 0.9 ms avg latency, 16.0 ms max latency.
|
||||
........
|
||||
25000 records sent, 5000.0 records/sec (9.54 MB/sec), 0.6 ms avg latency, 9.0 ms max latency.
|
||||
25005 records sent, 5001.0 records/sec (9.54 MB/sec), 0.7 ms avg latency, 30.0 ms max latency.
|
||||
1000000 records sent, 4999.625028 records/sec (9.54 MB/sec), 2.05 ms avg latency, 482.00 ms max latency, 1 ms 50th, 1 ms 95th, 16 ms 99th, 267 ms 99.9th.
|
||||
|
||||
```
|
||||
|
||||
可以看到每秒有9.54MB的消息产生，平均响应时延是2.05ms，最大时延是482ms。
|
||||
|
||||
### 生产1000W消息
|
||||
|
||||
在这个示例中，生产1000W消息，其他参数不变：
|
||||
|
||||
```
|
||||
[root@node-4 bin]# /home/zee/Kafka/Kafka_2.13-2.4.0/bin/Kafka-producer-perf-test.sh --topic test_perf --num-records 10000000 --record-size 2000 --throughput 5000 --producer-props bootstrap.servers=172.17.0.11:9092,172.19.0.14:9092,172.20.0.7:9092
|
||||
24992 records sent, 4998.4 records/sec (9.53 MB/sec), 22.7 ms avg latency, 480.0 ms max latency.
|
||||
25015 records sent, 5002.0 records/sec (9.54 MB/sec), 0.8 ms avg latency, 13.0 ms max latency.
|
||||
25005 records sent, 5000.0 records/sec (9.54 MB/sec), 0.7 ms avg latency, 21.0 ms max latency.
|
||||
..........
|
||||
25000 records sent, 5000.0 records/sec (9.54 MB/sec), 0.7 ms avg latency, 26.0 ms max latency.
|
||||
25010 records sent, 5001.0 records/sec (9.54 MB/sec), 0.7 ms avg latency, 24.0 ms max latency.
|
||||
10000000 records sent, 4999.900002 records/sec (9.54 MB/sec), 0.83 ms avg latency, 532.00 ms max latency, 1 ms 50th, 1 ms 95th, 4 ms 99th, 65 ms 99.9th.
|
||||
|
||||
```
|
||||
|
||||
从结果可以看到，每秒还是9.54MB大小的消息，平均时延0.83ms，最大时延是532ms。
|
||||
|
||||
来做一个图比对一下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e4/8f/e4f416d4dc41898ad5dd264d9e022f8f.jpg" alt="">
|
||||
|
||||
从这个图就明显看出生产的消息越少，平均响应时间越长。可见顺序写得越多，那每次写的平均时间就会越小，所以Kafka在大数据量的读写中会表现得非常好。
|
||||
|
||||
## 总结
|
||||
|
||||
严格来说，这一篇文章是为了告诉你一个逻辑，那就是对一个组件不了解的时候，如何用你的基础技术知识把对组件的性能优化方向整理出来，以及如何通过自己的基础知识来做一个非常合理的分析。
|
||||
|
||||
这个逻辑就是：
|
||||
|
||||
1. 先了解这个组件的基本知识：包括架构、实现原理等信息。
|
||||
1. 再整理出这个组件的配置参数。
|
||||
1. 找到合适的全局监控工具。
|
||||
1. 做压力测试时给出明显的判断。
|
||||
|
||||
这是个大体的逻辑，当然这个逻辑还有一个前提，那就是你得有相应的基础知识，在Kafka的这个分析中，要有操作系统和Java的基础知识，在实操中还需要多找几个不懂的组件做些练习才能理解这个逻辑的真谛。
|
||||
|
||||
就我自己来说，我会找一个完全没有接触过的组件，从安装部署开始直到性能测试、瓶颈判断、优化分析，看看需要多长时间，我才能理解得了这个组件。
|
||||
|
||||
这种思维方式，给了我很多的安全感，就是遇到了没接触过的内容，也不至心慌气短。
|
||||
|
||||
## 思考题
|
||||
|
||||
最后给你留两道思考题吧，你觉得如何分析一个未知组件呢？Kafka的分析逻辑又是什么？
|
||||
|
||||
欢迎你用自己的理解思考一下这两个问题，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
@@ -0,0 +1,266 @@
|
||||
<audio id="audio" title="25丨SkyWalking：性能监控工具之链路级监控及常用计数器解析" controls="" preload="none"><source id="mp3" src="https://static001.geekbang.org/resource/audio/42/39/4294a5192a112952a55b6c547ddb4739.mp3"></audio>
|
||||
|
||||
在微服务横行的年代，没有链路级监控简直就是灾难。技术在不断的发展过程中，总是会有新的工具被推出来，它们存在的价值就是解决问题。链路监控工具存在的价值就是尽快找到微服务中哪一个环节是最慢的。
|
||||
|
||||
## 我们对微服务的态度究竟是怎样的？
|
||||
|
||||
但是在讲链路级监控之前，我需要再说一下我们对微服务的态度。
|
||||
|
||||
我们认为微服务性能好，具有良好的扩展性，于是很多企业会把自己的架构改为微服务，但是呢，在不需要使用新技术的系统中，盲目地迷信和使用市场上被推崇的新技术，只会带来问题。
|
||||
|
||||
在前面我举过一个例子，我见过一个物流项目，开发团队认为拆分服务是可以让性能提高的一个重要技术思路，于是他们不断地细分项目。在不到百万级的车辆体量的项目阶段中，一个物流系统已经被拆分成了三四十个子项目，最后开发团队和运维团队都不堪重负，因为维护的成本变高了。于是，开发团队开始反省，认为应该合并一些子项目，最后就形成了中台项目。
|
||||
|
||||
这不是玩笑，而是一个真实的案例。
|
||||
|
||||
至于项目能不能拆分成多个微服务，你需要对整个项目的容量、硬件的体量进行评估。如果评估完觉得不需要，那么尽量不要干这种为了炫耀技术，而害人害已害公司的事情。如果确实有需要，那没什么说的，该拆就拆。
|
||||
|
||||
但是在拆的过程也一定要知道，对于多个微服务来说，相关的支持手段（比如说服务健康状态、链路跟踪、日志收集分析系统等）一定要跟上，如果跟不上，那就是灾难了。
|
||||
|
||||
## 链路级监控对微服务的重要作用
|
||||
|
||||
在微服务架构的系统中，没有好的链路监控工具，对性能分析来说就是灾难，因为体力活实在是太多了。这就是链路级监控在微服务中存在的价值了。
|
||||
|
||||
特别是现在Kubernetes+Docker的基础架构也在不断地被应用。微服务往里面一放，有问题想查都不知道从哪下手。因为容器出现问题被重启之后，可能你都不知道问题在哪个node上，只能通过Kubernetes先查在哪个node上，再查相应的日志等信息，这样就增加了很多工作量。
|
||||
|
||||
说回我们的链路监控，在一个合理的微服务架构中，一开始的架构规划就应该包括**链路监控**。可以用开源的，可以用商业的，也可以自己编写度量器做埋点。总之不管怎么实现，只要实现了就好。
|
||||
|
||||
常见的链路监控工具，我们都称之为APM（Application Performance Management或者 Application Performance Monitoring），而这些APM工具都是参考2010年Google的一个论文来做的。这篇有名的论文就叫Dapper, a Large-Scale Distributed Systems Tracing Infrastructure，点击[原文链接](https://static.googleusercontent.com/media/research.google.com/zh-CN//archive/papers/dapper-2010-1.pdf)就能看到。在[Github](http://bigbully.github.io/Dapper-translation/)上有人翻译成中文，有兴趣的话，你可以去看看。
|
||||
|
||||
在商业市场当然有很多APM工具可以使用了。在这里，我就不给它们打广告了。重点推荐几个开源的好用的工具，它们分别是Pinpoint、SkyWalking、Zipkin、CAT。
|
||||
|
||||
我们简单比对一下：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/00/ec/00da4e47a7582892f174ef56a14974ec.png" alt="">
|
||||
|
||||
每个产品都有自己的特点，产品之间也有细微的差别。网络上也有人对这几个工具做过测试比对，得到的结论是每个产品对性能的影响都在10%以下，其中SkyWalking对性能的影响最小。
|
||||
|
||||
在今天的内容里，我之所以用SkyWalking说明链路监控，原因只有一个：中国开发者贡献的，必须得支持！
|
||||
|
||||
## SkyWalking的链路关系
|
||||
|
||||
为了说明链路的调用逻辑，我这里准备了几个非常简单的Spring Cloud应用。在这个示例中，我有四个服务。这四个服务会有相互的调用关系。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/3d/fd/3d360a1f864a63beb56d6df6a48837fd.jpg" alt="">
|
||||
|
||||
其中用户可以直接访问Project A、B、C、D中的任何一个服务。同时这些服务器都会注册到Eureka中去，它们也会分别连Redis、RabbitMQ、MySQL等服务。
|
||||
|
||||
我们来看看SkyWalking是怎么体现链路关系的。
|
||||
|
||||
### 启动微服务Project A
|
||||
|
||||
首先我们启动Project A。为了让你能清晰地看到配置，我直接把Agent放到执行的命令行中。如下所示：
|
||||
|
||||
```
|
||||
nohup java -javaagent:/data/pa/agent/skywalking-agent.jar -jar -Xms128m -Xmx128m /data/pb/target/pa.jar --spring.profiles.active=prod &
|
||||
|
||||
```
|
||||
|
||||
接着我们访问Project A，通过Postman来访问这个示例提供的接口：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d8/19/d887718f0b2511be71f1c3061aa83b19.png" alt="">
|
||||
|
||||
然后我们再来查看SkyWalking首页：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/05/86/053cf7f2346f3fb05f0c12e4acebfa86.png" alt="">
|
||||
|
||||
最后我们查看拓扑图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/14/c2/143e70a5238c6ba767991825c6d85bc2.png" alt="">
|
||||
|
||||
从上面这张拓扑图中可以看到，当我访问了pa之后，这个pa链接了另外两个系统，一个是Eureka，另一个是MySQL。
|
||||
|
||||
加了Agent之后，至少我们可以看到这个服务现在在访问谁了。但是因为只有一个服务，所以还看不出来链路在哪里，现在我们启动Project B。
|
||||
|
||||
### 启动微服务Project B
|
||||
|
||||
首先启动Project B：
|
||||
|
||||
```
|
||||
nohup java -javaagent:/data/pb/agent/skywalking-agent.jar -jar -Xms128m -Xmx128m /data/pb/target/pb.jar --spring.profiles.active=prod &
|
||||
|
||||
|
||||
```
|
||||
|
||||
接着查看SkyWalking的拓扑图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/ed/15/edfb755d468433cfbf9735306f38cc15.png" alt="">
|
||||
|
||||
你可以看到pb（即Project B）服务上有一个有一个问号，因为它还没有被人访问过。不过已经连上了Eureka，所以和Eureka之间有条线。
|
||||
|
||||
然后我们使用Postman访问Project B：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/7e/96/7ea431e5f3a5d0e2f49d704dca5a2896.png" alt="">
|
||||
|
||||
请注意，这里我直接访问了Project B，并没有通过Project A访问。
|
||||
|
||||
然后我们再来查看一下拓扑图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c7/8f/c7e905ed7296388a10fd29d6b815498f.png" alt="">
|
||||
|
||||
现在可以看到上图中User和pb（即Project B）之间有连线了吧。
|
||||
|
||||
这还只是单独的访问逻辑。
|
||||
|
||||
### 通过Project A访问Project B
|
||||
|
||||
首先我们使用Postman访问pab接口：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/53/5e/5377ae9bc4a60f713700f20658ae855e.png" alt="">
|
||||
|
||||
注意，这里我通过Project A访问了Project B。
|
||||
|
||||
我们再来看拓扑图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/46/19/4630ef49ac30f0943f8958277a9d7a19.png" alt="">
|
||||
|
||||
看到了吧，pa（即Project A）和pb（即Project B）之间有连接线了。这就是SkyWalking的trace功能了。
|
||||
|
||||
下面我将Project C、Project D都启动，也都串行访问一下，即pa-pb-pc-pd。
|
||||
|
||||
我们通过拓扑图看下时间消耗，启动其他微服务并查看各服务响应时间。
|
||||
|
||||
首先，pa-pb-pc-pd串行访问：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/8f/71/8f27d67d1dc65eb48414a1145e87a471.png" alt="">
|
||||
|
||||
然后我们查看一下链路拓扑图：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/43/db/435a7ac22eff0682d62547db8b4fb8db.png" alt="">
|
||||
|
||||
这样，我们就看到了pa-pb-pc-pd的一条完整的链路。因为我们在前面直接访问了pb，所以可以看到user到pb之间也有连线。
|
||||
|
||||
当然SkyWaling的功能不止是拓扑图。我们来看一个拓扑图的全部界面。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/f3/64/f3b516d8f8d418090cf83b444287d064.png" alt="">
|
||||
|
||||
从上图就可以看到，当你点击两个服务之间连线上的那个蓝色点的时候，在右边会显示一个状态曲线。在这个状态曲线中，我们可以看到这两个服务之间的平均吞吐量（cpm）和平均响应时间（ms）。这样，我们就知道在这个链路上哪里消耗了时间。
|
||||
|
||||
现在，让我们来点一下看看。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/0a/e5/0afbb66d97e28edf9af009765ff41fe5.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/9f/18/9f7e41b15ad4b0b799f90628e78d3b18.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/77/b0/77942028f01c7997032a776b76d82db0.png" alt="">
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/e9/7c/e9b333d1c31a800d9c578f34f075347c.png" alt="">
|
||||
|
||||
通过这四个图，就能看到在每一个服务节点上，响应时间消耗了多少。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/9d/74/9db63d6ed5b16a3e620182e9064f9174.jpg" alt=""><br>
|
||||
通过上面的时间，显然也可以算出每个服务自己消耗了多少时间。用前面的时间减去后面的时间，就可以算出来，很简单吧。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/c4/ae/c45e2d986d9a8702c5e8075b72ba92ae.jpg" alt="">
|
||||
|
||||
上面的User是通过公网访问的，所以这里的时间也包括了网络的时间，不是说ProjectA上就会消耗600多ms。
|
||||
|
||||
## 追踪请求
|
||||
|
||||
从上面的图中，我们可以看到服务之间的整体性能表现，但是一个具体的请求节点是哪些，并体现不出来。SkyWalking提供了追踪功能，可以看到一个请求被拆分成了哪些子请求。如下所示：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/d1/ed/d17ca0617189e0308511cbd3f234c6ed.png" alt="">
|
||||
|
||||
通过追踪页面，我们可以看到请求都已经按照响应时间的高低排好序了，点击就可以看到这个请求的拆分以及拆分的每个子请求所消耗的时间。
|
||||
|
||||
此外它还提供了树结构。
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/89/01/89bfe5390b04c5e3eb1786ca72531601.png" alt="">
|
||||
|
||||
这样一来，调用过程清晰明了。
|
||||
|
||||
下面我们就压起来，通过SkyWalking来判断下性能瓶颈，以确定它在性能测试和分析中的作用。
|
||||
|
||||
这个场景是用JMeter来压pabcd接口，以此查看SkyWalking可以给我们一个什么样的结果。
|
||||
|
||||
JMeter结果如下：
|
||||
|
||||
```
|
||||
[root@7dgroup2 script]# /home/gaolou/apache-jmeter-5.1.1/bin/jmeter -n -t pabcddemo.jmx
|
||||
Creating summariser <summary>
|
||||
Created the tree successfully using pabcddemo.jmx
|
||||
Starting the test @ Wed Feb 12 02:21:47 CST 2020 (1581445307090)
|
||||
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
|
||||
summary + 165 in 00:00:12 = 13.8/s Avg: 69 Min: 36 Max: 153 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0
|
||||
summary + 687 in 00:00:30 = 22.9/s Avg: 59 Min: 26 Max: 206 Err: 0 (0.00%) Active: 2 Started: 2 Finished: 0
|
||||
summary = 852 in 00:00:42 = 20.3/s Avg: 61 Min: 26 Max: 206 Err: 0 (0.00%)
|
||||
summary + 1182 in 00:00:30 = 39.4/s Avg: 60 Min: 24 Max: 240 Err: 0 (0.00%) Active: 3 Started: 3 Finished: 0
|
||||
summary = 2034 in 00:01:12 = 28.3/s Avg: 60 Min: 24 Max: 240 Err: 0 (0.00%)
|
||||
summary + 1717 in 00:00:30 = 57.3/s Avg: 58 Min: 18 Max: 238 Err: 0 (0.00%) Active: 4 Started: 4 Finished: 0
|
||||
summary = 3751 in 00:01:42 = 36.8/s Avg: 59 Min: 18 Max: 240 Err: 0 (0.00%)
|
||||
summary + 2148 in 00:00:30 = 71.7/s Avg: 60 Min: 13 Max: 509 Err: 0 (0.00%) Active: 5 Started: 5 Finished: 0
|
||||
summary = 5899 in 00:02:12 = 44.7/s Avg: 60 Min: 13 Max: 509 Err: 0 (0.00%)
|
||||
summary + 2105 in 00:00:30 = 70.1/s Avg: 76 Min: 16 Max: 507 Err: 0 (0.00%) Active: 6 Started: 6 Finished: 0
|
||||
summary = 8004 in 00:02:42 = 49.4/s Avg: 64 Min: 13 Max: 509 Err: 0 (0.00%)
|
||||
summary + 2090 in 00:00:30 = 69.6/s Avg: 91 Min: 15 Max: 507 Err: 0 (0.00%) Active: 7 Started: 7 Finished: 0
|
||||
summary = 10094 in 00:03:12 = 52.6/s Avg: 70 Min: 13 Max: 509 Err: 0 (0.00%)
|
||||
summary + 2093 in 00:00:30 = 69.8/s Avg: 105 Min: 17 Max: 987 Err: 0 (0.00%) Active: 8 Started: 8 Finished: 0
|
||||
summary = 12187 in 00:03:42 = 54.9/s Avg: 76 Min: 13 Max: 987 Err: 0 (0.00%)
|
||||
summary + 2080 in 00:00:30 = 69.4/s Avg: 120 Min: 10 Max: 1135 Err: 0 (0.00%) Active: 9 Started: 9 Finished: 0
|
||||
summary = 14267 in 00:04:12 = 56.6/s Avg: 82 Min: 10 Max: 1135 Err: 0 (0.00%)
|
||||
summary + 2074 in 00:00:30 = 69.1/s Avg: 136 Min: 11 Max: 961 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 16341 in 00:04:42 = 58.0/s Avg: 89 Min: 10 Max: 1135 Err: 0 (0.00%)
|
||||
summary + 2057 in 00:00:30 = 68.6/s Avg: 144 Min: 9 Max: 1237 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 18398 in 00:05:12 = 59.0/s Avg: 95 Min: 9 Max: 1237 Err: 0 (0.00%)
|
||||
summary + 2063 in 00:00:30 = 68.7/s Avg: 145 Min: 9 Max: 1123 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 20461 in 00:05:42 = 59.8/s Avg: 100 Min: 9 Max: 1237 Err: 0 (0.00%)
|
||||
summary + 2058 in 00:00:30 = 68.6/s Avg: 145 Min: 8 Max: 1113 Err: 0 (0.00%) Active: 10 Started: 10 Finished: 0
|
||||
summary = 22519 in 00:06:12 = 60.5/s Avg: 104 Min: 8 Max: 1237 Err: 0 (0.00%)
|
||||
..................
|
||||
|
||||
```
|
||||
|
||||
为了不占篇幅，这里我把后面的部分截掉了，因为后面的10个线程的数据和上面的10个线程的数据差不多。
|
||||
|
||||
从JMeter的结果中可以看到，当线程增加的时候，确实响应时间也在不断增加。下面我们来看一下SkyWalking中的健康状态。
|
||||
|
||||
### Service Dashboard：
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/63/30/63a26cea45c00be9e904622c6ec3ee30.png" alt=""><br>
|
||||
在Service DashBoard中，你可以看到热力图，也就是在哪个时间段微服务比较繁忙，也可以看到微服务吞吐量的排序和慢端点的排序。
|
||||
|
||||
通过这个图，我们可以很快定位到哪个服务的哪个接口慢。图中直接就给出来了。
|
||||
|
||||
在Service DashBoard中，你还可以选择当前服务、当前端点和当前实例。
|
||||
|
||||
它们之间的关系是什么呢？实例就是一个具体的进程，服务是微服务的名字，至于端点，那就是接口了。你可以在多个主机上执行同样的微服务，那么每个主机上启动的就是具体的实例，有着共同的功能。
|
||||
|
||||
### Database Dashboard
|
||||
|
||||
<img src="https://static001.geekbang.org/resource/image/92/f2/92f2dcf95925aaba1fb4d063ecfdd1f2.png" alt="">
|
||||
|
||||
在Database Dashboard中，你可以看到数据库的处理能力——数据库的吞吐能力、SQL的执行时间百分比，以及哪些SQL慢。
|
||||
|
||||
通过这个图，我们可以直接判断出，现在数据库服务在压力下的处理能力。比如说我的这个示例：明显的就是压力上来了之后，数据库的SQL执行时间变长了。
|
||||
|
||||
在左下角的图中可以看到，90%的SQL在250ms左右，99%的SQL在压力下处于500ms以下。
|
||||
|
||||
这就是明显要调优的SQL，因为一个select，还是精确查找，怎么可能这么慢。
|
||||
|
||||
在右下角可以直接看到哪个SQL慢，这就可以用到前面文章中提到的数据库剖析功能了。
|
||||
|
||||
## 总结
|
||||
|
||||
对微服务来说，链路监控工具是标配。在性能分析中，需要查看微服务的性能状态时必须用到链路监控工具。
|
||||
|
||||
我们用APM工具要实现的就是以下四点：
|
||||
|
||||
1. 查看微服务节点的健康状态。
|
||||
1. 判断响应时间的消耗点。
|
||||
1. 通过我们前文中提到的**定向监控手段**进行详细地问题定位，细化到组件的配置、代码行和SQL层级。
|
||||
1. 最后根据定位的根本原因，提出具体的性能瓶颈解决方案。
|
||||
|
||||
从上面的步骤就可以看出，从性能瓶颈的判断逻辑上，APM工具给我们提供了很多便利。但是，APM工具也不能告诉你性能瓶颈的根本原因，因此还是需要定向分析来做细化。这也是我一直推崇的，创建性能瓶颈分析决策树，要有完整的逻辑思路的原因。
|
||||
|
||||
## 一个小声明
|
||||
|
||||
后续的一篇文章原计划是《性能分析之CPU分析：从CPU调用高到具体代码行》。可是想来想去，这里面的内容在整个专栏中的多篇文章中均有涉及，你可以参考《[CentOS：操作系统级监控及常用计数器解析](https://time.geekbang.org/column/article/191503)》《[Java & C++：代码级监控及常用计数器解析](https://time.geekbang.org/column/article/193551)》这两篇文章。
|
||||
|
||||
至于分析决策树，我在《[倾囊相授：我毕生所学的性能分析思路都在这里了](https://time.geekbang.org/column/article/182912)》中也都已经提到。
|
||||
|
||||
基于此，我认为没必要单独再写一篇文章凑篇幅，所以后面将跳过这一篇，请知悉。
|
||||
|
||||
## 思考题
|
||||
|
||||
了解了今天的内容后，你可以说一下APM工具可以为我们提供哪些分析便利吗？SkyWalking有哪些具体的功能点可以帮助我们进行性能分析呢？
|
||||
|
||||
欢迎你在评论区写下你的思考，也欢迎把这篇文章分享给你的朋友或者同事，一起交流一下。
|
||||
Reference in New Issue
Block a user