好多天没写实施日记了,这段时间,我也有些其他事情要做,因为前阵子答应了写些东西,所以这几天晚上弄到两三点,终于写完了五万字的东西交了差。
这一段时间是培训的课程关键内容,基本都是分析的关键环节。主要的分析思路仍然是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 Mem
PID 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 java
4710 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 java
5909 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 java
1450 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_exporter
7768 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 java
39 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 java
1 root 20 0 52812 3988 1528 S 0.7 0.0 43:10.60 systemd
6739 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/297525
Children 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 Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6542 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 prometheus
615 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 java
969 root 20 0 2006656 98540 32740 S 1.3 0.6 17:11.97 containerd
1216 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、压力线程之间的转换关系,也是要经过严格计算的。
在这些知识点的充分理解和执行之下,才有可能做出完美的性能项目。
在这段时间中,我们也有学员非常主动,自己也完全手工搭建庞大的测试环境,以便理解分析逻辑。
这是基本功。虽然不会搭建也是可以学习性能分析逻辑的,但是如果动手搭建的话,从理解上就会完全不一样了,会提升一个层级。
我希望学员可以理清思路,走上真正的性能分析道路,把优化效果的价值体现出来。
相关系列:
- 7DGroup性能实施项目日记1
- 7DGroup性能实施项目日记2
- 7DGroup性能实施项目日记3
- 7DGroup性能实施项目日记4
- 7DGroup性能实施项目日记5
- 7DGroup性能实施项目日记6
- 7DGroup性能实施项目日记7
- 7DGroup性能实施项目日记8
- 7DGroup性能实施项目日记9