一次RegionServer GC导致会话超时下线的原因分析记录
来源:互联网 发布:中国房产数据 编辑:程序博客网 时间:2024/05/20 04:09
查看了regionserver的log日志:
2017-10-30 03:18:02,718 INFO SecurityLogger.org.apache.hadoop.hbase.Server: Connection from 172.16.4.36 port: 38016 with unknown version info2017-10-30 03:20:32,334 WARN org.apache.hadoop.hdfs.DFSClient: DFSOutputStream ResponseProcessor exception for block BP-1954737973-172.16.4.81-1498561284109:blk_1237675060_163934648java.io.EOFException: Premature EOF: no length prefix availableat org.apache.hadoop.hdfs.protocolPB.PBHelper.vintPrefixed(PBHelper.java:2274)at org.apache.hadoop.hdfs.protocol.datatransfer.PipelineAck.readFields(PipelineAck.java:235)at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:1076)2017-10-30 03:20:32,335 INFO org.apache.hadoop.hbase.ScheduledChore: Chore: MovedRegionsCleaner for region my-hbase-srv3,60020,1506017784241 missed its start time2017-10-30 03:20:32,335 WARN org.apache.hadoop.hdfs.DFSClient: Error Recovery for block BP-1954737973-172.16.4.81-1498561284109:blk_1237675060_163934648 in pipeline DatanodeInfoWithStorage[172.16.4.94:50010,DS-153f2b54-c56c-461c-8983-e5b79cf7a248,DISK],DatanodeInfoWithStorage[172.16.4.69:50010,DS-d07aff02-28cf-4467-b089-5d1209614520,DISK], DatanodeInfoWithStorage[172.16.4.78:50010,DS-8a1665ae-7475-4a76-ae86-b61f5a765e98,DISK]: bad datanode DatanodeInfoWithStorage[172.16.4.94:50010,DS-153f2b54-c56c-461c-8983-e5b79cf7a248,DISK]2017-10-30 03:20:32,335 INFO org.apache.zookeeper.ClientCnxn: Client session timed out, have not heard from server in 168668ms for sessionid 0x25e189c7145bef4, closing socket connection and attempting reconnect2017-10-30 03:20:32,335 WARN org.apache.hadoop.hbase.util.Sleeper: We slept 150703ms instead of 3000ms, this is likely due to a long garbage collecting pause and it's usually bad, see http://hbase.apache.org/book.html#trouble.rs.runtime.zkexpired 2017-10-30 03:20:32,334 INFO org.apache.hadoop.hbase.ScheduledChore: Chore: my-hbase-srv3,60020,1506017784241-MemstoreFlusherChore missed its start time2017-10-30 03:20:32,334 INFO org.apache.hadoop.hbase.ScheduledChore: Chore: CompactionChecker missed its start time2017-10-30 03:20:32,334 INFO org.apache.hadoop.hbase.regionserver.HRegion: Flushing 1/1 column families, memstore=5.97 KB2017-10-30 03:20:32,334 INFO org.apache.hadoop.hbase.regionserver.HRegion: Flushing 1/1 column families, memstore=1.70 MB2017-10-30 03:20:32,334 INFO org.apache.zookeeper.ClientCnxn: Client session timed out, have not heard from server in 153223ms for sessionid 0x35e189c9b1ec599, closing socket connection and attempting reconnect2017-10-30 03:20:32,345 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: my-hbase-srv3,60020,1506017784241-MemstoreFlusherChore requesting flush of regionInfoKey,1469435548521.6b7e508e911c49cfbd64cf1baa4cadc3. because cfInfo has an old edit so flush to free WALs after random delay 125058ms2017-10-30 03:20:32,345 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: my-hbase-srv3,60020,1506017784241-MemstoreFlusherChore requesting flush of regionInfoKey,1502792046466.9fcb0c6de90135cf5d8791722410e6af. because cfInfo has an old edit so flush to free WALs after random delay 188675ms2017-10-30 03:20:32,345 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: my-hbase-srv3,60020,1506017784241-MemstoreFlusherChore requesting flush of regionInfoKey,1478593853887.0c94226b4cd94058b58daab02b7e184e. because Info has an old edit so flush to free WALs after random delay 20466ms2017-10-30 03:20:32,345 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: my-hbase-srv3,60020,1506017784241-MemstoreFlusherChore requesting flush of regionInfoKey,1499557430610.4ac8c97fadd652f676a803688d2ff07e. because cfInfo has an old edit so flush to free WALs after random delay 241441ms2017-10-30 03:20:32,344 INFO org.apache.hadoop.hbase.ScheduledChore: Chore: my-hbase-srv3,60020,1506017784241-HeapMemoryTunerChore missed its start time2017-10-30 03:20:32,344 INFO SecurityLogger.org.apache.hadoop.hbase.Server: Auth successful for root (auth:SIMPLE)2017-10-30 03:20:32,346 INFO SecurityLogger.org.apache.hadoop.hbase.Server: Connection from 172.16.4.114 port: 59124 with version info: version: "0.98.17-hadoop2" url: "git://aspire/home/apurtell/src/hbase" revision: "d5f8300c082a75ce8edbbe08b66f077e7d663a4a" user: "apurtell" date: "Fri Jan 15 22:49:31 PST 2016" src_checksum: "6e40b5bc9a3782b583c36af66806049d"2017-10-30 03:20:32,344 INFO SecurityLogger.org.apache.hadoop.hbase.Server: Auth successful for root (auth:SIMPLE)2017-10-30 03:20:32,344 WARN org.apache.hadoop.hbase.util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 148967msGC pool 'ParNew' had collection(s): count=1 time=99msGC pool 'ConcurrentMarkSweep' had collection(s): count=2 time=149192ms
然后就是一系列的由上面的错误导致的相关的错误。
这里看到了GC时间太长(153s>60s),导致regionServer的zkSession会话超时,然后认为regionServer下线。
这里应该是因为当时有个任务写入数据太多,
大量的数据进入Memstore,占用内存过大,达到了某个临界值,进行了数据刷新到hfile的操作,然后GC操作回收内存。
下面看看一些memStore的刷新数据到hfile的条件:
1、MemStore达到上限hbase.hregion.memstore.flush.size 默认是128M的时候,会触发MemStore的刷新。这个参数表示单个MemStore的大小的阈值。这个时候是不阻塞写操作的。
2、当一个Region的MemStore总量达到hbase.hregion.memstore.block.multiplier * hbase.hregion.memstore.flush.size(默认2*128M=256M)时,会阻塞这个region的写操作,并强制刷写到HFile。触发这个刷新只会发生在MemStore即将写满128M时put了一个巨大的记录的情况,这时会阻塞写操作,强制刷新成功才能继续写入。
3、一个RegionServer会有很多个Region,很多的MemStore,所以可能单个Region并没有超过阈值,但是整个RegionServer的内存已经占用非常多了,这时候还有另外两个参数控制内存的刷写:hbase.regionserver.global.memstore.upperLimit 默认0.4,当RegionServer上全部的MemStore占用超过heap(heap的大小在hbase-env.sh中设置HBASE_HEAPSIZE,默认1G,我们设置的4G)的40%时,强制阻塞所有的写操作,将所有的MemStore刷写到HFile;hbase.regionserver.global.memstore.lowerLimit 默认0.35,表示所有的MemStore占用超过heap的35%时,会选择一些占用内存比较大的MemStore阻塞写操作并进行flush,这是为了降低阻塞全部写操作flush带来的问题。
4、当HLog达到最大值(hbase.regionserver.maxlogs * hbase.regionserver.hlog.blocksize 默认32*64M = 2G)时,也会触发MemStore的刷新,强制将更新固化到HFile中,避免在RegionServer crash时恢复时间过长。
5、定期会进行MemStore的刷新,hbase.regionserver.optionalcacheflushinterval 默认3600000,一小时,确保MemStore的数据不会长时间没有固化到HFile中。为避免所有的MemStore在同一时间都进行flush导致的问题,定期的flush操作有20000左右的随机延时。
6、手工可以进行flush操作,在hbase shell调用flush,可以针对某个表或者某个region进行flush:
hbase(main):010:0> help 'flush'
Flush all regions in passed table or pass a region row to
flush an individual region. For example:
hbase> flush 'TABLENAME'
hbase> flush 'REGIONNAME'
7、手工flush:
在API中只看到有setMemStoreFlushSize 指定memstore flush到HDFS上的文件大小,默认是64M,不确定是否可以直接触发flush MemStore。
结论:
从cm监控看到 该regionserver的图标数据,由于比较大的数据加载(归根于region分布不均导致的)hbase堆内存短时间内陡增
从上面判断应该是超过了 hbase.regionserver.global.memstore.upperLimit(默认0.4) * RegionServer 的heap size。 (不好意思图片丢了)
,然而GC发生,最后导致zookeeper会话超时。
建议
1 采用预先创建region分区,尽量分布到各个节点上,我这region分布不均匀是因为集群迁移之后扩容导致的。后面看看如何将region迁移到其他的节点上。
2 最后应该进行添加集群的监控,当重启regionserver下线时候进行报警或者是重启。
- 一次RegionServer GC导致会话超时下线的原因分析记录
- zookeeper的maxSessionTimeout默认值导致hbase regionserver超时
- 记一次多次智商下线导致的奇耻大辱
- 一次Full GC 过程的日志分析
- 记录一次项目引用导致的StackOverflowError
- RegionServer异常超时检测
- 一次exp导出出错的原因分析
- PtSetResource() 导致 Memory fault 的原因分析
- Master只能控制其中1台RegionServer,无法控制其它RegionServer原因分析
- hbase多用户入库,regionserver下线问题
- 数据库日志文件自动增长导致连接超时的分析
- Tomcat会话超时的配置
- Tomcat会话超时的配置
- 一次windows漏洞导致的ora-07445错误整修记录
- 记录一次被keil优化导致程序异常的案例
- 一次故障记录keepalived配置疏忽导致的故障
- 优化hbase JVM GC 参数,避免由于JVM内存回收引发的ZooKeeper会话超时进程退出事件
- 一次显式GC导致的High CPU问题处理过程
- mysql乐观锁总结和实践
- css 中让多行内容垂直居中的方法
- 用Maven创建第一个web项目
- 学习笔记——吴恩达-机器学习课程-1.3 用神经网络进行监督学习
- 如何才能写好代码,做到以下几点即可
- 一次RegionServer GC导致会话超时下线的原因分析记录
- 验证手机号码工具类
- Jmeter如何更好的组织脚本结构进行接口测试
- 《Greenplum5.0 最佳实践》 内存与资源队列 (四)
- 用kibana consle 替代sense
- ElasticSearch IK中文分词器安装
- adb调试相关命令
- 机器学习基础04-凸优化
- PL/SQL 取每个分组第N条记录