I wish that explained it, but the last reassignment message happens around T+1(min) and then it's just 44 minutes of "skipping because balanced." Is there anything else that could be preventing HBase from serving data from the newly reassigned nodes?
Perhaps HDFS could also be the culprit. Hadoop namenode logs show a lot of this for T+5 minutes: 2014-08-15 16:45:21,169 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 172.19.152.251:9002 is added to blk_5924440019130413908_2033 size 14 2014-08-15 16:45:21,183 INFO org.apache.hadoop.hdfs.StateChange: Removing lease on file /system/balancer.id from client DFSClient_-1186888991 2014-08-15 16:45:21,183 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /system/balancer.id is closed by DFSClient_-1186888991 2014-08-15 16:45:21,183 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 198 Total time for transactions(ms): 3Number of transactions batched in Syncs: 0 Number of syncs: 9 SyncTimes(ms): 209 2014-08-15 16:45:21,201 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_5924440019130413908 is added to invalidSet of 172.19.152.251:9002 2014-08-15 16:45:23,017 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 172.19.152.251:9002 to delete blk_5924440019130413908_2033 2014-08-15 16:46:10,991 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 172.19.152.241:9002 is added to blk_3473904193447805515_2028 size 311 2014-08-15 16:46:10,995 INFO org.apache.hadoop.hdfs.StateChange: Removing lease on file /hbase/.logs/ But then there is not much log activity afterwards for the next hour. NameSystem.processReport: from 172.19.149.160:9002, blocks: 109, processing time: 16 msecs 2014-08-15 16:50:58,871 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.149.89:9002, blocks: 67, processing time: 0 msecs 2014-08-15 16:54:27,788 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.152.247:9002, blocks: 84, processing time: 3 msecs 2014-08-15 16:56:08,408 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.152.251:9002, blocks: 58, processing time: 1 msecs 2014-08-15 16:57:57,491 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.152.241:9002, blocks: 83, processing time: 3 msecs 2014-08-15 16:59:37,278 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 172.19.152.221 2014-08-15 16:59:37,278 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 205 Total time for transactions(ms): 3Number of transactions batched in Syncs: 0 Number of syncs: 15 SyncTimes(ms): 307 2014-08-15 16:59:37,920 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll FSImage from 172.19.152.221 2014-08-15 16:59:37,920 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 1 SyncTimes(ms): 33 2014-08-15 17:21:45,268 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.149.42:9002, blocks: 81, processing time: 0 msecs 2014-08-15 17:23:43,104 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.149.210:9002, blocks: 90, processing time: 2 msecs 2014-08-15 17:33:26,596 INFO org.apache.hadoop.hdfs.StateChange: *BLOCK* NameSystem.processReport: from 172.19.149.231:9002, blocks: 74, processing time: 1 msecs Thanks, Eric On Fri, Aug 22, 2014 at 5:00 PM, Ted Yu <yuzhih...@gmail.com> wrote: > Was the last 'Successfully deleted unassigned node' log close to T+45(min) > ? > > If so, it means that AssignmentManager was busy assigning these regions > during this period. > > Cheers > > > On Fri, Aug 22, 2014 at 1:50 PM, Eric K <codemonke...@gmail.com> wrote: > > > After about a minute everything appears to have been moved, since the > > master only prints out lines like: > > > > 2014-08-15 16:40:56,945 INFO org.apache.hadoop.hbase.master.LoadBalancer: > > Skipping load balancing because balanced cluster; servers=8 regions=126 > > average=15.75 mostloaded=16 leastloaded=15 > > > > Within the first minute, though, after adding the new nodes, I see a lot > of > > activity like this: > > > > 2014-08-15 16:40:49,142 INFO org.apache.hadoop.hbase.master.HMaster: > > balance > > > > > hri=usertable,user9673372036854775807,1408128925670.e3c3e82d52f54692a70e7b59aeb56b31., > > src=172-19-152-247,60020,1408131968632, > > dest=172-19-149-231,60020,1408135240788 > > 2014-08-15 16:40:49,142 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Starting unassignment > of > > region > > > > > usertable,user9673372036854775807,1408128925670.e3c3e82d52f54692a70e7b59aeb56b31. > > (offlining) > > 2014-08-15 16:40:49,142 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > > master:60000-0x147db34a2c80000 Creating unassigned node for > > e3c3e82d52f54692a70e7b59aeb56b31 in a CLOSING state > > 2014-08-15 16:40:49,181 DEBUG > org.apache.hadoop.hbase.master.ServerManager: > > New connection to 172-19-152-247,60020,1408131968632 > > 2014-08-15 16:40:49,189 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Sent CLOSE to > > 172-19-152-247,60020,1408131968632 for region > > > > > usertable,user9673372036854775807,1408128925670.e3c3e82d52f54692a70e7b59aeb56b31. > > 2014-08-15 16:40:49,189 INFO org.apache.hadoop.hbase.master.HMaster: > > balance > > > > > hri=usertable,user1068528100307123131,1408128925659.1fe73c5f470b78e7e9d2a0691659967a., > > src=172-19-152-241,60020,1408131968630, > > dest=172-19-149-89,60020,1408135238164 > > 2014-08-15 16:40:49,189 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Starting unassignment > of > > region > > > > > usertable,user1068528100307123131,1408128925659.1fe73c5f470b78e7e9d2a0691659967a. > > (offlining) > > 2014-08-15 16:40:49,189 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > > master:60000-0x147db34a2c80000 Creating unassigned node for > > 1fe73c5f470b78e7e9d2a0691659967a in a CLOSING state > > 2014-08-15 16:40:49,223 DEBUG > org.apache.hadoop.hbase.master.ServerManager: > > New connection to 172-19-152-241,60020,1408131968630 > > 2014-08-15 16:40:49,223 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Handling > > transition=RS_ZK_REGION_OPENED, > server=172-19-149-231,60020,1408135240788, > > region=7b08e35b1fb9f445d91a90ae89bb401a > > 2014-08-15 16:40:49,224 DEBUG > > org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling > OPENED > > event for > > > > > othertable,user1342640501535615655,1408128955190.7b08e35b1fb9f445d91a90ae89bb401a. > > from 172-19-149-231,60020,1408135240788; deleting unassigned node > > 2014-08-15 16:40:49,224 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > > master:60000-0x147db34a2c80000 Deleting existing unassigned node for > > 7b08e35b1fb9f445d91a90ae89bb401a that is in expected state > > RS_ZK_REGION_OPENED > > 2014-08-15 16:40:49,225 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Sent CLOSE to > > 172-19-152-241,60020,1408131968630 for region > > > > > usertable,user1068528100307123131,1408128925659.1fe73c5f470b78e7e9d2a0691659967a. > > 2014-08-15 16:40:49,225 INFO org.apache.hadoop.hbase.master.HMaster: > > balance > > > > > hri=usertable,user9873372036854775807,1408128925670.3eeb1e68835cbb98c9f796d437fe7ebc., > > src=172-19-152-241,60020,1408131968630, > > dest=172-19-149-89,60020,1408135238164 > > 2014-08-15 16:40:49,225 DEBUG > > org.apache.hadoop.hbase.master.AssignmentManager: Starting unassignment > of > > region > > > > > usertable,user9873372036854775807,1408128925670.3eeb1e68835cbb98c9f796d437fe7ebc. > > (offlining) > > 2014-08-15 16:40:49,225 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > > master:60000-0x147db34a2c80000 Creating unassigned node for > > 3eeb1e68835cbb98c9f796d437fe7ebc in a CLOSING state > > 2014-08-15 16:40:49,281 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > > master:60000-0x147db34a2c80000 Successfully deleted unassigned node for > > region 7b08e35b1fb9f445d91a90ae89bb401a in expected state > > RS_ZK_REGION_OPENED > > > > Thanks, > > Eric > > > > > > > > On Fri, Aug 22, 2014 at 2:24 PM, Ted Yu <yuzhih...@gmail.com> wrote: > > > > > Suppose you add new nodes at time T, can you check master log between T > > and > > > T+45(min) to see how long region movements took ? > > > > > > Cheers > > > > > > > > > On Fri, Aug 22, 2014 at 11:19 AM, Eric K <codemonke...@gmail.com> > wrote: > > > > > > > I'm experimenting with HBase (0.94.4) and Hadoop (1.0.4) runtime > > > balancers > > > > on just a very tiny 4 node cluster and finding that performance is > bad > > > for > > > > an hour after adding new nodes, even though all the data is > supposedly > > > > offloaded within a few minutes. > > > > > > > > Using YCSB-generated requests, I load the database with about 18 GB > > worth > > > > of data across 12 million records. The keyspace is initially > pre-split > > > to > > > > have ~30 regions per node with single replication of data. Then I > hit > > > > HBase with read requests from a set of clients so that there are 2000 > > > > requests outstanding, and new requests are immediately made after > > replies > > > > are received. While these requests are running, after about 2 > > minutes, I > > > > double the nodes from 4 to 8, add the new node information to the > > slaves > > > > and regionservers files, start up the new datanode and regionserver > > > > processes, and call the hdfs balancer with the smallest possible > > > threshold > > > > of 1. The hbase.balancer.period is also set to 10 seconds so as to > > > respond > > > > fast to new nodes. The dfs.bandwidth.bandwidthPerSec is set to 8 > MB/s > > > per > > > > node, but I have also tried higher numbers that don't bottleneck the > > > > offload rate and gotten similar results. > > > > > > > > The expected response is that about half the data and regions are > > > offloaded > > > > to the new nodes in the next few minutes, and the logs (and hdfsadmin > > > > reports) confirm that this is indeed happening. However, I'm seeing > > the > > > > throughput drop from 3000 to 500 requests/sec when the nodes are > added, > > > > with latencies jumping from ~1s to 4 or 5 seconds, and this poor > > > > performance persists for almost 45 minutes, when it abruptly gets > > better > > > to > > > > 4000 requests/sec and 500ms latencies. > > > > > > > > I'd appreciate any ideas as to what could be causing that 45 minute > > > > performance delay, and how I can debug this further. If I add the > new > > > > nodes and balance onto them before starting up any read requests, > > > > performance is much better from the start. > > > > > > > > Thanks, > > > > Eric > > > > > > > > > >
