性能分析之数据不均衡导致TPS下降_数据库

    上周五项目组成员报了一个问题。有支业务在测试的过程中出现压力持续一段时间后，TPS就下降的情况。如下所示：

性能分析之数据不均衡导致TPS下降_SQL_02

    据描述，这个情况每过一段时间就固定出现。并且服务器的CPU降得很低，看似是没有压力一样。

    前面的线程数比较多，有100以，我尝试把线程数降到10个线程，也还是会出现，并且还是1分钟左右出现一次。甚至我把压力降到1个线程，也还是会出现，只是时间长了一些。

    看起来和压力的大小无关。

    既然这么规则的出现，那就查一下像FGC这样有规律的动作。

性能分析之数据不均衡导致TPS下降_数据库_03

从图上看，并没有FGC。

同时也查了有没有固定的批量等进程，也是没有。

初步排查完了之后，那就先画一个拓扑图来看看。

性能分析之数据不均衡导致TPS下降_SQL_04

在这样的逻辑关系中，先连主机1、2（LB），再连主机3、4（LB），再连数据库。数据库是典型的互联网数据库结构，从网关到proxy，proxy从ZK上取状态，再把sql发给数据库集群。

    反复查了主机1、2、3、4上的状态，都没发现有什么问题。所有资源都正常。连数据量都不大。

    name server和渠道也都正常，因为还有其他人在测试的过程中用到这两个部分，并且用得很正常。

    数据库我查过processlist/innodb_trx/innodb_locks/innodb_lock_waits也都没有抓到慢的点。所以判断没有慢sql。 

    另外，如果数据有问题的话，应该不会这么规则的TPS降低，应该是一直都很低。

    基于这些考虑，对数据库没有再深入查下去。

    到这里再往前查，就是jmeter了。因为压力机的问题，我一般是不愿意多花时间在上面的，所以就直接换了一个压力机，问题也仍然没有得到解决。

    也尝试了把脚本和数据copy到别人的压力机上，也是没有解决。

    问题再回到主机1、2上。因为这两个主机是跟jmeter直连的。因为TPS下降了，所以响应时间肯定就上升了。那就找时间的消耗在哪里。

    在jmeter和主机1、2上抓了几个数据包，发现主机1、2并没有给jmeter返回。

性能分析之数据不均衡导致TPS下降_数据_05

    既然没返回，那就问题在1、2主机后面，因为之前为了让性能更快，把日志调到error级别，根本没有应用层的正常日志可查，也不知道时间是在1、2上还是在3、4上，还是在db上。

    只能根据经验来一层层判断了。

    前面说了GC是正常的，tomcat层也查了没问题。那还能有什么呢？网络层？对简单的方式就是先拿一个正常的主机的参数做个比对。

性能分析之数据不均衡导致TPS下降_数据库_06

    还真有几个不一样的参数值。但是瞄来瞄去，似乎这几个参数都和这个问题无关呀。

    那怎么办呢？

    还是要锁定数据库了。

    把慢日志捞出来再看一遍。

# Profile

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

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

#    1 0xB5DEC0207094BA2F 117365.8906 44.9% 14120  8.3120  8.46 SELECT

#    2 0xFF8A1413823E401F  62050.0287 23.7% 12078  5.1374  2.78 SELECT

#    3 0xC861142E667B5663  36004.3209 13.8% 21687  1.6602  0.13 SELECT

#    4 0xFB7DBC1F41799DDD  32413.9030 12.4% 19615  1.6525  0.09 SELECT

#    5 0xC065900AEAC5717F  11056.5444  4.2%  9304  1.1884  0.02 SELECT

#    9 0x6422DFBA813FC194    202.4342  0.1%    54  3.7488  1.83 INSERT

#   11 0x197C9DCF5DB927C8    137.4273  0.1%    36  3.8174  1.14 INSERT

#   13 0x1A9D64E72B53D706     97.9536  0.0%    31  3.1598  2.65 UPDATE

#   36 0x3B44178A8B9CE1C3     20.1134  0.0%    16  1.2571  0.04 INSERT

#   39 0x370753250D9FB9EF     14.5224  0.0%    11  1.3202  0.04 INSERT

