一次流量突增引发的小动静

雨翔河

首页列表关于

一次流量突增引发的小动静

2019-05-11 10:41

2019-5-10 早上 9:17，我们某服务的kafka某topic监控触发积压阈值发生告警，积压量达5W+。

正常情况下这个队列是不会产生积压的，因为这个队列的生产者的接口是个非常冷门的接口，调用量很少。

看了下这个积压的topic共有8个partition，8台机器每台机器单线程在消费这个队列。
这个队列在正常情况下量非常的少，量大的时候十分钟会产生有2W左右的数据，这样分配到8台机器，
单台的压力是十分钟处理2600条数据，一分钟处理260条，单线程一秒钟处理4条数据，这数据量单线程是没有问题的。

产生积压的时候，去看了下是否是因为gc过长导致的，查阅gc日志没有发现异常
我们开始断定是处理线程卡在了某处理区域，比如redis或者mysql或者网络，
马上找那时候的 `jstack` 的情况，找到当前topic的处理线程记录。

```
xxx_jstack_09:17:00:000.jstack.txt

"xxxxx (xxxxConsumerContext) thread #xx - KafkaTopic[xxxxxTopic]" #163 daemon prio=x os_prio=x tid=0x000xxxxe47eb742000 nid=0xe1xx waiting on condition [0x00xxxxxaba8cxxx00]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000xxx46ae4xx42> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2163)
	at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:96)
	at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:84)
	at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:96)
	at com.alibaba.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:144)
	at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
	at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:53)
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
	at com.alibaba.dubbo.rpc.filter.ConsumerContextFilter.invoke(ConsumerContextFilter.java:48)
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
	at com.alibaba.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:74)
	at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
	at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:77)
	at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:227)
	at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72)
	at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52)
	at com.alibaba.dubbo.common.bytecode.proxy1.selectXXXXXXXById(proxy1.java)
	at com.xxx.xxx.xxx.service.xxx.wrapper.XXXXWrapper.wrap(XXXXWrapper.java:44)
	......
```

线程执行到如图所示最后一行的类所在处就 `TIMED_WAITING` 了,这也看不出来有啥毛病，
只能说明这个地方可能真的执行的稍微慢了点需要优化，不至于积压这么多，
因为再次抽取 jstack 日志发现处理该topic的线程其实在正常执行的。

这个时候发现CPU其实随着积压而飙升，马上想到不会是这个冷门接口的流量出事了吧。

随机找了一台机器进入accessLog,查了下这个非常冷门的接口到底单台的调用量是多少：

cat XXXXXXX_access.2019-05-10-XXXXX.log  | grep  'XXXXController' | grep  '2019:08:0' | wc -l

2095

cat XXXXXXX_access.2019-05-10-XXXXX.log  | grep  'XXXXController' | grep  '2019:09:0' | wc -l

2321

cat XXXXXXX_access.2019-05-10-XXXXX.log | grep  'XXXXController' | grep  '2019:09:1' | wc -l

28071

cat XXXXXXX_access.2019-05-10-XXXXX.log  | grep  'XXXXController' | grep  '2019:09:2' | wc -l

2651

2019:09:1x 分钟的时候单台机器调用量 `28071` 次

原因水落石出，09:1x 分钟的时候这个接口的流量翻了10倍+，单线程处理不过来。

解决方案步骤：
1. 增加该topic的partition数量。
2. 横向扩展服务机器 或者 增加该topic处理的线程数（这需要发版本上线）。

题外话：因为历史原因，某些微服务本身无状态却因为安全策略等原因无法横向扩展服务扩展，这其实很蛋疼。
因为对于开发者来说，kafka的partition是可以实时扩的，服务本身也做到了无状态，增加机器就可以抵抗流量洪峰，这就算已经做好了分布式。
但是因为内部的安全策略问题导致访问某组件需要提策略等配置邮件，意味着增加机器的操作是有延时的，而且是不可接受的延时。
关于这个分布式微服务扩展问题我在以前的博客也有提到过：

[三个BUG引发的思考](https://yuxianghe.net/blog/45)

类型：工作标签：kafka,java