Hi,
    I recently suffered HBase insert slow issue (read from mysql, process
and then insert into HBase). The partial DEBUG log as below. It looks that
most of the time were spent near "Cached location" and "Got ping response
for sessionid". Is there any way to improve the performance ? Thanks
    I tried HTable and HTablePool, both showed the similiar result.

[13/02/08 08:59:07:106][][DEBUG]Call: next 2
[13/02/08 08:59:11:619][][DEBUG]Cached location for
TABLE2_IDX01,,1355799947553.1a08e9f6c702b56d3dc839b83ce86124. is
10.39.128.126:60020
...
...
[13/02/08 08:59:16:180][][DEBUG]Call: next 2
[13/02/08 08:59:19:298][][DEBUG]Got ping response for sessionid:
0x13c4449defa5228 after 0ms
Detail Log as below
==============================================================================================================
[13/02/08 08:58:25:863][][INFO]Initiating client connection,
connectString=SERVER1:2181 sessionTimeout=180000 watcher=hconnection
[13/02/08 08:58:25:866][][DEBUG]zookeeper.disableAutoWatchReset is false
[13/02/08 08:58:25:907][][INFO]Opening socket connection to server SERVER1/
10.39.128.115:2181
[13/02/08 08:58:25:910][][INFO]Socket connection established to SERVER1/
10.39.128.115:2181, initiating session
[13/02/08 08:58:25:912][][DEBUG]Session establishment request sent on
SERVER1/10.39.128.115:2181
[13/02/08 08:58:25:917][][INFO]Session establishment complete on server
SERVER1/10.39.128.115:2181, sessionid = 0x13c4449defa5228, negotiated
timeout = 40000

