0 目标

生成订单接口的基准场景是什么结果。

SQL的问题定位

JDBC池增加之后，由于数据量过大导致JVM内存被消耗光

批量业务和实时业务共存导致的锁问题

1 场景运行数据

第一次试执行性能场景：

40个压力线程只跑出50多的TPS，响应时间也蹭蹭跑了近700ms。这显然是很慢的接口。

2 架构图

画架构图是为知道分析的路径。

由于接口复杂，架构图看着乱，简化版本：

Order服务是接口的核心，把Order相关的服务都筛选出来，就很清楚知道它连接了哪些东西。

3 拆分响应时间

因为在场景运行时，看到响应时间较长。

Gateway ：

Gateway上的时间在700ms，与前面的场景数据对上了。

这张小图的采样间隔是分钟，因此，你可能会发现这个曲线和压力工具给出的TPS曲线，在一些细节上对应不起来。更应关注整体的趋势。

Order：

Order是生产订单信息这个接口的重点，并且它的业务逻辑也复杂，要多关注。

从数据上来看，Order的是时间消耗在350ms，占到整个响应时间的一半。Gateway的转发能力也要考虑，只是Gateway上没有逻辑，只做转发，若是因为数据量大而导致的Gateway转发慢，那解决Order的问题后，Gateway的问题也就会被解决。所以，先分析Order的问题。

4 一阶段

4.1 全局监控分析

没有明显CPU资源消耗、网络资源、IO资源瓶颈。

这时就要留意整个链路上有限制的点，如各种池（连接池、等）、栈中的锁、数据库连接、还有数据库的锁，即阻塞。

只要分析出阻塞的点，就能把链路扩宽，进而把资源都用起来。

也可能分析后，发现没有任何有阻塞点，可资源就是用不上去，那肯定是你分析不细。因为可能存在阻塞的地方实在太多。

4.2 定向监控分析

性能分析决策树，先分析Order服务：

分析Order的线程栈信息时，发现在Order的栈中，有大量这样的内容：

"http-nio-8086-exec-421" Id=138560 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@a268a48

   at sun.misc.Unsafe.park(Native Method)

   -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@a268a48

   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)

   at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1899)

   at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1460)

   at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1255)

   at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5007)

   at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:680)

   at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5003)

   at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1233)

   at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1225)

   at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90)

   ..........................

   at com.dunshan.mall.order.service.impl.PortalOrderServiceImpl$$EnhancerBySpringCGLIB$$f64f6aa2.generateOrder(<generated>)

   at com.dunshan.mall.order.controller.PortalOrderController.generateOrder$original$hak2sOst(PortalOrderController.java:48)

   at com.dunshan.mall.order.controller.PortalOrderController.generateOrder$original$hak2sOst$accessor$NTnIbuo7(PortalOrderController.java)

   at com.dunshan.mall.order.controller.PortalOrderController$auxiliary$MTWkGopH.call(Unknown Source)

   ..........................

   at com.dunshan.mall.order.controller.PortalOrderController.generateOrder(PortalOrderController.java)

   ..........................

栈信息中有很多getConnection，这明显是Order服务在等数据库连接池。所以要把JDBC池加大：

原配置：

     initial-size: 5 #连接池初始化大小

     min-idle: 10 #最小空闲连接数

     max-active: 20 #最大连接数

修改为：

     initial-size: 20 #连接池初始化大小

     min-idle: 10 #最小空闲连接数

     max-active: 40 #最大连接数

没把JDBC池一次性修改太大，因为不想为维护连接池而产生过多CPU消耗。建议你在增加资源池的时候，先一点点增加，看看有没有效果，有效果后再增加。

修改JDBC池后，再看压力场景的执行数据：

TPS有上升趋势，且一度达150。可接着TPS就掉下来，这时响应时间倒没明显增加。TPS不仅掉下来且断断续续，极不稳定。

后续的压力中不仅有错误信息产生，响应时间也上升。查看全局监控资源，并没发现太大资源消耗。

5 二阶段

5.1 全局监控分析

因为前面修改了Order的JDBC池，所以出现新问题后，先看Order服务的健康状态。

查看Order服务的top：

top - 01:28:17 up 19 days, 11:54,  3 users,  load average: 1.14, 1.73, 2.27

Tasks: 316 total,   1 running, 315 sleeping,   0 stopped,   0 zombie

%Cpu0  :100.0 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

%Cpu1  :  3.0 us,  2.7 sy,  0.0 ni, 93.6 id,  0.0 wa,  0.0 hi,  0.3 si,  0.3 st

