丨生成订单信息之二业务逻辑复杂怎么做性能优化

半夜惊出一身冷汗而我们在性能环境中的，要想给生产环境配置一个比较明确并且可以借鉴的结论，就必须先去分析生产的业务容量，然后再来确定当生产业务容量达到峰值的时候，相应的硬件资源用到多少比较合理。不过，在我们的优化环境中，我们可以通过把一个系统用起来，来判断软件的容量能力。所以，我们接着上节课的内容，再进入到第四阶段。你将看到在业务逻辑复杂的情况下，我们该怎么做优化。闲言少叙，直接开整在解决了前面三个不正经的问题之后，我们现在可以正常分析时间消耗到哪去了，只要解决了快慢的问题，我们才能进而解决资源没有用起来的问题。所以，我们先来拆分响应时间，同样，我们也不做全局分析，因为.哥嫌累。拆分响应时之前很多次我们都在用APM拆分响应时间，感觉没什么新意，这次我用日志来拆分一1123456783--3--3--3--3--3--3--]"POST/mall-]"POST/mall-]"POST/mall-]"POST/mall-]"POST/mall-]"POST/mall-]"POST/mall-1106--206--306--406--506--]"POST]"POST]"POST]"POST]"POST代项目中的话，你可以通过写或其他的方式自己做响应时间的统计。从上面的信息可以看到，这个接口的整个响应时间是150ms右，而在order务上就消耗了90毫秒。所以，下面我们要分析：为什么在order上会消耗这么久的时间。定向分要想知道Order务的时间消耗，那显然，我们得知道Order用中的线程都在做什么动作，所以我们先直接来分析Order的栈。通过SpringBootAdmin，我们可以查看到线程的整体状但是，由于系统资源还没有用到上限，我们得先调整一下Tomcat程数，把它加大一些，争取让Order应用把硬件资源用起来。代代max:max:我们看一下调整后的结果于是，通过用各个服务的日志拆分响应时间，我发现在Member务上有这样的日志（为Order的Tomcat线程池之后的结果）：1--]2--]3--]4--]5--]6--]7--]8--]9--]10--]111148--1248--1348--1448--]"GET/sso/feign/info]"GET/sso/feign/info]"GET/sso/feign/info]"GET/sso/feign/info显然，这个Member务的响应时间太长了。而在生成订单信息这个接口中，也确实调用Member务，因为要使用Token既然是OrderTomcat程池加大了，导致Member服务响应如此之慢，那我们就有理由作出判断：Order之所以消耗时间长，是因为Member服务不能提供Order请求时的快速响应。通俗点讲，就是Member的性能要想分析Member能为什么差，我们其实可以直接到Member打印栈信息来看看，而在讲，完整的分析逻辑应该是先看全局数据，再看定向数据。所以，高老师在这里，勤快一点。我们通过全局数据来看看整体的资源消耗：worker-8的CPU资源居然用到了这么高！这说明我们面增加Order的Tomcat线程数是有价值的。现在，瓶颈点到了另一个地方，也就是我们的Member服务。既然worker-8的资源使用率高，那我们就来看看它上面有什么Pod，不难看出就在worker81[root@k8s-master-2~]#kubectlget-|grepk8s-worker-2elasticsearch-- 3monitor-mall-monitor-d8bb58fcb- 4skywalking-oap-855f96b777- 5skywalking-oap-855f96b777- 6svc-mall-admin-75ff7dcc9b- 7svc-mall-demo-5584dbdc96- 89[root@k8s-master-20同时，我们还能发现，这个节点上有不少服务，而这些服务都是比较吃CPU并且在压力过程中，还出现了sycpu消耗很高的情况，我截两个瞬间的数据给你看看，一个是sycpu高的89[root@k8s-master-20-syscpu高的情[root@k8s-worker-8~]#top-00:38:51up28days,4:27,3 loadaverage:78.07,62.23,Tasks:275total,17running,257 1 0%Cpu0:4.2us,95.4sy,0.0ni,0.0id,0.0wa,0.0hi,0.0si,0.4%Cpu1:1.8us,98.2sy,0.0ni,0.0id,0.0wa,0.0hi,0.0si,0.0%Cpu2:2.1us,97.9sy,0.0ni,0.0id,0.0wa,0.0hi,0.0si,0.0%Cpu3:1.0us,99.0sy,0.0ni,0.0id,0.0wa,0.0hi,0.0si,0.0KiBMem KiB 0 0 avail PID PR SHRS%CPU TIME+1412902 3228017744S48.10.2751:39.59calico- 9 0R34.80.0131:14.01 3668 1.3g23056S33.98.5111:17.121726105 0 2704R25.8 0:02.36runc--1826163 R25.2 0:00.95iptables-1926150 1684R21.6 0:01.18runc2026086 2376R20.3 0:03.10runc-- 410 0S19.40.042:42.56 14 0S14.80.054:28.76 6 0S14.20.050:58.942426158 936R14.2 0:00.90runc--2531715 0129972 9564S11.30.112:41.98./kube-2610296 11320039320S10.3 2936:50 22 0 8.7 3:18.082826162 0 2508 8.4 6843 096582411024430364 7.7 1544:20 24 0 7.40.049:03.89 3636 280 6.8 0:12.19/tini--3226159 6.5 0:00.28runc-- 1755 0 4416 4.80.035:39.97-uscpu[root@k8s-worker-8~]#top-00:43:01up28days,4:31,3users,loadaverage:72.51,68.20,Tasks:263 2running,260 1 0%Cpu0:77.2us,15.7sy,0.0ni,2.2id,0.0wa,0.0hi,4.8si,0.0 PID PR SHRS%CPU TIME+4920072 68935215924S137.1 3127:04java-5029493 24896017408S98.3 0:06.70java-5128697 1.0g18760S61.66.7124:41.08java-5225885 1.2g18908S59.37.6183:12.97java- 6843 096582410956830364 7.6 1544:49 3668 1.3g23056 6.68.5111:58.565510296 11169239320 6.6 2937:43 18 0 5.0 5:57.54 6 0 2.60.051:21.52 410 0 2.60.043:08.235928310 56574015924 2.6 1036:53java-6029741 54037615848 2.33.3304:41.47java-6112902 3036817744 2.00.2752:30.32calico-6216712 0- 0 2.0 1:56.16 6381 49147615928 1.73.0441:08.96java-从sycpu高的top数据来看，这个节点显然在不断地调度系统资源，通过top中的rcu_sched/softirq等进程就可以知道，这种情况显然是因为Kubernetes在这个节点上过多地安排了任务。所以，我先把Member服务移到另一个worker上，然后看到TPS如你看，TPS增加到400多了，也就是说我们的方向是对那为什么我们之前修改Order务的Tomcat程数没有看到效果呢？这是因为压力已经到了Member服务上，这让Member服务所在的worker节点资源使用率增加，导致Member务无法正常响应请求。因此，整个TPS起来没有什么优化效果。现在，我们移走了Member服务，看到效果明显增加，这说明我们的方向还在正确的道。我们再回来看一下整体的资源现在，没有一个worker资源用满或者接近用满，完全不符合我们“把资源都用起到这里为止，我们查看了一次次的性能分析决策树，也调整了一些参数，比如SpringBoot的Tomcat接池、JDBC、Jedis、MQ等，调整之后TPS乎有增加的定位时间消在上一个阶段的分析中，我们用日志拆分了响应时间，是想让你看到我们用不同的都可以把响应时间拆出来。这也是我一直强调的：你不要在意用什么，而要在意你想要在这一阶段中，我们一个思路：方法的执行过程来判断时间消耗。让你看到：在优化过程中，唯有思路不变，任你选择。这个方法和我们用日志拆分时间的逻辑其实是一样的。我们可以直接用Arthas定位方法的时间消耗。请你记住，除了Arthas之外，还有很多其他工具也是可以的，比如JvisualVM/JMC/BTrace等。com.dunshan.mall.order.service.impl.PortalOrderServiceImpl的generateOrder，所以，我们直接trace（）它就可以了。你要注意，在这一步中，我们需要反复trace次，这是为了保证判断方向的正确性。不现在，我们来看一下反复trace后的结果。由于的栈实在太长了，我把多次的内112345+---+---+---为什么说这几个方法重要呢？这里我要说明一下，对于的内容，我们主要判断的是：消耗时间的方法是不是固定的。如果时间不是消耗在了固定的方法上，那就有些麻烦了，因为这说明不是方法本身的问题，而是其他的资源影响了方法的执行时间；如果时间一直消耗在了固定的方法上，就比较容易了，我们只要接着去这个方法就好了。而我反复了多次之后，总是发现上面几个方法都比较消耗时间。既然已经知道了方法的时间消耗，那全局已经救不了我们了，只有在定向中来分析了。定向分我先说明一下，根据我们的分析思路，我在定向分析之前，反复分析了全局计数器，没觉得有什么资源使用上的问题。并且从压力工具到数据库，我也没发现有什么阻塞经过反复确认后，我觉得有必要来看一下业务逻辑了。因为对于一个复杂的业务来说，如果业务代码逻辑太长，那我们不管怎么优化，都不会有什么效果，最后只能按照扩容的思路来加机器了。在这里，我多说几句闲话。我看到过很多企业连一些简单的优化都没有做，就从寻找心理安全感的角度去增加机器，结果耗费了大量的成本，这是非常不理智的。从技术的角度来说，花不多的时间成本就可以节省大量的资源成本，这显然是很划算的。可是，受一些社会不良思维的误导，有些企业就觉得只要能通过加机器解决的问题，都不是啥大问题。对于这种思路，我们就得放到成本上来算一算了。大部分打工人可能会觉得，反正用的又不是自己的钱，管花加机器干嘛？没意义。但是，从节能减排的全球大局观来看，一个该做的优化没有做，不仅浪费公司的成本，还一点儿都不环保！呃.好像扯的有点远了。我们回到正题，既然我们想优化业务，就得先知道业务的调用逻辑是个啥样子。所以我们打开iea，找到eeraerer方法，然后把seeneiaram（idea的一个插件）打开，就看到了这样一张很长的业务逻辑图：如果你看不懂这张图，也没有关系。我在这里给你大致描述一下这张图里有什么东获取用户名获取购物车列表获取促销活动信息判断库存判断卷判断积分计算金额转订单并插库获取地址信息计算积分和成长插入订单表更新卷状态扣积分删除购物车商品发送取消订单消息返回结果是不是有种很复杂的感觉？通过我大概列出来的这些内容，你就能知道下订单这个动作有多长了。对这样的复杂接口，如果业务逻辑要求必须是这样的，那我们在接口上就没有什么优化空间了。面，我们已经把TPS优化到了400多，在这样的硬件机器上，也基本上就这样了。在这节课中，我们不是要去设计一个下订单的业务逻辑，因为每个企业的下订单逻辑，都会有不同的业务限制。做为性能工程师，我们没有对业务逻辑的设计说改就改的权利，因为修改业务逻辑需要所有的相关人员一起商讨确定。不过，我们可以通过分析的结果给出优化的建议。在这里，我把卷、积分、发送延时取消订单信息的步骤都从下订单的步骤中删掉。有人可能会问这样改合适吗？我强调一下，不是我要这样改业务逻辑，而是想看看这样改了之后，TPS有没有增加。如果增加了，就说明我们的方向是对的，也就是说，这个业务逻辑需要再和各方商量一下，重新设计。我们来看修改之后的TPS图：分库分表利用缓存异步处理非关键步骤大接口拆成小接口但是，建议终归是建议，通常在一个企业中，对于这样的接口，技术团队会根据具体的业务逻辑做长时间的技术分析，来判断如何实现。如果确实没办法在技术上做优化，那就只能上最后一招：扩容！这个扩容就不再是扩某一段了，而是一整条链涉及到的服务。还有一点，在一个业务链路中，每个企业通常都是根据发展的速度做相应的技术沉淀。如果技术团队太追潮流了，学习成本大，不见得是好事；如果太陈旧了，的成本大，也不见得是好事。因此，我们只有根据实际的业务发展不断地演进业务流程和技术实现，才是正道。定位TPS会降下来具体是什么原因呢？我在接着压的时候，又出现了这样的问你看，TPS呀掉的，心都碎了……虽说在每个项目的优化过程中，都会出现各种意外的事仍然是按照高老师强调的性能分析决策树（如果你不清楚，可以再看看第4讲），我们一个个计数器看过去，最后在mysqlreport中看到了下面这些数据：1InnoDB 2Time 显然当前的锁有点多，并且这锁的时间还挺长。要想查锁，就得先知道当前正在运行的是什么样的事务，所以我们就去查一下innodbtrx表，因为MySL在这个表中会记录所有正在执行的事务。在数据库中，我们发现了大量的lock_wait（锁等待）：事务自然是从应用中来的。按照这样的逻辑，我们在MySQL中和在应用中看到的事务SQL，应该是对应的。而现在我们只看到了MySQL中的锁，还不知道在应用中会是什么这里温馨提醒一句：在这个时候，我们还需要注意，不要用重压力工具中的某些具有唯一性的参数化数据。因为当参数化数据用重了，在数据库中执行update语句也照样会出现在查看了应用日志之后，我们看到如下信112345678[2021-02-0600:46:59.059][org.apache.juli.logging.DirectJDKLog][http-nio-###ErrorupdatingCause:###Theerrormayinvolvecom.dunshan.mall.mapper.OmsOrderMapper.insert-###Theerroroccurredwhilesetting###SQL:insertintooms_order(member_id,coupon_id,###Cause:com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:;Lockwaittimeoutexceeded;tryrestartingtransaction;nestedexceptioncom.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:Lockwait你看，连一个insert都会报lock_wait，这显然是出现表级锁了。因为insert本身是不会1[2021-02-0601:00:51.051]22345678###Errorupdatingdatabase.Cause:com.mysql.cj.jdbc.exceptions.MySQLTransac###TheerrormayinvolvedefaultParameterMap###Theerroroccurredwhilesetting###SQL:updatesetwhereid(###Cause:com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:;Lockwaittimeoutexceeded;tryrestartingtransaction;nestedexception你看，其中有update语句，这样一来，逻辑就成立了：我们知道，update是会锁数据的，但是，MySQL用的是InnoDB的引擎。如果update的条件是精确查找，那就应该可是，如果update的范围比较大，就会有问题了，因为这会导致insert语句被阻塞。过我们看到，所有的insert在LOCKWAIT状态了，这就是表级锁对insert生的影响。不难看出，lock_mode列的值全是X，意思是X。我们知道，排他锁（X），又叫写锁。图中的锁类型（lock_type）全是RECORD，锁住的是索引，并且索引是GEN_CLUST_INDEX，说明这个锁等待是因为innodb创建的隐藏的索引