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 <[email protected]> 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 >
