技术组件优化分析：原理、方法与实战分享

àì夳堔傛蜴生んèń 2024-03-24 17:07 39阅读 0赞

对一个固定的技术组件的分析优化思路，即组件不是我们开发的，但又要分析优化它，怎么办？

当数据库的CPU并没有全部用完，而是只用了几颗的时候，如何具体定向？将用到查看数据库本身线程栈的方法，这和前面直接看trx表有所不同。

### 1 场景运行数据 ###

对于支付前查询订单列表接口，先看第一次运行的性能场景结果：

![c558033e2ad9cae4f396b8f58286c3ec.png][]

从运行的场景数据来看，这接口TPS一开始还挺高，达800。但响应时间也增加，瓶颈已出现。只要知道瓶颈在哪，就能知道这个接口有无优化空间。

### 2 架构图 ###

![888650a0a6cefcf3ef497ef477aa6a2b.png][]

可见，当前接口的逻辑为：Gateway - Order - Member，其中也使用到MySQL和Redis。

### 3 拆分响应时间 ###

*  Gateway：  
    ![img][]
 *  Order：  
    ![img][img 1]
 *  Member：  
    ![img][img 2]

从响应时间分布看，Gateway（网关）消耗时间长。接下来从Gateway下手，分析到底哪消耗了时间。

### 4 第一阶段 ###

#### 4.1 全局监控分析 ####

先看这个接口的全局监控：

![img][img 3]

由于Gateway消耗的响应时间长，看过全局监控视图后，要判断Gateway在哪个worker：

[root@k8s-master-2 ~]# kubectl get pods -o wide | grep gateway
    gateway-mall-gateway-757659dbc9-tdwnm       1/1     Running     0          3d16h   10.100.79.96     k8s-worker-4   <none>           <none>
    [root@k8s-master-2 ~]#

在worker-4，同时在全局监控图上可看到，虽然Gateway只消耗70%CPU，但它还是消耗最多响应时间。那就看Gateway的线程状态，在处理什么。

#### 4.2 定向监控分析 ####

先看一下线程的CPU消耗：

![3c8f616d3ee519d674e51851f389446a.png][]

通过上图可看，Gateway有两类重要工作线程：

*  reactor-http-epoll
    
    reactor-http-epoll线程的设置最好与CPU个数一致。当前reactor-http-epoll线程4个，而这个worker有6C，所以还能增加两个
 *  boundedElastic
    
    有边界的弹性线程池，默认为CPU核x10，也没啥可优化

再持续看一会儿Gateway服务中的线程所消耗的时间比例，看方法级的时间消耗有没有异常的情况，即比例非常高的：

![7ef13713f838921ce72743e102c81b97.png][]

当前的执行方法也都没啥异常。

现在我们就把线程增加到6个，看能不能把CPU用高一点。如果CPU用多了之后，仍然是Gateway消耗的时间长，那就只有再继续加CPU。

性能项目中，不要轻易给出加CPU这样的建议。一定要在你分析了逻辑后，确定没有其他优化空间，再给这样的建议。

#### 4.3 优化效果 ####

![9300edee7fbba52a6374f0ee2f00bba2.png][]

通过回归测试，看到TPS有一点增加，只是在图的后半段（由于在测试过程中，Gateway重启过，前面的TPS就当是预热了）增加的并不明显，大概有50多TPS的样子。不过，也算是有了效果。

还没结束，查看各Worker的过程中，还发现DB里有两个CPU使用率很高。

优化效果不咋样，重新开始分析。

### 5 二阶段 ###

#### 5.1 全局监控分析 ####

![bb36d72ee9ec4a6f0bb22e3482455eaf.png][]

DB所在的worker-1也没啥大的资源消耗。

文章中经常用这个界面看全局监控数据。但这不是只看这界面。当我在这界面中看不到明显问题点时，也会去看命令像top/vmstat，这和我一直说的全局监控的完整计数器有关。因此，你要有全局监控计数器的视图，然后才能真正看全第一层的计数器。

再看DB所在的worker上的top数据：

