Hadoop HA主备切换导致JournalNode epoch增加的函数调用流程

切换至active namenode执行日志

2021-12-07 08:08:19,784 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Stopping services started for standby state
2021-12-07 08:08:19,786 WARN org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Edit log tailer interrupted
java.lang.InterruptedException: sleep interrupted
        at java.lang.Thread.sleep(Native Method)
        at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:469)
        at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$300(EditLogTailer.java:399)
        at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:416)
        at org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:482)
        at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:412)
2021-12-07 08:08:19,790 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Starting services required for active state
2021-12-07 08:08:19,803 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Starting recovery process for unclosed journal segments...
2021-12-07 08:08:19,888 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Successfully started new epoch 1407
2021-12-07 08:08:19,888 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Beginning recovery of unclosed segment starting at txid 6287063928
2021-12-07 08:08:19,921 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Recovery prepare phase complete. Responses:
172.18.21.201:8485: segmentState { startTxId: 6287063928 endTxId: 6287064037 isInProgress: false } lastWriterEpoch: 1406 lastCommittedTxId: 6287064037
172.18.21.203:8485: segmentState { startTxId: 6287063928 endTxId: 6287064037 isInProgress: false } lastWriterEpoch: 1406 lastCommittedTxId: 6287064037
172.18.21.204:8485: segmentState { startTxId: 6287063928 endTxId: 6287064037 isInProgress: false } lastWriterEpoch: 1406 lastCommittedTxId: 6287064037
2021-12-07 08:08:19,922 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Using longest log: 172.18.21.201:8485=segmentState {
  startTxId: 6287063928
  endTxId: 6287064037
  isInProgress: false
}
lastWriterEpoch: 1406
lastCommittedTxId: 6287064037

2021-12-07 08:08:19,974 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Recovering unfinalized segments in /var/lib/hadoop/data/vol1/namenode/current
2021-12-07 08:08:20,070 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /var/lib/hadoop/data/vol1/namenode/current/edits_inprogress_0000000006286833303 -> /var/lib/hadoop/data/vol1/namenode/current/edits_0000000006286833303-0000000006286833656
2021-12-07 08:08:20,088 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Catching up to latest edits from old active before taking over writer role in edits logs
2021-12-07 08:08:20,093 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream@70abca62 expecting start txid #6287063928
2021-12-07 08:08:20,093 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Start loading edits file http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal4:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true maxTxnsToRead = 9223372036854775807
2021-12-07 08:08:20,093 INFO org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream: Fast-forwarding stream 'http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal4:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true' to transaction ID 6287063928
2021-12-07 08:08:20,093 INFO org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream: Fast-forwarding stream 'http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true' to transaction ID 6287063928
2021-12-07 08:08:20,099 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal4:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287063928&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true of size 14917 edits # 110 loaded in 0 seconds
2021-12-07 08:08:20,099 INFO org.apache.hadoop.hdfs.server.blockmanagement.DatanodeManager: Marking all datanodes as stale
2021-12-07 08:08:20,100 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Processing 903 messages from DataNodes that were previously queued during standby state
2021-12-07 08:08:20,101 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521789585_774208590 on 172.18.21.59:9866: ignoring it, since it is complete with the same genstamp
2021-12-07 08:08:20,101 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521785497_774203360 on 172.18.21.59:9866: ignoring it, since it is complete with the same genstamp
2021-12-07 08:08:20,101 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521789573_774208643 on 172.18.21.59:9866: ignoring it, since it is complete with the same genstamp
2021-12-07 08:08:20,102 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521789474_774208636 on 172.18.21.40:9866: ignoring it, since it is complete with the same genstamp
2021-12-07 08:08:20,102 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521908707_774522463 on 172.18.21.12:9866: ignoring it, since it is complete with the same genstamp
2021-12-07 08:08:20,102 INFO org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: Received an RBW replica for blk_1521908707_774522463 on 172.18.21.18:9866: ignoring it, since it is complete with the same genstamp

切换至standby namenode执行日志

