[
https://issues.apache.org/jira/browse/HBASE-15265?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15184500#comment-15184500
]
Duo Zhang commented on HBASE-15265:
-----------------------------------
Run WALPE with 5 threads
{noformat}
./bin/hbase org.apache.hadoop.hbase.wal.WALPerformanceEvaluation -threads 5
{noformat}
master
{noformat}
-- Histograms ------------------------------------------------------------------
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.latencyHistogram.nanos
count = 5000000
min = 452200
max = 1834676
mean = 723087.74
stddev = 125994.96
median = 703103.00
75% <= 745173.00
95% <= 920767.00
98% <= 1148129.00
99% <= 1288697.00
99.9% <= 1554315.00
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncCountHistogram.countPerSync
count = 4571938
min = 1
max = 2
mean = 1.06
stddev = 0.23
median = 1.00
75% <= 1.00
95% <= 2.00
98% <= 2.00
99% <= 2.00
99.9% <= 2.00
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncHistogram.nanos-between-syncs
count = 4571938
min = 415874
max = 1571407
mean = 693891.09
stddev = 107159.47
median = 673660.00
75% <= 717641.00
95% <= 896732.00
98% <= 992794.00
99% <= 1098338.00
99.9% <= 1518093.00
-- Meters ----------------------------------------------------------------------
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.appendMeter.bytes
count = 2785000000
mean rate = 3354500.98 events/second
1-minute rate = 3613345.23 events/second
5-minute rate = 3254224.23 events/second
15-minute rate = 2049616.71 events/second
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncMeter.syncs
count = 4571938
mean rate = 5506.81 events/second
1-minute rate = 6090.84 events/second
5-minute rate = 5397.76 events/second
15-minute rate = 3376.47 events/second
2016-03-08 13:59:10,692 INFO [t4,r0] wal.WALPerformanceEvaluation: t4,r0 took
809.430s 1235.437ops/s
2016-03-08 13:59:10,730 INFO [t0,r0] wal.WALPerformanceEvaluation: t0,r0 took
809.469s 1235.378ops/s
2016-03-08 13:59:10,925 INFO [t3,r0] wal.WALPerformanceEvaluation: t3,r0 took
809.664s 1235.080ops/s
2016-03-08 13:59:11,164 INFO [t2,r0] wal.WALPerformanceEvaluation: t2,r0 took
809.903s 1234.716ops/s
2016-03-08 13:59:11,232 INFO [t1,r0] wal.WALPerformanceEvaluation: t1,r0 took
809.972s 1234.611ops/s
2016-03-08 13:59:11,233 INFO [main] wal.WALPerformanceEvaluation: Summary:
threads=5, iterations=1000000, syncInterval=0 took 809.973s 6173.045ops/s
{noformat}
patched
{noformat}
-- Histograms ------------------------------------------------------------------
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.latencyHistogram.nanos
count = 5000000
min = 67653
max = 1211514
mean = 355929.64
stddev = 100616.20
median = 338680.00
75% <= 386992.00
95% <= 466571.00
98% <= 678368.00
99% <= 767800.00
99.9% <= 1174408.00
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncCountHistogram.countPerSync
count = 2982546
min = 0
max = 4
mean = 1.63
stddev = 0.74
median = 2.00
75% <= 2.00
95% <= 3.00
98% <= 4.00
99% <= 4.00
99.9% <= 4.00
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncHistogram.nanos-between-syncs
count = 2982546
min = 180697
max = 57874230
mean = 375459.18
stddev = 1551439.38
median = 310104.00
75% <= 349804.00
95% <= 469386.00
98% <= 755095.00
99% <= 1064668.00
99.9% <= 1679322.00
-- Meters ----------------------------------------------------------------------
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.appendMeter.bytes
count = 2785000000
mean rate = 6784702.13 events/second
1-minute rate = 6957392.69 events/second
5-minute rate = 5188375.04 events/second
15-minute rate = 2511006.30 events/second
org.apache.hadoop.hbase.wal.WALPerformanceEvaluation.syncMeter.syncs
count = 2982546
mean rate = 7265.86 events/second
1-minute rate = 7499.49 events/second
5-minute rate = 5574.20 events/second
15-minute rate = 2692.50 events/second
2016-03-08 14:06:59,454 INFO [t3,r0] wal.WALPerformanceEvaluation: t3,r0 took
386.169s 2589.540ops/s
2016-03-08 14:06:59,997 INFO [t2,r0] wal.WALPerformanceEvaluation: t2,r0 took
386.712s 2585.904ops/s
2016-03-08 14:07:00,037 INFO [t0,r0] wal.WALPerformanceEvaluation: t0,r0 took
386.752s 2585.636ops/s
2016-03-08 14:07:01,290 INFO [t4,r0] wal.WALPerformanceEvaluation: t4,r0 took
388.004s 2577.293ops/s
2016-03-08 14:07:01,513 INFO [t1,r0] wal.WALPerformanceEvaluation: t1,r0 took
388.227s 2575.813ops/s
2016-03-08 14:07:01,513 INFO [main] wal.WALPerformanceEvaluation: Summary:
threads=5, iterations=1000000, syncInterval=0 took 388.228s 12879.030ops/s
{noformat}
Still 2x faster :)
12879.030ops/s vs. 6173.045ops/s
And one more thing, in the 5 threads test, it prints a lot of slow sync logs.
For master, the latency is usually 300~400ms, and for the patched version, it
is usually 100~150ms. I do not know why there will be slow sync, maybe
something related to the config of datanode. But at least, the fan out
mechanism can reduce about 3x of the slow sync latency.
> Implement an asynchronous FSHLog
> --------------------------------
>
> Key: HBASE-15265
> URL: https://issues.apache.org/jira/browse/HBASE-15265
> Project: HBase
> Issue Type: Sub-task
> Components: wal
> Reporter: Duo Zhang
> Assignee: Duo Zhang
> Fix For: 2.0.0
>
> Attachments: HBASE-15265-v1.patch, HBASE-15265-v2.patch,
> HBASE-15265-v3.patch, HBASE-15265-v4.patch, HBASE-15265-v5.patch,
> HBASE-15265-v6.patch, HBASE-15265.patch
>
>
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
