我的云之旅–HBase调试(139)

下面是运行日志：

<?xml version="1.0"?>HBase-site.xml

<?xml-stylesheet type="text/xsl" href="configuration.xsl"?>

See the NOTICE file * distributed with this work for additional information * regarding copyright ownership. The ASF licenses this file * to you under the Apache

License, Version 2.0 (the * "License"); you may not use this file except in compliance * with the License. You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0

* * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES

OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ -->

<name>hbase.rootdir</name>

<value>file:///D:/hbase-0.20.3/data</value>

<description>The directory shared by region servers.

Should be fully-qualified to include the filesystem to use.

E.g: hdfs://NAMENODE_SERVER:PORT/HBASE_ROOTDIR

</description>

</property>

<name>hbase.cluster.distributed</name>

<value>false </value>

<description>The mode the cluster will be in. Possible values are

false: standalone and pseudo-distributed setups with managed Zookeeper

true: fully-distributed

with unmanaged Zookeeper Quorum (see hbase-env.sh)

</description>

</property>

<name>hbase.tmp.dir</name>

<value>D:/hbase-0.20.3/tmp </value>

<description>Temporary directory on the local filesystem.</description>

</property>

</configuration>

1 ZooKeeper日志：

2012-04-13 22:16:30,734 - INFO [main:QuorumPeerConfig@90] - Reading configuration from: G:\program\zookeeper-3.3.3\conf\zoo.cfg

2012-04-13 22:16:30,750 - WARN [main:QuorumPeerMain@105] - Either no config or no quorum defined in config, running in standalone mode

2012-04-13 22:16:30,843 - INFO [main:QuorumPeerConfig@90] - Reading configuration from: G:\program\zookeeper-3.3.3\conf\zoo.cfg

2012-04-13 22:16:30,843 - INFO [main:ZooKeeperServerMain@94] - Starting server

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:zookeeper.version=3.3.3-1073969, built on 02/24/2011 03:33 GMT

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:host.name=rollin

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:java.version=1.6.0_22

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc.

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:java.home=C:\glassfishv3\jdk\jre

2012-04-13 22:16:30,890 - INFO [main:Environment@97] - Server environment:java.class.path=G:\program\zookeeper-3.3.3\bin;G:\program\zookeeper-3.3.3\contrib\bookkeeper\zookeeper-3.3.3-bookkeeper.jar;G:\program\zookeeper-3.3.3\contrib\fatjar\zookeeper-3.3.3-fatjar.jar;G:\program\zookeeper-3.3.3\contrib\rest\zookeeper-3.3.3-rest.jar;G:\program\zookeeper-3.3.3\contrib\ZooInspector\lib\jtoaster-1.0.4.jar;G:\program\zookeeper-3.3.3\contrib\ZooInspector\lib;G:\program\zookeeper-3.3.3\contrib\ZooInspector\zookeeper-3.3.3-ZooInspector.jar;G:\program\zookeeper-3.3.3\dist-maven\bookkeeper-3.3.3.jar;G:\program\zookeeper-3.3.3\dist-maven\zookeeper-3.3.3-javadoc.jar;G:\program\zookeeper-3.3.3\dist-maven\zookeeper-3.3.3-sources.jar;G:\program\zookeeper-3.3.3\dist-maven\zookeeper-3.3.3.jar;G:\program\zookeeper-3.3.3\lib\jline-0.9.94.jar;G:\program\zookeeper-3.3.3\lib\log4j-1.2.15.jar;G:\program\zookeeper-3.3.3\src\contrib\zooinspector\lib\jtoaster-1.0.4.jar;G:\program\zookeeper-3.3.3\zookeeper-3.3.3.jar

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:java.library.path=C:\glassfishv3\jdk\bin;.;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:/glassfishv3/jdk/bin/../jre/bin/client;C:/glassfishv3/jdk/bin/../jre/bin;C:/glassfishv3/jdk/bin/../jre/lib/i386;C:\WINDOWS\System32;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\WINDOWS\System32;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\glassfishv3\jdk\bin;C:\Program Files\Common Files\Thunder Network\KanKan\Codecs;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;G:\JavaEE\apache-maven-3.0.3\bin;C:\Program Files\Subversion\bin;G:\JavaEE\apache2.2\bin;G:\cygwin\bin;G:\cygwin\usr\bin;C:\glassfishv3\jdk\bin;G:\JavaEE\eclipse;

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:java.io.tmpdir=C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:java.compiler=<NA>

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:os.name=Windows XP

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:os.arch=x86

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:os.version=5.1

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:user.name=Administrator

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:user.home=C:\Documents and Settings\Administrator

