You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hbase.apache.org by "Andrew Purtell (JIRA)" <ji...@apache.org> on 2009/02/11 01:43:59 UTC

[jira] Commented: (HBASE-866) Blocking for ten minutes at a time

    [ https://issues.apache.org/jira/browse/HBASE-866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12672469#action_12672469 ] 

Andrew Purtell commented on HBASE-866:
--------------------------------------

Here is a Hertitrix hbase-writer thread stuck in RPC for over an hour:

[ToeThread #96: http://esinidc.onlinedown.net/down/NXSetup.zip
 CrawlURI http://esinidc.onlinedown.net/down/NXSetup.zip LX http://www.onlinedown.net/soft/2919.htm    0 attempts
    in processor: Archiver
    ACTIVE for 1h21m41s176ms
    step: ABOUT_TO_BEGIN_PROCESSOR for 1h21m2s77ms
Java Thread State: WAITING
Blocked/Waiting On: NONE
    java.lang.Object.wait(Native Method)
    java.lang.Object.wait(Object.java:485)
    org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:695)
    org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:321)
    $Proxy12.batchUpdates(Unknown Source)
    org.apache.hadoop.hbase.client.HConnectionManager$TableServers$2.call(HConnectionManager.java:953)
    org.apache.hadoop.hbase.client.HConnectionManager$TableServers$2.call(HConnectionManager.java:951)
    org.apache.hadoop.hbase.client.HConnectionManager$TableServers.getRegionServerWithRetries(HConnectionManager.java:845)
    org.apache.hadoop.hbase.client.HConnectionManager$TableServers.processBatchOfRows(HConnectionManager.java:950)
    org.apache.hadoop.hbase.client.HTable.flushCommits(HTable.java:1372)
    org.apache.hadoop.hbase.client.HTable.commit(HTable.java:1316)
    org.apache.hadoop.hbase.client.HTable.commit(HTable.java:1296)
    net.iridiant.heritrix.writer.HBaseWriter.write(Unknown Source)
    net.iridiant.heritrix.writer.HBaseWriterProcessor.write(Unknown Source)
    net.iridiant.heritrix.writer.HBaseWriterProcessor.innerProcessResult(Unknown Source)
    org.archive.modules.Processor.process(Processor.java:123)
    org.archive.crawler.framework.ToeThread.processCrawlUri(ToeThread.java:310)
    org.archive.crawler.framework.ToeThread.run(ToeThread.java:157)
]

I have a pool of 100 TOE threads all stuck in Archiver, a few in RPC, but only on one node. There are two other nodes still writing at full speed into HBase.

Intermittent synchronization/wake problem on the write path? Needs investigation.

> Blocking for ten minutes at a time
> ----------------------------------
>
>                 Key: HBASE-866
>                 URL: https://issues.apache.org/jira/browse/HBASE-866
>             Project: Hadoop HBase
>          Issue Type: Bug
>            Reporter: stack
>            Priority: Minor
>         Attachments: thread_dump.txt
>
>
> I've been testing running biggish MR jobs uploading into hbase.  My jobs consistently fail with child task timing out its ten minute period.  Adding logging, was able to see that we're actual stuck in a commit.  Following the thread of the row we're committing, I see this in the log:
> {code}
> ...
> 2008-09-03 18:37:03,446 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on TestTable,0029377106,1220466998108
> 2008-09-03 18:37:03,446 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memcache flush for region TestTable,0029377106,1220466998108. Current region memcache size 64.0m
> 2008-09-03 18:37:03,446 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 1 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:13,450 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 1 on 60020'
> 2008-09-03 18:37:16,089 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 16 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 1 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 4 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 6 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 2 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 12 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,090 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 9 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:16,091 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 7 on 60020' on region TestTable,0029377106,1220466998108: Memcache size 64.0m is >= than blocking 64.0m size
> 2008-09-03 18:37:21,984 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished memcache flush for region TestTable,0029377106,1220466998108 in 18538ms, sequence id=2852547, compaction requested=false
> 2008-09-03 18:47:06,241 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memcache flush for region TestTable,0029377106,1220466998108. Current region memcache size 64.0m
> 2008-09-03 18:47:10,031 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished memcache flush for region TestTable,0029377106,1220466998108 in 3790ms, sequence id=2919208, compaction requested=true
> 2008-09-03 18:47:10,031 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 9 on 60020'
> 2008-09-03 18:47:10,031 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for region: TestTable,0029377106,1220466998108
> 2008-09-03 18:47:10,031 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 12 on 60020'
> 2008-09-03 18:47:10,032 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction on region TestTable,0029377106,1220466998108
> 2008-09-03 18:47:10,032 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 7 on 60020'
> 2008-09-03 18:47:10,035 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 6 on 60020'
> 2008-09-03 18:47:10,035 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 4 on 60020'
> 2008-09-03 18:47:10,035 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 2 on 60020'
> 2008-09-03 18:47:10,037 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 16 on 60020'
> 2008-09-03 18:47:10,043 INFO org.apache.hadoop.hbase.regionserver.HRegion: Unblocking updates for region TestTable,0029377106,1220466998108 'IPC Server handler 1 on 60020'
> 2008-09-03 18:47:18,403 INFO org.apache.hadoop.hbase.regionserver.HRegion: compaction completed on region TestTable,0029377106,1220466998108 in 8sec
> ...
> {code}
> Notice how we're blocked for ten minutes until new flush runs.  My guess is that the flush that is going on concurrent with the blocking is clearing the flag 

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.