业务逻辑复杂如何解决性能问题

news2024/10/7 14:32:50

0 前言

上节针对生成订单信息这个接口做了三个阶段的分析定位和优化动作,让TPS变得正常。不过,系统资源并没有完全用起来,这个接口显然还有优化空间。性能优化的过程中,要把资源都用起来。

在性能环境中做优化,把资源用起来是为了看系统的最大容量在哪里。这并不意味着,你可以在生产环境中让硬件使用到这种程度。

对于一个不可控的系统容量来说,资源使用率高,极有可能导致各种问题出现。所以,安全稳妥起见,很多生产环境的资源利用率都是非常低的,倘若用得超过20%,运维都得半夜惊出一身冷汗。

而我们在性能环境中的测试结果,要想给生产环境配置个明确且可借鉴的结论,就必须先去分析生产的业务容量,然后再来确定当生产业务容量达到峰值的时候,相应的硬件资源用到多少比较合理。

不过,在我们的优化环境中,可通过把一个系统用起来,来判断软件的容量能力。所以,接着上节内容,来第四阶段。你将看到在业务逻辑复杂的情况下,我们该怎么做优化。

1 第四阶段

现在正常分析时间消耗到哪去了,解决快慢问题,才能进而解决资源没用起来的问题。

1.1 拆分响应时间

