女主宣言
服务的核心需求是长连接的需求，最近由于业务线的需求，突然增加对发消息的接口调用，由于之前对接口的压力测试还是处于在物理机（24核心，64G内存），目前部署在线上的数据是（16核心，24G内存）的线上环境上，物理机器的测试数据是2W+的测试结果，就按照当时3千一台的评估，线上在真实提供服务的时候，却和预期有很大出入，接着详细介绍一下这次的性能瓶颈，以及如何解决，解决的方法本身不麻烦，主要还是分享一下整个的排查过程，也希望能够学习一些线上的问题排查的思路，欢迎大家积极留言讨论。
PS：丰富的一线技术、多元化的表现形式，尽在“360云计算”，点关注哦！
问题描述
业务方的请求增多，流量的整体峰值QPS在5000，服务部署在九台虚拟机器上（分属于三个机房，三个不同的集群），由于流量不够均匀，流量开始主要集中到了其中一个机房的三台机器上，基本每台机器上的QPS在1350左右，而次数服务的CPU使用率已经达到了90%以上，触发了相应的报警，而次数的内存使用不大，基本维持在10%左右。
CPU使用率排查？
第一感觉CPU消耗比较多，但是服务本身并不是一个计算密集型的服务，CPU保持这么高的使用率肯定是在执行指令，服务本身没有出现无响应，或其他的异常表现，可以排除程序中存在死循环等验证的程序BUG导致的问题。那么，接下来就是先确定CPU到底在做什么，只有找到了消耗在哪里，才能针对性进行调整。备注：笔者使用的语言是小众Erlang语言，基于EVM。
准备一些需要检查的场景？
检查CPU的使用情况
recon:scheduler_usage(1000).
检查以下内存使用最多的前20进程
recon:proc_count(memory, 20).
获取节点上reduction使用最多的前20进程
recon:proc_count(reductions, 20).
获取一段时间reductions使用最多的20个进程
%% {<0.4490.1084>,983981,
%% [{current_function,{gen_server,loop,7}},
%% {initial_call,{proc_lib,init_p,5}}]}
recon:proc_window(reductions, 5, 1000).
[rp({recon:info(P), Num}) || {P, Num, _} <- recon:proc_window(reductions, 20, 5000)].
查询当前node的统计数据的变化
%% node_stats(N, Interval, fun(X,_) -> io:format("~p~n",[X]) end, nostate).
%% 每个500ms打印一个当前的统计信息,总共打印5次
recon:node_stats_print(5, 500).
线上环境的排查？
线上由于解决了负载均衡的问题之后，每台机器的负载峰值QPS也不到500，平时基本在200QPS左右，只能通过线上当前的CPU使用较大的系统，根据线上的情况评估出CPU消耗最多的位置（其中接口调用依然占用较大的使用比例，否则其他的信息会出现干扰）
// TCP接收相关的进程
{[{meta,[{registered_name,[]},
{dictionary,[]},
{group_leader,<0.1466.0>},
{status,waiting}]},
{signals,[{links,[<0.1900.0>]},
{monitors,[]},
{monitored_by,[#Port<0.21>]},
{trap_exit,false}]},
{location,[{initial_call,{ranch_acceptor,loop,3}},
{current_stacktrace,[{prim_inet,accept0,3,[]},
{inet_tcp,accept,2,[{file,"inet_tcp.erl"},{line,175}]},
{ranch_acceptor,loop,3,
[{file,"/home/sync360/iot_mqtt/_build/default/lib/ranch/src/ranch_acceptor.erl"},
{line,28}]}]}]},
{memory_used,[{memory,5800},
{message_queue_len,0},
{heap_size,233},
{total_heap_size,609},
{garbage_collection,[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,1000},
{minor_gcs,927}]}]},
{work,[{reductions,51141345}]}],
195520}
// Kafka写入相关的
{[{meta,[{registered_name,[]},
{dictionary,[{'$initial_call',{brod_producer,init,1}},
{'$ancestors',[<0.2043.0>,<0.2041.0>,event_post,brod_sup,
<0.1551.0>]}]},
{group_leader,<0.1550.0>},
{status,waiting}]},
{signals,[{links,[<0.2043.0>]},
{monitors,[{process,<0.3197.0>}]},
{monitored_by,[]},
{trap_exit,false}]},
{location,[{initial_call,{proc_lib,init_p,5}},
{current_stacktrace,[{gen_server,loop,7,
[{file,"gen_server.erl"},{line,403}]},
{proc_lib,init_p_do_apply,3,
[{file,"proc_lib.erl"},{line,249}]}]}]},
{memory_used,[{memory,21696},
{message_queue_len,0},
{heap_size,1598},
{total_heap_size,2585},
{garbage_collection,[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,1000},
{minor_gcs,894}]}]},
{work,[{reductions,25976991}]}],
108405}通过预估，准备压力测试环境，尽可能复现线上环境？
初步对比了线上的环境和之前的压测数据的差异这么大，对比了相应的变化发现，变化点主要有以下三个
- 机器配置的不同
- 线上环境多了Nginx的代理
- 增加了用来排查问题的日志（正常处理的日志）
- 增加了写入Kafka的插件（没有合适的kafka测试环境）
综合对比上面的情况，Kafka的最有可能是系统的瓶颈点
进行压力测试
备注：以上数据仅仅进行了一组测试，没有进行多次，但是从大体的数据对比中已经可以说明问题，环境主要和线上在Kafka的性能上存在不一样，压测环境的使用的共有集群，线上环境使用的是私有集群。
数据分析
进行组1的测试数据可以看出性能指标确实不容乐观，通过对当时环境的CPU的使用情况进行抓包看出
(emqx@10.216.6.159)1> [rp({recon:info(P), Num}) || {P, Num, _} <- recon:proc_window(reductions, 20, 5000)].
%%写日志的进程
{[{meta,[{registered_name,logger_disk_log_h_file_for_info},
{dictionary,[{'$ancestors',[logger_sup,kernel_sup,
<0.1366.0>]},
{'$initial_call',{logger_h_common,init,1}}]},
{group_leader,<0.1365.0>},
{status,running}]},
{signals,[{links,[<0.1399.0>,<0.1405.0>]},
{monitors,[]},
{monitored_by,[<0.13884.752>,<0.13086.752>,<0.12947.752>,
<0.12443.752>,<0.14194.752>,<0.6277.752>,<0.13735.752>,
<0.13916.752>,<0.13549.752>,<0.13686.752>,<0.14010.752>,
<0.5855.752>,<0.13455.752>,<0.12666.752>,<0.13945.752>,
<0.12490.752>,<0.32587.751>,<0.5895.752>,<0.13400.752>,
<0.13271.752>,<0.13976.752>,<0.1400.0>]},
{trap_exit,true}]},
{location,[{initial_call,{proc_lib,init_p,5}},
{current_stacktrace,[{gen_server,loop,7,
[{file,"gen_server.erl"},{line,403}]},
{proc_lib,init_p_do_apply,3,
[{file,"proc_lib.erl"},{line,249}]}]}]},
{memory_used,[{memory,35784},
{message_queue_len,1},
{heap_size,2586},
{total_heap_size,4284},
{garbage_collection,[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,1000},
{minor_gcs,199}]}]},
{work,[{reductions,758926433}]}],
845062}
%% ranch接收HTTP相关的进程
{[{meta,[{registered_name,[]},
{dictionary,[]},
{group_leader,<0.1457.0>},
{status,running}]},
{signals,[{links,[<0.1757.0>]},
{monitors,[]},
{monitored_by,[]},
{trap_exit,false}]},
{location,[{initial_call,{ranch_acceptor,loop,3}},
{current_stacktrace,[{ranch_conns_sup,start_protocol,2,
[{file,"/home/sync360/iot_mqtt/_build/default/lib/ranch/src/ranch_conns_sup.erl"},
{line,73}]},
{ranch_acceptor,loop,3,
[{file,"/home/sync360/iot_mqtt/_build/default/lib/ranch/src/ranch_acceptor.erl"},
{line,34}]}]}]},
{memory_used,[{memory,11772},
{message_queue_len,0},
{heap_size,987},
{total_heap_size,1363},
{garbage_collection,[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,1000},
{minor_gcs,960}]}]},
{work,[{reductions,2681352616}]}],
624395}
%% 写入kafka相关的进程
{[{meta,[{registered_name,[]},
{dictionary,[{'$ancestors',[<0.22379.258>,<0.22372.258>,
event_post,brod_sup,<0.22452.258>]},
{'$initial_call',{brod_producer,init,1}}]},
{group_leader,<0.22459.258>},
{status,waiting}]},
{signals,[{links,[<0.22379.258>]},
{monitors,[{process,<0.15563.737>}]},
{monitored_by,[<0.15356.752>,<0.8237.752>,<0.15477.752>,
<0.9175.752>,<0.14682.752>,<0.14831.752>,<0.15023.752>,
<0.2041.752>,<0.14115.752>,<0.14779.752>,<0.14640.752>,
<0.14804.752>]},
{trap_exit,false}]},
{location,[{initial_call,{proc_lib,init_p,5}},
{current_stacktrace,[{gen_server,loop,7,
[{file,"gen_server.erl"},{line,403}]},
{proc_lib,init_p_do_apply,3,
[{file,"proc_lib.erl"},{line,249}]}]}]},
{memory_used,[{memory,68696},
{message_queue_len,0},
{heap_size,4185},
{total_heap_size,8370},
{garbage_collection,[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,1000},
{minor_gcs,11}]}]},
{work,[{reductions,61643916}]}],
219381}分析结论：
- 通过上述CPU的占用消耗，比线上环境多了LOG写入的开销，这个也和代码对比中的LOG增加相互对应。
- 对比1和9（线上环境，扩容一台机器进行测试，由于不能频繁写入数据，这里只对线上环境进行了一组 测试），发现由于不同的Kafka的影响，对整体性能的差异近3倍。具体的差异的原因不在本次的性能 调优里面。
- 对比1和2的数据，可以看出Kafka在没有的情况下，基本是有的2.4倍。
- 对比4和1的数据，Nginx没有的情况下是有的1.2倍。
- 对比7和1的数据，Log没有的情况下是有的2.3倍。
分析结论
通过上述数据分析，Kafka，Log是性能下降的主要原因，Nginx的代理也有一定的衰减。针对以上三点并且结合项目的具体需要，主要进行了以下三个方向的优化调整
1.Log日志记录
a.去掉非必须的排查日志，该日志早期主要为了帮助排查定位问题
- b.是否可以提高写日志的效率？
比如减少日志的格式化操作，目前为了方便，程序会将日志格式化为JSON形式收集，一方面工具进行展示
2.Nginx代理
a.检查Nginx的参数设置是否合理，日志记录是否合理？
具体的调研和测试还在进一步进行中，目前的方向主要是日志方面和是否可以采用长连接的形式
3.Kafka写入
目前采用的是同步写入的方式，考虑是否能够添加缓存以及批处理的形式，来进行CPU的削峰操作。
具体操作实施
去掉非核心日志之后的压力测试数据如下所示
从数据的结果来看，性能提升了一倍多，已经可以满足目前的业务需求，以上的各点还在持续的优化跟进中。
总结
线上遇到瓶颈问题，首先以满足业务需求为根本出发点，第一时间解决业务线的需求。瓶颈问题主要是如何定位瓶颈在哪里，以及如何找到具体的瓶颈点，一旦找到了之后，就可以根据具体的情况处理相应的瓶颈点。
