7DGroup性能实施项目日记9

好多天没写实施日记了，这段时间，我也有些其他事情要做，因为前阵子答应了写些东西，所以这几天晚上弄到两三点，终于写完了五万字的东西交了差。

这一段时间是培训的课程关键内容，基本都是分析的关键环节。主要的分析思路仍然是RESAR性能分析七步法。

跟着这个思路把所有的接口都用基准场景分析一遍。

为了让环境中出现更多的可分析的问题。我们的学员们搭建了一套最原始的应用代码。在这套代码中，几乎每个接口都有性能问题。所以是一个练手的好项目。

像这样的情况：

比比皆是。当我们看到这样的情况时，需要的是一步步地判断出问题在哪里。

通常监控工具给出这样的红色警告时，也只能是知道大体哪个服务器出现了问题，但是这不足以让我们判断问题是什么。这是全局监控可以告诉我们的，而定向监控是让我们找到根本原因的，所以要进入这个机器去查看更细的数据。

top - 08:25:49 up 19 days, 23:37,  1 user,  load average: 6.93, 4.62, 2.51
Tasks: 242 total,   1 running, 241 sleeping,   0 stopped,   0 zombie
%Cpu0  : 41.2 us, 20.1 sy,  0.0 ni, 37.4 id,  0.0 wa,  0.0 hi,  1.4 si,  0.0 st
%Cpu1  : 31.5 us, 20.9 sy,  0.0 ni, 47.3 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu2  : 39.7 us, 21.0 sy,  0.0 ni, 38.3 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
%Cpu3  : 30.4 us, 19.8 sy,  0.0 ni, 49.1 id,  0.0 wa,  0.0 hi,  0.7 si,  0.0 st
%Cpu4  : 39.7 us, 19.9 sy,  0.0 ni, 39.7 id,  0.0 wa,  0.0 hi,  0.7 si,  0.0 st
%Cpu5  : 30.0 us, 21.5 sy,  0.0 ni, 47.8 id,  0.0 wa,  0.0 hi,  0.7 si,  0.0 st
%Cpu6  : 41.0 us, 20.3 sy,  0.0 ni, 33.4 id,  0.0 wa,  0.0 hi,  5.2 si,  0.0 st
%Cpu7  : 34.6 us, 20.1 sy,  0.0 ni, 44.3 id,  0.3 wa,  0.0 hi,  0.7 si,  0.0 st
KiB Mem : 16265592 total,   309672 free, 12787200 used,  3168720 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2284988 avail MemPID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                                                                                                                                   28352 root      20   0 9838.1m   1.9g   7640 S 219.6 12.3   1128:06 java4710 root      20   0 1874064  87764  10168 S 130.9  0.5 526:30.47 containerd                                                                                                                                                                                                                                                28060 root      20   0  712640   6992   3060 S  76.4  0.0  44:56.95 containerd-shim
13485 1001      20   0   17.4g 158408   4736 S  16.3  1.0 324:59.43 java                                                                                                                                                                                                                                                      10680 1001      20   0 6867304 984.6m   6852 S   7.3  6.2 170:32.20 java5909 root      20   0 2152364 109368  19292 S   7.0  0.7   1143:26 kubelet                                                                                                                                                                                                                                                   29009 root      20   0 8109832   1.1g  10068 S   5.3  7.3  89:34.59 java1450 root      10 -10  218072  33204   6148 S   4.0  0.2 690:11.54 AliYunDun                                                                                                                                                                                                                                                  6998 65534     20   0  719412  19852   4524 S   3.7  0.1 159:25.53 node_exporter7768 root      20   0 9850256 745992   4988 S   3.0  4.6 405:03.94 java
34870 root      20   0 1970232  31504  12380 S   3.0  0.2 170:16.71 calico-node
52779 root      20   0 9958104   1.0g   6092 S   3.0  6.5 428:17.16 java39 root      20   0       0      0      0 S   1.3  0.0   5:13.77 ksoftirqd/6
64520 root      20   0 9988776   1.4g   6056 S   1.0  9.1 105:13.75 java1 root      20   0   52812   3988   1528 S   0.7  0.0  43:10.60 systemd6739 1000      20   0 8258792 442808  10564 S   0.7  2.7  54:02.29 java
32870 1000      20   0 6536936   1.3g   9512 S   0.7  8.4 152:21.97 java
63323 root      20   0  162360   2536   1612 R   0.7  0.0   0:08.11 top
65164 1000      20   0 1503844 393800   6364 S   0.7  2.4  84:12.83 node```

看到这样的数据之后，还要进一步判断，如果sy cpu高，我通常是会去看cpu热点的。

Samples: 892K of event 'cpu-clock', 4000 Hz, Event count (approx.): 105440194773 lost: 0/0 drop: 19853/297525Children      Self  Shared Object                                                           Symbol
-   22.94%     1.93%  [kernel]                                                                [k] system_call                                                 ◆- 3.15% system_call                                                                                                                                        ▒- 2.20% sys_write                                                                                                                                       ▒- 2.08% vfs_write                                                                                                                                    ▒- 1.73% do_sync_write                                                                                                                             ▒- 1.54% pipe_write                                                                                                                             ▒
+   14.22%     0.00%  [kernel]                                                                [k] do_softirq                                                  ▒
+   14.13%     0.03%  perf                                                                    [.] ordered_events__flush                                       ▒
+   13.59%     0.02%  perf                                                                    [.] hist_entry_iter__add                                        ▒
+   13.51%     2.63%  [kernel]                                                                [k] __do_softirq                                                ▒
+   10.83%     0.23%  [kernel]                                                                [k] sys_write                                                   ▒
+   10.13%    10.13%  [kernel]                                                                [k] _raw_spin_unlock_irqrestore                                 ▒
+   10.00%     0.04%  containerd                                                              [.] github.com/containerd/containerd/pkg/cri/io.redirectLogs    ▒
+    9.90%     0.15%  [kernel]                                                                [k] vfs_write                                                   ▒
+    8.96%     0.26%  [kernel]                                                                [k] do_sync_write                                               ▒
+    8.29%     0.11%  containerd                                                              [.] github.com/containerd/containerd/pkg/cri/io.redirectLogs.fun▒
+    7.07%     0.87%  containerd                                                              [.] syscall.Syscall.abi0                                        ▒
+    6.67%     0.00%  perf-28352.map                                                          [.] 0x00007f0130289c06          

从热点上可以看出sy cpu消耗的原因。

当然也会看到这种情况。

top - 08:42:11 up 17:22,  1 user,  load average: 20.50, 7.99, 6.19
Tasks: 220 total,   2 running, 218 sleeping,   0 stopped,   0 zombie
%Cpu0  : 98.3 us,  0.3 sy,  0.0 ni,  1.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  : 98.3 us,  0.7 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu2  : 98.7 us,  0.7 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  : 98.7 us,  0.7 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu4  : 98.3 us,  0.7 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu5  : 98.7 us,  0.7 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu6  : 99.0 us,  0.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.7 si,  0.0 st
%Cpu7  : 99.7 us,  0.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 16265592 total,   993540 free,  9788672 used,  5483380 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  6088020 avail MemPID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND6542 1001      20   0 5785516 630748  13244 S 758.9  3.9 360:15.02 mysqld
46631 1000      20   0 7060812   1.6g 213256 S  14.6 10.4 111:42.06 prometheus615 root      20   0 2785824 128860  37536 S   3.6  0.8  45:34.58 kubelet
37829 root      20   0 8075908   1.1g  22108 S   2.6  6.9  18:46.63 java
21909 1000      20   0 5398160   1.3g  23024 S   1.7  8.4   8:35.88 java969 root      20   0 2006656  98540  32740 S   1.3  0.6  17:11.97 containerd1216 root      10 -10  214852  40280  16460 S   1.3  0.2  29:20.38 AliYunDun
19233 1000      20   0 6206584   1.3g  23676 S   1.0  8.5   6:21.62 java

---ts=2022-11-08 00:36:02;thread_name=http-nio-8085-exec-25;id=117;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@25567581`---[185.983454ms] com.dunshan.mall.portal.service.impl.OmsCartItemServiceImpl$$EnhancerBySpringCGLIB$$cd2e3e20:list()`---[99.99% 185.971347ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()`---[99.99% 185.952096ms ] com.dunshan.mall.portal.service.impl.OmsCartItemServiceImpl:list()+---[0.00% 0.003533ms ] com.dunshan.mall.model.OmsCartItemExample:<init>() #76+---[0.00% 0.003134ms ] com.dunshan.mall.model.OmsCartItemExample:createCriteria() #77+---[0.00% 0.004088ms ] com.dunshan.mall.model.OmsCartItemExample$Criteria:andDeleteStatusEqualTo() #77+---[0.00% 0.00294ms ] com.dunshan.mall.model.OmsCartItemExample$Criteria:andMemberIdEqualTo() #77`---[99.98% 185.905947ms ] com.dunshan.mall.mapper.OmsCartItemMapper:selectByExample() #78`---ts=2022-11-08 00:36:02;thread_name=http-nio-8085-exec-28;id=11a;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@25567581`---[187.017573ms] com.dunshan.mall.portal.service.impl.OmsCartItemServiceImpl$$EnhancerBySpringCGLIB$$cd2e3e20:list()`---[99.99% 187.004684ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()`---[99.99% 186.988005ms ] com.dunshan.mall.portal.service.impl.OmsCartItemServiceImpl:list()+---[0.00% 0.004173ms ] com.dunshan.mall.model.OmsCartItemExample:<init>() #76+---[0.00% 0.00325ms ] com.dunshan.mall.model.OmsCartItemExample:createCriteria() #77+---[0.00% 0.003512ms ] com.dunshan.mall.model.OmsCartItemExample$Criteria:andDeleteStatusEqualTo() #77+---[0.00% 0.003019ms ] com.dunshan.mall.model.OmsCartItemExample$Criteria:andMemberIdEqualTo() #77`---[99.98% 186.945735ms ] com.dunshan.mall.mapper.OmsCartItemMapper:selectByExample() #78