bash-4.2$ top      
    top - 09:57:43 up 3 days, 17:54,  0 users,  load average: 4.40, 3.57, 3.11
    Tasks:  11 total,   1 running,   9 sleeping,   1 stopped,   0 zombie
    %Cpu0  :  8.0 us,  4.7 sy,  0.0 ni, 84.3 id,  0.0 wa,  0.0 hi,  2.2 si,  0.7 st
    %Cpu1  :100.0 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
    %Cpu2  :  6.5 us,  4.4 sy,  0.0 ni, 85.5 id,  0.0 wa,  0.0 hi,  2.2 si,  1.5 st
    %Cpu3  :  7.8 us,  5.7 sy,  0.0 ni, 83.7 id,  0.0 wa,  0.0 hi,  2.1 si,  0.7 st
    %Cpu4  : 96.0 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  4.0 si,  0.0 st
    %Cpu5  :  7.0 us,  4.0 sy,  0.0 ni, 84.9 id,  0.0 wa,  0.0 hi,  2.6 si,  1.5 st
    KiB Mem : 16265992 total,  1203032 free,  6695156 used,  8367804 buff/cache
    KiB Swap:        0 total,        0 free,        0 used.  9050344 avail Mem 
    
    
      PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                      
        1 mysql     20   0 8272536   4.7g  13196 S 248.8 30.5   6184:36 mysqld

有两个CPU的使用率高，就定向分析DB。

#### 5.2 定向监控分析 ####

可在DB上又不是所有CPU使用率都高，所以，要看DB线程到底在做啥。有了上面的进程信息后，再深入线程级：

bash-4.2$ top -Hp 1
    top - 09:56:40 up 3 days, 17:53,  0 users,  load average: 3.05, 3.30, 3.01
    Threads:  92 total,   2 running,  90 sleeping,   0 stopped,   0 zombie
    %Cpu0  :  5.4 us,  2.9 sy,  0.0 ni, 89.2 id,  0.0 wa,  0.0 hi,  2.2 si,  0.4 st
    %Cpu1  : 99.7 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.3 st
    %Cpu2  :  5.4 us,  3.2 sy,  0.0 ni, 88.2 id,  0.0 wa,  0.0 hi,  2.5 si,  0.7 st
    %Cpu3  :  6.3 us,  4.2 sy,  0.0 ni, 87.0 id,  0.0 wa,  0.0 hi,  2.1 si,  0.4 st
    %Cpu4  : 96.3 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  3.7 si,  0.0 st
    %Cpu5  :  4.0 us,  2.5 sy,  0.0 ni, 91.0 id,  0.0 wa,  0.0 hi,  1.8 si,  0.7 st
    KiB Mem : 16265992 total,  1205356 free,  6692736 used,  8367900 buff/cache
    KiB Swap:        0 total,        0 free,        0 used.  9052664 avail Mem 
    
    
      PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                       
      311 mysql     20   0 8272536   4.7g  13196 R 99.9 30.5  18:20.34 mysqld                                                                        
      241 mysql     20   0 8272536   4.7g  13196 R 99.7 30.5   1906:40 mysqld                                                                        
      291 mysql     20   0 8272536   4.7g  13196 S  3.3 30.5  15:49.21 mysqld                                                                        
      319 mysql     20   0 8272536   4.7g  13196 S  3.0 30.5  11:50.34 mysqld                                                                        
      355 mysql     20   0 8272536   4.7g  13196 S  3.0 30.5  13:01.53 mysqld                                                                        
      265 mysql     20   0 8272536   4.7g  13196 S  2.7 30.5  18:17.48 mysqld                                                                        
      307 mysql     20   0 8272536   4.7g  13196 S  2.7 30.5  16:47.77 mysqld                                                                        
      328 mysql     20   0 8272536   4.7g  13196 S  2.7 30.5  15:34.92 mysqld                                                                        
      335 mysql     20   0 8272536   4.7g  13196 S  2.7 30.5   8:55.38 mysqld                                                                        
      316 mysql     20   0 8272536   4.7g  13196 S  2.3 30.5  14:38.68 mysqld                                                                        
      350 mysql     20   0 8272536   4.7g  13196 S  2.3 30.5  10:37.94 mysqld                                                                        
      233 mysql     20   0 8272536   4.7g  13196 S  2.0 30.5  14:19.32 mysqld                                                                        
      279 mysql     20   0 8272536   4.7g  13196 S  2.0 30.5  19:51.80 mysqld                                                                        
      318 mysql     20   0 8272536   4.7g  13196 S  2.0 30.5  11:34.62 mysqld                                                                        
      331 mysql     20   0 8272536   4.7g  13196 S  2.0 30.5  11:46.94 mysqld                                                                        
      375 mysql     20   0 8272536   4.7g  13196 S  2.0 30.5   1:29.22 mysqld                                                                        
      300 mysql     20   0 8272536   4.7g  13196 S  1.7 30.5  17:45.26 mysqld                                                                        
      380 mysql     20   0 8272536   4.7g  13196 S  1.7 30.5   1:24.32 mysqld

只有两个MySQL的线程在使用CPU。接下来查SQL！虽然可能就是SQL的问题，但建议你找到相应证据。

