SNN web页面加载缓慢

发表于 2015-04-16

我们的SNN已经运行很长时间了。中间发生过几次failover。
最近打开web页面的时候非常卡。因为Loading edits的条目非常多，日积月累。
其实重启下就可以了。但还是要从代码里研究下。顺便整理下SNN的作用。

在一个HA的集群中，StandbyNN负责以前SecondaryNN的工作：合并editlog、做checkpoint。
ANN与SNN之间通过JN分享editlog。

合并editlog

在HA的情况下，standbyNN中有一个线程EditLogTailerThread每隔一段时间（dfs.ha.tail-edits.period，单位秒，默认60）从JN中读取editlog合并到fsimage里（此时fsimage在内存中）。这是为了保持SNN和ANN的状态一致，应对随时可能的failover。
实际上SNN的状态还是会稍微落后于ANN的，但不会落后太多。

SNN读取editlog的日志：

1
2
3
4
5
2015-04-15 10:38:26,177 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream@3486113d expecting start txid #52576338
2015-04-15 10:38:26,177 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Start loading edits file http://inspur122.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269, http://inspur129.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269
2015-04-15 10:38:26,177 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream 'http://inspur122.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269, http://inspur129.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269' to transaction ID 52576338
2015-04-15 10:38:26,177 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream 'http://inspur122.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269' to transaction ID 52576338
2015-04-15 10:38:26,196 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file http://inspur122.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269, http://inspur129.photo.163.org:8480/getJournal?jid=hp1&segmentTxId=52576338&storageInfo=-47%3A200695073%3A1406364468930%3ACID-ae986bcb-6ca9-40c3-a54b-ff20c5b14269 of size 13723 edits # 114 loaded in 0 seconds

EditLogTailerThread同时负责触发rollEditLog。这个线程每次运行时，如果距离上次rollEditLog的时间超过dfs.ha.log-roll.period（单位秒，默认120），就触发一次rollEditLog（通过RPC协议NamenodeProtocol。这个协议是用于ANN与SNN间通信的）。

相关代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
private void doWork() {
      while (shouldRun) {
        try {
          // 检查距离上次rollEditLog的间隔是否超过2分钟（dfs.ha.log-roll.period）
          // There's no point in triggering a log roll if the Standby hasn't
          // read any more transactions since the last time a roll was
          // triggered. 
          if (tooLongSinceLastLoad() &&
              lastRollTriggerTxId < lastLoadedTxnId) {
            triggerActiveLogRoll();
          }
          /**
           * Check again in case someone calls {@link EditLogTailer#stop} while
           * we're triggering an edit log roll, since ipc.Client catches and
           * ignores {@link InterruptedException} in a few places. This fixes
           * the bug described in HDFS-2823.
           */
          if (!shouldRun) {
            break;
          }
          // 从JN中读取editlog并合并到内存中的fsimage里
          doTailEdits();
        } catch (EditLogInputException elie) {
          LOG.warn("Error while reading edits from disk. Will try again.", elie);
        } catch (InterruptedException ie) {
          // interrupter should have already set shouldRun to false
          continue;
        } catch (Throwable t) {
          LOG.fatal("Unknown error encountered while tailing edits. " +
              "Shutting down standby NN.", t);
          terminate(1, t);
        }
        try {
          // sleep 1分钟（dfs.ha.tail-edits.period）
          Thread.sleep(sleepTimeMs);
        } catch (InterruptedException e) {
          LOG.warn("Edit log tailer interrupted", e);
        }
      }
    }

所谓的rollEditLog操作就是ANN将内存中的editlog刷到磁盘上，重命名文件，同时txid++，生成一个新的edit文件开始写，以我们的测试集群为例：

1
2
3
4
5
6
7
8
9
10
11
hadoop@inspur129:~$ ls -lh /mnt/dfs/0/hdfs/name/current | tail
-rw-r--r-- 1 root root  20K  4月 15 11:30 edits_0000000000052577094-0000000000052577263
-rw-r--r-- 1 root root  30K  4月 15 11:32 edits_0000000000052577264-0000000000052577515
-rw-r--r-- 1 root root 6.8K  4月 15 11:34 edits_0000000000052577516-0000000000052577562
-rw-r--r-- 1 root root 1.0M  4月 15 11:34 edits_inprogress_0000000000052577563
-rw-r--r-- 1 root root  17M  4月 15 09:47 fsimage_0000000000052575292
-rw-r--r-- 1 root root   62  4月 15 09:47 fsimage_0000000000052575292.md5
-rw-r--r-- 1 root root  17M  4月 15 10:47 fsimage_0000000000052576563
-rw-r--r-- 1 root root   62  4月 15 10:47 fsimage_0000000000052576563.md5
-rw-r--r-- 1 root root    9  4月 15 11:34 seen_txid
-rw-r--r-- 1 root root  216  4月 14 16:45 VERSION

可见这种edits_xxx的文件都是每2分钟生成一个。（因为测试集群读写少，合并editlog时间可以忽略不计，线上集群就不一定了）
rollEditLog后，对应的txid就可以被SNN读到了（通过JN的“中转”）。
rollEditLog的逻辑见FSImage.rollEditLog()方法。

SNN页面加载缓慢就是因为它把每次EditLogTailerThread读取的editlog都显示在页面上了
时间长了，条目会非常多。

做checkpoint

关于checkpoint，Cloudera Blog讲得很清楚。
checkpoint的作用就是合并editlog到fsimage。editlog有点类似hbase中的WAL。

触发checkpoint的条件：

  1. 上次checkpoint后经过一定时间（dfs.namenode.checkpoint.period，默认3600秒）。
  2. 未合并的事务数达到某个值（dfs.namenode.checkpoint.txns，这个值很大，一般达不到）。

有一个线程每60秒（dfs.namenode.checkpoint.check.period）运行一次，检查是否满足上面任意一个条件，满足则开始checkpoint。

我以前一直以为是触发checkpoint后再合并editlog。但根据上面的分析，SNN是每隔1分钟就合并一次的。所以checkpoint过程就很简单了，其实就是先saveNameSpace，将内存中的fsimage写到磁盘上，然后通知ANN来拉取（我没记错的话应该是这样）。checkpoint时没有合并editlog的步骤了，省时间。checkpoint相关逻辑见StandbyCheckpointer类。

关于checkpoint要注意的几个问题：

  1. 如果fsimage传输的速度太慢，超过dfs.image.transfer.timeout（默认10分钟），SNN会认为checkpoint失败，1分钟之后又会触发checkpoint，再失败、再触发，一直这样循环。我们以前ANN和SNN网络比较慢，碰到过这个问题。另外，传输fsimage时可以设置带宽上限（dfs.image.transfer.bandwidthPerSec）。
  2. 在fsimage传输过程中，failover会部分失败：可能出现脑裂，一个NN进程会自杀。我们也碰到过。这是个bug：HDFS-4816。
  3. 在SNN做checkpoint的过程中，zkfc会认为SNN挂掉了。。。这是个bug：HDFS-6184。zkfc的检查机制见以前的文章。观察zkfc的日志可以看到SNN的状态在SERVICE_NOT_RESPONDING和SERVICE_HEALTHY之间变化，周期和checkpoint的周期一致。SERVICE_NOT_RESPONDING时zkfc会重新发起选举，试图让当前节点成为standby。但当前节点本来就是standby，所以无影响。只有zkfc的日志中能看到异常。一切正常的话，zkfc进程不应该产生任何日志。
#hadoop #namenode #HA #checkpoint #运维
Kerberos豆知识
HA集群中如何判断ActiveNN