# MISC 0xMISC               2152.2442  0.8%   151 14.2533   0.0 <72 ITEMS>

    确实有四个SQL消耗了更多的时间，并且时间还不短。这是明显的性能问题，但是我考虑是另外的问题，不是我现在要定位的问题。因为我把SQL都拿出来执行过一遍，并且单个执行都不慢。

    而我之前把用户降到一个用户的时候也照样会出现TPS下降的情况。

    那还有什么呢？顿时觉得生无可恋了。

    

    不管怎么说，前面主机1、2、3、4上都查过了，我还是对自己查的结果有信心的，那只能是在数据库层面。之前我是直接自己写语句查的，查得不是很彻底。

    于是我让数据中心的人，把DB所有的proxy日志拿出来，做一次过滤。

    先cat printf了一下time cost大于200ms以上的。结果真的找到在压力的那个TPS下降的点上出现了time cost大于200ms的SQL，并且就在是前面慢日志中的3、4两个SQL。我奇怪了。数据我也换了好几次了，查出来并不慢呀，基本上是在十几ms完成。

性能分析之数据不均衡导致TPS下降_SQL_07

性能分析之数据不均衡导致TPS下降_SQL_08

    这是我之前执行的。看执行计划，似乎也没什么呀。

    可是为什么抓得出来这几个SQL呢。既然慢，就用抓出来的来执行吧。

性能分析之数据不均衡导致TPS下降_SQL_09

性能分析之数据不均衡导致TPS下降_数据_10

    哟，同结构的SQL，差距怎么这么大呢？14倍的时间差！

    下面就看下用的数据有什么不同了。

    比对了一下之后，发现只有数据不一样。那明显的就是一个查出来的多。于是group了一下，看根据查询的ID看看数据是不是分布均匀。

客户ID, 数量

'这一列只是客户id，无它', '91307'

'这一列只是客户id，无它', '69865'

'这一列只是客户id，无它', '55075'

'这一列只是客户id，无它', '54990'

'这一列只是客户id，无它', '54975'

'这一列只是客户id，无它', '54962'

'这一列只是客户id，无它', '54899'

'这一列只是客户id，无它', '54898'

'这一列只是客户id，无它', '54874'

'这一列只是客户id，无它', '54862'

'这一列只是客户id，无它', '54849'

'这一列只是客户id，无它', '54847'

'这一列只是客户id，无它', '54844'

'这一列只是客户id，无它', '54836'

'这一列只是客户id，无它', '54833'

'这一列只是客户id，无它', '54827'

'这一列只是客户id，无它', '54819'

'这一列只是客户id，无它', '54819'

'这一列只是客户id，无它', '54791'

'这一列只是客户id，无它', '54783'

'这一列只是客户id，无它', '54783'

'这一列只是客户id，无它', '54749'

'这一列只是客户id，无它', '54749'

'这一列只是客户id，无它', '54749'

'这一列只是客户id，无它', '54731'

'这一列只是客户id，无它', '54726'

'这一列只是客户id，无它', '54711'

'这一列只是客户id，无它', '54703'

'这一列只是客户id，无它', '54693'

'这一列只是客户id，无它', '54693'

'这一列只是客户id，无它', '54687'

'这一列只是客户id，无它', '54686'

'这一列只是客户id，无它', '54686'

'这一列只是客户id，无它', '54667'

'这一列只是客户id，无它', '54667'

'这一列只是客户id，无它', '54658'

'这一列只是客户id，无它', '54657'

'这一列只是客户id，无它', '54647'

'这一列只是客户id，无它', '54645'

'这一列只是客户id，无它', '54639'

'这一列只是客户id，无它', '54629'

'这一列只是客户id，无它', '54612'

'这一列只是客户id，无它', '54606'

'这一列只是客户id，无它', '54585'

'这一列只是客户id，无它', '54584'

'这一列只是客户id，无它', '54565'

'这一列只是客户id，无它', '54563'

'这一列只是客户id，无它', '54563'

'这一列只是客户id，无它', '54554'

'这一列只是客户id，无它', '54552'

'这一列只是客户id，无它', '54551'

'这一列只是客户id，无它', '54546'

'这一列只是客户id，无它', '54542'

'这一列只是客户id，无它', '54536'

'这一列只是客户id，无它', '54523'

'这一列只是客户id，无它', '54511'

'这一列只是客户id，无它', '54503'

'这一列只是客户id，无它', '54498'

'这一列只是客户id，无它', '54498'

'这一列只是客户id，无它', '54496'

'这一列只是客户id，无它', '54484'

'这一列只是客户id，无它', '54480'

'这一列只是客户id，无它', '54480'

'这一列只是客户id，无它', '54465'

'这一列只是客户id，无它', '54463'

'这一列只是客户id，无它', '54461'

'这一列只是客户id，无它', '54457'

'这一列只是客户id，无它', '54457'

'这一列只是客户id，无它', '54451'

'这一列只是客户id，无它', '54447'

'这一列只是客户id，无它', '54446'

'这一列只是客户id，无它', '54428'

'这一列只是客户id，无它', '54428'

'这一列只是客户id，无它', '54424'

