hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "stack (JIRA)" <j...@apache.org>
Subject [jira] Commented: (HBASE-1394) Uploads sometimes fall to 0 requests/second (Binding up on HLog#append?)
Date Sat, 09 May 2009 20:56:45 GMT

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

stack commented on HBASE-1394:
------------------------------

Here is a sample from a recent upload:

{code}
2009-05-09 20:50:05,268 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
Opening region TestTable,0265339432,1241902192276, encoded=904457967
2009-05-09 20:50:05,281 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.Store:
loaded /hbasetrunk2/TestTable/904457967/info/1846359708595609270.99884447, isReference=true,
sequence id=70531758, length=158510337, majorCompaction=false
2009-05-09 20:50:05,292 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.Store:
loaded /hbasetrunk2/TestTable/904457967/info/516935528186138325.99884447, isReference=true,
sequence id=127140420, length=157409190, majorCompaction=false
2009-05-09 20:50:05,292 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.Store:
Loaded 2 file(s) in Store info, max sequence id 127140420
2009-05-09 20:50:05,293 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
Next sequence id for region TestTable,0265339432,1241902192276 is 127140421
2009-05-09 20:50:05,294 [regionserver/0:0:0:0:0:0:0:0:60021.worker] INFO org.apache.hadoop.hbase.regionserver.HRegion:
region TestTable,0265339432,1241902192276/904457967 available
2009-05-09 20:50:05,294 [regionserver/0:0:0:0:0:0:0:0:60021.worker] DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction requested for region TestTable,0265339432,1241902192276/904457967 because: Region
open check
2009-05-09 20:50:05,918 [IPC Server handler 8 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 8 on 60021 TOOK 1386ms to commit 1
2009-05-09 20:50:06,410 [IPC Server handler 9 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 9 on 60021 TOOK 2140ms to commit 1
2009-05-09 20:50:06,413 [IPC Server handler 5 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 5 on 60021 TOOK 1774ms to commit 1
2009-05-09 20:50:06,413 [IPC Server handler 6 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 6 on 60021 TOOK 1882ms to commit 1
2009-05-09 20:50:06,413 [IPC Server handler 1 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 1 on 60021 TOOK 1882ms to commit 1
2009-05-09 20:50:06,414 [IPC Server handler 7 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 7 on 60021 TOOK 1883ms to commit 1
2009-05-09 20:50:07,786 [IPC Server handler 8 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 8 on 60021 TOOK 1371ms to commit 1
2009-05-09 20:50:07,786 [IPC Server handler 1 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 1 on 60021 TOOK 1372ms to commit 1
2009-05-09 20:50:09,663 [IPC Server handler 7 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 7 on 60021 TOOK 1129ms to commit 1
2009-05-09 20:50:11,458 [IPC Server handler 6 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 6 on 60021 TOOK 1192ms to commit 1
2009-05-09 20:50:11,458 [IPC Server handler 0 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 0 on 60021 TOOK 1068ms to commit 1
2009-05-09 20:50:11,458 [IPC Server handler 9 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 9 on 60021 TOOK 1177ms to commit 1
2009-05-09 20:50:11,458 [IPC Server handler 7 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 7 on 60021 TOOK 1184ms to commit 1
2009-05-09 20:50:11,458 [IPC Server handler 8 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 8 on 60021 TOOK 1177ms to commit 1
2009-05-09 20:50:12,949 [IPC Server handler 6 on 60021] INFO org.apache.hadoop.hbase.regionserver.HLog:
IPC Server handler 6 on 60021 TOOK 1061ms to commit 1
...
{code}

Thats a single put/append to SequenceFile taking over a second to complete and it goes on
for a while.  I had us log at 1000ms so not sure how many are actually going in at this time
totally.

> Uploads sometimes fall to 0 requests/second (Binding up on HLog#append?)
> ------------------------------------------------------------------------
>
>                 Key: HBASE-1394
>                 URL: https://issues.apache.org/jira/browse/HBASE-1394
>             Project: Hadoop HBase
>          Issue Type: Bug
>            Reporter: stack
>         Attachments: loghowlongittookappendinghlog.patch
>
>
> Trying to figure why rate sometimes goes to zero.
> Studying the reginoserver, HLog#append looks like a possible culprit.
> {code}
> "IPC Server handler 7 on 60021" daemon prio=10 tid=0x000000004057dc00 nid=0x1bc4 in Object.wait()
[0x0000000043393000..0x0000000043393b80]
>    java.lang.Thread.State: WAITING (on object monitor)
>         at java.lang.Object.wait(Native Method)
>         at java.lang.Object.wait(Object.java:485)
>         at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.writeChunk(DFSClient.java:2964)
>         - locked <0x00007f9e3e449ff0> (a java.util.LinkedList)
>         - locked <0x00007f9e3e449e18> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream)
>         at org.apache.hadoop.fs.FSOutputSummer.writeChecksumChunk(FSOutputSummer.java:150)
>         at org.apache.hadoop.fs.FSOutputSummer.write1(FSOutputSummer.java:100)
>         at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:86)
>         - locked <0x00007f9e3e449e18> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream)
>         at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:49)
>         at java.io.DataOutputStream.write(DataOutputStream.java:90)
>         - locked <0x00007f9e434e5588> (a org.apache.hadoop.fs.FSDataOutputStream)
>         at org.apache.hadoop.io.SequenceFile$Writer.append(SequenceFile.java:1020)
>         - locked <0x00007f9e434e55c0> (a org.apache.hadoop.io.SequenceFile$Writer)
>         at org.apache.hadoop.io.SequenceFile$Writer.append(SequenceFile.java:984)
>         - locked <0x00007f9e434e55c0> (a org.apache.hadoop.io.SequenceFile$Writer)
>         at org.apache.hadoop.hbase.regionserver.HLog.doWrite(HLog.java:565)
>         at org.apache.hadoop.hbase.regionserver.HLog.append(HLog.java:521)
>         - locked <0x00007f9dfa376f70> (a java.lang.Object)
>         at org.apache.hadoop.hbase.regionserver.HRegion.update(HRegion.java:1777)
>         at org.apache.hadoop.hbase.regionserver.HRegion.batchUpdate(HRegion.java:1348)
>         at org.apache.hadoop.hbase.regionserver.HRegion.batchUpdate(HRegion.java:1289)
>         at org.apache.hadoop.hbase.regionserver.HRegionServer.batchUpdates(HRegionServer.java:1727)
>         at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>         at java.lang.reflect.Method.invoke(Method.java:597)
>         at org.apache.hadoop.hbase.ipc.HBaseRPC$Server.call(HBaseRPC.java:642)
>         at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:911)
> {code}

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


Mime
View raw message