2021-12-07 08:08:18,331 INFO org.apache.hadoop.util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 5626ms
GC pool 'PS MarkSweep' had collection(s): count=1 time=5914ms
2021-12-07 08:08:18,335 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Took 5924ms to send a batch of 2 edits (50 bytes) to remote journal 172.18.21.202:8485
2021-12-07 08:08:18,336 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Took 5924ms to send a batch of 2 edits (50 bytes) to remote journal 172.18.21.203:8485
2021-12-07 08:08:18,337 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Took 5926ms to send a batch of 2 edits (50 bytes) to remote journal 172.18.21.204:8485
2021-12-07 08:08:18,342 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Took 5930ms to send a batch of 2 edits (50 bytes) to remote journal 172.18.21.205:8485
2021-12-07 08:08:18,351 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Took 5940ms to send a batch of 2 edits (50 bytes) to remote journal 172.18.21.201:8485
2021-12-07 08:08:19,743 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Stopping services started for active state
2021-12-07 08:08:19,744 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 6287063928, 6287064036
2021-12-07 08:08:19,744 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: NameNodeEditLogRoller was interrupted, exiting
2021-12-07 08:08:19,744 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: LazyPersistFileScrubber was interrupted, exiting
2021-12-07 08:08:19,765 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 110 Total time for transactions(ms): 6 Number of transactions batched in Syncs: 23 Number of syncs: 87 SyncTimes(ms): 6270 774
2021-12-07 08:08:19,769 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /var/lib/hadoop/data/vol1/namenode/current/edits_inprogress_0000000006287063928 -> /var/lib/hadoop/data/vol1/namenode/current/edits_0000000006287063928-0000000006287064037
2021-12-07 08:08:19,769 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: FSEditLogAsync was interrupted, exiting
2021-12-07 08:08:19,775 INFO org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Shutting down CacheReplicationMonitor
2021-12-07 08:08:19,775 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Starting services required for standby state
2021-12-07 08:08:19,784 INFO org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Will roll logs on active node every 120 seconds.
2021-12-07 08:08:19,786 INFO org.apache.hadoop.hdfs.server.namenode.ha.StandbyCheckpointer: Starting standby checkpoint thread...
Checkpointing active NN to possible NNs: [http://hdfs-namenode2:9870]
Serving checkpoints at http://hdfs-namenode1:9870
2021-12-07 08:10:19,817 INFO org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Triggering log roll on remote NameNode
2021-12-07 08:10:19,984 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream@5cf2b168 expecting start txid #6287064038
2021-12-07 08:10:19,985 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Start loading edits file http://apache-journal1:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal2:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true maxTxnsToRead = 9223372036854775807
2021-12-07 08:10:19,985 INFO org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream: Fast-forwarding stream 'http://apache-journal1:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal2:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true' to transaction ID 6287064038
2021-12-07 08:10:19,985 INFO org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream: Fast-forwarding stream 'http://apache-journal1:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true' to transaction ID 6287064038
2021-12-07 08:10:20,046 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file http://apache-journal1:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal2:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal5:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true, http://apache-journal3:8480/getJournal?jid=mfphadoop&segmentTxId=6287064038&storageInfo=-64%3A1054388883%3A1540822651972%3ACID-65a27ba2-269d-4d73-b4f9-07a1c8976e56&inProgressOk=true of size 411502 edits # 2841 loaded in 0 seconds
2021-12-07 08:12:20,096 INFO org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Triggering log roll on remote NameNode

Journalnode日志

2021-12-07 08:07:52,208 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_inprogress_0000000006287057111 -> /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287057111-0000000006287063927
2021-12-07 08:08:19,754 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_inprogress_0000000006287063928 -> /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287063928-0000000006287064037
2021-12-07 08:08:19,838 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Updating lastPromisedEpoch from 1406 to 1407 for client /172.18.21.10 ; journal id: mfphadoop
2021-12-07 08:08:19,885 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Scanning storage FileJournalManager(root=/var/lib/hadoop/data/vol1/journalnode/mfphadoop)
2021-12-07 08:08:19,887 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Latest log is EditLogFile(file=/var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287063928-0000000006287064037,first=0000000006287063928,last=0000000006287064037,inProgress=false,hasCorruptHeader=false) ; journal id: mfphadoop
2021-12-07 08:08:19,900 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: getSegmentInfo(6287063928): EditLogFile(file=/var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287063928-0000000006287064037,first=0000000006287063928,last=0000000006287064037,inProgress=false,hasCorruptHeader=false) -> startTxId: 6287063928 endTxId: 6287064037 isInProgress: false ; journal id: mfphadoop
2021-12-07 08:08:19,900 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Prepared recovery for segment 6287063928: segmentState { startTxId: 6287063928 endTxId: 6287064037 isInProgress: false } lastWriterEpoch: 1406 lastCommittedTxId: 6287064037 ; journal id: mfphadoop
2021-12-07 08:08:19,932 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: getSegmentInfo(6287063928): EditLogFile(file=/var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287063928-0000000006287064037,first=0000000006287063928,last=0000000006287064037,inProgress=false,hasCorruptHeader=false) -> startTxId: 6287063928 endTxId: 6287064037 isInProgress: false ; journal id: mfphadoop
2021-12-07 08:08:19,932 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Skipping download of log startTxId: 6287063928 endTxId: 6287064037 isInProgress: false: already have up-to-date logs ; journal id: mfphadoop
2021-12-07 08:08:19,951 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Accepted recovery for segment 6287063928: segmentState { startTxId: 6287063928 endTxId: 6287064037 isInProgress: false } acceptedInEpoch: 1407 ; journal id: mfphadoop
2021-12-07 08:08:20,096 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Sending fileName: /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287063928-0000000006287064037, fileSize: 14917. Sent total: 14917 bytes. Size of last segment intended to send: -1 bytes.
2021-12-07 08:08:20,122 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Updating lastWriterEpoch from 1406 to 1407 for client /172.18.21.10 ; journal id: mfphadoop
2021-12-07 08:09:36,830 INFO org.apache.hadoop.hdfs.qjournal.server.JournalNodeSyncer: Syncing Journal /0.0.0.0:8485 with apache-journal4/172.18.21.204:8485, journal id: mfphadoop
2021-12-07 08:10:19,822 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_inprogress_0000000006287064038 -> /var/lib/hadoop/data/vol1/journalnode/mfphadoop/current/edits_0000000006287064038-0000000006287066878
posted @ 2021-12-08 14:18  Yu\.W  阅读(753)  评论(0)  编辑  收藏  举报