1. 首页
  2. 系列专栏
  3. 大数据框架

182、故障排除和调试HBase：日志

分类：大数据框架 标签：HBase 教程

日志

关键进程日志如下…（将 替换为启动服务的用户，将 替换为计算机名称）

NameNode： $ HADOOP_HOME / logs / hadoop- -namenode- .log

DataNode： $ HADOOP_HOME / logs / hadoop- -datanode- .log

JobTracker： $ HADOOP_HOME / logs / hadoop- -jobtracker- .log

TaskTracker： $ HADOOP_HOME / logs / hadoop- -tasktracker- .log

HMaster： $ HBASE_HOME / logs / hbase- -master- .log

RegionServer： $ HBASE_HOME / logs / hbase- -regionserver- .log

ZooKeeper：TODO

日志位置

对于独立部署，日志显然将位于单个计算机上，但这只是一个开发配置。生产部署需要在群集上运行。

NameNode

NameNode日志位于NameNode服务器上。HBase Master通常在NameNode服务器上运行，也可以在ZooKeeper上运行。

对于较小的群集，JobTracker/ResourceManager通常也在NameNode服务器上运行。

DataNode

每个DataNode服务器都有一个HDFS的DataNode日志，以及HBase的RegionServer日志。

此外，每个DataNode服务器还将具有用于MapReduce任务执行的TaskTracker/NodeManager日志。

日志级别

启用RPC级别日志记录

在RegionServer上启用RPC级别日志记录通常可以深入了解服务器的计时。启用后，记录的日志量很大。建议您不要将此登录时间保留在短时间。要启用RPC级别日志记录，请浏览到RegionServer UI并单击“日志级别”。将日志级别设置为包org.apache.hadoop.ipc的DEBUG（这对于hadoop.ipc这是正确的，对于hbase.ipc不是）。然后尾随RegionServers日志、分析。

要禁用，请将日志记录级别设置回INFO级别。

JVM垃圾回收日志

本节中的所有示例垃圾回收日志都基于Java 8输出。在Java 9和更新版本中引入统一的日志记录将导致非常不同的日志。

HBase是内存密集型的，使用默认的GC可以看到所有线程中的长时间暂停，包括Juliet Pause又名“GC of Death”。为了帮助调试或确认发生这种情况，可以在Java虚拟机中打开GC日志记录。

要在hbase-env.sh中启用，请取消注释以下行之一：

# This enables basic gc logging to the .out file.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps"

# This enables basic gc logging to its own file.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH>"

# This enables basic GC logging to its own file with automatic log rolling. Only applies to jdk 1.6.0_34+ and 1.7.0_2+.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=1 -XX:GCLogFileSize=512M"

# If <FILE-PATH> is not replaced, the log file(.gc) would be generated in the HBASE_LOG_DIR.

此时你应该看到这样的日志：