2012-04-13 22:16:30,906 - INFO [main:Environment@97] - Server environment:user.dir=G:\program\zookeeper-3.3.3

2012-04-13 22:16:31,046 - INFO [main:ZooKeeperServer@663] - tickTime set to 2000

2012-04-13 22:16:31,046 - INFO [main:ZooKeeperServer@672] - minSessionTimeout set to -1

2012-04-13 22:16:31,046 - INFO [main:ZooKeeperServer@681] - maxSessionTimeout set to -1

2012-04-13 22:16:31,140 - INFO [main:NIOServerCnxn$Factory@143] - binding to port 0.0.0.0/0.0.0.0:2181

2012-04-13 22:16:31,187 - INFO [main:FileTxnSnapLog@208] - Snapshotting: 0

2012-04-13 22:19:36,359 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2064

2012-04-13 22:19:36,390 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x0 due to java.io.IOException: Len error 1195725856

2012-04-13 22:19:36,390 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2064 (no session established for client)

2012-04-13 22:24:10,171 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2121

2012-04-13 22:24:10,203 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /127.0.0.1:2121

2012-04-13 22:24:10,203 - INFO [SyncThread:0:FileTxnLog@197] - Creating new log file: log.1

2012-04-13 22:24:12,125 - INFO [SyncThread:0:NIOServerCnxn@1580] - Established session 0x136ac0ffee30000 with negotiated timeout 40000 for client /127.0.0.1:2121

2012-04-13 22:24:12,375 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2129

2012-04-13 22:24:12,375 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /127.0.0.1:2129

2012-04-13 22:24:12,406 - INFO [SyncThread:0:NIOServerCnxn@1580] - Established session 0x136ac0ffee30001 with negotiated timeout 40000 for client /127.0.0.1:2129

2012-04-13 22:24:12,546 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2132

2012-04-13 22:24:12,546 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /127.0.0.1:2132

2012-04-13 22:24:12,625 - INFO [SyncThread:0:NIOServerCnxn@1580] - Established session 0x136ac0ffee30002 with negotiated timeout 40000 for client /127.0.0.1:2132

2012-04-13 22:24:36,562 - INFO [ProcessThread:-1:PrepRequestProcessor@387] - Processed session termination for sessionid: 0x136ac0ffee30000

2012-04-13 22:24:36,593 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2121 which had sessionid 0x136ac0ffee30000

2012-04-13 22:24:37,453 - INFO [ProcessThread:-1:PrepRequestProcessor@387] - Processed session termination for sessionid: 0x136ac0ffee30001

2012-04-13 22:24:37,500 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@634] - EndOfStreamException: Unable to read additional data from client sessionid 0x136ac0ffee30001, likely client has closed socket

2012-04-13 22:24:37,500 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2129 which had sessionid 0x136ac0ffee30001

2012-04-13 22:25:10,218 - INFO [ProcessThread:-1:PrepRequestProcessor@387] - Processed session termination for sessionid: 0x136ac0ffee30002

2012-04-13 22:25:10,281 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@634] - EndOfStreamException: Unable to read additional data from client sessionid 0x136ac0ffee30002, likely client has closed socket

2012-04-13 22:25:10,281 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2132 which had sessionid 0x136ac0ffee30002

2012-04-13 22:27:07,406 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2180

2012-04-13 22:27:07,421 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /127.0.0.1:2180

2012-04-13 22:27:07,484 - INFO [SyncThread:0:NIOServerCnxn@1580] - Established session 0x136ac0ffee30003 with negotiated timeout 40000 for client /127.0.0.1:2180

2012-04-13 22:27:59,203 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /127.0.0.1:2192

2012-04-13 22:27:59,218 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /127.0.0.1:2192

2012-04-13 22:27:59,281 - INFO [SyncThread:0:NIOServerCnxn@1580] - Established session 0x136ac0ffee30004 with negotiated timeout 40000 for client /127.0.0.1:2192

