Java tutorial
/* * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package org.apache.bookkeeper.tools.perf.dlog; import static org.apache.bookkeeper.common.concurrent.FutureUtils.result; import com.beust.jcommander.Parameter; import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.databind.ObjectWriter; import com.google.common.util.concurrent.RateLimiter; import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import io.netty.buffer.Unpooled; import java.text.DecimalFormat; import java.util.ArrayList; import java.util.List; import java.util.concurrent.CompletableFuture; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.Semaphore; import java.util.concurrent.ThreadLocalRandom; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.LongAdder; import java.util.stream.Collectors; import lombok.extern.slf4j.Slf4j; import org.HdrHistogram.Histogram; import org.HdrHistogram.Recorder; import org.apache.bookkeeper.common.concurrent.FutureUtils; import org.apache.bookkeeper.common.net.ServiceURI; import org.apache.bookkeeper.tools.framework.CliFlags; import org.apache.bookkeeper.tools.perf.utils.PaddingDecimalFormat; import org.apache.commons.lang3.tuple.Pair; import org.apache.distributedlog.DistributedLogConfiguration; import org.apache.distributedlog.LogRecord; import org.apache.distributedlog.api.AsyncLogWriter; import org.apache.distributedlog.api.DistributedLogManager; import org.apache.distributedlog.api.namespace.Namespace; import org.apache.distributedlog.api.namespace.NamespaceBuilder; /** * A perf writer to evaluate write performance. */ @Slf4j public class PerfWriter implements Runnable { /** * Flags for the write command. */ public static class Flags extends CliFlags { @Parameter(names = { "-r", "--rate" }, description = "Write rate bytes/s across log streams") public int writeRate = 0; @Parameter(names = { "-rs", "--record-size" }, description = "Log record size") public int recordSize = 1024; @Parameter(names = { "-ln", "--log-name" }, description = "Log name or log name pattern if more than 1 log is specified at `--num-logs`") public String logName = "test-log-%06d"; @Parameter(names = { "-l", "--num-logs" }, description = "Number of log streams") public int numLogs = 1; @Parameter(names = { "-t", "--threads" }, description = "Number of threads writing") public int numThreads = 1; @Parameter(names = { "-mob", "--max-outstanding-megabytes" }, description = "Number of threads writing") public long maxOutstandingMB = 200; @Parameter(names = { "-n", "--num-records" }, description = "Number of records to write in total. If 0, it will keep writing") public long numRecords = 0; @Parameter(names = { "-mlss", "--max-log-segment-size" }, description = "Max log segment size") public int maxLogSegmentSize = 64 * 1024 * 1024; @Parameter(names = { "-b", "--num-bytes" }, description = "Number of bytes to write in total. If 0, it will keep writing") public long numBytes = 0; @Parameter(names = { "-e", "--ensemble-size" }, description = "Ledger ensemble size") public int ensembleSize = 1; @Parameter(names = { "-w", "--write-quorum-size" }, description = "Ledger write quorum size") public int writeQuorumSize = 1; @Parameter(names = { "-a", "--ack-quorum-size" }, description = "Ledger ack quorum size") public int ackQuorumSize = 1; } // stats private final LongAdder recordsWritten = new LongAdder(); private final LongAdder bytesWritten = new LongAdder(); private final byte[] payload; private final ServiceURI serviceURI; private final Flags flags; private final Recorder recorder = new Recorder(TimeUnit.SECONDS.toMillis(120000), 5); private final Recorder cumulativeRecorder = new Recorder(TimeUnit.SECONDS.toMillis(120000), 5); private final AtomicBoolean isDone = new AtomicBoolean(false); PerfWriter(ServiceURI serviceURI, Flags flags) { this.serviceURI = serviceURI; this.flags = flags; this.payload = new byte[flags.recordSize]; ThreadLocalRandom.current().nextBytes(payload); } @Override public void run() { try { execute(); } catch (Exception e) { log.error("Encountered exception at running dlog perf writer", e); } } void execute() throws Exception { ObjectMapper m = new ObjectMapper(); ObjectWriter w = m.writerWithDefaultPrettyPrinter(); log.info("Starting dlog perf writer with config : {}", w.writeValueAsString(flags)); DistributedLogConfiguration conf = newDlogConf(flags); try (Namespace namespace = NamespaceBuilder.newBuilder().conf(conf).uri(serviceURI.getUri()).build()) { execute(namespace); } } void execute(Namespace namespace) throws Exception { List<Pair<Integer, DistributedLogManager>> managers = new ArrayList<>(flags.numLogs); for (int i = 0; i < flags.numLogs; i++) { String logName = String.format(flags.logName, i); managers.add(Pair.of(i, namespace.openLog(logName))); } log.info("Successfully open {} logs", managers.size()); // register shutdown hook to aggregate stats Runtime.getRuntime().addShutdownHook(new Thread(() -> { isDone.set(true); printAggregatedStats(cumulativeRecorder); })); ExecutorService executor = Executors.newFixedThreadPool(flags.numThreads); try { for (int i = 0; i < flags.numThreads; i++) { final int idx = i; final List<DistributedLogManager> logsThisThread = managers.stream() .filter(pair -> pair.getLeft() % flags.numThreads == idx).map(pair -> pair.getRight()) .collect(Collectors.toList()); final long numRecordsForThisThread = flags.numRecords / flags.numThreads; final long numBytesForThisThread = flags.numBytes / flags.numThreads; final double writeRateForThisThread = flags.writeRate / (double) flags.numThreads; final long maxOutstandingBytesForThisThread = flags.maxOutstandingMB * 1024 * 1024 / flags.numThreads; executor.submit(() -> { try { write(logsThisThread, writeRateForThisThread, (int) maxOutstandingBytesForThisThread, numRecordsForThisThread, numBytesForThisThread); } catch (Exception e) { log.error("Encountered error at writing records", e); } }); } log.info("Started {} write threads", flags.numThreads); reportStats(); } finally { executor.shutdown(); if (!executor.awaitTermination(5, TimeUnit.SECONDS)) { executor.shutdownNow(); } managers.forEach(manager -> manager.getRight().asyncClose()); } } void write(List<DistributedLogManager> logs, double writeRate, int maxOutstandingBytesForThisThread, long numRecordsForThisThread, long numBytesForThisThread) throws Exception { log.info( "Write thread started with : logs = {}, rate = {}," + " num records = {}, num bytes = {}, max outstanding bytes = {}", logs.stream().map(l -> l.getStreamName()).collect(Collectors.toList()), writeRate, numRecordsForThisThread, numBytesForThisThread, maxOutstandingBytesForThisThread); List<CompletableFuture<AsyncLogWriter>> writerFutures = logs.stream() .map(manager -> manager.openAsyncLogWriter()).collect(Collectors.toList()); List<AsyncLogWriter> writers = result(FutureUtils.collect(writerFutures)); long txid = writers.stream().mapToLong(writer -> writer.getLastTxId()).max().orElse(0L); txid = Math.max(0L, txid); RateLimiter limiter; if (writeRate > 0) { limiter = RateLimiter.create(writeRate); } else { limiter = null; } final Semaphore semaphore; if (maxOutstandingBytesForThisThread > 0) { semaphore = new Semaphore(maxOutstandingBytesForThisThread); } else { semaphore = null; } // Acquire 1 second worth of records to have a slower ramp-up if (limiter != null) { limiter.acquire((int) writeRate); } long totalWritten = 0L; long totalBytesWritten = 0L; final int numLogs = logs.size(); while (true) { for (int i = 0; i < numLogs; i++) { if (numRecordsForThisThread > 0 && totalWritten >= numRecordsForThisThread) { markPerfDone(); } if (numBytesForThisThread > 0 && totalBytesWritten >= numBytesForThisThread) { markPerfDone(); } if (null != semaphore) { semaphore.acquire(payload.length); } totalWritten++; totalBytesWritten += payload.length; if (null != limiter) { limiter.acquire(payload.length); } final long sendTime = System.nanoTime(); writers.get(i).write(new LogRecord(++txid, Unpooled.wrappedBuffer(payload))).thenAccept(dlsn -> { if (null != semaphore) { semaphore.release(payload.length); } recordsWritten.increment(); bytesWritten.add(payload.length); long latencyMicros = TimeUnit.NANOSECONDS.toMicros(System.nanoTime() - sendTime); recorder.recordValue(latencyMicros); cumulativeRecorder.recordValue(latencyMicros); }).exceptionally(cause -> { log.warn("Error at writing records", cause); System.exit(-1); return null; }); } } } @SuppressFBWarnings("DM_EXIT") void markPerfDone() throws Exception { log.info("------------------- DONE -----------------------"); printAggregatedStats(cumulativeRecorder); isDone.set(true); Thread.sleep(5000); System.exit(0); } void reportStats() { // Print report stats long oldTime = System.nanoTime(); Histogram reportHistogram = null; while (true) { try { Thread.sleep(10000); } catch (InterruptedException e) { break; } if (isDone.get()) { break; } long now = System.nanoTime(); double elapsed = (now - oldTime) / 1e9; double rate = recordsWritten.sumThenReset() / elapsed; double throughput = bytesWritten.sumThenReset() / elapsed / 1024 / 1024; reportHistogram = recorder.getIntervalHistogram(reportHistogram); log.info( "Throughput written : {} records/s --- {} MB/s --- Latency: mean:" + " {} ms - med: {} - 95pct: {} - 99pct: {} - 99.9pct: {} - 99.99pct: {} - Max: {}", throughputFormat.format(rate), throughputFormat.format(throughput), dec.format(reportHistogram.getMean() / 1000.0), dec.format(reportHistogram.getValueAtPercentile(50) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(95) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.9) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.99) / 1000.0), dec.format(reportHistogram.getMaxValue() / 1000.0)); reportHistogram.reset(); oldTime = now; } } private static DistributedLogConfiguration newDlogConf(Flags flags) { return new DistributedLogConfiguration().setEnsembleSize(flags.ensembleSize) .setWriteQuorumSize(flags.writeQuorumSize).setAckQuorumSize(flags.ackQuorumSize) .setOutputBufferSize(512 * 1024).setPeriodicFlushFrequencyMilliSeconds(2).setWriteLockEnabled(false) .setMaxLogSegmentBytes(flags.maxLogSegmentSize).setLogSegmentRollingIntervalMinutes(1) .setExplicitTruncationByApplication(true); } private static final DecimalFormat throughputFormat = new PaddingDecimalFormat("0.0", 8); private static final DecimalFormat dec = new PaddingDecimalFormat("0.000", 7); private static void printAggregatedStats(Recorder recorder) { Histogram reportHistogram = recorder.getIntervalHistogram(); log.info( "Aggregated latency stats --- Latency: mean: {} ms - med: {} - 95pct: {} - 99pct: {}" + " - 99.9pct: {} - 99.99pct: {} - 99.999pct: {} - Max: {}", dec.format(reportHistogram.getMean() / 1000.0), dec.format(reportHistogram.getValueAtPercentile(50) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(95) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.9) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.99) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.999) / 1000.0), dec.format(reportHistogram.getMaxValue() / 1000.0)); } }