64898.952: [GC [1 CMS-initial-mark: 2811538K(3055704K)] 2812179K(3061272K), 0.0007360 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
64898.953: [CMS-concurrent-mark-start]
64898.971: [GC 64898.971: [ParNew: 5567K->576K(5568K), 0.0101110 secs] 2817105K->2812715K(3061272K), 0.0102200 secs] [Times: user=0.07 sys=0.00, real=0.01 secs]

在本节中，第一行表示CMS最初标记的0.0007360秒暂停。这将暂停整个VM，该段时间内的所有线程。

第三行表示“次要GC”，暂停VM 0.0101110秒 – 也就是10毫秒。它将“ParNew”从大约5.5m减少到576k。在这个循环的后期，我们看到：

64901.445: [CMS-concurrent-mark: 1.542/2.492 secs] [Times: user=10.49 sys=0.33, real=2.49 secs]
64901.445: [CMS-concurrent-preclean-start]
64901.453: [GC 64901.453: [ParNew: 5505K->573K(5568K), 0.0062440 secs] 2868746K->2864292K(3061272K), 0.0063360 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
64901.476: [GC 64901.476: [ParNew: 5563K->575K(5568K), 0.0072510 secs] 2869283K->2864837K(3061272K), 0.0073320 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]
64901.500: [GC 64901.500: [ParNew: 5517K->573K(5568K), 0.0120390 secs] 2869780K->2865267K(3061272K), 0.0121150 secs] [Times: user=0.09 sys=0.00, real=0.01 secs]
64901.529: [GC 64901.529: [ParNew: 5507K->569K(5568K), 0.0086240 secs] 2870200K->2865742K(3061272K), 0.0087180 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
64901.554: [GC 64901.555: [ParNew: 5516K->575K(5568K), 0.0107130 secs] 2870689K->2866291K(3061272K), 0.0107820 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
64901.578: [CMS-concurrent-preclean: 0.070/0.133 secs] [Times: user=0.48 sys=0.01, real=0.14 secs]
64901.578: [CMS-concurrent-abortable-preclean-start]
64901.584: [GC 64901.584: [ParNew: 5504K->571K(5568K), 0.0087270 secs] 2871220K->2866830K(3061272K), 0.0088220 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
64901.609: [GC 64901.609: [ParNew: 5512K->569K(5568K), 0.0063370 secs] 2871771K->2867322K(3061272K), 0.0064230 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
64901.615: [CMS-concurrent-abortable-preclean: 0.007/0.037 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
64901.616: [GC[YG occupancy: 645 K (5568 K)]64901.616: [Rescan (parallel) , 0.0020210 secs]64901.618: [weak refs processing, 0.0027950 secs] [1 CMS-remark: 2866753K(3055704K)] 2867399K(3061272K), 0.0049380 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
64901.621: [CMS-concurrent-sweep-start]

第一行表示CMS并发标记（查找垃圾）花费了2.4秒。但这是一个并发的2.4秒，Java在任何时候都没有被暂停。

还有一些较小的GC，然后在最后一行停顿：

64901.616: [GC[YG occupancy: 645 K (5568 K)]64901.616: [Rescan (parallel) , 0.0020210 secs]64901.618: [weak refs processing, 0.0027950 secs] [1 CMS-remark: 2866753K(3055704K)] 2867399K(3061272K), 0.0049380 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]

这里的暂停是0.0049380秒（也就是4.9毫秒）来“注释”堆。

此时扫描开始，您可以观察到堆大小下降：

64901.637: [GC 64901.637: [ParNew: 5501K->569K(5568K), 0.0097350 secs] 2871958K->2867441K(3061272K), 0.0098370 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
...  lines removed ...
64904.936: [GC 64904.936: [ParNew: 5532K->568K(5568K), 0.0070720 secs] 1365024K->1360689K(3061272K), 0.0071930 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
64904.953: [CMS-concurrent-sweep: 2.030/3.332 secs] [Times: user=9.57 sys=0.26, real=3.33 secs]

此时，CMS扫描需要3.332秒，堆从大约2.8 GB到大约1.3 GB（近似值）。

这里的关键点是保持所有这些暂停低。CMS暂停总是很低，但如果您的ParNew开始增长，您可以看到较小的GC暂停接近100ms，超过100ms并达到400ms的高位。

这可能是由于ParNew的大小，它应该相对较小。如果你的ParNew在运行HBase一段时间后非常大，在一个例子中ParNew大约是150MB，那么你可能不得不约束ParNew的大小（它越大，集合采取的时间越长，但是如果它太小，对象太快被提升为老一代）。在下面我们将新的基因大小限制在64m。

在hbase-env.sh中添加以下行：

export SERVER_GC_OPTS="$SERVER_GC_OPTS -XX:NewSize=64m -XX:MaxNewSize=64m"

同样，要为客户端进程启用GC日志记录，请取消注释hbase-env.sh中的以下某行：

# This enables basic gc logging to the .out file.
# export CLIENT_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps"

# This enables basic gc logging to its own file.
# export CLIENT_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH>"

# This enables basic GC logging to its own file with automatic log rolling. Only applies to jdk 1.6.0_34+ and 1.7.0_2+.
# export CLIENT_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=1 -XX:GCLogFileSize=512M"

# If <FILE-PATH> is not replaced, the log file(.gc) would be generated in the HBASE_LOG_DIR .