又到周天了啊！每次到周天都会有问题啊啊啊！加班，加班，呃呃呃，本来已经想好了，这个周天，红烧老鳖，搞点豆瓣酱爆出红油，再来点青红二荆条什么的，哇，肯定好看又好吃。但是，XXX啊这个问题你要解决啊，下周一大家都等着用数据。。。。。
我不知道大家知不知道？
我身边的程序员一般都是特别敬岗爱业，长的特别好看，说话特别好听，职业道德又特别高尚的人，电话秒接，信息秒回，一年365天一天24小时，从不关机，随叫随到，加班不要钱，多么无私啊。除此之外我还是一个特别特别特别喜欢解决问题的人，有成就感啊，不然程序员这勾当，敲敲代码，改改配置，整整文档，接接电话，发发信息，拍拍照片，上上厕所，吃吃面条，也就太无趣了，，，
这原本是一个很基础，很常规，很简单的问题，但最近人家晚上一个人很无聊（啊説的好像以前有两个人似的）想写写博客呀
其实也不会写啦，总是前言不搭后语，逻辑混乱，思维跳跃,但事在人为嘛，，，
废话ZJE多啊，整理下发型，言归正传
整理发型中……..
整理发型中…………
整理发型中…………….
整理发型中………………
整理发型中…………………..
整理完毕。。。。。。。。。。。。。。。
现场同事反应，启动了十几个flume的file2kafka进程去把本地目录下的文件接入到kafka，但是程序处理数据却极慢，一天一个进程才处理20G的文件，一个文件1G左右。在公司大概问了下现场的情况，并没有做数据转换的动作，应该是很快的，所以起初怀疑是数据积压太多，已经从pagecache落盘，启动了太多进程读磁盘，一下达到了磁盘的性能瓶颈，但到现场top了一下发现不是这么回事，失误，失误
来来来，让你们见识见识咱们这普普通通256G内存，48核CPU，万兆网卡，(啥盘啊?sorry没关注过唉)的服务器，有了这服务器，咱们平常代码那就是仨个字，随便写，放开了写，内存我有，cpu我有，什么服务器不够，再来10台，，，
top如下:
服务器一切正常，swap为0，iowait为0，cpu使用率也不是很高，对不起我根本没看网络，咱万兆网卡还是光纤啊，如果负载比较高还要用iostat vmstat dstat iotop iftop netstat lsof等命令XJB去查看磁盘，内存，网络的具体情况
fullgc会导致cpu使用率突然飙升，看了一会cpu使用很稳定，jstat -gcutil 确认一下fullgc基本没有，不应该一天才处理20G的数据啊！看了下日志程序也一直在跑，但日志级别是debug，到这一个老司机应该就大致知道是什么问题了
接下来随便挑了一个看着顺眼的pid ，top -Hp 37205看下这个进程中各个线程的情况，如下
这个进程内一共有67个线程，有2个正在运行，top默认是按cpu占用率排序，有3个线程cpu占用率较高，这个flume进程内有两个工作线程，一个扫描目录读文件并进行数据处理的DirectorySource线程，一个写数据到kafka的kafkaSink线程，由于kafka客户端生产者接口内部还会启动一个kafkaProducer的网络IO线程，做实际数据的写入，所以一共会有3个工作线程
要想知道这3个线程中的那个是DirectorySource线程，那个是KafkaSink线程，那个是kafkaProducer网络IO线程，我们还需
jstack 37205 > 37205.jstack一下
我们把第一个线程id 37521转换成16进制得到0x9291
然后vi 37205.jstack输入 /0x9291找到此线程的堆栈如下：
由函数调用栈可知这个线程是kafkaProducer网络IO线程，在我的印象中kafka的生产者异步写是很高效的，虽然flume的KafkaSink使用的是同步写但也不会cpu吃到84%一天才写20G数据，这个线程正在打debug日志，问题很可能就出在了打debug日志上，在函数调用栈中我们还可以看到在写日志时会获取锁做同步
咱们strace -p 37521如下：
可以看到kafkaProcucer网络IO线程基本上是在获得锁（futex用户空间快速锁）而write的大部分是日志文件，木好意思，还少了张图忘拍了，ll /proc/37521/fd/294，可知fd 294是日志文件，由此我们可以知道大量的write写的是日志文件而不是写socket发送数据到kafka，由于写日志用的是行缓冲，每当遇到换行时就会调用系统调write，把jvm堆内存缓冲的数据写到磁盘的pagecache，如果用全缓冲，当buffer满后再写到磁盘，就会出现日志刷一半显示不全，或写的日志没填满缓冲区，tail日志时看不到日志的现象，体验感极差。而且一行日志才180字节左右，大量频繁的这种系统调用无疑又拖慢了线程的运行速度，在我映像中write这种系统调用每秒60W次不是问题
到这咱们其实就可以结束了，直接调整日志级别到INFO，重启收工，不打日志线程就不会去获取锁就不会write文件了啊，节约下来的时间就可以用来写数据到kafka了啊，不就可以一路狂奔了？单位时间内处理的数据不就上去了？
接下来咱们看下第二个线程的堆栈，37522转16进制得0x9292
vi 37205.jstack输入/0x9292找到此线程的堆栈如下
由函数调用栈我们可知此线程是flume的kafkaSink线程，并且此线程在打debug日志做同步时没获取到锁而被挂起了
到这咱们其实就可以结束了，直接调整日志级别到INFO，重启收工，不打日志线程就不会去获取锁就不会write文件了啊，节约下来的时间就可以用来写数据到kafka了啊，不就可以一路狂奔了？单位时间内处理的数据不就上去了？
接下来咱们看下第三个线程的堆栈，37502转16进制得0x927e
vi 37205.jstack输入/0x927e找到此线程的堆栈如下
由函数调用栈可知此线程是DirectorySource线程，此线程在进行事务的commit时由于没有获取到资源被挂起了，而此线程的调用栈中是没有打印debug日志的，查看DirectorySource源码发现在业务处理逻辑中是没有打degug日志，但它不应该很快？毕竟不用获取锁，不用write啊
Strace一下
发现此线程很少read数据98%的时间都是在等待获取锁
此线程cpu占用率是11%，是3个线程中占用最少的，此线程也是数据的源头，如果能把此线程的cpu占用率提高，那么单个进程一天处理的数据就会增加
为什么DirecotrySource线程没打debug日志，但是却在事务commit时被挂起了？
我们来看下flume数据处理的流程
首先source线程从外部读取数据，调用注册的interceptor进行拦截进行业务处理，然后把数据放入channel（配置的是MemoryChannel，就是一个LinkedBlockingDeque），最后sink线程从channel拿取数据输出到外部
现在线程卡在了把数据放入channel，可以排除是业务代码的问题，我们看下flume的MemoryChannel事务commit的代码
此段代码的大意就是，判断此次事务commit前，sink从channel拿走的数据所占用的空间是否可以容纳此次事务commit前source放入的数据，如果不可以就tryAcquire尝试获取空间（其实就是等待sink取走数据）
tryAcquire代码如下
当获取不到时就会等待，这个等待时长我们配置的是10s，到此整个问题的前因后果已经很明了了
由于kafkaSink线程会频繁的打印debug日志，kafkaProducer网络io线程也会频繁的打印debug日志，两个线程在争用同一把保护日志文件的锁时，kafkaSink线程有时还会获取不到锁，导致kafkaSink线程会被挂起等待，从而导致kafkaSink线程从channel消费数据的速度小于DirectorySource线程生产速度，等到chnnel的剩余空间无法容纳DirectorySource线程生产的数据时，DirectorySource就只能停下来等待，如果10s内还没有空间，就抛出异常，就出现了，这一现象，DirectorySource线程很少read数据
OK，更改日志级别为INFO，重启top如下
猜猜这次那个线程的cpu占用率会最高？
第一个线程pid 40870转16进制得0x9fa6 线程堆栈如下：
由函数调用栈可知这个cpu占用率最高的线程是DirectorySource线程，处于正在运行状态，在日志级别是debug时这个线程的cpu占用率是最低的
strace如下
我们看到read从之前的0.81%提升到了24.12%，futex从98.24%降到了48.28%
第二个线程pid 40872转16进制得0x9fa8 线程堆栈如下：
由函数调用栈可知这个线程是kafkaProducer网络IO线程，处于正在运行状态
第三个线程pid 40873转16进制得0x9fa9 线程堆栈如下：
由函数调用栈可知这个线程是kafkaSink线程，由于kafkaSink在写完一批数据到kafka并确认写成功后才会进行事务的commit，所以kafkaSink写数据时是以同步的方式写的，当写完数据后获取kafka ack的同步调用结果时被挂起了
至此我们已经没有什么可以再调整的了，source线程的生产与sink线程的消费速度基本匹配，sink线程还有盈余