2012-04-13 22:28:01,375 - INFO [ProcessThread:-1:PrepRequestProcessor@407] - Got user-level KeeperException when processing sessionid:0x136ac0ffee30003 type:create cxid:0xd zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/hbase/safe-mode Error:KeeperErrorCode = NodeExists for /hbase/safe-mode

2 HMaster

2012-04-13 22:27:06,421 INFO [main] master.HMaster(1127): vmName=Java HotSpot(TM) Client VM, vmVendor=Sun Microsystems Inc., vmVersion=17.1-b03

2012-04-13 22:27:06,421 INFO [main] master.HMaster(1128): vmInputArguments=[-Dfile.encoding=UTF-8]

2012-04-13 22:27:06,546 INFO [main] master.HMaster(166): My address is rollin:60000

2012-04-13 22:27:07,265 INFO [main] ipc.HBaseRpcMetrics(52): Initializing RPC Metrics with hostName=HMaster, port=60000

2012-04-13 22:27:07,453 INFO [main] master.RegionManager(160): -ROOT- region unset (but not set to be reassigned)

2012-04-13 22:27:07,453 INFO [main] master.RegionManager(172): ROOT inserted into regionsInTransition

2012-04-13 22:27:07,500 DEBUG [main-EventThread] master.HMaster(1076): Got event None with path null

2012-04-13 22:27:07,515 DEBUG [main] zookeeper.ZooKeeperWrapper(382): Failed to read: org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /hbase/master

2012-04-13 22:27:07,546 DEBUG [main] zookeeper.ZooKeeperWrapper(528): Wrote master address 192.168.1.110:60000 to ZooKeeper

2012-04-13 22:27:07,578 DEBUG [main] zookeeper.ZooKeeperWrapper(339): State node wrote in ZooKeeper

2012-04-13 22:27:07,578 DEBUG [main] zookeeper.ZooKeeperWrapper(398): Read ZNode /hbase/master got 192.168.1.110:60000

2012-04-13 22:27:07,578 INFO [main] master.HMaster(219): HMaster initialized on 192.168.1.110:60000

2012-04-13 22:27:07,578 DEBUG [HMaster] master.HMaster(514): Checking cluster state...

2012-04-13 22:27:07,593 DEBUG [HMaster] zookeeper.ZooKeeperWrapper(398): Read ZNode /hbase/root-region-server got 192.168.1.110:2122

2012-04-13 22:27:07,593 DEBUG [HMaster] master.HMaster(519): This is a fresh start, proceeding with normal startup

2012-04-13 22:27:07,593 DEBUG [HMaster] master.HMaster(568): No log files to split, proceeding...

2012-04-13 22:27:07,609 INFO [HMaster] metrics.MasterMetrics(61): Initialized

2012-04-13 22:27:07.687::INFO: Logging to STDERR via org.mortbay.log.StdErrLog

2012-04-13 22:27:07.796::INFO: jetty-6.1.14

2012-04-13 22:27:07.875::INFO: Extract jar:file:/G:/hbase/hbase-0.20.5/hbase-0.20.5.jar!/webapps/master to C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\Jetty_0_0_0_0_60010_master____q3nwom\webapp

2012-04-13 22:27:08.375::INFO: Extract jar:file:/G:/hbase/hbase-0.20.5/hbase-0.20.5.jar!/webapps/rest to C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\Jetty_0_0_0_0_60010_rest__api__uxgjk0\webapp

2012-04-13 22:27:08.671::INFO: Started SelectChannelConnector@0.0.0.0:60010

2012-04-13 22:27:08,687 DEBUG [HMaster] master.HMaster(625): Started service threads

2012-04-13 22:27:59,687 INFO [IPC Server handler 1 on 60000] master.ServerManager(166): Received start message from: rollin,60020,1334327279640

2012-04-13 22:27:59,718 DEBUG [IPC Server handler 1 on 60000] zookeeper.ZooKeeperWrapper(613): Updated ZNode /hbase/rs/1334327279640 with data 192.168.1.110:60020

2012-04-13 22:28:01,265 INFO [IPC Server handler 2 on 60000] master.RegionManager(327): Assigning region -ROOT-,,0 to rollin,60020,1334327279640

2012-04-13 22:28:01,359 INFO [IPC Server handler 3 on 60000] master.ServerManager(460): Processing MSG_REPORT_OPEN: -ROOT-,,0 from rollin,60020,1334327279640; 1 of 1

