[
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.