gstack（装了GDB后就有的命令）打印这两个MySQL的栈，看具体函数。把那两个PID（311、241）的栈拿出来之后，看到：

Thread 59 (Thread 0x7f1d60174700 (LWP 241)):
    #0  0x000055a431fefea9 in JOIN_CACHE::read_record_field(st_cache_field*, bool) ()
    #1  0x000055a431ff01ca in JOIN_CACHE::read_some_record_fields() ()
    #2  0x000055a431ff070f in JOIN_CACHE::get_record() ()
    #3  0x000055a431ff2a92 in JOIN_CACHE_BNL::join_matching_records(bool) ()
    #4  0x000055a431ff18f0 in JOIN_CACHE::join_records(bool) ()
    #5  0x000055a431e397c0 in evaluate_join_record(JOIN*, QEP_TAB*) ()
    #6  0x000055a431e3f1a5 in sub_select(JOIN*, QEP_TAB*, bool) ()
    #7  0x000055a431e37a90 in JOIN::exec() ()
    #8  0x000055a431eaa0ba in handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) ()
    #9  0x000055a43194760d in execute_sqlcom_select(THD*, TABLE_LIST*) ()
    #10 0x000055a431e6accf in mysql_execute_command(THD*, bool) ()
    #11 0x000055a431e6d455 in mysql_parse(THD*, Parser_state*) ()
    #12 0x000055a431e6e3b6 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
    #13 0x000055a431e6fc00 in do_command(THD*) ()
    #14 0x000055a431f33938 in handle_connection ()
    #15 0x000055a4320e66d4 in pfs_spawn_thread ()
    #16 0x00007f1e8f1fcdd5 in start_thread () from /lib64/libpthread.so.0
    #17 0x00007f1e8d3cc02d in clone () from /lib64/libc.so.6
    Thread 41 (Thread 0x7f1d585e0700 (LWP 311)):
    #0  0x000055a4319dbe44 in Item_field::val_int() ()
    #1  0x000055a4319fb839 in Arg_comparator::compare_int_signed() ()
    #2  0x000055a4319fbd9b in Item_func_eq::val_int() ()
    #3  0x000055a431ff24ab in JOIN_CACHE::check_match(unsigned char*) ()
    #4  0x000055a431ff26ec in JOIN_CACHE::generate_full_extensions(unsigned char*) ()
    #5  0x000055a431ff2ab4 in JOIN_CACHE_BNL::join_matching_records(bool) ()
    #6  0x000055a431ff18f0 in JOIN_CACHE::join_records(bool) ()
    #7  0x000055a431e397c0 in evaluate_join_record(JOIN*, QEP_TAB*) ()
    #8  0x000055a431e3f1a5 in sub_select(JOIN*, QEP_TAB*, bool) ()
    #9  0x000055a431e37a90 in JOIN::exec() ()
    #10 0x000055a431eaa0ba in handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) ()
    #11 0x000055a43194760d in execute_sqlcom_select(THD*, TABLE_LIST*) ()
    #12 0x000055a431e6accf in mysql_execute_command(THD*, bool) ()
    #13 0x000055a431e6d455 in mysql_parse(THD*, Parser_state*) ()
    #14 0x000055a431e6e3b6 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
    #15 0x000055a431e6fc00 in do_command(THD*) ()
    #16 0x000055a431f33938 in handle_connection ()
    #17 0x000055a4320e66d4 in pfs_spawn_thread ()
    #18 0x00007f1e8f1fcdd5 in start_thread () from /lib64/libpthread.so.0
    #19 0x00007f1e8d3cc02d in clone () from /lib64/libc.so.6

两个execute\_sqlcom\_select函数，即两个select语句。接着往上看栈，还可看到JOIN函数。既然是select语句中的JOIN，直接找SQL语句。

直接查innodb\_trx表，看正在执行SQL有没有消耗时间长的。你也许会执行show processlist之类的命令，但为看全SQL，建议直接查trx表。

由于我们使用的thread\_handling是默认的one-thread-per-connection，os的线程和MySQL里的线程都是一一对应。所以，这里直接查trx表不会有误判。

查找innodb\_trx表，看到这两个SQL消耗时间长：

-- sql1
    SELECT
    	count(*)
    FROM
    	oms_order o
    LEFT JOIN oms_order_item ot ON o.id = ot.order_id
    WHERE
    	o. STATUS = 0
    AND o.create_time < date_add(NOW(), INTERVAL - 120 MINUTE)
    LIMIT 0,
     1000
    
    
    -- sql2：
    SELECT
    	o.id,
    	o.order_sn,
    	o.coupon_id,
    	o.integration,
    	o.member_id,
    	o.use_integration,
    	ot.id ot_id,
    	ot.product_name ot_product_name,
    	ot.product_sku_id ot_product_sku_id,
    	ot.product_sku_code ot_product_sku_code,
    	ot.product_quantity ot_product_quantity
    FROM
    	oms_order o
    LEFT JOIN oms_order_item ot ON o.id = ot.order_id
    WHERE
    	o. STATUS = 0
    AND o.create_time < date_add(NOW(), INTERVAL - 120 MINUTE)