在这样的分析过程中，可以看到io问题、sql问题、代码逻辑问题等等。例子太过，不一而足。

而我们的要做的就是一步步的找到这些问题，并给出优化方案，像上面的例子中，我们要把sql和io的问题解决，解决的方式要根据瓶颈的原因来提出解决方案。像记日志、加索引、平衡资源等手段也都是要上的。

最终我们希望看到的是这样的情况。

其实瓶颈的解决通常都是不难的，难的是怎么快速判断出瓶颈在哪里。

tps的提升是性能要解决的瓶颈类型中的一种，还有这种。

tps并不低，但是会掉下来。在这个例子中，因为缓存的节点的问题，导致缓存失效，当缓存节点在其他节点自动重建时，tps就恢复了。当解决了这样的失效问题之后，就会得到稳定的tps。

作为性能分析人员，你是无法预料会发生什么问题的，也无法判断还有哪些没有解决的问题。

所以容量场景要满足生产的业务模型是非常重要的场景设计前提。这一点在我们的培训过程中也是不停在强调的。包括：在线用户数、并发用户数、并发度、tps、压力线程之间的转换关系，也是要经过严格计算的。

在这些知识点的充分理解和执行之下，才有可能做出完美的性能项目。

在这段时间中，我们也有学员非常主动，自己也完全手工搭建庞大的测试环境，以便理解分析逻辑。

这是基本功。虽然不会搭建也是可以学习性能分析逻辑的，但是如果动手搭建的话，从理解上就会完全不一样了，会提升一个层级。

我希望学员可以理清思路，走上真正的性能分析道路，把优化效果的价值体现出来。

相关系列：