'这一列只是客户id，无它', '54418'

'这一列只是客户id，无它', '54415'

'这一列只是客户id，无它', '54401'

'这一列只是客户id，无它', '54399'

'这一列只是客户id，无它', '54368'

'这一列只是客户id，无它', '54365'

'这一列只是客户id，无它', '54365'

'这一列只是客户id，无它', '54359'

'这一列只是客户id，无它', '54358'

'这一列只是客户id，无它', '54356'

'这一列只是客户id，无它', '54356'

'这一列只是客户id，无它', '54351'

'这一列只是客户id，无它', '54348'

'这一列只是客户id，无它', '54324'

'这一列只是客户id，无它', '54323'

'这一列只是客户id，无它', '54315'

'这一列只是客户id，无它', '54309'

'这一列只是客户id，无它', '54303'

'这一列只是客户id，无它', '54278'

'这一列只是客户id，无它', '54250'

'这一列只是客户id，无它', '54245'

'这一列只是客户id，无它', '54238'

'这一列只是客户id，无它', '54198'

'这一列只是客户id，无它', '54192'

'这一列只是客户id，无它', '54111'

'这一列只是客户id，无它', '54013'

'这一列只是客户id，无它', '187'

'这一列只是客户id，无它', '186'

'这一列只是客户id，无它', '185'

'这一列只是客户id，无它', '185'

'这一列只是客户id，无它', '183'

'这一列只是客户id，无它', '183'

'这一列只是客户id，无它', '183'

'这一列只是客户id，无它', '183'

'这一列只是客户id，无它', '182'

'这一列只是客户id，无它', '182'

'这一列只是客户id，无它', '182'

'这一列只是客户id，无它', '181'

'这一列只是客户id，无它', '180'

'这一列只是客户id，无它', '180'

'这一列只是客户id，无它', '180'

'这一列只是客户id，无它', '180'

'这一列只是客户id，无它', '180'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '179'

'这一列只是客户id，无它', '178'

'这一列只是客户id，无它', '178'

'这一列只是客户id，无它', '178'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '177'

'这一列只是客户id，无它', '176'

'这一列只是客户id，无它', '176'

'这一列只是客户id，无它', '176'

'这一列只是客户id，无它', '176'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '175'

'这一列只是客户id，无它', '174'

'这一列只是客户id，无它', '174'

'这一列只是客户id，无它', '174'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '173'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '172'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '171'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '170'

'这一列只是客户id，无它', '169'

'这一列只是客户id，无它', '169'

'这一列只是客户id，无它', '169'

'这一列只是客户id，无它', '169'

'这一列只是客户id，无它', '168'

'这一列只是客户id，无它', '168'

'这一列只是客户id，无它', '168'

'这一列只是客户id，无它', '168'

'这一列只是客户id，无它', '168'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '167'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '166'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '165'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '164'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '163'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '162'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '161'

'这一列只是客户id，无它', '160'

'这一列只是客户id，无它', '160'

    明显数据量分布的太不均匀了呀。查160条和查9万多条，那肯定是不一样喽。

    到这里，问题基本上就明确了，查了下参数化的数据，里面有10万条。而取到6万左右的时候，才出现了响应时间长的问题，所以才有前面的用户量大的时候，一分钟一次，用户量越少，出现的间隔就越长。那就说明，前面的5万条，都是数据量少的ID，而6万左右ID中有不少一部分是数据量大的。遇到这些数据量大的，主机1、2、3、4都得等着DB返回了数据之后才返回给jmeter。所以从jmeter上来看，就是在等主机1、2给数据。

    而我之前的执行的SQL，恰好试了多次都是数据量少的。

    悲催的人，今天适合买彩票！

    下面怎么办呢？先做个最规矩的实验，把5万条往后的数据全都删掉！场景再执行一遍。

性能分析之数据不均衡导致TPS下降_数据_11

    顿时人生又有了希望！


    我在培训的时候说到参数化的时候，都是在强调说，参数化的数据要做到：模拟真实环境的数据分布。

    而在这个例子中，这些通过脚本造出来的数据，本来应该分布均匀的，并且还是我在前面开会的时候强调过多次的。但是还是没把数据造均匀了。项目就是这样一步步做歪了的。哈哈。幸好现在发现了这个问题，还有纠正的余地。

    细想一下，其实不是造的数据也是会出现这种情况的。并且还不在少数。


    从这个例子来看，查数据还是要看趋势图、统计图。层层的排查，有些容易漏掉的点是意想不到的。但是找到问题之后，又觉得“哎呀，这问题怎么这么简单！”。 

    

    再次强调，性能分析还是要有明确的思路。