一、确定慢请求是否突然暴增

查看RegionServer日志,搜索responseTooSlow,确认用户反馈的时间点是否出现慢请求。如果所有的RS在该时间点都没有明显的慢请求日志,可以让用户复查一下是否是其他因素导致的慢请求(大概率不是hbase的问题了)

慢请求参考日志:

2021-04-30 09:09:56,557 | WARN | RpcServer.FifoWFPBQ.default.handler=61,queue=21,port=16020 | (responseTooSlow): {``"call"``:``"Get(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$GetRequest)"``,``"starttimems"``:1619744995231,``"responsesize"``:2254,``"method"``:``"Get"``,``"param"``:"regi``on= profile_recommend_pic_recognition,ccccccc8,1616800548557.997b5a47cc0d3c1d50f31d44788f4315., row=d07f_2038231756``","``processingtimems``":1326,"``client``":"``10.244.19.241:35072``","``queuetimems``":0,"``class``":"``HRegionServer"} | org.apache.hadoop.hbase.ipc.RpcServer.logResponse(RpcServ``er.java:2546)

上面这条表示查询 profile_recommend_pic_recognition 表的时候出现慢请求,processingtimems 表示实际的处理时间(1326ms),queuetimems 请求在队列的排队时间(0ms)。这里我们可以看到,这条请求处理了1326毫秒。

如果确实出现了大量慢请求,就需要从各方面介入排查了。

如果看到大量的慢请求,也先不要慌,因为GC的缘故,偶尔也会有一些慢请求的出现,这是正常现象,我们可以通过以下命令查询历史各个时间点的慢请求数量,来判断当前时间点的慢请求数量是否正常。

# 查询各个分钟出现的慢请求数量``cat` `hbase-omm-regionserver-node-ana-corefGhl.log | ``grep` `"responseTooSlow"` `| ``awk` `-F``'[ :]+'` `'{print $1,$2,$3}'` `| ``uniq` `-c | ``less

关于慢请求日志,和配置hbase.ipc.warn.response.time有关,没有设置的话默认是10s。也就是说,如果一个请求超过了10s,就会输出上hbase的日志上

二、慢请求暴增可能的因素

以下的标题顺序按照可能性排序(比如第一个系统繁忙是最有可能导致慢请求突增的因素)

1、系统繁忙导致的慢请求

系统繁忙最常见的就是IO和CPU,对于历史的负载数据,可以看机器的历史指标,看是否有明显的尖刺等(和平时对比)。如果有尖刺,就需要分析导致IO高和CPU高的原因是什么了。大多数原因如下:

  • 用户请求短时间暴增
  • Hbase compact
  • 其他的一些潜在进程导致,这个通过top、iostat等命令排查,找出具体的进程然后关闭

关于系统繁忙根因排查可以见第三章

2、GC导致的慢请求

基本上大多数的慢请求都是GC导致的,具体的GC问题需要分析GC日志。