之前都用APM拆分响应时间,这次用日志拆分时间。

  • Gateway:
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 151 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 147 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 141 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 122 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 125 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 150 ms
10.100.79.93 - - [04/Feb/2021:00:13:17 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 200 726 8201 177 ms
  • Order:
10.100.79.106 - - [04/Feb/2021:00:13:31 +0800] "POST /order/generateOrder HTTP/1.1" 200 738 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 72 ms 72 ms
10.100.79.106 - - [04/Feb/2021:00:13:31 +0800] "POST /order/generateOrder HTTP/1.1" 200 738 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 94 ms 93 ms
10.100.79.106 - - [04/Feb/2021:00:13:31 +0800] "POST /order/generateOrder HTTP/1.1" 200 738 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 76 ms 76 ms
10.100.79.106 - - [04/Feb/2021:00:13:31 +0800] "POST /order/generateOrder HTTP/1.1" 200 738 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 95 ms 95 ms
10.100.79.106 - - [04/Feb/2021:00:13:31 +0800] "POST /order/generateOrder HTTP/1.1" 200 738 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 90 ms 90 ms

先不用看后面的服务,因为从这个接口往后就直接到数据库,先看应用本身有没有问题。

这里只截取部分数据,但并不是说我们只看这些就够。在项目中的话,可通过写脚本或其他的方式自己做响应时间的统计。

从上面的信息可看,这接口的整个响应时间150ms,而在order服务上就消耗90毫秒。所以,下面我们要分析:为什么在order上会消耗这么久的时间。

1.2 定向监控分析

想知道Order服务的时间消耗,得知道Order应用中的线程都在做什么动作,先直接分析Order的栈。

Spring Boot Admin查看线程的整体状态:

线程确实繁忙。至于这些线程在做什么,通过栈的内容可知,再确定优化方向。

但由于系统资源还没用到上限,先调整Tomcat线程数,加大些,争取让Order应用把硬件资源用起来。

原值:
max: 20
修改为:
max: 100

调整后结果:

性能更差……事实证明,偷懒绕不过坑,只有再次查看响应时间消耗到哪。

通过用各个服务的日志拆分响应时间,发现在Member服务有这样日志(为让你看清楚,截取一些时间消耗较大的日志,这是改Order的Tomcat线程池后的结果):

10.100.69.248 - - [04/Feb/2021:00:37:15 +0800] "GET /sso/feign/info HTTP/1.1" 200 814 "-" "okhttp/3.14.8" 2348 ms 2348 ms
10.100.69.248 - - [04/Feb/2021:00:37:17 +0800] "GET /sso/feign/info HTTP/1.1" 200 816 "-" "okhttp/3.14.8" 4155 ms 4155 ms
10.100.69.248 - - [04/Feb/2021:00:37:17 +0800] "GET /sso/feign/info HTTP/1.1" 200 817 "-" "okhttp/3.14.8" 4968 ms 1813 ms
10.100.69.248 - - [04/Feb/2021:00:37:15 +0800] "GET /sso/feign/info HTTP/1.1" 200 810 "-" "okhttp/3.14.8" 2333 ms 2333 ms
10.100.69.248 - - [04/Feb/2021:00:37:17 +0800] "GET /sso/feign/info HTTP/1.1" 200 815 "-" "okhttp/3.14.8" 5206 ms 4970 ms
10.100.69.248 - - [04/Feb/2021:00:37:20 +0800] "GET /sso/feign/info HTTP/1.1" 200 818 "-" "okhttp/3.14.8" 6362 ms 6362 ms
10.100.69.248 - - [04/Feb/2021:00:37:20 +0800] "GET /sso/feign/info HTTP/1.1" 200 818 "-" "okhttp/3.14.8" 6710 ms 6710 ms
10.100.69.248 - - [04/Feb/2021:00:37:20 +0800] "GET /sso/feign/info HTTP/1.1" 200 817 "-" "okhttp/3.14.8" 6696 ms 6587 ms
10.100.69.248 - - [04/Feb/2021:00:37:21 +0800] "GET /sso/feign/info HTTP/1.1" 200 813 "-" "okhttp/3.14.8" 7987 ms 7976 ms
10.100.69.248 - - [04/Feb/2021:00:37:22 +0800] "GET /sso/feign/info HTTP/1.1" 200 814 "-" "okhttp/3.14.8" 8784 ms 8784 ms
10.100.69.248 - - [04/Feb/2021:00:37:22 +0800] "GET /sso/feign/info HTTP/1.1" 200 817 "-" "okhttp/3.14.8" 9100 ms 8764 ms
10.100.69.248 - - [04/Feb/2021:00:37:22 +0800] "GET /sso/feign/info HTTP/1.1" 200 834 "-" "okhttp/3.14.8" 9126 ms 9013 ms
10.100.69.248 - - [04/Feb/2021:00:37:22 +0800] "GET /sso/feign/info HTTP/1.1" 200 817 "-" "okhttp/3.14.8" 9058 ms 9058 ms
10.100.69.248 - - [04/Feb/2021:00:37:23 +0800] "GET /sso/feign/info HTTP/1.1" 200 820 "-" "okhttp/3.14.8" 9056 ms 9056 ms

显然Member服务响应时间太长。而在生成订单信息这个接口中,也确实调用Member服务,因为要使用Token。既然是Order的Tomcat线程池加大了,导致Member服务响应如此慢,有理由判断:Order消耗时间长是因为Member服务不能提供Order请求时的快速响应,即Member的性能差。

要分析Member性能为何差,可直接到Member打印栈信息。

完整的分析逻辑先看全局监控数据,再看定向监控数据。通过全局监控数据看整体资源消耗:

worker-8 CPU资源居然用这么高!说明在前面增加Order的Tomcat线程数有价值。现在,瓶颈点到另一个地方,Member服务。

既然worker-8的资源使用率高,看它上面的Pod,Member就在worker8:

[root@k8s-master-2 ~]# kubectl get pods -o wide | grep k8s-worker-8
elasticsearch-client-0                      1/1     Running     0          38h   10.100.231.233   k8s-worker-8   <none>           <none>
monitor-mall-monitor-d8bb58fcb-kfbcj        1/1     Running     0          23d   10.100.231.242   k8s-worker-8   <none>           <none>
skywalking-oap-855f96b777-5nxll             1/1     Running     6          37h   10.100.231.235   k8s-worker-8   <none>           <none>
skywalking-oap-855f96b777-6b7jd             1/1     Running     5          37h   10.100.231.234   k8s-worker-8   <none>           <none>
svc-mall-admin-75ff7dcc9b-8gtr5             1/1     Running     0          17d   10.100.231.208   k8s-worker-8   <none>           <none>
svc-mall-demo-5584dbdc96-fskg9              1/1     Running     0          17d   10.100.231.207   k8s-worker-8   <none>           <none>
svc-mall-member-5fc984b57c-bk2fd            1/1     Running     0          12d   10.100.231.231   k8s-worker-8   <none>           <none>
[root@k8s-master-2 ~]# 

同时,我们还能发现,这个节点上有不少服务,而这些服务都是比较吃CPU的,并且在压力过程中,还出现了sy cpu消耗很高的情况,我截两个瞬间的数据给你看看,一个是sy cpu高的情况,一个是us cpu高的情况,具体如下所示:

- sys cpu高的情况
[root@k8s-worker-8 ~]# top
top - 00:38:51 up 28 days,  4:27,  3 users,  load average: 78.07, 62.23, 39.14
Tasks: 275 total,  17 running, 257 sleeping,   1 stopped,   0 zombie
%Cpu0  :  4.2 us, 95.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.4 st
%Cpu1  :  1.8 us, 98.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu2  :  2.1 us, 97.9 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  :  1.0 us, 99.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 16266296 total,  1819300 free,  7642004 used,  6804992 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  8086580 avail Mem 


  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                 
12902 root      20   0 1410452  32280  17744 S  48.1  0.2 751:39.59 calico-node -felix                                                                                      
    9 root      20   0       0      0      0 R  34.8  0.0 131:14.01 [rcu_sched]                                                                                             
 3668 techstar  20   0 4816688   1.3g  23056 S  33.9  8.5 111:17.12 /usr/share/elasticsearch/jdk/bin/java -Xshare:auto -Des.networkaddress.cache.ttl=60 -Des.networkaddress+
26105 root      20   0  119604   6344   2704 R  25.8  0.0   0:02.36 runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v1.linux/moby+
26163 root      20   0   19368    880    636 R  25.2  0.0   0:00.95 iptables-legacy-save -t nat                                                                             
26150 root      20   0   18740   3136   1684 R  21.6  0.0   0:01.18 runc init                                                                                               
26086 root      20   0   18744   5756   2376 R  20.3  0.0   0:03.10 runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v1.linux/moby+
  410 root      20   0       0      0      0 S  19.4  0.0  42:42.56 [xfsaild/dm-1]                                                                                          
   14 root      20   0       0      0      0 S  14.8  0.0  54:28.76 [ksoftirqd/1]                                                                                           
    6 root      20   0       0      0      0 S  14.2  0.0  50:58.94 [ksoftirqd/0]                                                                                           
26158 root      20   0   18740   1548    936 R  14.2  0.0   0:00.90 runc --version                                                                                          
31715 nfsnobo+  20   0  129972  19856   9564 S  11.3  0.1  12:41.98 ./kube-rbac-proxy --logtostderr --secure-listen-address=[172.16.106.56]:9100 --tls-cipher-suites=TLS_EC+
10296 root      20   0 3402116 113200  39320 S  10.3  0.7   2936:50 /usr/bin/kubelet --bootstrap-kubeconfig=/etc/kubernetes/bootstrap-kubelet.conf --kubeconfig=/etc/kubern+
   22 root      rt   0       0      0      0 S   8.7  0.0   3:18.08 [watchdog/3]                                                                                            
26162 root      20   0  139592   2792   2508 R   8.4  0.0   0:00.39 /opt/cni/bin/calico                                                                                     
 6843 root      20   0  965824 110244  30364 S   7.7  0.7   1544:20 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock                                  
   24 root      20   0       0      0      0 S   7.4  0.0  49:03.89 [ksoftirqd/3]                                                                                           
 3636 techstar  20   0    4368    364    280 S   6.8  0.0   0:12.19 /tini -- /usr/local/bin/docker-entrypoint.sh eswrapper                                                  
26159 root      20   0   18740    760    552 R   6.5  0.0   0:00.28 runc --version                                                                                          
 1755 root      20   0  411108   5836   4416 S   4.8  0.0  35:39.97 /usr/libexec/packagekitd                       


- us cpu高的情况
[root@k8s-worker-8 ~]# top
top - 00:43:01 up 28 days,  4:31,  3 users,  load average: 72.51, 68.20, 47.01
Tasks: 263 total,   2 running, 260 sleeping,   1 stopped,   0 zombie
%Cpu0  : 77.2 us, 15.7 sy,  0.0 ni,  2.2 id,  0.0 wa,  0.0 hi,  4.8 si,  0.0 st
%Cpu1  : 77.0 us, 15.7 sy,  0.0 ni,  2.3 id,  0.0 wa,  0.0 hi,  5.0 si,  0.0 st
%Cpu2  : 70.3 us, 20.9 sy,  0.0 ni,  2.9 id,  0.0 wa,  0.0 hi,  5.9 si,  0.0 st
%Cpu3  : 76.6 us, 12.2 sy,  0.0 ni,  5.1 id,  0.0 wa,  0.0 hi,  6.1 si,  0.0 st
KiB Mem : 16266296 total,  1996620 free,  7426512 used,  6843164 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  8302092 avail Mem 


  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                 
20072 root      20   0 7944892 689352  15924 S 137.1  4.2   3127:04 java -Dapp.id=svc-mall-member -javaagent:/opt/skywalking/agent/skywalking-agent.jar -Dskywalking.agent.+
29493 root      20   0 3532496 248960  17408 S  98.3  1.5   0:06.70 java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -Dmode=no-init -Xmx2g -Xms2g -cl+
28697 root      20   0 3711520   1.0g  18760 S  61.6  6.7 124:41.08 java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -Dmode=no-init -Xmx2g -Xms2g -cl+
25885 root      20   0 3716560   1.2g  18908 S  59.3  7.6 183:12.97 java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -Dmode=no-init -Xmx2g -Xms2g -cl+
 6843 root      20   0  965824 109568  30364 S   7.6  0.7   1544:49 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock                                  
 3668 techstar  20   0 4816688   1.3g  23056 S   6.6  8.5 111:58.56 /usr/share/elasticsearch/jdk/bin/java -Xshare:auto -Des.networkaddress.cache.ttl=60 -Des.networkaddress+
10296 root      20   0 3402372 111692  39320 S   6.6  0.7   2937:43 /usr/bin/kubelet --bootstrap-kubeconfig=/etc/kubernetes/bootstrap-kubelet.conf --kubeconfig=/etc/kubern+
   18 root      rt   0       0      0      0 S   5.0  0.0   5:57.54 [migration/2]                                                                                           
    6 root      20   0       0      0      0 S   2.6  0.0  51:21.52 [ksoftirqd/0]                                                                                           
  410 root      20   0       0      0      0 D   2.6  0.0  43:08.23 [xfsaild/dm-1]                                                                                          
28310 root      20   0 7807048 565740  15924 S   2.6  3.5   1036:53 java -Dapp.id=svc-mall-admin -javaagent:/opt/skywalking/agent/skywalking-agent.jar -Dskywalking.agent.s+
29741 root      20   0 7749608 540376  15848 S   2.3  3.3 304:41.47 java -Dapp.id=svc-mall-monitor -javaagent:/opt/skywalking/agent/skywalking-agent.jar -Dskywalking.agent+
12902 root      20   0 1410452  30368  17744 S   2.0  0.2 752:30.32 calico-node -felix                                                                                      
16712 root       0 -20       0      0      0 S   2.0  0.0   1:56.16 [kworker/2:0H]                                                                                          
 6381 root      20   0 7782400 491476  15928 S   1.7  3.0 441:08.96 java -Dapp.id=svc-mall-demo -

从sy cpu高的top数据看,这节点显然在不断调度系统资源,通过top中的rcu_sched/softirq等进程可知,这显然是因为k8s在这节点过多安排任务。所以,先把Member服务移到另一个worker,然后看到TPS:

TPS增加到400多,方向对的。

那之前修改Order服务的Tomcat线程数没看到效果?因为压力已到Member服务,这让Member服务所在worker节点资源使用率增加,导致Member服务无法正常响应请求。因此,整个TPS看起来没有什么优化效果。现在,移走Member服务,看到效果明显增加,这说明方向还在正确道路。

再回看整体的资源监控:

现在,没有一个worker的资源用满或接近用满,完全不符“把资源都用起来”目标。

长时间压力中,发现资源怎么也用不上去。而且在上节第三阶段的最后一个图也能清楚看到这点。

至此,查看了一次次性能分析决策树,也调整一些参数,如Spring Boot中的Tomcat连接池、JDBC池、Jedis池、MQ池等,TPS似有增加趋势,但很不明显。

只能开始新一轮定位。

2 第五阶段

2.1 定位时间消耗

跟踪方法的执行过程来判断时间消耗。优化过程中,唯有思路不变,手段任选。

这方法和我们用日志拆分时间的逻辑一样。可直接用Arthas定位方法的时间消耗,很多其他工具也是可以的,如JvisualVM/JMC/BTrace。

已知道接口方法com.dunshan.mall.order.service.impl.PortalOrderServiceImpl#generateOrder,直接trace它。

这步需反复trace,为保证判断方向正确性,这的确是耗时又枯燥工作。

看反复trace后结果。由于跟踪的栈实在太长,我把多次跟踪的内容简化,其中重要部分如下:

+---[91.314104ms] com.dunshan.mall.order.feign.MemberService:getCurrentMember() #150     
.................... 
+---[189.777528ms] com.dunshan.mall.order.feign.CartItemService:listPromotionnew() #154
....................
+---[47.300765ms] com.dunshan.mall.order.service.impl.PortalOrderServiceImpl:sendDelayMessageCancelOrder() #316   

为何说这几个方法重要?对跟踪的内容,我们主要判断:消耗时间的方法是不是固定的。若时间不是消耗在固定的方法,就麻烦了,因为这说明不是方法本身问题,而是其他的资源影响了方法的执行时间;若时间一直消耗在固定的方法较容易,只要接着去跟踪这个方法。

而我反复跟踪了多次之后,总是发现上面几个方法都比较消耗时间。既然已经知道了方法的时间消耗,那全局监控已救不了。

2.2 定向监控分析

根据分析思路,定向监控分析前,反复分析了全局监控计数器,没觉得有什么资源使用问题。并从压力工具到数据库,也没发现阻塞点。

但上面我们也确实看到响应时间消耗在了几个具体方法,并且这几个方法并不是一直都消耗这么长的时间,而是有快有慢。

反复确认后,有必要看业务逻辑。因为对于一个复杂的业务来说,若业务代码逻辑太长,不管咋优化,都不会有啥效果,最后只能按扩容。

不过即便加机器,也要给出加机器逻辑。若业务可优化,更要尽力一试。从成本说,优化代码是更优选。

既然我们想优化业务,得知业务的调用逻辑。打开IDEA,找到generateOrder方法,把sequence diagram打开看到业务逻辑图:

img

  1. 获取用户名
  2. 获取购物车列表
  3. 获取促销活动信息
  4. 判断库存
  5. 判断优惠卷
  6. 判断积分
  7. 计算金额
  8. 转订单并插库
  9. 获取地址信息
  10. 计算赠送积分和成长值
  11. 插入订单表
  12. 更新优惠卷状态
  13. 扣积分
  14. 删除购物车商品
  15. 发送取消订单消息
  16. 返回结果

下订单动作真长。对这样复杂接口,若业务逻辑要求必须这样,那在接口上就没啥优化空间。在前面,已将TPS优化到400多,在这样硬件机器,基本就这样了。

不是要去设计一个下订单的业务逻辑,因为每个企业下订单逻辑有不同业务限制,修改业务逻辑需要所有的相关人员一起商讨确定。不过,可通过分析结果给出优化建议。

优惠卷、积分、发送延时取消订单信息的步骤都从下订单步骤删掉。不是我要这样改业务逻辑,而是想看这样改后,TPS是否增加。若增加,说明方向对,即这个业务逻辑需要再和各方商量,重新设计。

修改后的TPS:

确实有效果。若你在项目中遇到这样的接口,优化建议就可提:

  1. 分库分表
  2. 利用缓存
  3. 异步处理非关键步骤
  4. 大接口拆成小接口

但建议终归是建议,通常在一个企业中,对于这样的接口,技术团队会根据具体的业务逻辑做长时间的技术分析,判断如何实现。如果确实没办法在技术上做优化,那就只能上最后一招:扩容!这扩容就不再是扩某段,而是一整条链路上涉及到的服务。

在一个业务链路中,每个企业通常都是根据发展的速度做相应的技术沉淀:

  • 如果技术团队太追潮流了,学习成本大,不见得是好事
  • 太陈旧,维护的成本大,也不见得是好事

只有根据实际的业务发展不断地演进业务流程和技术实现,才是正道。

3 第六阶段

3.1 定位TPS会降下来的问题

接着压,又出现:

TPS掉的心碎!仍按性能分析决策树,一个个计数器看过去,最后在mysqlreport看到:

__ InnoDB Lock _________________________________________________________
Waits             889     0.1/s
Current            77
Time acquiring
  Total      36683515 ms
  Average       41263 ms
  Max           51977 ms

当前锁有点多,且这锁的时间还挺长。要想查锁,得先知道当前正在运行的事务,查innodb_trx表,因为MySQL在这个表中会记录所有正在执行的事务。发现大量lock_wait(锁等待):

有锁等待,就查锁关系,看什么在等待锁。看具体的锁关系前,查看一下应用日志。

为什么要看应用日志呢?因为对DB,锁是为保护数据的一致性,而产生锁的事务自然从应用中来。在MySQL中和在应用中看到的事务SQL应该对应。而现在我们只看到MySQL中的锁,还不知道在应用中会是什么样子,所以,要看应用日志。

不要用重压力工具中的某些具有唯一性的参数化数据。因为当参数化数据用重了,在数据库中执行update语句也照样会出现锁。

查看应用日志:

[2021-02-06 00:46:59.059] [org.apache.juli.logging.DirectJDKLog] [http-nio-8086-exec-72] [175] [ERROR] Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: 
### Error updating database.  Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
### The error may involve com.dunshan.mall.mapper.OmsOrderMapper.insert-Inline
### The error occurred while setting parameters
### SQL: insert into oms_order (member_id, coupon_id, order_sn,        create_time, member_username, total_amount,        pay_amount, freight_amount, promotion_amount,        integration_amount, coupon_amount, discount_amount,        pay_type, source_type, status,        order_type, delivery_company, delivery_sn,        auto_confirm_day, integration, growth,        promotion_info, bill_type, bill_header,        bill_content, bill_receiver_phone, bill_receiver_email,        receiver_name, receiver_phone, receiver_post_code,        receiver_province, receiver_city, receiver_region,        receiver_detail_address, note, confirm_status,        delete_status, use_integration, payment_time,        delivery_time, receive_time, comment_time,        modify_time)     values (?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?, ?, ?,        ?)
### Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction] with root cause
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

连一个insert都会报lock_wait,显然表级锁。因为insert本身是不会出现表级锁,所以应该还有其他信息。接着看日志:

[2021-02-06 01:00:51.051] [org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler] [scheduling-1] [95] [ERROR] Unexpected error occurred in scheduled task
org.springframework.dao.CannotAcquireLockException: 
### Error updating database.  Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: update oms_order         set status=?         where id in          (               ?          )
### Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

其中有update语句,这逻辑就成立了:update会锁数据,但MySQL用InnoDB。若update条件是精确查找,那就应该不会出现表级锁。

可若update范围较大,就有问题,因为这会导致insert语句被阻塞。过一会儿之后,你就会看到:

所有insert都在LOCK WAIT状态,这就是表级锁对insert产生的影响。再查一下锁和锁等待的话,就会看到:

img

lock_mode这一列的值全是X,即X锁。排他锁(X锁),又叫写锁。图中的锁类型(lock_type)全是RECORD,锁住的是索引,且索引是GEN_CLUST_INDEX,说明这锁等待是因为innodb创建的隐藏的聚集索引。

当一个SQL没走任何索引时,就会在每条聚集索引后面加X锁,这和表级锁现象一样,只是在原理上有所不同。为了方便描述,仍用“表级锁”描述。

要查锁,就得看看是谁持有锁。经过仔细查看上面的INNODB_LOCK_WAIT后,确定这锁对应的事务ID是157710723,对应SQL:

update oms_order set status=4 where id in  (       0  );

去代码查这段update代码:

/**
 * 批量修改订单状态
 */
int updateOrderStatus(@Param("ids") List<Long> ids,@Param("status") Integer status);

原来这是批量任务调用:

批量任务问题在于,在一个订单表中做批量更新操作,并且这个批量查询的内容还挺多。因为上面的ID是0,表示订单未支付,而未支付订单在这表很多,所以,在更新时做大范围查找,会进而导致表级锁。

这个批量任务的设计明显有问题。要在订单表中做更新这么大的动作,那也应该精准更新,而非范围更新。对订单的更新逻辑,可选择其他实现方式。

锁的原因找到,现在要把范围更新改为非常精准的更新,让它不产生表级锁。修改后,重新执行场景:

从优化效果来看,TPS已经达到700。对这样一个复杂的接口来说,不错。

其实,这个订单业务还有很多优化空间:

  1. 异步生成订单序列号,然后存放到Redis里,随用随取
  2. 批量业务需要重新设计
  3. 读写分离之后,对业务代码也做相应更新
  4. ……

由于订单逻辑是电商复杂一步,再说就超出性能范畴。

4 总结

性能优化过程中,问题是像洋葱一样一个个剥开的。虽然有可能一个优化动作就可以产生很好的效果,但是我们一定不要着急,要慢慢分析问题。

  • 一阶段,修改线程池产生了效果,但也出现了新问题
  • 二阶段,解决查询大量数据导致内存被耗光的问题
  • 三阶段,解决了索引问题
  • 四阶段,重新调配资源,让系统的调度更合理
  • 五阶段,定位方法的时间消耗问题,要在分析了业务逻辑之后再做相应的优化,不要因一味追求性能的优化效果而纠结
  • 六阶段中,定位了批量任务设计不合理的问题。在正经的批量任务中,批量产生的表级锁和insert的功能点,一定要分开。

总之,在分析的过程中,我们不要界定问题的边界,遇到什么问题就解决什么问题,不急不燥,不卑不亢。

  • 如何快速定位内存被消耗光的情况?

    使用jmap可以查看消耗内存占比,对消耗内存占比较大的方法进行分析。
    比如数据库查询结果太大,存入内存会消耗大量内存;或者循环调用;

  • 如何快速定位业务逻辑导致的TPS上不去、资源也用不上的情况?

    分析响应时间。找出响应时间长的节点,时间消耗在哪里,在干什么从而根据情况继续分析

参考

  • 日志响应时间配置可以参考本文:https://mp.weixin.qq.com/s/JeKdirFrM5LGAqZrrdKoXA

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.coloradmin.cn/o/415959.html

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈,一经查实,立即删除!

相关文章

自动化测试框架之selenium

目录1 自动化测试1.1 单元测试1.2 接口测试1.3 UI测试1.3.1 UI自动化测试的优点&#xff1a;1.3.2 UI自动化测试的适用对象1.4 自动化测试流程2 selenium3 selenium IDE 录制脚本1 自动化测试 自动化测试指软件测试的自动化&#xff0c;在预设状态下运行应用程序或者系统&…

50 openEuler搭建PostgreSQL数据库服务器-配置环境

文章目录50 openEuler搭建PostgreSQL数据库服务器-配置环境50.1 关闭防火墙并取消开机自启动50.2 修改SELINUX为disabled50.3 创建组和用户50.4 创建数据盘50.4.1 方法一&#xff1a;在root权限下使用fdisk进行磁盘管理50.4.2 方法二&#xff1a;在root权限下使用LVM进行磁盘管…

图解HTTP阅读笔记:第5章 与HTTP协作的Web服务器

《图解HTTP》第五章读书笔记 图解HTTP第5章 与HTTP协作的Web服务器5.1 用单台虚拟主机实现多个域名5.2 通信数据转发程序&#xff1a;代理、网关、隧道5.2.1 代理5.2.2 网关5.2.3 隧道5.3 保存资源的缓存5.3.1 缓存的有限期限5.3.2 客户端的缓存第5章 与HTTP协作的Web服务器 5…

学习系统编程No.18【进程间通信之管道实战】

引言&#xff1a; 北京时间&#xff1a;2023/4/11/21:17&#xff0c;今天的文章更新啦&#xff01;但是还是没有上热榜&#xff0c;所以我们需要继续更文啦&#xff01;我相信下一篇博客肯定是可以上热榜的&#xff0c;加油&#xff01;并且今天晚上因为有一节体育课&#xff…

Linux下让进程不再被拉起

Linux下为了防止应用挂掉&#xff0c;我们会设置服务进程来拉起这些应用。但某些流氓软件也会利用该机制使得它们被杀掉后能再被拉起来。本文讲述让这些进程不再被拉起的方法。 比如&#xff0c;有名称为recordmain.bin的进程&#xff0c;使用kill -9 杀掉它后&#xff0c;过几…

NVIDIA jetson tensorrt加速yolov5摄像头检测

link 在使用摄像头直接检测目标时&#xff0c;检测的实时画面还是有点慢&#xff0c;下面是tensorrt加速过程记录。 一、设备 1、设备jetson agx xavier 2、jetpack4.6.1 3、tensorrt 8.2.1.8 4、conda虚拟环境 python3.6 二、虚拟环境搭建及依赖 1、参考此博客安装torch Nvidi…

做自动化测试时所谓的“难点”

这篇关于自动化测试的文章&#xff0c;可能和你看到的大多数自动化的文章有所不同。我不是一位专职的自动化测试工程师&#xff0c;没有开发过自动化的工具或者框架&#xff0c;用的自动化的工具也不多&#xff0c;也没有做过开发&#xff0c;所以我讲不出那些现在很多人很看重…

[C++]日期类计算器的模拟实现

目录 日期类计算器的模拟实现&#xff1a;&#xff1a; 1.获取某年某月的天数 2.构造函数 3.拷贝构造函数 4.赋值运算符重载 5.析构函数 6.日期天数 7.日期天数 8.日期-天数 9.日期-天数 10.前置的运算符重载 11.后置的运算符重载 12.前置--的运算符重载 13.后置--的运算符重载…

前后端交互系列之Axios详解(包括拦截器)

目录前言一&#xff0c;服务器的搭建二&#xff0c;Axios的基本使用2.1 Axios的介绍及页面配置2.2 如何安装2.3 Axios的前台代码2.4 Axios的基本使用2.5 axios请求响应结果的结构2.6 带参数的axios请求2.7 axios修改默认配置三&#xff0c;axios拦截器3.1 什么是拦截器3.2 拦截…

Go分布式爬虫笔记(二十)

文章目录20 调度引擎调度引擎目标通道函数选项模式函数式选项模式的好处通道底层原理无缓冲区的通道带缓冲区的通道Select 机制的底层原理思考题在我们的课程中&#xff0c;schedule 函数其实有一个 bug&#xff0c;您能看出来吗&#xff1f;你觉得可以用什么方式找出这样的 Bu…

OTA A/B 分区升级 update_engine简介

近期猛然发现公司的项目都已经换成了AB升级&#xff0c;AB升级之前一直有所了解&#xff0c;只是一直都没有去仔细查看过其具体升级流程&#xff0c;这两天抽空捋了捋&#xff0c;简单整理下。 AB升级&#xff08;谷歌官网叫法无缝更新&#xff09;是自android7.0开始新增的一…

头歌(Linux之进程管理一):第2关:进程创建操作-fork

任务描述 在上一关我们学习如何获取进程的pid信息&#xff0c;本关我们将介绍如何编程创建一个新的进程。 本关任务&#xff1a;学会使用C语言在Linux系统中使用fork系统调用创建一个新的进程。 相关知识 在Linux系统中创建进程有很多函数可以使用&#xff0c;其中包括了系…

初识Elasticsearch

文章目录介绍一、什么是elasticsearch&#xff1f;二、基本概念三、安装elasticsearch与kibana四、安装kibana&#xff08;跟ES要在同一个网络中&#xff09;五、IK分词器总结介绍 好处&#xff1a;可以帮助从海量数据中查找需要的内容&#xff1b; 一、什么是elasticsearch&…

ETL工具-pentaho企业实战部署

&#x1f4e2;&#x1f4e2;&#x1f4e2;&#x1f4e3;&#x1f4e3;&#x1f4e3; 哈喽&#xff01;大家好&#xff0c;我是【IT邦德】&#xff0c;江湖人称jeames007&#xff0c;10余年DBA及大数据工作经验 一位上进心十足的【大数据领域博主】&#xff01;&#x1f61c;&am…

C++二叉搜索树与KV模型

二叉搜索树与KV模型二叉搜索树概念与操作性能分析实现KV模型二叉搜索树 本章是为了C的map和set做铺垫 概念与操作 二叉搜索树又称二叉排序树&#xff0c;它或者是一棵空树&#xff0c;或者是具有以下性质的二叉树: 若它的左子树不为空&#xff0c;则左子树上所有节点的值都小…

面试题之vue的响应式

文章目录前言一、响应式是什么&#xff1f;二、Object.defineProperty二、简单模拟vue三、深度监听四、监听数组总结前言 为了应对面试而进行的学习记录&#xff0c;可能不够有深度甚至有错误&#xff0c;还请各位谅解&#xff0c;并不吝赐教&#xff0c;共同进步。 一、响应式…

如何做好 IT 项目管理?做好项目管理常用的9大项目管理平台、7大管理方法

一个好的管理&#xff0c;是70%在流程、规范、工具&#xff0c;剩下的30%自由发挥。一个不好的管理&#xff0c;只有地板&#xff0c;每个人都要自己想办法&#xff0c;够到天花板。一个好的工具&#xff0c;就是帮助团队够到天花板的台阶。——刘润 项目管理是一门复杂的艺术&…

统一的文件管理,团队轻松协作

目前IT行业大都采用项目经理制的管理方式&#xff0c;这种管理方式下各个部门间相互独立&#xff0c;同时各部门间也缺乏沟通协作。因此IT行业在文件管理上主要面临以下几个问题&#xff1a; 文档缺乏集中管理&#xff1a;企业在管理过程中产生的大量文件分散在各个部门中&…

Python升级 pip : python -m pip install --upgrade pip,socket.timeout加入超时处理方法

人生苦短&#xff0c;我用python 最近又遇到了一个小的报错问题&#xff0c; 趁现在我还没有忘记&#xff0c; 赶紧来写一写… python 安装包资料报错交流:点击此处跳转文末名片获取 WARNING: You are using pip version 19.3.1; however, version 20.0.2 is available. You…

系统学习Numpy(一)——numpy的安装与基础入门[向量、矩阵]

系列文章目录 numpy的安装与基础入门[向量、矩阵与维度] numpy的安装与基础入门[向量、矩阵与维度]系列文章目录前言numpy安装向量与矩阵生成向量生成矩阵向量类型前言 numpy是科学计算以及机器学习深度学习的基础必备工具&#xff0c;本文将介绍numpy的安装&#xff0c;以及…