No one can give some suggestions? 2009/9/25 Zheng Lv <[email protected]>
> Hello Everyone, > We have a cluster with one namenode and three datanodes. And we got > these logs when starting hadoop0.20. Is it normal? > 2009-09-25 10:45:00,616 INFO > org.apache.hadoop.hdfs.server.namenode.NameNode: STARTUP_MSG: > /************************************************************ > STARTUP_MSG: Starting NameNode > STARTUP_MSG: host = ubuntu6/192.168.33.7 > STARTUP_MSG: args = [] > STARTUP_MSG: version = 0.20.1-dev > STARTUP_MSG: build = -r ; compiled by 'cyd' on 2009?ê 08?? 07?? ?????? > 15:20:16 CST > ************************************************************/ > 2009-09-25 10:45:00,721 INFO org.apache.hadoop.ipc.metrics.RpcMetrics: > Initializing RPC Metrics with hostName=NameNode, port=9000 > 2009-09-25 10:45:00,767 INFO > org.apache.hadoop.hdfs.server.namenode.NameNode: Namenode up at: ubuntu6/ > 192.168.33.7:9000 > 2009-09-25 10:45:00,769 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: > Initializing JVM Metrics with processName=NameNode, sessionId=null > 2009-09-25 10:45:00,771 INFO > org.apache.hadoop.hdfs.server.namenode.metrics.NameNodeMetrics: Initializing > NameNodeMeterics using context > object:org.apache.hadoop.metrics.spi.NullContext > 2009-09-25 10:45:00,835 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: > fsOwner=cyd,cyd,adm,dialout,cdrom,plugdev,lpadmin,sambashare,admin > 2009-09-25 10:45:00,835 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup > 2009-09-25 10:45:00,835 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: > isPermissionEnabled=true > 2009-09-25 10:45:00,842 INFO > org.apache.hadoop.hdfs.server.namenode.metrics.FSNamesystemMetrics: > Initializing FSNamesystemMetrics using context > object:org.apache.hadoop.metrics.spi.NullContext > 2009-09-25 10:45:00,843 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Registered > FSNamesystemStatusMBean > 2009-09-25 10:45:00,871 INFO org.apache.hadoop.hdfs.server.common.Storage: > Number of files = 2834 > 2009-09-25 10:45:01,412 INFO org.apache.hadoop.hdfs.server.common.Storage: > Number of files under construction = 1 > 2009-09-25 10:45:01,416 INFO org.apache.hadoop.hdfs.server.common.Storage: > Image file of size 329240 loaded in 0 seconds. > 2009-09-25 10:45:01,417 INFO org.apache.hadoop.hdfs.server.common.Storage: > Edits file /home/cyd/hdfs2/name/current/edits of size 4 edits # 0 loaded in > 0 seconds. > 2009-09-25 10:45:01,683 INFO org.apache.hadoop.hdfs.server.common.Storage: > Image file of size 329240 saved in 0 seconds. > 2009-09-25 10:45:01,805 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Finished loading > FSImage in 1007 msecs > 2009-09-25 10:45:01,821 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Safe mode ON. > The ratio of reported blocks 0.0000 has not reached the threshold 0.9990. > Safe mode will be turned off automatically. > 2009-09-25 10:45:07,162 INFO org.mortbay.log: Logging to > org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via > org.mortbay.log.Slf4jLog > 2009-09-25 10:45:07,228 INFO org.apache.hadoop.http.HttpServer: Jetty bound > to port 50070 > 2009-09-25 10:45:07,229 INFO org.mortbay.log: jetty-6.1.14 > 2009-09-25 10:47:34,305 INFO org.mortbay.log: Started > [email protected]:50070 > 2009-09-25 10:47:34,319 INFO > org.apache.hadoop.hdfs.server.namenode.NameNode: Web-server up at: > 0.0.0.0:50070 > 2009-09-25 10:47:34,320 INFO org.apache.hadoop.ipc.Server: IPC Server > Responder: starting > 2009-09-25 10:47:34,321 INFO org.apache.hadoop.ipc.Server: IPC Server > listener on 9000: starting > 2009-09-25 10:47:34,355 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 0 on 9000: starting > 2009-09-25 10:47:34,355 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 1 on 9000: starting > 2009-09-25 10:47:34,356 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 2 on 9000: starting > 2009-09-25 10:47:34,356 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 3 on 9000: starting > 2009-09-25 10:47:34,384 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 5 on 9000: starting > 2009-09-25 10:47:34,397 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 4 on 9000: starting > 2009-09-25 10:47:34,398 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 6 on 9000: starting > 2009-09-25 10:47:34,400 WARN org.apache.hadoop.ipc.Server: IPC Server > Responder, call > getProtocolVersion(org.apache.hadoop.hdfs.protocol.ClientProtocol, 41) from > 192.168.33.7:54977: output error > 2009-09-25 10:47:34,401 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 7 on 9000: starting > 2009-09-25 10:47:34,402 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 8 on 9000: starting > 2009-09-25 10:47:34,404 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 9 on 9000: starting > 2009-09-25 10:47:34,433 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 1 on 9000 caught: java.nio.channels.ClosedChannelException > at > sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:126) > at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:324) > at org.apache.hadoop.ipc.Server.channelWrite(Server.java:1195) > at org.apache.hadoop.ipc.Server.access$1900(Server.java:77) > at > org.apache.hadoop.ipc.Server$Responder.processResponse(Server.java:613) > at > org.apache.hadoop.ipc.Server$Responder.doRespond(Server.java:677) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:981) > 2009-09-25 10:48:09,304 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* > NameSystem.registerDatanode: node registration from 192.168.33.5:50010storage > DS-1782592326-192.168.33.5-50010-1253784633678 > 2009-09-25 10:48:09,311 INFO org.apache.hadoop.net.NetworkTopology: Adding > a new node: /default-rack/192.168.33.5:50010 > 2009-09-25 10:48:09,920 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Safe mode ON. > The ratio of reported blocks 0.0005 has not reached the threshold 0.9990. > Safe mode will be turned off automatically. > 2009-09-25 10:48:09,985 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Safe mode extension entered. > The ratio of reported blocks 0.9990 has reached the threshold 0.9990. Safe > mode will be turned off automatically in 29 seconds. > 2009-09-25 10:48:29,989 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Safe mode ON. > The ratio of reported blocks 1.0000 has reached the threshold 0.9990. Safe > mode will be turned off automatically in 9 seconds. > 2009-09-25 10:48:32,412 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* > NameSystem.registerDatanode: node registration from 192.168.33.6:50010storage > DS-119886468-192.168.33.6-50010-1253784635966 > 2009-09-25 10:48:32,412 INFO org.apache.hadoop.net.NetworkTopology: Adding > a new node: /default-rack/192.168.33.6:50010 > 2009-09-25 10:48:40,147 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Total number of blocks > = 2052 > 2009-09-25 10:48:40,147 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of invalid > blocks = 0 > 2009-09-25 10:48:40,147 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of > under-replicated blocks = 2051 > 2009-09-25 10:48:40,147 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of > over-replicated blocks = 0 > 2009-09-25 10:48:40,147 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Leaving safe mode after 219 secs. > 2009-09-25 10:48:40,147 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Safe mode is OFF. > 2009-09-25 10:48:40,148 INFO org.apache.hadoop.hdfs.StateChange: STATE* > Network topology has 1 racks and 2 datanodes > 2009-09-25 10:48:40,148 INFO org.apache.hadoop.hdfs.StateChange: STATE* > UnderReplicatedBlocks has 2051 blocks > > > I noticed the exceptions and "org.apache.hadoop.hdfs.StateChange: > STATE* Network topology has 1 racks and 2 datanodes".Sometimes it tells 1 > datanodes, and sometimes 2, but we have 3.Please give some suggestions, > thank you. > > > > Following is logs in one of datanodes: > 2009-09-25 10:47:22,110 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Registered > FSDatasetStatusMBean > 2009-09-25 10:47:22,112 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Opened info server at 50010 > 2009-09-25 10:47:22,114 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Balancing bandwith is > 1048576 bytes/s > 2009-09-25 10:47:27,257 INFO org.mortbay.log: Logging to > org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via > org.mortbay.log.Slf4jLog > 2009-09-25 10:47:27,434 INFO org.apache.hadoop.http.HttpServer: Jetty bound > to port 50075 > 2009-09-25 10:47:27,434 INFO org.mortbay.log: jetty-6.1.14 > 2009-09-25 10:48:14,324 INFO org.mortbay.log: Started > [email protected]:50075 > 2009-09-25 10:48:14,334 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: > Initializing JVM Metrics with processName=DataNode, sessionId=null > 2009-09-25 10:48:19,369 INFO org.apache.hadoop.ipc.metrics.RpcMetrics: > Initializing RPC Metrics with hostName=DataNode, port=50020 > 2009-09-25 10:48:19,376 INFO org.apache.hadoop.ipc.Server: IPC Server > Responder: starting > 2009-09-25 10:48:19,376 INFO org.apache.hadoop.ipc.Server: IPC Server > listener on 50020: starting > 2009-09-25 10:48:19,378 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 0 on 50020: starting > 2009-09-25 10:48:19,380 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 1 on 50020: starting > 2009-09-25 10:48:19,380 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 2 on 50020: starting > 2009-09-25 10:48:19,381 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 3 on 50020: starting > 2009-09-25 10:48:19,381 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 4 on 50020: starting > 2009-09-25 10:48:19,381 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 5 on 50020: starting > 2009-09-25 10:48:19,382 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 6 on 50020: starting > 2009-09-25 10:48:19,382 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 7 on 50020: starting > 2009-09-25 10:48:19,382 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 8 on 50020: starting > 2009-09-25 10:48:19,383 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 9 on 50020: starting > 2009-09-25 10:48:19,383 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 10 on 50020: starting > 2009-09-25 10:48:19,383 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 11 on 50020: starting > 2009-09-25 10:48:19,384 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 12 on 50020: starting > 2009-09-25 10:48:19,384 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 13 on 50020: starting > 2009-09-25 10:48:19,385 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 14 on 50020: starting > 2009-09-25 10:48:19,385 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 15 on 50020: starting > 2009-09-25 10:48:19,385 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 16 on 50020: starting > 2009-09-25 10:48:19,386 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 17 on 50020: starting > 2009-09-25 10:48:19,386 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 18 on 50020: starting > 2009-09-25 10:48:19,386 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 19 on 50020: starting > 2009-09-25 10:48:19,387 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 20 on 50020: starting > 2009-09-25 10:48:19,387 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 21 on 50020: starting > 2009-09-25 10:48:19,388 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 22 on 50020: starting > 2009-09-25 10:48:19,388 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 23 on 50020: starting > 2009-09-25 10:48:19,388 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 24 on 50020: starting > 2009-09-25 10:48:19,388 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 25 on 50020: starting > 2009-09-25 10:48:19,389 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 26 on 50020: starting > 2009-09-25 10:48:19,389 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 27 on 50020: starting > 2009-09-25 10:48:19,390 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 28 on 50020: starting > 2009-09-25 10:48:19,390 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 29 on 50020: starting > 2009-09-25 10:48:19,390 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 30 on 50020: starting > 2009-09-25 10:48:19,391 INFO org.apache.hadoop.ipc.Server: IPC Server > handler 31 on 50020: starting > 2009-09-25 10:48:19,391 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: dnRegistration = > DatanodeRegistration(ubuntu7:50010, > storageID=DS-119886468-192.168.33.6-50010-1253784635966, infoPort=50075, > ipcPort=50020) > 2009-09-25 10:48:19,434 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: DatanodeRegistration( > 192.168.33.6:50010, > storageID=DS-119886468-192.168.33.6-50010-1253784635966, infoPort=50075, > ipcPort=50020)In DataNode.run, data = > FSDataset{dirpath='/home/cyd/hdfs2/data/current'} > 2009-09-25 10:48:19,456 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: using BLOCKREPORT_INTERVAL > of 3600000msec Initial delay: 0msec > 2009-09-25 10:48:19,950 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: BlockReport of 2052 blocks > got processed in 458 msecs > 2009-09-25 10:48:19,951 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Starting Periodic block > scanner. > 2009-09-25 10:48:20,601 INFO > org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification > succeeded for blk_2990263655324635865_9556 > 2009-09-25 10:48:58,692 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: BlockReport of 2052 blocks > got processed in 224 msecs > 2009-09-25 10:51:07,955 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block > blk_-1955286602120745744_18039 src: /192.168.33.5:43889 dest: / > 192.168.33.6:50010 > 2009-09-25 10:51:07,982 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: / > 192.168.33.5:43889, dest: /192.168.33.6:50010, bytes: 4, op: HDFS_WRITE, > cliID: DFSClient_2050853952, srvID: > DS-119886468-192.168.33.6-50010-1253784635966, blockid: > blk_-1955286602120745744_18039 > 2009-09-25 10:51:07,983 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block > blk_-1955286602120745744_18039 terminating > 2009-09-25 10:51:10,742 INFO > org.apache.hadoop.hdfs.server.datanode.DataNode: Deleting block > blk_-6733538557527582040_18038 file > /home/cyd/hdfs2/data/current/blk_-6733538557527582040 > 2009-09-25 10:56:45,523 INFO > org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification > succeeded for blk_-8204684875565980176_3413 > 2009-09-25 11:03:06,572 INFO > org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification > succeeded for blk_8093352211012570299_17220 > 2009-09-25 11:10:28,649 INFO > org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification > succeeded for blk_-6978381366409301329_8279 > > Thanks a lot, > LvZheng >