2012-04-13 22:28:01,437 WARN [IPC Server handler 3 on 60000] zookeeper.ZooKeeperWrapper(569): Failed to create out of safe mode in ZooKeeper: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /hbase/safe-mode

2012-04-13 22:28:01,437 INFO [IPC Server handler 3 on 60000] zookeeper.ZooKeeperWrapper(571): Node exists; just move on

2012-04-13 22:28:01,437 INFO [IPC Server handler 3 on 60000] master.RegionManager(1180): exiting safe mode

2012-04-13 22:28:01,453 DEBUG [IPC Server handler 3 on 60000] zookeeper.ZooKeeperWrapper(479): SetData of ZNode /hbase/root-region-server with 192.168.1.110:60020

2012-04-13 22:28:01,468 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:28:01,640 DEBUG [RegionManager.rootScanner] master.BaseScanner(580): Current assignment of .META.,,1 is not valid; serverAddress=192.168.1.110:2122, startCode=1334327054515 unknown.

2012-04-13 22:28:01,640 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

2012-04-13 22:28:02,468 INFO [IPC Server handler 4 on 60000] master.RegionManager(327): Assigning region .META.,,1 to rollin,60020,1334327279640

2012-04-13 22:28:02,484 INFO [IPC Server handler 5 on 60000] master.ServerManager(460): Processing MSG_REPORT_OPEN: .META.,,1 from rollin,60020,1334327279640; 1 of 1

2012-04-13 22:28:02,484 DEBUG [HMaster] master.HMaster(459): Processing todo: PendingOpenOperation from rollin,60020,1334327279640

2012-04-13 22:28:02,484 INFO [HMaster] master.ProcessRegionOpen(70): .META.,,1 open on 192.168.1.110:60020

2012-04-13 22:28:02,500 INFO [HMaster] master.ProcessRegionOpen(80): Updated row .META.,,1 in region -ROOT-,,0 with startcode=1334327279640, server=192.168.1.110:60020

2012-04-13 22:28:02,500 DEBUG [HMaster] master.ProcessRegionOpen(98): Adding to onlineMetaRegions: {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:28:02,500 INFO [RegionManager.metaScanner] master.BaseScanner(163): RegionManager.metaScanner scanning meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:28:02,515 DEBUG [RegionManager.metaScanner] master.BaseScanner(580): Current assignment of org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515 is not valid; serverAddress=192.168.1.110:2122, startCode=1334327054515 unknown.

2012-04-13 22:28:02,515 INFO [RegionManager.metaScanner] master.BaseScanner(242): RegionManager.metaScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>} complete

2012-04-13 22:28:02,515 INFO [RegionManager.metaScanner] master.MetaScanner(132): All 1 .META. region(s) scanned

2012-04-13 22:28:03,500 INFO [IPC Server handler 6 on 60000] master.RegionManager(327): Assigning region org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515 to rollin,60020,1334327279640

2012-04-13 22:28:03,500 INFO [IPC Server handler 7 on 60000] master.ServerManager(460): Processing MSG_REPORT_OPEN: org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515 from rollin,60020,1334327279640; 1 of 1

2012-04-13 22:28:03,515 DEBUG [HMaster] master.HMaster(459): Processing todo: PendingOpenOperation from rollin,60020,1334327279640

2012-04-13 22:28:03,515 INFO [HMaster] master.ProcessRegionOpen(70): org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515 open on 192.168.1.110:60020

2012-04-13 22:28:03,515 INFO [HMaster] master.ProcessRegionOpen(80): Updated row org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515 in region .META.,,1 with startcode=1334327279640, server=192.168.1.110:60020

2012-04-13 22:28:07,437 INFO [Thread-7] master.ServerManager$ServerMonitor(128): 1 region servers, 0 dead, average load 3.0

2012-04-13 22:28:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:28:07,625 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

2012-04-13 22:29:02,500 INFO [RegionManager.metaScanner] master.BaseScanner(163): RegionManager.metaScanner scanning meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:29:02,515 INFO [RegionManager.metaScanner] master.BaseScanner(242): RegionManager.metaScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>} complete

2012-04-13 22:29:02,515 INFO [RegionManager.metaScanner] master.MetaScanner(132): All 1 .META. region(s) scanned