通过查看GC日志,我们可以很明显的看出在问题时间点是否有异常的STW停顿时间(如果gc日志看的比较吃力,可以将日志放到https://gceasy.io/上解析,会有比较可观的报表)。如果有长时间的停顿时间,就需要分析造成长时间的停顿的原因:

  • Full GC:出现Full gc就得排查服务本身是否有请求暴增或者是否有内存泄露等问题 (临时解决方案:重启RS服务)
  • 系统繁忙导致GC时间变长:这种一般要看一下当时的IO、CPU负载
  • 其他原因导致的长时间停顿(偏向锁等)

3、系统故障导致的慢请求

如果没有长时间GC,系统各方面指标也比较正常。那可能是硬件故障导致的。一般硬盘出现故障的概率比较大:

  • 通过 dmesg -T | grep ERROR 命令检测硬盘是否有问题,如果检测出来有问题就找相关的运维人员修复硬盘
  • 有时可能硬件没问题,但是文件系统出现问题。比如有次我们集群的硬盘目录无法正常写入数据(可以读取),验证这种情况我们可以往对应的硬盘目录写一份文件看看:touch /hbase/data1/test.log

这种情况一般只有个别机器会出现慢请求日志。如果所有机器都有大量慢请求日志,那大概率不是系统故障

4、HDFS因素

因为hbase的数据是存储在hdfs上,因此hdfs的读写性能也会影响到请求(不过系统负载、硬件故障都会反映到hdfs的读写性能上)。需要额外关注的就是NameNode和各节点Datanode的GC情况,查看是否出现长时间停顿(可以通过MRS和GC日志)

三、系统负载高根因排查

上面有说到系统繁忙会导致大量的慢请求,下面介绍一下当因为系统繁忙出现大量慢请求时,我们该如何快速定位导致系统繁忙的根因(这里主要介绍CPU和IO负载)。

1、CPU 持续飙高

通过top命令查看当前cpu负载

在这里插入图片描述

重点可以关注load average这个指标,通过这个值,可以大概了解当前cpu的负载情况(假设16核的机器,load average 32表示每个cpu大概要同时服务两个进程,此时的负载系数为 32/16=2,已经算相对比较繁忙了,如果负载系数超过5,则表示系统此时非常繁忙)。关于top命令的详解可以见:https://blog.csdn.net/u013332124/article/details/95731226

在确定了cpu负载高之后,我们通过top命令也可以看到哪些进程长时间占用cpu,然后进行进一步的分析。

对于java进行,我们可以进一步定位到具体哪个线程在占用cpu

  • 通过top确定占用大量cpu时间的进程ID
  • 通过top -H 确定占用大量cpu时间的线程ID
  • 通过 printf %x xxxx 输出16进制地址 (xxxx是对应的线程ID)
  • 通过 jstack -l yyyy 搜索上面的得到的16进制地址,就可以找到具体哪个线程在占用cpu

2、IO负载持续打满

通过 iostat -x 1 输出当前机器的IO负载情况:

在这里插入图片描述

重点可以看最后一列util,它代表了各个磁盘的当前利用率,当各个磁盘的util达到8-90%,甚至100%,说明当前IO磁盘的负载已经很高了。另外也可以看一下每秒的读请求数量和读的量,一般我们hbase-offline的磁盘读的tps到200+,读的量到2w+ kb/s,就会达到80%以上,以后也可以以这个为标准值来评估一下磁盘是否有问题(可能一些磁盘出现问题,很低的IO请求里就会导致util打高

在确定了当前IO负载高时,我们可以通过 iotop -o 来查看当前是哪些进程在大量占用IO资源:

在这里插入图片描述

需要留意的是,如果是Java 进程,最左边的TID显示的线程ID。我们可以通过 printf %x 线程ID的方式输出16进制地址,然后jstack -l javaPid 的方式去堆栈中找到具体哪个线程在占用IO资源。

3、导致 IO 负载升高的情况汇总

对大部分的慢请求场景来说,基本都是IO负载高导致的。因此我们看一下常见的导致IO负载高都有哪些情况

用户请求突增

这个比较好定位,可以去Hbase的HMaster页面查看一下各个region当前的请求数量,然后去MRS的曲线查看一下历史的请求数,对比一下是否存在请求突增的情况。

在这里插入图片描述

Hbase在进行大量compact

Hbase 的compact又分成minor compact和major compact,通常会造成系统繁忙的大多都是major compact。在compact的过程中,hbase需要读取旧文件的KV然后写入到新的文件中,因此如果有大量的compact线程在做compact,就会导致IO负载持续升高。

对于某台RegionServer是否在做compact可以看这台RegionServer的UI页面(会标记状态和持续时间):

在这里插入图片描述

PS:对于Major compact,因为它会占用大量的IO,因此通常线上环境建议关闭major compact(设置hbase.hregion.majorcompaction=0)。然后可以写个crontab在业务低峰期定时执行major compact

StoreFile 数量增多

在实际排查过程中,有发现请求数量没变(业务场景基本都是Get请求),也没compact,但是IO变高的情况。

通过arthas排查了下,发现落到磁盘的IO比平时变多了:

在attach到RegionSever进程后,先查看当前rpc get的请求数:

monitor org.apache.hadoop.hbase.regionserver.RSRpcServices get -c 1

在这里插入图片描述

之后再查看实际查询磁盘的请求数:

monitor org.apache.hadoop.hdfs.client.impl.BlockReaderLocal readAll -c 1

在这里插入图片描述
那这种会是什么原因呢?就目前看来,一般有两种原因:

1、一些访问量大的表StoreFile变多,一次请求要落到IO的次数就会变多

2、缓存命中率突然变低

对于第一种情况,我们可以先找出访问量最大的几张表,然后判断这些表的StoreFile数量近期是否提升。如果确定是由于StoreFile数量过多,可以手动执行major compact合并StoreFile(建议在业务低峰期执行)。

我们集群遇到这种情况,每周有3-4天集群IO负载就会变高,然后剩下的几天IO负载又会下来,请求量基本没太大变化。一开始怀疑是缓存导致的,后面多番排查才发现是由于我们每周在某一天凌晨会对表进行一次major compact,因此在这次major compact后,IO负载会有几天的较低值,后面随着数据由不断写入,StoreFile又开始增多,IO负载慢慢提升。

缓存命中率变低

如上面所说的情况,缓存命中率可以通过Hbase的页面查看。

比如原先2000个请求,缓存命中率50%,实际落到磁盘的请求也就1000。突然缓存命中率变成了10%,这时候会有2000 * 0.9 = 1800个请求落到磁盘,就会导致IO负载突增。

四、总结

在这里插入图片描述

Logo

为开发者提供学习成长、分享交流、生态实践、资源工具等服务,帮助开发者快速成长。

更多推荐