%Cpu2  :  3.4 us,  3.4 sy,  0.0 ni, 93.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

%Cpu3  :  3.7 us,  2.8 sy,  0.0 ni, 93.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

%Cpu4  :  3.6 us,  2.1 sy,  0.0 ni, 93.6 id,  0.0 wa,  0.0 hi,  0.3 si,  0.3 st

%Cpu5  :  2.8 us,  1.8 sy,  0.0 ni, 95.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

KiB Mem : 16265992 total,  2229060 free,  9794944 used,  4241988 buff/cache

KiB Swap:        0 total,        0 free,        0 used.  6052732 avail Mem

 PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                  

29349 root      20   0 8836040   4.3g  16828 S  99.7 27.4  20:51.90 java                                                                                                                    

1089 root      20   0 2574864  98144  23788 S   6.6  0.6   2066:38 kubelet  

有个us cpu达100%！

top -Hp和jstack -l 1 查看进程后发现，是VM Thread线程占用CPU，这个线程是做GC的。那就来看内存的回收状态，查看jstat：

[root@svc-mall-order-7fbdd7b85f-ks828 /]# jstat -gcutil 1 1s

 S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT  

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    93  652.664  681.486

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    94  659.863  688.685

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.86  93.15    168   28.822    95  667.472  696.294

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

 0.00 100.00 100.00 100.00  94.85  93.14    168   28.822    96  674.816  703.638

从上面数据来看，FullGC在不断出现，但又回收不了内存！

这种情况，正常判断逻辑：一个实时的业务系统，就算有FullGC，也应每次都回收到正常状态。若HEAP内存确实不够用，那可以增加。但若HEAP一直在减少，直到FullGC也回收不了，那就有问题。

因此，对于这样的问题，我们要做两方面的分析：

内存确实在被使用，所以，FullGC回收不了。

内存有泄露，并且已经泄露完，所以，FullGC无法回收。

那么接下来，我们在做定向监控分析时就要从这两个角度来思考。

5.2 定向监控分析

既然内存已满，执行一下jmap -histo:live 1|head -n 50，看占比相对较多的内存：

[root@svc-mall-order-7fbdd7b85f-ks828 /]# jmap -histo:live 1|head -n 50

num     #instances         #bytes  class name