2012-04-13 22:29:07,437 INFO [Thread-7] master.ServerManager$ServerMonitor(128): 1 region servers, 0 dead, average load 3.0

2012-04-13 22:29:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:29:07,625 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

2012-04-13 22:30:02,500 INFO [RegionManager.metaScanner] master.BaseScanner(163): RegionManager.metaScanner scanning meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:30:02,515 INFO [RegionManager.metaScanner] master.BaseScanner(242): RegionManager.metaScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>} complete

2012-04-13 22:30:02,515 INFO [RegionManager.metaScanner] master.MetaScanner(132): All 1 .META. region(s) scanned

2012-04-13 22:30:07,437 INFO [Thread-7] master.ServerManager$ServerMonitor(128): 1 region servers, 0 dead, average load 3.0

2012-04-13 22:30:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:30:07,656 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

3 HRegionServer

2012-04-13 22:27:58,796 INFO [main] regionserver.HRegionServer(2279): vmInputArguments=[-Dfile.encoding=UTF-8]

2012-04-13 22:27:58,828 INFO [main] regionserver.HRegionServer(214): My address is rollin:60020

2012-04-13 22:27:58,968 INFO [main] ipc.HBaseRpcMetrics(52): Initializing RPC Metrics with hostName=HRegionServer, port=60020

2012-04-13 22:27:59,078 INFO [main] regionserver.MemStoreFlusher(107): globalMemStoreLimit=99.0m, globalMemStoreLimitLowMark=86.6m, maxHeap=247.5m

2012-04-13 22:27:59,078 INFO [main] regionserver.HRegionServer$MajorCompactionChecker(875): Runs every 10000000ms

2012-04-13 22:27:59,296 DEBUG [main] zookeeper.ZooKeeperWrapper(374): Set watcher on master address ZNode /hbase/master

2012-04-13 22:27:59,312 INFO [main-EventThread] regionserver.HRegionServer(297): Got ZooKeeper event, state: SyncConnected, type: None, path: null

2012-04-13 22:27:59,390 DEBUG [regionserver/192.168.1.110:60020] zookeeper.ZooKeeperWrapper(398): Read ZNode /hbase/master got 192.168.1.110:60000

2012-04-13 22:27:59,390 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(1190): Telling master at 192.168.1.110:60000 that we are up

2012-04-13 22:27:59,640 DEBUG [regionserver/192.168.1.110:60020] regionserver.HRegionServer(1226): sending initial server load: requests=0, regions=0, usedHeap=21, maxHeap=247

2012-04-13 22:27:59,687 DEBUG [regionserver/192.168.1.110:60020] zookeeper.ZooKeeperWrapper(591): Created ZNode /hbase/rs/1334327279640 with data 192.168.1.110:60020

2012-04-13 22:27:59,750 DEBUG [regionserver/192.168.1.110:60020] regionserver.HRegionServer(665): Config from master: hbase.regionserver.address=192.168.1.110

2012-04-13 22:27:59,750 DEBUG [regionserver/192.168.1.110:60020] regionserver.HRegionServer(665): Config from master: fs.default.name=file:/D:/hbase-0.20.3/data

2012-04-13 22:27:59,750 DEBUG [regionserver/192.168.1.110:60020] regionserver.HRegionServer(665): Config from master: hbase.rootdir=file:/D:/hbase-0.20.3/data

2012-04-13 22:27:59,750 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(674): Master passed us address to use. Was=192.168.1.110:60020, Now=192.168.1.110

2012-04-13 22:28:00,265 DEBUG [regionserver/192.168.1.110:60020] regionserver.HRegionServer(950): Log dir file:/D:/hbase-0.20.3/data/.logs/rollin,60020,1334327279640

2012-04-13 22:28:00,281 INFO [regionserver/192.168.1.110:60020] regionserver.HLog(246): HLog configuration: blocksize=33554432, rollsize=31876710, enabled=true, flushlogentries=100, optionallogflushinternal=10000ms

2012-04-13 22:28:00,437 INFO [regionserver/192.168.1.110:60020] regionserver.HLog(346): New hlog /D:/hbase-0.20.3/data/.logs/rollin,60020,1334327279640/hlog.dat.1334327280281

2012-04-13 22:28:00,453 INFO [regionserver/192.168.1.110:60020] metrics.RegionServerMetrics(146): Initialized

