You are viewing a plain text version of this content. The canonical link for it is here.

Posted to user@hbase.apache.org by Pavel Dvorin <pd...@post.km.ru> on 2012/01/20 09:54:55 UTC

strange read delays from hbase

Hi!

I notice the strange behavior of HBase during reading and writing
simultaneously.

About my cluster:
Master and 16 regionservers, quorum of 3 zookeepers, gigabit ethernet,
all nodes are in same subnet. Data is read from a table containing ~100
millions binary records (images). I use Cloudera-cdh3u2 hadoop distro
and Oracle JDK-1.6.0 update 26

About read:
I'm reading data from HBase to server A using Java-app written in
Netty, directly from Hbase using native objects and methods. Speed of
reading is 1.2-10 thousands requests per second. For reading I use
Jmeter, all requests are distributed evenly among all regionservers.

About write:
Data comes from servers B and C in bulk mode every minute, size is
90-100 MB. For data recording I use local hbase-thrift on source hosts
which is configured to communicate with cluster's zookeeper quorum. So,
data is recording into regionservers directly bypassing the master
server.

About problem:
Normally response time for read request is ~30 milliseconds, but 1 time
per 1-3 min I see very large response delays on server A.(1-8 secs).
This occurs at random regionserver, each time at different one, and at
random region, each time at different one too. Part of log from reading
host:

12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.433sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.393sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.219sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.339sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.246sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.359sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.346sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.197sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.383sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.205sec) request to
hbase: /?key=bd71769b0aa6406e24ee948bc789a46b85e77116 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
bd71769b0aa6406e24ee948bc789a46b85e77116 locate on address:
hd-16:60020, regioninfo:
images,bccccccccccccccccccccccccccccccccccccc86,1325059350066.77574daf582ff29f16bd3c0f1628dfcf.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.33sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.364sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.168sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.209sec) request to
hbase: /?key=022142ffbfab5825223488378cff8db8d455005a 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
022142ffbfab5825223488378cff8db8d455005a locate on address:
hd-16:60020, regioninfo:
images,0199999999999999999999999999999999999999,1325058729876.48e77eb08590018acc60c4e2b2bde218.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.192sec) request to
hbase: /?key=bcda6745963faeaf825a8a80b6817352f8cceb87 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
bcda6745963faeaf825a8a80b6817352f8cceb87 locate on address:
hd-16:60020, regioninfo:
images,bccccccccccccccccccccccccccccccccccccc86,1325059350066.77574daf582ff29f16bd3c0f1628dfcf.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.17sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.186sec) request to
hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
WARN search.ImageNettyServerRequestHandler: Key
9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
hd-16:60020, regioninfo:
images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
(2.169sec) request to
hbase: /?key=01de935e5c6da618ce9d4f8f278bf137c7eb214b Disabling record
operations at other hosts (B and C) doesn't solve this problem, but
delays occur less frequently and for a shorter period when recording is
disabled. There are no errors or warns in any regionserver logs. Time
of bulk writing is different from time delays occur when. Time of
region compacting  is different from time delays occur when too.

My questions:

If  I'm doing something wrong, what is it? Is there way to fix this
float delays? Where should I look for the cause of this trouble?

Any ideas are welcome, thanks in advance!

-- 
Best regards,
Paul

Re: strange read delays from hbase

Posted by T Vinod Gupta <tv...@readypulse.com>.

did you check your gc logs from around the time you are seeing a delay?

On Fri, Jan 20, 2012 at 12:54 AM, Pavel Dvorin <pd...@post.km.ru> wrote:

> Hi!
>
> I notice the strange behavior of HBase during reading and writing
> simultaneously.
>
> About my cluster:
> Master and 16 regionservers, quorum of 3 zookeepers, gigabit ethernet,
> all nodes are in same subnet. Data is read from a table containing ~100
> millions binary records (images). I use Cloudera-cdh3u2 hadoop distro
> and Oracle JDK-1.6.0 update 26
>
> About read:
> I'm reading data from HBase to server A using Java-app written in
> Netty, directly from Hbase using native objects and methods. Speed of
> reading is 1.2-10 thousands requests per second. For reading I use
> Jmeter, all requests are distributed evenly among all regionservers.
>
> About write:
> Data comes from servers B and C in bulk mode every minute, size is
> 90-100 MB. For data recording I use local hbase-thrift on source hosts
> which is configured to communicate with cluster's zookeeper quorum. So,
> data is recording into regionservers directly bypassing the master
> server.
>
> About problem:
> Normally response time for read request is ~30 milliseconds, but 1 time
> per 1-3 min I see very large response delays on server A.(1-8 secs).
> This occurs at random regionserver, each time at different one, and at
> random region, each time at different one too. Part of log from reading
> host:
>
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.433sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.393sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.219sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.339sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.246sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.359sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.346sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.197sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.383sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.205sec) request to
> hbase: /?key=bd71769b0aa6406e24ee948bc789a46b85e77116 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> bd71769b0aa6406e24ee948bc789a46b85e77116 locate on address:
> hd-16:60020, regioninfo:
>
> images,bccccccccccccccccccccccccccccccccccccc86,1325059350066.77574daf582ff29f16bd3c0f1628dfcf.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.33sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.364sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.168sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.209sec) request to
> hbase: /?key=022142ffbfab5825223488378cff8db8d455005a 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 022142ffbfab5825223488378cff8db8d455005a locate on address:
> hd-16:60020, regioninfo:
>
> images,0199999999999999999999999999999999999999,1325058729876.48e77eb08590018acc60c4e2b2bde218.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.192sec) request to
> hbase: /?key=bcda6745963faeaf825a8a80b6817352f8cceb87 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> bcda6745963faeaf825a8a80b6817352f8cceb87 locate on address:
> hd-16:60020, regioninfo:
>
> images,bccccccccccccccccccccccccccccccccccccc86,1325059350066.77574daf582ff29f16bd3c0f1628dfcf.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.17sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.186sec) request to
> hbase: /?key=9db4b4f2a1ccf495214f8f03c522edba500e062b 12/01/19 10:20:02
> WARN search.ImageNettyServerRequestHandler: Key
> 9db4b4f2a1ccf495214f8f03c522edba500e062b locate on address:
> hd-16:60020, regioninfo:
>
> images,9d9a591ebb50ff0a2a83c0eedf8a7ea4f6334738,1325059724340.730ce4bd61fd984e666ed53a34806225.
> 12/01/19 10:20:02 WARN search.ImageNettyServerRequestHandler: Long time
> (2.169sec) request to
> hbase: /?key=01de935e5c6da618ce9d4f8f278bf137c7eb214b Disabling record
> operations at other hosts (B and C) doesn't solve this problem, but
> delays occur less frequently and for a shorter period when recording is
> disabled. There are no errors or warns in any regionserver logs. Time
> of bulk writing is different from time delays occur when. Time of
> region compacting  is different from time delays occur when too.
>
> My questions:
>
> If  I'm doing something wrong, what is it? Is there way to fix this
> float delays? Where should I look for the cause of this trouble?
>
> Any ideas are welcome, thanks in advance!
>
> --
> Best regards,
> Paul
>