----------------------------------------------

  1:      74925020     2066475600  [B

  2:       2675397      513676056  [[B

  3:       2675385       85612320  com.mysql.cj.protocol.a.result.ByteArrayRow

  4:       2675386       42806176  com.mysql.cj.protocol.a.MysqlTextValueDecoder

  5:        246997       27488016  [C

  6:         80322       16243408  [Ljava.lang.Object;

  7:         14898        7514784  [Ljava.util.HashMap$Node;

  8:        246103        5906472  java.lang.String

  9:        109732        3511424  java.util.concurrent.ConcurrentHashMap$Node

 10:         37979        3342152  java.lang.reflect.Method

 11:         24282        2668712  java.lang.Class

 12:         55296        2654208  java.util.HashMap

 13:         15623        2489384  [I

 14:         81370        1952880  java.util.ArrayList

 15:         50199        1204776  org.apache.skywalking.apm.agent.core.context.util.TagValuePair

 16:         36548        1169536  java.util.HashMap$Node

 17:           566        1161296  [Ljava.util.concurrent.ConcurrentHashMap$Node;

 18:         28143        1125720  java.util.LinkedHashMap$Entry

 19:         13664        1093120  org.apache.skywalking.apm.agent.core.context.trace.ExitSpan

 20:         23071         922840  com.sun.org.apache.xerces.internal.dom.DeferredTextImpl

 21:         35578         853872  java.util.LinkedList$Node

 22:         15038         842128  java.util.LinkedHashMap

 23:         52368         837888  java.lang.Object

 24:         17779         711160  com.sun.org.apache.xerces.internal.dom.DeferredAttrImpl

 25:         11260         630560  com.sun.org.apache.xerces.internal.dom.DeferredElementImpl

 26:         18743         599776  java.util.LinkedList

 27:         26100         598888  [Ljava.lang.Class;

 28:         22713         545112  org.springframework.core.MethodClassKey

 29:           712         532384  [J

 30:          6840         492480  org.apache.skywalking.apm.agent.core.context.trace.LocalSpan

 31:          6043         483440  org.apache.skywalking.apm.dependencies.net.bytebuddy.pool.TypePool$Default$LazyTypeDescription$MethodToken

 32:          7347         352656  org.aspectj.weaver.reflect.ShadowMatchImpl

 33:          6195         297360  org.springframework.core.ResolvableType

 34:          6249         271152  [Ljava.lang.String;

 35:         11260         270240  com.sun.org.apache.xerces.internal.dom.AttributeMap

 36:          3234         258720  java.lang.reflect.Constructor

 37:           390         255840  org.apache.skywalking.apm.dependencies.io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue

 38:          7347         235104  org.aspectj.weaver.patterns.ExposedState

 39:          5707         228280  java.lang.ref.SoftReference

 40:          3009         216648  org.apache.skywalking.apm.agent.core.context.TracingContext

 41:         13302         212832  org.apache.ibatis.scripting.xmltags.StaticTextSqlNode

 42:          8477         203448  org.apache.skywalking.apm.dependencies.net.bytebuddy.pool.TypePool$Default$LazyTypeDescription$MethodToken$ParameterToken

 43:          5068         162176  java.util.concurrent.locks.ReentrantLock$NonfairSync

 44:          2995         143760  org.apache.skywalking.apm.agent.core.context.trace.TraceSegmentRef

 45:          2426         135856  java.lang.invoke.MemberName

 46:          3262         130480  java.util.WeakHashMap$Entry

 47:          1630         130400  org.apache.skywalking.apm.agent.core.context.trace.EntrySpan

[root@svc-mall-order-7fbdd7b85f-ks828 /]#

在分析内存时，可过滤掉java自己的对象，只看业务相关对象。从上面的第3、4条可以看出，com.mysql.cj.protocol和SQL相关，那就到innodb_trx表查一下，看有无执行时间较长的SQL。

查询过程中，看到这样一条SQL：

select id, 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

from oms_order

WHERE (id = 0

      and status = 0

      and delete_status = 0)

进而我又查询了这个语句，发现涉及数据435,8761条，显然代码有问题。查看一下在代码中，哪里调用了这SQL：

example.createCriteria().andIdEqualTo(orderId).andStatusEqualTo(0).andDeleteStatusEqualTo(0);

List<OmsOrder> cancelOrderList = orderMapper.selectByExample(example);

这段代码对应select语句：

<select id="selectByExample" parameterType="com.dunshan.mall.model.OmsOrderExample" resultMap="BaseResultMap">

   select

   <if test="distinct">

     distinct

   </if>

   <include refid="Base_Column_List" />

   from oms_order

   <if test="_parameter != null">

     <include refid="Example_Where_Clause" />

   </if>

   <if test="orderByClause != null">

     order by ${orderByClause}

   </if>

 </select>

典型的语句没过滤。直接修改代码加上limit，不让它一次性查询出所有的数据。

然后，看优化效果：

没有出现TPS断裂情况了，优化效果有的，说明那条SQL语句不会再查出太多数据把内存给占满了。

但TPS值并增加多少，须三阶段分析。

6 三阶段

这次不从全局监控数据来看，有前面经验，直接定向监控分析。

定向监控分析

因为我们在前面改了SQL，所以在执行SQL之后，我们要去查一下innodb_trx表，看看还有没有慢的SQL。 结果，看到了如下SQL：

这SQL执行计划：

又是全表扫描，且由一个update使用。

生成订单信息是复杂接口，不急收拾这SQL，先把slow log全都拿出来分析。

有时项目执行的场景多了，数据相互之间的影响就会很大，易导致我们分析的方向不准确。最好把slow log都清一遍。

清理完慢SQL、重新执行场景后，又把slow log拿出来，用pt-digest-query分析一遍：

# Profile

# Rank Query ID                     Response time   Calls R/Call   V/M   I

# ==== ============================ =============== ===== ======== ===== =

#    1 0x2D9130DB1449730048AA1B5... 1233.4054 70.5%     3 411.1351  2.73 UPDATE oms_order

#    2 0x68BC6C5F4E7FFFC7D17693A...  166.3178  9.5%  2677   0.0621  0.60 INSERT oms_order

#    3 0xB86E9CC7B0BA539BD447915...   91.3860  5.2%  1579   0.0579  0.01 SELECT ums_member

#    4 0x3135E50F729D62260977E0D...   61.9424  3.5%     4  15.4856  0.30 SELECT oms_order

#    5 0xAE72367CD45AD907195B3A2...   59.6041  3.4%     3  19.8680  0.13 SELECT oms_order

#    6 0x695C8FFDF15096AAE9DBFE2...   49.1613  2.8%  1237   0.0397  0.01 SELECT ums_member_receive_address

#    7 0xD732B16862C1BC710680BB9...   25.5382  1.5%   471   0.0542  0.01 SELECT oms_cart_item

# MISC 0xMISC                         63.2937  3.6%  1795   0.0353   0.0 <9 ITEMS>

1. UPDATE oms_order SET member_id = 260869, order_sn = '202102030100205526', create_time = '2021-02-03 01:05:56.0', member_username = '7dcmppdtest15176472465', total_amount = 0.00, pay_amount = 0.00, freight_amount = 0.00, promotion_amount = 0.00, integration_amount = 0.00, coupon_amount = 0.00, discount_amount = 0.00, pay_type = 0, source_type = 1, STATUS = 4, order_type = 0, auto_confirm_day = 15, integration = 0, growth = 0, promotion_info = '', receiver_name = '6mtf3', receiver_phone = '18551479920', receiver_post_code = '66343', receiver_province = '北京', receiver_city = '7dGruop性能实战', receiver_region = '7dGruop性能实战区', receiver_detail_address = '3d16z吉地12号', confirm_status = 0, delete_status = 0 WHERE id = 0;

2. 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 (391265, null, '202102030100181755',   '2021-02-03 01:01:03.741', '7dcmpdtest17793405657', 0,   0, 0, 0,   0, 0, 0,   0, 1, 0,   0, null, null,   15, 0, 0,   '', null, null,   null, null, null,   'belod', '15618648303', '93253',   '北京', '7dGruop性能实战', '7dGruop性能实战区',   'hc9r1吉地12号', null, 0,   0, null, null,   null, null, null,   null);

先看第一个语句。这update语句虽然被调用的次数不多，但特慢。这显然不应是实时接口在调用，查一下到底是什么业务调用了这个语句。在这语句中，update更新的是where条件中ID为0的数据，批量业务。

再看第二个语句。第二个insert语句调用次数多，应该是实时交易的SQL。通常，会通过批量插入数据来优化insert，所以要调整bulk_insert_buffer_size参数（默认8M）。因为bulk_insert_buffer_size就是在批量插入数据时提高效率的。查询了一下这参数，确实没优化过，还是默认值。

生产环境因为Order表中要加索引，所以在架构设计时也最好主从分离，让update、insert和select不会相互影响。

分析完这两个SQL语句，先查找第一个SQL的来源。通过查找代码，可以看到这里调用该语句：

orderMapper.updateByPrimaryKeySelective(cancelOrder);

但请注意，这个updateByPrimaryKeySelective方法是批量任务中的，而批量任务应该和实时交易分开才是。如果你是作为性能团队的人给架构或开发提优化建议，那你可以这样给建议：

读写分离

批量业务和实时业务分离

这里先把这个批量业务给分离开，并且也不去调用它。但真实的业务逻辑中，不能这么干。我之所以这么做，是为了看后续性能优化的效果和方向。

修改后TPS：

TPS能达到300，响应时间看起来也稳定。终于可以进入正常的性能分析阶段。

上图看，系统资源并没有完全用起来，这个接口显然还有优化的空间。

7 总结

在这节课中，我们做了三个阶段的分析优化。

在第一阶段中，我们修改了JDBC池，虽然TPS有上升的趋势，但是，新问题也同样出现了：TPS非常不稳定，还有断断续续的情况。

在第二阶段中，我们分析了内存溢出的问题，定位出了原因并优化了内存问题。虽然我们在TPS曲线上明显看到了优化的效果，但仍然没有达到理想的程度。

在第三阶段中，我们分析定位了SQL的问题，这是非常合乎逻辑的。因为我们在第二阶段中修改了SQL，所以到了第三阶段，就要直接到数据库中做相应的定位。从结果上看，效果不错，TPS已经有明显正常的趋势了。不过，你要注意的是，当批量业务和实时业务同时出现在同一个数据库中，并且是对同样的表进行操作，这时，你就得考虑一下架构设计是否合理了。

当SQL查询出来的数据到了应用内存的时候，导致了内存的增加。而应用内存的增加也增加了GC的次数，进而消耗了更多的CPU资源。

为什么JDK中看到VM Thread线程消耗CPU高，会去查看内存消耗是否合理？

在MySQL中分析SQL问题时为什么要先查询innodb_trx表？

1.VM Thread 线程消耗 CPU 高的异常，查看JAVA gc 是否合理

2.innodb_trx表提供了当前innodb引擎内每个事务的信息（只读事务除外），包括当一个事务启动，事务是否在等待一个锁，以及交易正在执行的语句