[13/02/08 08:58:30:581][][DEBUG]Lookedup root region location,
connection=org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@1df2964;
hsa=10.39.128.152:60020
[13/02/08 08:58:30:664][][DEBUG]The ping interval is60000ms.
[13/02/08 08:58:30:729][][DEBUG]Connecting to
10.39.128.152/10.39.128.152:60020
[13/02/08 08:58:30:757][][DEBUG]IPC Client (47) connection to
10.39.128.152/10.39.128.152:60020 from an unknown user sending #0
[13/02/08 08:58:30:827][][DEBUG]IPC Client (47) connection to
10.39.128.152/10.39.128.152:60020 from an unknown user: starting, having
connections 1
[13/02/08 08:58:30:836][][DEBUG]IPC Client (47) connection to
10.39.128.152/10.39.128.152:60020 from an unknown user got value #0
[13/02/08 08:58:30:837][][DEBUG]Call: getProtocolVersion 117
[13/02/08 08:58:30:838][][DEBUG]IPC Client (47) connection to
10.39.128.152/10.39.128.152:60020 from an unknown user sending #1
[13/02/08 08:58:30:846][][DEBUG]IPC Client (47) connection to
10.39.128.152/10.39.128.152:60020 from an unknown user got value #1
[13/02/08 08:58:30:848][][DEBUG]Call: getClosestRowBefore 10
[13/02/08 08:58:35:396][][DEBUG]Cached location for .META.,,1.1028785192 is
10.39.128.158:60020
[13/02/08 08:58:35:398][][DEBUG]Connecting to
10.39.128.158/10.39.128.158:60020
[13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #2
[13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user: starting, having
connections 2
[13/02/08 08:58:35:401][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #2
[13/02/08 08:58:35:401][][DEBUG]Call: getProtocolVersion 3
[13/02/08 08:58:35:417][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #3
[13/02/08 08:58:35:420][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #3
[13/02/08 08:58:35:420][][DEBUG]Call: getClosestRowBefore 3
[13/02/08 08:58:35:422][][DEBUG]Scanning .META. starting at
row=TABLE1,,00000000000000 for max=10 rows
[13/02/08 08:58:35:423][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #4
[13/02/08 08:58:35:425][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #4
[13/02/08 08:58:35:425][][DEBUG]Call: openScanner 2
[13/02/08 08:58:35:426][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #5
[13/02/08 08:58:35:428][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #5
[13/02/08 08:58:35:429][][DEBUG]Call: next 3
[13/02/08 08:58:39:298][][DEBUG]Got ping response for sessionid:
0x13c4449defa5228 after 1ms
[13/02/08 08:58:39:944][][DEBUG]Cached location for
TABLE1,,1355799993197.a450d2725873a369896e123b57d30394. is
10.39.128.157:60020
[13/02/08 08:58:39:945][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #6
[13/02/08 08:58:39:947][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #6
[13/02/08 08:58:39:947][][DEBUG]Call: close 2
[13/02/08 08:58:39:948][][DEBUG]The connection to
hconnection-0x13c4449defa5228 has been closed.
[13/02/08 08:58:39:948][][INFO]|||TABLE1 table connectted|||

[13/02/08 08:58:39:950][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #7
[13/02/08 08:58:39:952][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #7
[13/02/08 08:58:39:952][][DEBUG]Call: getClosestRowBefore 2
[13/02/08 08:58:39:952][][DEBUG]Scanning .META. starting at
row=TABLE1_IDX01,,00000000000000 for max=10 rows
[13/02/08 08:58:39:953][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #8
[13/02/08 08:58:39:954][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #8
[13/02/08 08:58:39:955][][DEBUG]Call: openScanner 2
[13/02/08 08:58:39:955][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user sending #9
[13/02/08 08:58:39:958][][DEBUG]IPC Client (47) connection to
10.39.128.158/10.39.128.158:60020 from an unknown user got value #9
[13/02/08 08:58:39:959][][DEBUG]Call: n

What's the rate you're getting (MB/sec or lines/sec)?
What's your cluster setup?

On Feb 8, 2013, at 6:23 PM, 徐歷盛 wrote:

> Hi,
>    I recently suffered HBase insert slow issue (read from mysql, process
> and then insert into HBase). The partial DEBUG log as below. It looks that
> most of the time were spent near "Cached location" and "Got ping response
> for sessionid". Is there any way to improve the performance ? Thanks
>    I tried HTable and HTablePool, both showed the similiar result.
>
> [13/02/08 08:59:07:106][][DEBUG]Call: next 2
> [13/02/08 08:59:11:619][][DEBUG]Cached location for
> TABLE2_IDX01,,1355799947553.1a08e9f6c702b56d3dc839b83ce86124. is
> 10.39.128.126:60020
> ...
> ...
> [13/02/08 08:59:16:180][][DEBUG]Call: next 2
> [13/02/08 08:59:19:298][][DEBUG]Got ping response for sessionid:
> 0x13c4449defa5228 after 0ms
>
>
> Detail Log as below
> ==============================================================================================================>
> [13/02/08 08:58:25:863][][INFO]Initiating client connection,
> connectString=SERVER1:2181 sessionTimeout=180000 watcher=hconnection
> [13/02/08 08:58:25:866][][DEBUG]zookeeper.disableAutoWatchReset is false
> [13/02/08 08:58:25:907][][INFO]Opening socket connection to server SERVER1/
> 10.39.128.115:2181
> [13/02/08 08:58:25:910][][INFO]Socket connection established to SERVER1/
> 10.39.128.115:2181, initiating session
> [13/02/08 08:58:25:912][][DEBUG]Session establishment request sent on
> SERVER1/10.39.128.115:2181
> [13/02/08 08:58:25:917][][INFO]Session establishment complete on server
> SERVER1/10.39.128.115:2181, sessionid = 0x13c4449defa5228, negotiated
> timeout = 40000
>
> [13/02/08 08:58:30:581][][DEBUG]Lookedup root region location,
> connection=org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@1df2964;
> hsa=10.39.128.152:60020
> [13/02/08 08:58:30:664][][DEBUG]The ping interval is60000ms.
> [13/02/08 08:58:30:729][][DEBUG]Connecting to
> 10.39.128.152/10.39.128.152:60020
> [13/02/08 08:58:30:757][][DEBUG]IPC Client (47) connection to
> 10.39.128.152/10.39.128.152:60020 from an unknown user sending #0
> [13/02/08 08:58:30:827][][DEBUG]IPC Client (47) connection to
> 10.39.128.152/10.39.128.152:60020 from an unknown user: starting, having
> connections 1
> [13/02/08 08:58:30:836][][DEBUG]IPC Client (47) connection to
> 10.39.128.152/10.39.128.152:60020 from an unknown user got value #0
> [13/02/08 08:58:30:837][][DEBUG]Call: getProtocolVersion 117
> [13/02/08 08:58:30:838][][DEBUG]IPC Client (47) connection to
> 10.39.128.152/10.39.128.152:60020 from an unknown user sending #1
> [13/02/08 08:58:30:846][][DEBUG]IPC Client (47) connection to
> 10.39.128.152/10.39.128.152:60020 from an unknown user got value #1
> [13/02/08 08:58:30:848][][DEBUG]Call: getClosestRowBefore 10
> [13/02/08 08:58:35:396][][DEBUG]Cached location for .META.,,1.1028785192 is
> 10.39.128.158:60020
> [13/02/08 08:58:35:398][][DEBUG]Connecting to
> 10.39.128.158/10.39.128.158:60020
> [13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user sending #2
> [13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user: starting, having
> connections 2
> [13/02/08 08:58:35:401][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user got value #2
> [13/02/08 08:58:35:401][][DEBUG]Call: getProtocolVersion 3
> [13/02/08 08:58:35:417][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user sending #3
> [13/02/08 08:58:35:420][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user got value #3
> [13/02/08 08:58:35:420][][DEBUG]Call: getClosestRowBefore 3
> [13/02/08 08:58:35:422][][DEBUG]Scanning .META. starting at
> row=TABLE1,,00000000000000 for max=10 rows
> [13/02/08 08:58:35:423][][DEBUG]IPC Client (47) connection to
> 10.39.128.158/10.39.128.158:60020 from an unknown user sending #4

Could you please show your hbase-site.xml? Also, try the basic tweaks like
usign putlist instead of put, turning wal off(if it is fine with you) etc.

Warm Regards,
Tariq
https://mtariq.jux.com/
cloudfront.blogspot.com
On Fri, Feb 8, 2013 at 10:08 PM, Mesika, Asaf <[EMAIL PROTECTED]> wrote:

> What's the rate you're getting (MB/sec or lines/sec)?
> What's your cluster setup?
>
> On Feb 8, 2013, at 6:23 PM, 徐歷盛 wrote:
>
> > Hi,
> >    I recently suffered HBase insert slow issue (read from mysql, process
> > and then insert into HBase). The partial DEBUG log as below. It looks
> that
> > most of the time were spent near "Cached location" and "Got ping response
> > for sessionid". Is there any way to improve the performance ? Thanks
> >    I tried HTable and HTablePool, both showed the similiar result.
> >
> > [13/02/08 08:59:07:106][][DEBUG]Call: next 2
> > [13/02/08 08:59:11:619][][DEBUG]Cached location for
> > TABLE2_IDX01,,1355799947553.1a08e9f6c702b56d3dc839b83ce86124. is
> > 10.39.128.126:60020
> > ...
> > ...
> > [13/02/08 08:59:16:180][][DEBUG]Call: next 2
> > [13/02/08 08:59:19:298][][DEBUG]Got ping response for sessionid:
> > 0x13c4449defa5228 after 0ms
> >
> >
> > Detail Log as below
> >
> ==============================================================================================================> >
> > [13/02/08 08:58:25:863][][INFO]Initiating client connection,
> > connectString=SERVER1:2181 sessionTimeout=180000 watcher=hconnection
> > [13/02/08 08:58:25:866][][DEBUG]zookeeper.disableAutoWatchReset is false
> > [13/02/08 08:58:25:907][][INFO]Opening socket connection to server
> SERVER1/
> > 10.39.128.115:2181
> > [13/02/08 08:58:25:910][][INFO]Socket connection established to SERVER1/
> > 10.39.128.115:2181, initiating session
> > [13/02/08 08:58:25:912][][DEBUG]Session establishment request sent on
> > SERVER1/10.39.128.115:2181
> > [13/02/08 08:58:25:917][][INFO]Session establishment complete on server
> > SERVER1/10.39.128.115:2181, sessionid = 0x13c4449defa5228, negotiated
> > timeout = 40000
> >
> > [13/02/08 08:58:30:581][][DEBUG]Lookedup root region location,
> >
> connection=org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@1df2964
> ;
> > hsa=10.39.128.152:60020
> > [13/02/08 08:58:30:664][][DEBUG]The ping interval is60000ms.
> > [13/02/08 08:58:30:729][][DEBUG]Connecting to
> > 10.39.128.152/10.39.128.152:60020
> > [13/02/08 08:58:30:757][][DEBUG]IPC Client (47) connection to
> > 10.39.128.152/10.39.128.152:60020 from an unknown user sending #0
> > [13/02/08 08:58:30:827][][DEBUG]IPC Client (47) connection to
> > 10.39.128.152/10.39.128.152:60020 from an unknown user: starting, having
> > connections 1
> > [13/02/08 08:58:30:836][][DEBUG]IPC Client (47) connection to
> > 10.39.128.152/10.39.128.152:60020 from an unknown user got value #0
> > [13/02/08 08:58:30:837][][DEBUG]Call: getProtocolVersion 117
> > [13/02/08 08:58:30:838][][DEBUG]IPC Client (47) connection to
> > 10.39.128.152/10.39.128.152:60020 from an unknown user sending #1
> > [13/02/08 08:58:30:846][][DEBUG]IPC Client (47) connection to
> > 10.39.128.152/10.39.128.152:60020 from an unknown user got value #1
> > [13/02/08 08:58:30:848][][DEBUG]Call: getClosestRowBefore 10
> > [13/02/08 08:58:35:396][][DEBUG]Cached location for .META.,,1.1028785192
> is
> > 10.39.128.158:60020
> > [13/02/08 08:58:35:398][][DEBUG]Connecting to
> > 10.39.128.158/10.39.128.158:60020
> > [13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
> > 10.39.128.158/10.39.128.158:60020 from an unknown user sending #2
> > [13/02/08 08:58:35:399][][DEBUG]IPC Client (47) connection to
> > 10.39.128.158/10.39.128.158:60020 from an unknown user: starting, having
> > connections 2
> > [13/02/08 08:58:35:401][][DEBUG]IPC Client (47) connection to
> > 10.39.128.158/10.39.128.158:60020 from an unknown user got value #2
> > [13/02/08 08:58:35:401][][DEBUG]Call: getProtocolVersion 3
> > [13/02/08 08:58:35:417][][DEBUG]IPC Client (47) connection to

Actually I tried in two different environments with the same configuration
except cluster A is the production env with more than 30 nodes and Cluster
B is testing environment with 6 nodes.
Performance is ok in testing environment but it's relative bad in
production environment (4 times slower).
Cluster A has more than 10000 regions and more than 30TB of data already in
HBase but Cluster B is an empty one.
It seems that the data size already put in HBase will impact the put
performance. That's why I did some test and turn on DEBUG to see what
actually slow down the insert performance.
With 2 log files comparison, the Cluster A's issue is as my previous post.

2013/2/9 Mohammad Tariq <[EMAIL PROTECTED]>

> Could you please show your hbase-site.xml? Also, try the basic tweaks like
> usign putlist instead of put, turning wal off(if it is fine with you) etc.
>
> Warm Regards,
> Tariq
> https://mtariq.jux.com/
> cloudfront.blogspot.com
>
>
> On Fri, Feb 8, 2013 at 10:08 PM, Mesika, Asaf <[EMAIL PROTECTED]>
> wrote:
>
> > What's the rate you're getting (MB/sec or lines/sec)?
> > What's your cluster setup?
> >
> > On Feb 8, 2013, at 6:23 PM, 徐歷盛 wrote:
> >
> > > Hi,
> > >    I recently suffered HBase insert slow issue (read from mysql,
> process
> > > and then insert into HBase). The partial DEBUG log as below. It looks
> > that
> > > most of the time were spent near "Cached location" and "Got ping
> response
> > > for sessionid". Is there any way to improve the performance ? Thanks
> > >    I tried HTable and HTablePool, both showed the similiar result.
> > >
> > > [13/02/08 08:59:07:106][][DEBUG]Call: next 2
> > > [13/02/08 08:59:11:619][][DEBUG]Cached location for
> > > TABLE2_IDX01,,1355799947553.1a08e9f6c702b56d3dc839b83ce86124. is
> > > 10.39.128.126:60020
> > > ...
> > > ...
> > > [13/02/08 08:59:16:180][][DEBUG]Call: next 2
> > > [13/02/08 08:59:19:298][][DEBUG]Got ping response for sessionid:
> > > 0x13c4449defa5228 after 0ms
> > >
> > >
> > > Detail Log as below
> > >
> >
> ==============================================================================================================> > >
> > > [13/02/08 08:58:25:863][][INFO]Initiating client connection,
> > > connectString=SERVER1:2181 sessionTimeout=180000 watcher=hconnection
> > > [13/02/08 08:58:25:866][][DEBUG]zookeeper.disableAutoWatchReset is
> false
> > > [13/02/08 08:58:25:907][][INFO]Opening socket connection to server
> > SERVER1/
> > > 10.39.128.115:2181
> > > [13/02/08 08:58:25:910][][INFO]Socket connection established to
> SERVER1/
> > > 10.39.128.115:2181, initiating session
> > > [13/02/08 08:58:25:912][][DEBUG]Session establishment request sent on
> > > SERVER1/10.39.128.115:2181
> > > [13/02/08 08:58:25:917][][INFO]Session establishment complete on server
> > > SERVER1/10.39.128.115:2181, sessionid = 0x13c4449defa5228, negotiated
> > > timeout = 40000
> > >
> > > [13/02/08 08:58:30:581][][DEBUG]Lookedup root region location,
> > >
> >
> connection=org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@1df2964
> > ;
> > > hsa=10.39.128.152:60020
> > > [13/02/08 08:58:30:664][][DEBUG]The ping interval is60000ms.
> > > [13/02/08 08:58:30:729][][DEBUG]Connecting to
> > > 10.39.128.152/10.39.128.152:60020
> > > [13/02/08 08:58:30:757][][DEBUG]IPC Client (47) connection to
> > > 10.39.128.152/10.39.128.152:60020 from an unknown user sending #0
> > > [13/02/08 08:58:30:827][][DEBUG]IPC Client (47) connection to
> > > 10.39.128.152/10.39.128.152:60020 from an unknown user: starting,
> having
> > > connections 1
> > > [13/02/08 08:58:30:836][][DEBUG]IPC Client (47) connection to
> > > 10.39.128.152/10.39.128.152:60020 from an unknown user got value #0
> > > [13/02/08 08:58:30:837][][DEBUG]Call: getProtocolVersion 117
> > > [13/02/08 08:58:30:838][][DEBUG]IPC Client (47) connection to
> > > 10.39.128.152/10.39.128.152:60020 from an unknown user sending #1
> > > [13/02/08 08:58:30:846][][DEBUG]IPC Client (47) connection to
> > > 10.39.128.152/10.39.128.152:60020 from an unknown user got value #1