[
https://issues.apache.org/jira/browse/HBASE-17085?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15668360#comment-15668360
]
stack commented on HBASE-17085:
-------------------------------
Default:
{code}
...
(Hard to copy in histograms because they were logged over..)
...
7555417 2016-11-15 12:14:25,321 INFO [main] wal.WALPerformanceEvaluation:
Summary: threads=100, iterations=100000, syncInterval=0 took 382.163s
26166.846ops/s
7555418 2016-11-15 12:14:25,321 DEBUG [main] regionserver.HRegion: Closing
WALPerformanceEvaluation:0,,1479240482214.23f202a47ef65215f3d85a5fe08ce8e3.:
disabling compactions & flushes
7555419 2016-11-15 12:14:25,322 DEBUG [main] regionserver.HRegion: Updates
disabled for region
WALPerformanceEvaluation:0,,1479240482214.23f202a47ef65215f3d85a5fe08ce8e3.
7555420 2016-11-15 12:14:25,326 INFO
[StoreCloserThread-WALPerformanceEvaluation:0,,1479240482214.23f202a47ef65215f3d85a5fe08ce8e3.-1]
regionserver.HStore: Closed cf0
7555421 2016-11-15 12:14:25,326 INFO [main] regionserver.HRegion: Closed
WALPerformanceEvaluation:0,,1479240482214.23f202a47ef65215f3d85a5fe08ce8e3.
7555422 2016-11-15 12:14:25,328 DEBUG [main] wal.FSHLog: Closing WAL writer in
/user/stack/test-data/300d7166-b729-47da-965d-936ec5f7bb43/WALPerformanceEvaluation/WALs/wals
7555423 2016-11-15 12:14:25,328 DEBUG [main] hdfs.DFSClient: DFSClient
writeChunk allocating new packet seqno=1260314,
src=/user/stack/test-data/300d7166-b729-47da-965d-936ec5f7bb43/WALPerformanceEvaluation/WALs/wals/wals.1479240483655,
packetSize=65016, chunksPerPacket=126, bytesCurBlock=1 6408064
7555424 2016-11-15 12:14:25,328 DEBUG [main] hdfs.DFSClient: Queued packet
1260314
7555425 2016-11-15 12:14:25,328 DEBUG [main] hdfs.DFSClient: Queued packet
1260315
7555426 2016-11-15 12:14:25,328 DEBUG [main] hdfs.DFSClient: Waiting for ack
for: 1260315
7555427 2016-11-15 12:14:25,328 DEBUG [DataStreamer for file
/user/stack/test-data/300d7166-b729-47da-965d-936ec5f7bb43/WALPerformanceEvaluation/WALs/wals/wals.1479240483655
block BP-1837290273-10.17.240.20-1458945429978:blk_1077044408_3304141]
hdfs.DFSClient: DataStreamer block BP-18372902
73-10.17.240.20-1458945429978:blk_1077044408_3304141 sending packet packet
seqno: 1260314 offsetInBlock: 16408064 lastPacketInBlock: false
lastByteOffsetInBlock: 16408265
7555428 2016-11-15 12:14:25,329 DEBUG [ResponseProcessor for block
BP-1837290273-10.17.240.20-1458945429978:blk_1077044408_3304141]
hdfs.DFSClient: DFSClient seqno: 1260314 reply: SUCCESS downstreamAckTimeNanos:
0 flag: 0
7555429 2016-11-15 12:14:25,329 DEBUG [DataStreamer for file
/user/stack/test-data/300d7166-b729-47da-965d-936ec5f7bb43/WALPerformanceEvaluation/WALs/wals/wals.1479240483655
block BP-1837290273-10.17.240.20-1458945429978:blk_1077044408_3304141]
hdfs.DFSClient: DataStreamer block BP-18372902
73-10.17.240.20-1458945429978:blk_1077044408_3304141 sending packet packet
seqno: 1260315 offsetInBlock: 16408265 lastPacketInBlock: true
lastByteOffsetInBlock: 16408265
7555430 2016-11-15 12:14:25,329 DEBUG [ResponseProcessor for block
BP-1837290273-10.17.240.20-1458945429978:blk_1077044408_3304141]
hdfs.DFSClient: DFSClient seqno: 1260315 reply: SUCCESS downstreamAckTimeNanos:
0 flag: 0
7555431 2016-11-15 12:14:25,329 DEBUG [DataStreamer for file
/user/stack/test-data/300d7166-b729-47da-965d-936ec5f7bb43/WALPerformanceEvaluation/WALs/wals/wals.1479240483655
block BP-1837290273-10.17.240.20-1458945429978:blk_1077044408_3304141]
hdfs.DFSClient: Closing old block BP-183729027
3-10.17.240.20-1458945429978:blk_1077044408_3304141
7555432 2016-11-15 12:14:25,344 INFO [main] hbase.MockRegionServerServices:
Shutting down due to request 'test clean up.'
7555433 2016-11-15 12:14:25,344 INFO [main] wal.WALPerformanceEvaluation:
shutting down log roller.
7555434 2016-11-15 12:14:25,345 INFO [WALPerfEval.logRoller]
regionserver.LogRoller: LogRoller exiting.
7555435
7555436 Performance counter stats for './hbase/bin/hbase --config
/home/stack/conf_hbase org.apache.hadoop.hbase.wal.WALPerformanceEvaluation
-threads 100 -iterations 100000 -qualifiers 25 -keySize 50 -valueSize 200':
7555437
7555438 4987370.861017 task-clock (msec) # 12.922 CPUs utilized
7555439 18,957,350 context-switches # 0.004 M/sec
7555440 2,815,124 cpu-migrations # 0.564 K/sec
7555441 10,054,046 page-faults # 0.002 M/sec
7555442 9,934,495,287,070 cycles # 1.992 GHz
7555443 <not supported> stalled-cycles-frontend
7555444 <not supported> stalled-cycles-backend
7555445 3,796,677,865,651 instructions # 0.38 insns per cycle
7555446 608,865,750,776 branches # 122.082 M/sec
7555447 7,478,401,535 branch-misses # 1.23% of all branches
7555448
7555449 385.959774164 seconds time elapsed
{code}
With patch:
{code}
....
36055
36056 -- Histograms
------------------------------------------------------------------
36057
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.latencyHistogram.nanos
36058 count = 9873855
36059 min = 1127719
36060 max = 250382688
36061 mean = 6424109.99
36062 stddev = 25553185.95
36063 median = 2244495.00
36064 75% <= 2799994.00
36065 95% <= 6014066.00
36066 98% <= 123609725.00
36067 99% <= 159854827.00
36068 99.9% <= 250382688.00
36069
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncCountHistogram.countPerSync
36070 count = 1594661
36071 min = 0
36072 max = 15
36073 mean = 6.27
36074 stddev = 3.73
36075 median = 7.00
36076 75% <= 9.00
36077 95% <= 12.00
36078 98% <= 13.00
36079 99% <= 13.00
36080 99.9% <= 15.00
36081
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncHistogram.nanos-between-syncs
36082 count = 1594661
36083 min = 694960
36084 max = 258463438
36085 mean = 8069691.28
36086 stddev = 30755921.05
36087 median = 2010634.00
36088 75% <= 2722606.00
36089 95% <= 8582150.00
36090 98% <= 146740612.00
36091 99% <= 170899248.00
36092 99.9% <= 244034570.00
36093
36094 -- Meters
----------------------------------------------------------------------
36095 org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.appendMeter.bytes
36096 count = 69018945450
36097 mean rate = 114652018.58 events/second
36098 1-minute rate = 112275313.29 events/second
36099 5-minute rate = 107994241.97 events/second
36100 15-minute rate = 91648849.44 events/second
36101 org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncMeter.syncs
36102 count = 1594661
36103 mean rate = 2648.98 events/second
36104 1-minute rate = 2574.82 events/second
36105 5-minute rate = 2445.82 events/second
36106 15-minute rate = 1864.69 events/second
36107
....
36511 2016-11-15 12:59:04,660 INFO [main] wal.WALPerformanceEvaluation:
Summary: threads=100, iterations=100000, syncInterval=0 took 608.742s
16427.320ops/s
36512 2016-11-15 12:59:04,661 DEBUG [main] regionserver.HRegion: Closing
WALPerformanceEvaluation:0,,1479242934744.ad2a33c783996382bcf80bc14f03e3bf.:
disabling compactions & flushes
36513 2016-11-15 12:59:04,662 DEBUG [main] regionserver.HRegion: Updates
disabled for region
WALPerformanceEvaluation:0,,1479242934744.ad2a33c783996382bcf80bc14f03e3bf.
36514 2016-11-15 12:59:04,667 INFO
[StoreCloserThread-WALPerformanceEvaluation:0,,1479242934744.ad2a33c783996382bcf80bc14f03e3bf.-1]
regionserver.HStore: Closed cf0
36515 2016-11-15 12:59:04,668 INFO [main] regionserver.HRegion: Closed
WALPerformanceEvaluation:0,,1479242934744.ad2a33c783996382bcf80bc14f03e3bf.
36516 2016-11-15 12:59:04,713 INFO [main] hbase.MockRegionServerServices:
Shutting down due to request 'test clean up.'
36517 2016-11-15 12:59:04,713 INFO [main] wal.WALPerformanceEvaluation:
shutting down log roller.
36518 2016-11-15 12:59:04,714 INFO [WALPerfEval.logRoller]
regionserver.LogRoller: LogRoller exiting.
36519
36520 Performance counter stats for './hbase/bin/hbase --config
/home/stack/conf_hbase org.apache.hadoop.hbase.wal.WALPerformanceEvaluation
-threads 100 -iterations 100000 -qualifiers 25 -keySize 50 -valueSize 200':
36521
36522 4568572.588814 task-clock (msec) # 7.454 CPUs utilized
36523 11,307,856 context-switches # 0.002 M/sec
36524 1,620,191 cpu-migrations # 0.355 K/sec
36525 16,534,487 page-faults # 0.004 M/sec
36526 9,292,754,813,201 cycles # 2.034 GHz
36527 <not supported> stalled-cycles-frontend
36528 <not supported> stalled-cycles-backend
36529 3,245,931,999,369 instructions # 0.35 insns per cycle
36530 504,972,460,674 branches # 110.532 M/sec
36531 6,824,754,683 branch-misses # 1.35% of all branches
36532
36533 612.925849943 seconds time elapsed
{code}
40% slower?
Picking out sync counts from default WAL, its doing about 35 or so mean.... so
we are syncing differently still. Did this patch make a difference? Seems same
as what we had over in HBASE-16890?
Here is what I ran against a single node HDFS:
2337 perf stat ./hbase/bin/hbase --config ~/conf_hbase
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation -threads 100 -iterations
100000 -qualifiers 25 -keySize 50 -valueSize 200 &> /tmp/log_async.txt
> AsyncFSWAL may issue unnecessary AsyncDFSOutput.sync
> ----------------------------------------------------
>
> Key: HBASE-17085
> URL: https://issues.apache.org/jira/browse/HBASE-17085
> Project: HBase
> Issue Type: Sub-task
> Components: wal
> Affects Versions: 2.0.0
> Reporter: Duo Zhang
> Assignee: Duo Zhang
> Fix For: 2.0.0
>
> Attachments: HBASE-17085-v1.patch, HBASE-17085-v2.patch,
> HBASE-17085-v2.patch, HBASE-17085.patch
>
>
> The problem is in appendAndSync method, we will issue an AsyncDFSOutput.sync
> if syncFutures is not empty. The SyncFutures in syncFutures can only be
> removed after an AsyncDFSOutput.sync comes back, so before the
> AsyncDFSOutput.sync actually returns, we will always issue an
> AsyncDFSOutput.sync after an append even if there is no new sync request.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