想看SQL慢，就看SQL执行计划（MySQL执行计划看不清楚，还可看Profile信息）：

![c9d1caf89922b516abc7c75c61b54e36.png][]

![eea78f801c497eec7758b406dbf33631.png][]

全表扫描。

支付前查询订单列表这个接口并没有用到这俩SQL。到代码看下这两个SQL的生成过程，反向查找到：

@Scheduled(cron = "0 0/20 * ? * ?")
        private void cancelTimeOutOrder(){
            Integer count = portalOrderService.cancelTimeOutOrder();
            LOGGER.info("取消订单释放锁定库存：{}",count);
        }

这是个定时计划，每20分钟执行一次。原来是定时任务调用了这两个批量的查询语句，导致两个CPU使用率达到100%，并且持续了一段时间。

像这样的定时任务，要格外关注，注意把它和实时业务分开部署和处理，减少批量业务对实时业务的资源争用。若放在一起处理，要控制好要批量查询的数据量级，让SQL查询更合理。

由于数据库可用的CPU较多，这定时任务对TPS并没有产生明显影响，在这里我们不用做什么处理，以后注意分开就好。

### 6 总结 ###

虽然优化没有让TPS明显增加，但因为分析的技术细节不一样，也完整记录了分析过程。

一阶段分析不同点在于，对一个成熟固定组件，要想优化它，就要去了解它的架构，找到相关性能参数。因为实际性能项目中，面对这样的组件，往往没有时间去纠结内部的实现，需要非常快速地作出判断。如时间允许，慢慢折腾。

理解一个技术组件的原理，并没有想像中的那么高不可攀、深不可测，只要耐心看下去，总会成长。

二阶段分析，由某几个CPU高的现象分析到了具体的SQL问题。这个过程虽然简单，但从这问题，可以看出这系统还有很多优化空间，如主从分离、定时任务拆为单独的服务等等。

不过，性能分析中，重点仍是分析思路。

### FAQ ###

为什么要看全部的全局监控计数器？

也可能存在关联系统影响导致性能差？在性能分析中没有“可能”。其实这个问题要问的是一个思路，而不是原因。

因为一个全局监控方法可能不能包含所有性能计数器，要知道自己想看什么计数器，知道计数器可以通过哪些工具来查看，使用全部是为了不漏点存在问题的任何可能性。

单CPU高时，如何定位具体的问题点？你有什么思路？

单cpu高，可以先查看cpu在跑哪些线程，找到对应高效耗线程，然后再去使用工具查看这些线程在干什么，从而定位问题。  
CPU使用率高，也可以使用perf抓去调用函数？也同样是问思路。不过cpu使用率，应该先看是哪个计数器，再确定后续的思路，而不是直接用perf去看系统调用。

一切性能问题，都能通过jstack pid找到线索

那要看是不是和代码有关的问题。  
jstack是查看栈信息的，也就是代码的执行逻辑。

[c558033e2ad9cae4f396b8f58286c3ec.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/693e802d0e4f4ee9b0c8ce4da1169876.png
[888650a0a6cefcf3ef497ef477aa6a2b.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/1ed68e8711b44fe082e4a1385330c669.png
[img]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/75d65492673b4e568d59d6813de38cd9.png
[img 1]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/d2164cd97f8c431fa97c9cf8825a7ddb.png
[img 2]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/af1cf4726c044043a128eedb4ecf734e.png
[img 3]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/ab80d4d90cfa463fb4bf3cb69f56020d.png
[3c8f616d3ee519d674e51851f389446a.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/947b61c1939e4c28aac2662978e7c2b5.png
[7ef13713f838921ce72743e102c81b97.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/0fbd52e9d00a45e8aa6818c7381cd72f.png
[9300edee7fbba52a6374f0ee2f00bba2.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/4c12a1771a7c403a836585a2245632e7.png
[bb36d72ee9ec4a6f0bb22e3482455eaf.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/011cb80e6ac54ca1b4a53fc08abebfa6.png
[c9d1caf89922b516abc7c75c61b54e36.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/6efef2b5c56f46d190a07c8e36a8b933.png
[eea78f801c497eec7758b406dbf33631.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/bb16728adbb249d599643f02f598221b.png