2012-04-13 22:28:00.515::INFO: Logging to STDERR via org.mortbay.log.StdErrLog

2012-04-13 22:28:00.656::INFO: jetty-6.1.14

2012-04-13 22:28:00.734::INFO: Extract jar:file:/G:/hbase/hbase-0.20.5/hbase-0.20.5.jar!/webapps/regionserver to C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\Jetty_0_0_0_0_60030_regionserver____.h599vl\webapp

2012-04-13 22:28:01.234::INFO: Started SelectChannelConnector@0.0.0.0:60030

2012-04-13 22:28:01,234 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(1088): HRegionServer started at: 192.168.1.110:60020

2012-04-13 22:28:01,234 DEBUG [regionserver/192.168.1.110:60020] zookeeper.ZooKeeperWrapper(398): Read ZNode /hbase/root-region-server got 192.168.1.110:2122

2012-04-13 22:28:01,250 INFO [regionserver/192.168.1.110:60020] regionserver.StoreFile(241): Allocating LruBlockCache with maximum size 49.5m

2012-04-13 22:28:01,265 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(428): MSG_REGION_OPEN: -ROOT-,,0

2012-04-13 22:28:01,265 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegionServer$Worker(1316): Worker: MSG_REGION_OPEN: -ROOT-,,0

2012-04-13 22:28:01,296 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(284): Creating region -ROOT-,,0, encoded=70236052

2012-04-13 22:28:01,343 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.Store(424): loaded /D:/hbase-0.20.3/data/-ROOT-/70236052/info/7471940505945003795, isReference=false, sequence id=2, length=839, majorCompaction=false

2012-04-13 22:28:01,343 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.Store(424): loaded /D:/hbase-0.20.3/data/-ROOT-/70236052/info/3861644384671521953, isReference=false, sequence id=10, length=461, majorCompaction=false

2012-04-13 22:28:01,343 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(360): region -ROOT-,,0/70236052 available; sequence id is 11

2012-04-13 22:28:02,468 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(428): MSG_REGION_OPEN: .META.,,1

2012-04-13 22:28:02,468 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegionServer$Worker(1316): Worker: MSG_REGION_OPEN: .META.,,1

2012-04-13 22:28:02,468 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(284): Creating region .META.,,1, encoded=1028785192

2012-04-13 22:28:02,484 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.Store(424): loaded /D:/hbase-0.20.3/data/.META./1028785192/info/7125721025097489400, isReference=false, sequence id=9, length=913, majorCompaction=false

2012-04-13 22:28:02,484 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(360): region .META.,,1/1028785192 available; sequence id is 10

2012-04-13 22:28:03,500 INFO [regionserver/192.168.1.110:60020] regionserver.HRegionServer(428): MSG_REGION_OPEN: org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515

2012-04-13 22:28:03,500 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegionServer$Worker(1316): Worker: MSG_REGION_OPEN: org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515

2012-04-13 22:28:03,500 DEBUG [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(284): Creating region org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515, encoded=1645514350

2012-04-13 22:28:03,500 INFO [regionserver/192.168.1.110:60020.worker] regionserver.HRegion(360): region org.apache.hadoop.hbase.LocalHBaseCluster,,1334327054515/1645514350 available; sequence id is 0

2012-04-13 22:29:01,265 DEBUG [pool-1-thread-1] hfile.LruBlockCache(551): Cache Stats: Sizes: Total=0.23448181MB (245872), Free=49.26552MB (51658640), Max=49.5MB (51904512), Counts: Blocks=3, Access=10, Hit=7, Miss=3, Evictions=0, Evicted=0, Ratios: Hit Ratio=69.9999988079071%, Miss Ratio=30.000001192092896%, Evicted/Run=NaN

2012-04-13 22:30:01,265 DEBUG [pool-1-thread-1] hfile.LruBlockCache(551): Cache Stats: Sizes: Total=0.23448181MB (245872), Free=49.26552MB (51658640), Max=49.5MB (51904512), Counts: Blocks=3, Access=16, Hit=13, Miss=3, Evictions=0, Evicted=0, Ratios: Hit Ratio=81.25%, Miss Ratio=18.75%, Evicted/Run=NaN

2012-04-13 22:31:01,265 DEBUG [pool-1-thread-1] hfile.LruBlockCache(551): Cache Stats: Sizes: Total=0.23448181MB (245872), Free=49.26552MB (51658640), Max=49.5MB (51904512), Counts: Blocks=3, Access=22, Hit=19, Miss=3, Evictions=0, Evicted=0, Ratios: Hit Ratio=86.36363744735718%, Miss Ratio=13.636364042758942%, Evicted/Run=NaN

HMaster更新：

2012-04-13 22:31:02,500 INFO [RegionManager.metaScanner] master.BaseScanner(163): RegionManager.metaScanner scanning meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:31:02,531 INFO [RegionManager.metaScanner] master.BaseScanner(242): RegionManager.metaScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>} complete

