Mailing-List: contact user-help@hbase.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@hbase.apache.org
Received-SPF: pass (nike.apache.org: domain of apamecha@x.com designates
 216.33.244.6 as permitted sender)
DomainKey-Signature: s=paypalcorp; d=x.com; c=simple; q=dns;
  h=X-EBay-Corp:X-IronPort-AV:Received:Received:From:To:CC:
   Subject:Thread-Topic:Thread-Index:Date:Message-ID:
   References:In-Reply-To:Accept-Language:Content-Language:
   X-MS-Has-Attach:X-MS-TNEF-Correlator:x-originating-ip:
   Content-Type:MIME-Version:X-CFilter-Loop;
  b=uizVSptoiUccqrL+K89amlJYzv/JQcUaBPdWQEOcFNVbvhYB81pQtdW8
   1ABXwXX4oErQDxU1k3JRv+3Vqpye1gmFjqLM7o4sCJC/sOpNeIoqn1Sfj
   /xZkkT4asESAfd1ibyndDyvMK89/yA3nr35b7n0xHUYO+k/MPuJlMCrta
   w=;
From: "Pamecha, Abhishek" <apamecha@x.com>
To: "user@hbase.apache.org" <user@hbase.apache.org>
CC: Ivan Brondino <ibrondino@fi.upm.es>, =?iso-8859-1?Q?Ricardo_Vila=E7a?=
	<rmvilaca@di.uminho.pt>
Subject: RE: High IPC Latency
Thread-Topic: High IPC Latency
Thread-Index: AQHNrV5RbFcSh0sjLEqDH/oxV7PSoJe/ZIrg
Date: Thu, 18 Oct 2012 18:38:44 +0000
Message-ID: 
 <2E362ACC9493D747B488241C66B3B66520E519@RHV-EXRDA-S11.corp.ebay.com>
References: 
 <CACu4QvsuH+pLgwarS0ih2-LUwQ+8N+UVbSMmoa+PT=b5kSMKQw@mail.gmail.com>
In-Reply-To: 
 <CACu4QvsuH+pLgwarS0ih2-LUwQ+8N+UVbSMmoa+PT=b5kSMKQw@mail.gmail.com>
Accept-Language: en-US
Content-Language: en-US
Content-Type: multipart/alternative;
	boundary="_000_2E362ACC9493D747B488241C66B3B66520E519RHVEXRDAS11corpeb_"
MIME-Version: 1.0

--_000_2E362ACC9493D747B488241C66B3B66520E519RHVEXRDAS11corpeb_
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable

Is it sustained for the same client hitting the same region server OR does =
it get better for the same client-RS combination when run for longer durati=
on?  Trying to eliminate Zookeeper from this.

Thanks,
Abhishek

From: Yousuf Ahmad [mailto:myahmad0@gmail.com]
Sent: Thursday, October 18, 2012 11:26 AM
To: user@hbase.apache.org
Cc: Ivan Brondino; Ricardo Vila=E7a
Subject: High IPC Latency

Hello,

We are seeing slow times for read operations in our experiments. We are hop=
ing that you guys can help us figure out what's going wrong.

Here are some details:

  *   We are running a read-only benchmark on our HBase cluster.
  *
  *   There are 10 regionservers, each co-located with a datanode. HDFS rep=
lication is 3x.
  *   All the data read by the experiment is already in the block cache and=
 the hit ratio is 99%.
  *
  *   We have 10 clients, each with around 400 threads making a mix of read=
-only requests involving multi-gets and scans.
  *
  *   We settled on the default client pool type/size (roundrobin/1) and a =
regionserver handler count of 100 after testing various combinations to see=
 what setting worked best.
  *
  *   Our scans are short, fetching around 10 rows on average. Scanner cach=
ing is set to 50.
  *   An average row in a scan has either around 10 columns (small row) or =
around 200 columns (big row).
  *
  *   Our multi-gets fetch around 200 rows on average.
  *   An average row in a multi-get has around 10 columns.
  *   Each column holds an integer (encoded into bytes).
  *
  *   None of the machines involved reach CPU, memory, or IO saturation. In=
 fact resource utilization stays quite low.
  *
  *   Our statistics show that the average time for a scan, measured starti=
ng from the first scanner.next() call to the last one which returns a null,=
 is around 2-3 seconds.
  *   Since we use scanner caching, the major portion of this time (around =
2 seconds) is spent on the first call to next(), while the remaining calls =
take a negligible amount of time.
  *   Similarly, we see that a multi-get on average takes around 2 seconds.
  *   A single get on average takes around 1 second.
We are not sure what the bottleneck is or where it lies. We thought we shou=
ld look deeper into what is going on at the regionservers. We monitored the=
 IPC calls during one of the experiments. Here is a sample of one regionser=
ver log:

2012-10-18 17:00:09,969 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115483; Served: HRegionInterface#get queueTime=3D0 processingTime=3D1 con=
tents=3D1 Get, 75 bytes
2012-10-18 17:00:09,969 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115487; Served: HRegionInterface#get queueTime=3D0 processingTime=3D0 con=
tents=3D1 Get, 75 bytes
2012-10-18 17:00:09,969 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115489; Served: HRegionInterface#get queueTime=3D0 processingTime=3D0 con=
tents=3D1 Get, 75 bytes
2012-10-18 17:00:09,982 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #111421; Served: HRegionInterface#get queueTime=3D0 processingTime=3D0 con=
tents=3D1 Get, 75 bytes
2012-10-18 17:00:09,982 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115497; Served: HRegionInterface#multi queueTime=3D0 processingTime=3D9 c=
ontents=3D200 Gets
2012-10-18 17:00:09,984 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115499; Served: HRegionInterface#openScanner queueTime=3D0 processingTime=
=3D0 contents=3D1 Scan, 63 bytes
2012-10-18 17:00:09,990 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #115503; Served: HRegionInterface#get queueTime=3D0 processingTime=3D0 con=
tents=3D1 Get, 75 bytes
2012-10-18 17:00:09,992 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #103230; Served: HRegionInterface#next queueTime=3D0 processingTime=3D0 co=
ntents=3D1 Long, 1 Integer
2012-10-18 17:00:09,994 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #103234; Served: HRegionInterface#close queueTime=3D0 processingTime=3D0 c=
ontents=3D1 Long
2012-10-18 17:00:09,994 DEBUG org.apache.hadoop.ipc.HBaseServer.trace: Call=
 #103232; Served: HRegionInterface#next queueTime=3D0 processingTime=3D0 co=
ntents=3D1 Long, 1 Integer

I have attached a larger chunk of the logs we collected for this experiment=
 in case that helps.

>From the logs, we saw that the next() operation at the regionserver takes 1=
 millisecond or less; and a multi-get takes 10 ms on average.
Yet the corresponding times we see at the client are orders of magnitude hi=
gher.
Ping times between the machines are at most 1ms and we are not saturating t=
he network.

We would really appreciate some insights from you guys on this.
Where do you suggest we focus our efforts in order to hunt down this bottle=
neck/contention?

Thanks!
Yousuf


--_000_2E362ACC9493D747B488241C66B3B66520E519RHVEXRDAS11corpeb_--