Hadoop系列四： HDFS相关的checkpoint交互

以下为停止运行任何job后，整个hadoop系统的日志输出：[bruce@iRobot hadoop]$ tail -f logs/*-namenode*.log2015-11-19 16:17:18,303 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 192.168.100.2002015-11-19 16:17:18,303 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs2015-11-19 16:17:18,303 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 132015-11-19 16:17:18,303 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 96 Total time for transactions(ms): 10Number of transactions batched in Syncs: 0 Number of syncs: 53 SyncTimes(ms): 269 2015-11-19 16:17:18,313 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 96 Total time for transactions(ms): 10Number of transactions batched in Syncs: 0 Number of syncs: 54 SyncTimes(ms): 279 2015-11-19 16:17:18,314 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_inprogress_0000000000000000013 -> /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_0000000000000000013-00000000000000001082015-11-19 16:17:18,314 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at 1092015-11-19 16:17:18,474 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://iRobot:50090/getimage?getimage=1&txid=108&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 16:17:18,495 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 47.62 KB/s2015-11-19 16:17:18,495 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file fsimage.ckpt_0000000000000000108 size 1767 bytes.2015-11-19 16:17:18,514 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 122015-11-19 16:17:18,515 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/name/current/fsimage_0000000000000000002, cpktTxId=0000000000000000002)2015-11-19 17:17:18,825 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 192.168.100.2002015-11-19 17:17:18,825 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs2015-11-19 17:17:18,825 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 1092015-11-19 17:17:18,826 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 1Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 31 2015-11-19 17:17:18,836 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 1Number of transactions batched in Syncs: 0 Number of syncs: 3 SyncTimes(ms): 41 2015-11-19 17:17:18,837 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_inprogress_0000000000000000109 -> /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_0000000000000000109-00000000000000001102015-11-19 17:17:18,837 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at 1112015-11-19 17:17:18,969 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://iRobot:50090/getimage?getimage=1&txid=110&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 17:17:18,985 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 62.50 KB/s2015-11-19 17:17:18,986 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file fsimage.ckpt_0000000000000000110 size 1767 bytes.2015-11-19 17:17:19,004 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1082015-11-19 17:17:19,005 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/name/current/fsimage_0000000000000000012, cpktTxId=0000000000000000012)2015-11-19 18:02:04,122 INFO BlockStateChange: BLOCK* processReport: from DatanodeRegistration(192.168.100.200, storageID=DS-1689463280-192.168.100.200-50010-1447913181338, infoPort=50075, ipcPort=50020, storageInfo=lv=-40;cid=CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e2;nsid=337807999;c=0), blocks: 5, processing time: 1 msecs2015-11-19 18:17:19,301 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 192.168.100.2002015-11-19 18:17:19,301 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs2015-11-19 18:17:19,301 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 1112015-11-19 18:17:19,301 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 32 2015-11-19 18:17:19,306 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 3 SyncTimes(ms): 37 2015-11-19 18:17:19,307 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_inprogress_0000000000000000111 -> /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_0000000000000000111-00000000000000001122015-11-19 18:17:19,307 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at 1132015-11-19 18:17:19,459 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://iRobot:50090/getimage?getimage=1&txid=112&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 18:17:19,482 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 43.48 KB/s2015-11-19 18:17:19,482 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file fsimage.ckpt_0000000000000000112 size 1767 bytes.2015-11-19 18:17:19,501 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1102015-11-19 18:17:19,502 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/name/current/fsimage_0000000000000000108, cpktTxId=0000000000000000108)2015-11-19 19:17:19,795 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 192.168.100.2002015-11-19 19:17:19,795 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs2015-11-19 19:17:19,795 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 1132015-11-19 19:17:19,795 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 38 2015-11-19 19:17:19,800 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 3 SyncTimes(ms): 43 2015-11-19 19:17:19,801 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_inprogress_0000000000000000113 -> /u01/hadoopdata/hadoop-bruce/dfs/name/current/edits_0000000000000000113-00000000000000001142015-11-19 19:17:19,801 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at 1152015-11-19 19:17:19,948 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://iRobot:50090/getimage?getimage=1&txid=114&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 19:17:19,974 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.03s at 38.46 KB/s2015-11-19 19:17:19,974 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file fsimage.ckpt_0000000000000000114 size 1767 bytes.2015-11-19 19:17:19,993 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1122015-11-19 19:17:19,993 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/name/current/fsimage_0000000000000000110, cpktTxId=0000000000000000110)-----------------------------------------------------[bruce@iRobot hadoop]$ tail -f logs/*datanode*.log2015-11-19 17:04:32,484 INFO org.apache.hadoop.hdfs.server.datanode.DirectoryScanner: BlockPool BP-981411196-192.168.100.200-1447912540337 Total blocks: 5, missing metadata files:0, missing block files:0, missing blocks in memory:0, mismatched blocks:02015-11-19 18:02:04,124 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: BlockReport of 5 blocks took 2 msec to generate and 4 msecs for RPC and NN processing2015-11-19 18:02:04,124 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: sent block report, processed command:org.apache.hadoop.hdfs.server.protocol.FinalizeCommand@3325070-----------------------------------------------------[bruce@iRobot hadoop]$ tail -f logs/*secondarynamenode*.log2015-11-19 16:17:18,372 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Image has not changed. Will not download image.2015-11-19 16:17:18,373 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?getedit=1&startTxId=13&endTxId=108&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 16:17:18,392 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 473.68 KB/s2015-11-19 16:17:18,392 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file edits_tmp_0000000000000000013-0000000000000000108_0000001447921038372 size 0 bytes.2015-11-19 16:17:18,393 INFO org.apache.hadoop.hdfs.server.namenode.Checkpointer: Checkpointer about to load edits from 1 stream(s).2015-11-19 16:17:18,393 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000013-0000000000000000108 expecting start txid #132015-11-19 16:17:18,417 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000013-0000000000000000108 of size 9686 edits # 96 loaded in 0 seconds2015-11-19 16:17:18,418 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage.ckpt_0000000000000000108 using no compression2015-11-19 16:17:18,440 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Image file of size 1767 saved in 0 seconds.2015-11-19 16:17:18,460 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 122015-11-19 16:17:18,461 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage_0000000000000000002, cpktTxId=0000000000000000002)2015-11-19 16:17:18,471 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?putimage=1&txid=108&port=50090&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 16:17:18,518 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.05s at 0.00 KB/s2015-11-19 16:17:18,518 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Uploaded image with txid 108 to namenode at 192.168.100.200:500702015-11-19 16:17:18,518 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 17672015-11-19 17:17:18,892 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Image has not changed. Will not download image.2015-11-19 17:17:18,893 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?getedit=1&startTxId=109&endTxId=110&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 17:17:18,913 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 0.00 KB/s2015-11-19 17:17:18,913 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file edits_tmp_0000000000000000109-0000000000000000110_0000001447924638892 size 0 bytes.2015-11-19 17:17:18,914 INFO org.apache.hadoop.hdfs.server.namenode.Checkpointer: Checkpointer about to load edits from 1 stream(s).2015-11-19 17:17:18,914 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000109-0000000000000000110 expecting start txid #1092015-11-19 17:17:18,914 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000109-0000000000000000110 of size 30 edits # 2 loaded in 0 seconds2015-11-19 17:17:18,916 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage.ckpt_0000000000000000110 using no compression2015-11-19 17:17:18,943 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Image file of size 1767 saved in 0 seconds.2015-11-19 17:17:18,956 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1082015-11-19 17:17:18,956 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage_0000000000000000012, cpktTxId=0000000000000000012)2015-11-19 17:17:18,967 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?putimage=1&txid=110&port=50090&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 17:17:19,008 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.04s at 0.00 KB/s2015-11-19 17:17:19,008 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Uploaded image with txid 110 to namenode at 192.168.100.200:500702015-11-19 17:17:19,009 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 17672015-11-19 18:17:19,372 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Image has not changed. Will not download image.2015-11-19 18:17:19,373 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?getedit=1&startTxId=111&endTxId=112&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 18:17:19,393 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 0.00 KB/s2015-11-19 18:17:19,393 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file edits_tmp_0000000000000000111-0000000000000000112_0000001447928239373 size 0 bytes.2015-11-19 18:17:19,394 INFO org.apache.hadoop.hdfs.server.namenode.Checkpointer: Checkpointer about to load edits from 1 stream(s).2015-11-19 18:17:19,394 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000111-0000000000000000112 expecting start txid #1112015-11-19 18:17:19,394 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000111-0000000000000000112 of size 30 edits # 2 loaded in 0 seconds2015-11-19 18:17:19,396 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage.ckpt_0000000000000000112 using no compression2015-11-19 18:17:19,429 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Image file of size 1767 saved in 0 seconds.2015-11-19 18:17:19,449 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1102015-11-19 18:17:19,449 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage_0000000000000000108, cpktTxId=0000000000000000108)2015-11-19 18:17:19,456 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?putimage=1&txid=112&port=50090&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 18:17:19,506 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.05s at 0.00 KB/s2015-11-19 18:17:19,506 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Uploaded image with txid 112 to namenode at 192.168.100.200:500702015-11-19 18:17:19,506 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 17672015-11-19 19:17:19,859 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Image has not changed. Will not download image.2015-11-19 19:17:19,860 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?getedit=1&startTxId=113&endTxId=114&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 19:17:19,883 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.02s at 0.00 KB/s2015-11-19 19:17:19,883 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Downloaded file edits_tmp_0000000000000000113-0000000000000000114_0000001447931839859 size 0 bytes.2015-11-19 19:17:19,884 INFO org.apache.hadoop.hdfs.server.namenode.Checkpointer: Checkpointer about to load edits from 1 stream(s).2015-11-19 19:17:19,884 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Reading /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000113-0000000000000000114 expecting start txid #1132015-11-19 19:17:19,885 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/edits_0000000000000000113-0000000000000000114 of size 30 edits # 2 loaded in 0 seconds2015-11-19 19:17:19,886 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage.ckpt_0000000000000000114 using no compression2015-11-19 19:17:19,913 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Image file of size 1767 saved in 0 seconds.2015-11-19 19:17:19,933 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Going to retain 2 images with txid >= 1122015-11-19 19:17:19,933 INFO org.apache.hadoop.hdfs.server.namenode.NNStorageRetentionManager: Purging old image FSImageFile(file=/u01/hadoopdata/hadoop-bruce/dfs/namesecondary/current/fsimage_0000000000000000110, cpktTxId=0000000000000000110)2015-11-19 19:17:19,946 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Opening connection to http://192.168.100.200:50070/getimage?putimage=1&txid=114&port=50090&storageInfo=-40:337807999:0:CID-4fb81ac3-7e61-42c2-a707-46f2af89a6e22015-11-19 19:17:19,998 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Transfer took 0.05s at 0.00 KB/s2015-11-19 19:17:19,998 INFO org.apache.hadoop.hdfs.server.namenode.TransferFsImage: Uploaded image with txid 114 to namenode at 192.168.100.200:500702015-11-19 19:17:19,998 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 1767