2012-04-13 22:31:02,531 INFO [RegionManager.metaScanner] master.MetaScanner(132): All 1 .META. region(s) scanned

2012-04-13 22:31:07,437 INFO [Thread-7] master.ServerManager$ServerMonitor(128): 1 region servers, 0 dead, average load 3.0

2012-04-13 22:31:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:31:07,625 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

HRegionServer更新

2012-04-13 22:32:07,437 INFO [Thread-7] master.ServerManager$ServerMonitor(128): 1 region servers, 0 dead, average load 3.0

2012-04-13 22:32:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(163): RegionManager.rootScanner scanning meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>}

2012-04-13 22:32:07,609 INFO [RegionManager.rootScanner] master.BaseScanner(242): RegionManager.rootScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: -ROOT-,,0, startKey: <>} complete

2012-04-13 22:33:02,500 INFO [RegionManager.metaScanner] master.BaseScanner(163): RegionManager.metaScanner scanning meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>}

2012-04-13 22:33:02,515 INFO [RegionManager.metaScanner] master.BaseScanner(242): RegionManager.metaScanner scan of 1 row(s) of meta region {server: 192.168.1.110:60020, regionname: .META.,,1, startKey: <>} complete

2012-04-13 22:33:02,515 INFO [RegionManager.metaScanner] master.MetaScanner(132): All 1 .META. region(s) scanned

Master停掉后HRegionServer：

2012-04-13 22:36:57,359 WARN [regionserver/192.168.1.110:60020] regionserver.HRegionServer(482): Attempt=14

java.net.ConnectException: Connection refused: no further information

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:574)

at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)

at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:404)

at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupIOstreams(HBaseClient.java:308)

at org.apache.hadoop.hbase.ipc.HBaseClient.getConnection(HBaseClient.java:843)

at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:715)

at org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:334)

at $Proxy0.regionServerReport(Unknown Source)

at org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:410)

at java.lang.Thread.run(Thread.java:662)

2012-04-13 22:36:59,375 WARN [regionserver/192.168.1.110:60020] regionserver.HRegionServer(482): Attempt=15

java.net.ConnectException: Connection refused: no further information

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:574)

at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)

at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:404)

at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupIOstreams(HBaseClient.java:308)

at org.apache.hadoop.hbase.ipc.HBaseClient.getConnection(HBaseClient.java:843)

at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:715)

at org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:334)

at $Proxy0.regionServerReport(Unknown Source)

at org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:410)

at java.lang.Thread.run(Thread.java:662)

ZooKeeper信息

gotiated timeout 40000 for client /127.0.0.1:2192

2012-04-13 22:36:30,984 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x136ac0ffee30003 due to java.io.IOException: 远程主机强迫关闭了一个现有的连接。

2012-04-13 22:36:31,000 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2180 which had sessionid 0x136ac0ffee30003

2012-04-13 22:37:10,000 - INFO [SessionTracker:ZooKeeperServer@314] - Expiring session 0x136ac0ffee30003, timeout of 40000ms exceeded

2012-04-13 22:37:10,000 - INFO [ProcessThread:-1:PrepRequestProcessor@387] - Processed session termination for sessionid: 0x136ac0ffee30003

2012-04-13 22:37:45,296 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x136ac0ffee30004 due to java.io.IOException: 远程主机强迫关闭了一个现有的连接。

2012-04-13 22:37:45,296 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /127.0.0.1:2192 which had sessionid 0x136ac0ffee30004

LocalHBaseCluster也可以测试。

参考文献:

http://tangay.iteye.com/blog/724589

疯子123

我的云之旅–HBase调试(139)

导航

公告