一个flume agent异常的解决过程记录

时间:2023-04-30 17:40:56

今天在使用flume agent的时候,遇到了一个异常,  现把解决的过程记录如下:

问题的背景:

我使用flume agent 来接收从storm topology发送下来的accesslog , 做本地文件落盘。flume配置文件如下:

#用于syslog和accesslog的本地文件滚动。
a1.sources=r1
a1.sinks = sink1
a1.channels = c1
#thrift source;
a1.sources.r1.type= thrift
a1.sources.r1.channels = c1
a1.sources.r1.bind = 127.0.0.1
a1.sources.r1.port = 8081
#先用内存通道测试。
#a1.channels.c1.type = memory
#a1.channels.c1.capacity = 10000000
#a1.channels.c1.byteCapacity = 524288000
a1.channels.c1.type = file
a1.channels.c1.checkpointDir=/Users/dongqingswt/workdir/logs/checkpoint
a1.channels.c1.dataDirs = /Users/dongqingswt/workdir/logs/datadir
#使用自定义的文件滚动sink
a1.sinks.sink1.type=  com.beibei.datahamal.flume.extend.sink.roll.FileRollSink
a1.sinks.sink1.channel = c1
启动flume agent以后, thrift source在本机建立套接字监听,然后用flume-ng-sdk提供的RpcClientFactory 创建thrift rpc client , 进行消息发送的压测。
发现rpcclient 发送消息到一定量(100000) 时, FileRollSink就无法从memory channel拉取数据了, 而thrift rpc client 也得到了如下异常:
Exception in thread "main" org.apache.flume.EventDeliveryException: Failed to send event.
at org.apache.flume.api.ThriftRpcClient.append(ThriftRpcClient.java:155)
at com.beibei.datahamal.flume.extend.sink.rolling.FilerRollSinkSender.main(FilerRollSinkSender.java:42)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)
Caused by: java.util.concurrent.TimeoutException
at java.util.concurrent.FutureTask.get(FutureTask.java:201)
at org.apache.flume.api.ThriftRpcClient.append(ThriftRpcClient.java:134)
... 6 more

查看源码, 发现thrift client有一个20s的请求超时,这时候 , 查看thrift 错误日志,发现了如下异常:

java.lang.OutOfMemoryError: unable to create new native thread
at java.lang.Thread.start0(Native Method) ~[na:1.7.0_45]
at java.lang.Thread.start(Thread.java:713) ~[na:1.7.0_45]
at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:949) ~[na:1.7.0_45]
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1360) ~[na:1.7.0_45]
at org.apache.thrift.server.TThreadedSelectorServer.requestInvoke(TThreadedSelectorServer.java:306) ~[libthrift-0.9.3.jar:0.9.3]
at org.apache.thrift.server.AbstractNonblockingServer$AbstractSelectThread.handleRead(AbstractNonblockingServer.java:210) ~[libthrift-0.9.3.jar:0.9.3]
at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.select(TThreadedSelectorServer.java:586) ~[libthrift-0.9.3.jar:0.9.3]
at org.apache.thrift.server.TThreadedSelectorServer$SelectorThread.run(TThreadedSelectorServer.java:541) ~[libthrift-0.9.3.jar:0.9.3]

直观的看这个异常,会让人想到是堆内存不够用, 调节-Xmx1024m 参数以后,问题依旧。

接着用jconsole attach到flume agent这个进程,查看堆内存的使用量, 远没有达到预设的xmx阈值。

但是·有一个表现就是线程数猛涨到2000以后,直接掉到了20左右,为什么会创建这么多线程呢, 都是什么线程呢?

结合thrift source 的源码, 发现thrift server 采用的也是java nio   , 有SelectorThread做socket的read/write 就绪select

AcceptorThread做socket的accept的select ,而socket读就绪以后,收到的FrameBuffer会被包装成一个Runnable丢到线程池处理(查看

TThreadedSelectorServer的304 行),代码如下:
protected boolean requestInvoke(FrameBuffer frameBuffer) {
Runnable invocation = getRunnable(frameBuffer);
if (invoker != null) {
try {
invoker.execute(invocation);
return true;
} catch (RejectedExecutionException rx) {
LOGGER.warn("ExecutorService rejected execution!", rx);
return false;
}
} else {
// Invoke on the caller's thread
invocation.run();
return true;
}
} 这个任务invocation的处理逻辑是在ThriftSource的ThriftSourceHandler定义的,也就是把thrift flume event直接丢到memchannel以后返回。起初 ,我怀疑是不是flume event丢到memchannel处理太慢(比如有线程死锁),导致线程堆积, 但后面换成file channel
问题依旧,于是继续看jconsole上thrift 的Flume 线程,因为线程工厂在创建线程的时候,指定了线程名:
ThreadFactory threadFactory = new ThreadFactoryBuilder().setNameFormat(
"Flume Thrift IPC Thread %d").build();
if (maxThreads == 0) {
sourceService = Executors.newCachedThreadPool(threadFactory);
} else {
sourceService = Executors.newFixedThreadPool(maxThreads, threadFactory);
} 所以, 查看这些线程发现这些线程:
堆栈跟踪:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)
说明线程池中的这些线程都在等任务工作, 既然大量的线程都在等任务,为什么还要创建这么多线程呢?是不是因为超过了单进程最大可建立的线程数呢,
结合ThriftSource源码,发现不指定最大线程数时, thrift server的线程池的确是不停的新建线程,而maxThreads又是一个Integer.MAX_VALUE,
if (maxThreads == 0) {
sourceService = Executors.newCachedThreadPool(threadFactory);
} else {
sourceService = Executors.newFixedThreadPool(maxThreads, threadFactory);
} 试着在flume 配置文件中指定最大线程数:
a1.channels.r1.threads=10 问题解决。
 这个问题的解决也让我们反思线程池的使用,不要设定太大的最大线程数。