in pulsar-testclient/src/main/java/org/apache/pulsar/testclient/PerformanceConsumer.java [214:513]
public void run() throws Exception {
// Dump config variables
PerfClientUtils.printJVMInformation(log);
ObjectMapper m = new ObjectMapper();
ObjectWriter w = m.writerWithDefaultPrettyPrinter();
log.info("Starting Pulsar performance consumer with config: {}", w.writeValueAsString(this));
final Recorder qRecorder = this.autoScaledReceiverQueueSize
? new Recorder(this.receiverQueueSize, 5) : null;
final RateLimiter limiter = this.rate > 0 ? RateLimiter.create(this.rate) : null;
long startTime = System.nanoTime();
long testEndTime = startTime + (long) (this.testTime * 1e9);
ClientBuilder clientBuilder = PerfClientUtils.createClientBuilderFromArguments(this)
.enableTransaction(this.isEnableTransaction);
PulsarClient pulsarClient = clientBuilder.build();
AtomicReference<Transaction> atomicReference;
if (this.isEnableTransaction) {
atomicReference = new AtomicReference<>(pulsarClient.newTransaction()
.withTransactionTimeout(this.transactionTimeout, TimeUnit.SECONDS).build().get());
} else {
atomicReference = new AtomicReference<>(null);
}
AtomicLong messageAckedCount = new AtomicLong();
Semaphore messageReceiveLimiter = new Semaphore(this.numMessagesPerTransaction);
Thread thread = Thread.currentThread();
MessageListener<ByteBuffer> listener = (consumer, msg) -> {
if (this.testTime > 0) {
if (System.nanoTime() > testEndTime) {
log.info("------------------- DONE -----------------------");
PerfClientUtils.exit(0);
thread.interrupt();
}
}
if (this.totalNumTxn > 0) {
if (totalEndTxnOpFailNum.sum() + totalEndTxnOpSuccessNum.sum() >= this.totalNumTxn) {
log.info("------------------- DONE -----------------------");
PerfClientUtils.exit(0);
thread.interrupt();
}
}
if (qRecorder != null) {
qRecorder.recordValue(((ConsumerBase<?>) consumer).getTotalIncomingMessages());
}
messagesReceived.increment();
bytesReceived.add(msg.size());
totalMessagesReceived.increment();
totalBytesReceived.add(msg.size());
if (this.numMessages > 0 && totalMessagesReceived.sum() >= this.numMessages) {
log.info("------------------- DONE -----------------------");
PerfClientUtils.exit(0);
thread.interrupt();
}
if (limiter != null) {
limiter.acquire();
}
long latencyMillis = System.currentTimeMillis() - msg.getPublishTime();
if (latencyMillis >= 0) {
if (latencyMillis >= MAX_LATENCY) {
latencyMillis = MAX_LATENCY;
}
recorder.recordValue(latencyMillis);
cumulativeRecorder.recordValue(latencyMillis);
}
if (this.isEnableTransaction) {
try {
messageReceiveLimiter.acquire();
} catch (InterruptedException e){
log.error("Got error: ", e);
}
consumer.acknowledgeAsync(msg.getMessageId(), atomicReference.get()).thenRun(() -> {
totalMessageAck.increment();
messageAck.increment();
}).exceptionally(throwable ->{
log.error("Ack message {} failed with exception", msg, throwable);
totalMessageAckFailed.increment();
return null;
});
} else {
consumer.acknowledgeAsync(msg).thenRun(()->{
totalMessageAck.increment();
messageAck.increment();
}
).exceptionally(throwable ->{
log.error("Ack message {} failed with exception", msg, throwable);
totalMessageAckFailed.increment();
return null;
}
);
}
if (this.poolMessages) {
msg.release();
}
if (this.isEnableTransaction
&& messageAckedCount.incrementAndGet() == this.numMessagesPerTransaction) {
Transaction transaction = atomicReference.get();
if (!this.isAbortTransaction) {
transaction.commit()
.thenRun(() -> {
if (log.isDebugEnabled()) {
log.debug("Commit transaction {}", transaction.getTxnID());
}
totalEndTxnOpSuccessNum.increment();
numTxnOpSuccess.increment();
})
.exceptionally(exception -> {
log.error("Commit transaction failed with exception : ", exception);
totalEndTxnOpFailNum.increment();
return null;
});
} else {
transaction.abort().thenRun(() -> {
if (log.isDebugEnabled()) {
log.debug("Abort transaction {}", transaction.getTxnID());
}
totalEndTxnOpSuccessNum.increment();
numTxnOpSuccess.increment();
}).exceptionally(exception -> {
log.error("Abort transaction {} failed with exception",
transaction.getTxnID().toString(),
exception);
totalEndTxnOpFailNum.increment();
return null;
});
}
while (true) {
try {
Transaction newTransaction = pulsarClient.newTransaction()
.withTransactionTimeout(this.transactionTimeout, TimeUnit.SECONDS)
.build().get();
atomicReference.compareAndSet(transaction, newTransaction);
totalNumTxnOpenSuccess.increment();
messageAckedCount.set(0);
messageReceiveLimiter.release(this.numMessagesPerTransaction);
break;
} catch (Exception e) {
log.error("Failed to new transaction with exception:", e);
totalNumTxnOpenFail.increment();
}
}
}
};
List<Future<Consumer<ByteBuffer>>> futures = new ArrayList<>();
ConsumerBuilder<ByteBuffer> consumerBuilder = pulsarClient.newConsumer(Schema.BYTEBUFFER) //
.messageListener(listener) //
.receiverQueueSize(this.receiverQueueSize) //
.maxTotalReceiverQueueSizeAcrossPartitions(this.maxTotalReceiverQueueSizeAcrossPartitions)
.acknowledgmentGroupTime(this.acknowledgmentsGroupingDelayMillis, TimeUnit.MILLISECONDS) //
.subscriptionType(this.subscriptionType)
.subscriptionInitialPosition(this.subscriptionInitialPosition)
.autoAckOldestChunkedMessageOnQueueFull(this.autoAckOldestChunkedMessageOnQueueFull)
.enableBatchIndexAcknowledgment(this.batchIndexAck)
.poolMessages(this.poolMessages)
.replicateSubscriptionState(this.replicatedSubscription)
.autoScaledReceiverQueueSizeEnabled(this.autoScaledReceiverQueueSize);
if (this.maxPendingChunkedMessage > 0) {
consumerBuilder.maxPendingChunkedMessage(this.maxPendingChunkedMessage);
}
if (this.expireTimeOfIncompleteChunkedMessageMs > 0) {
consumerBuilder.expireTimeOfIncompleteChunkedMessage(this.expireTimeOfIncompleteChunkedMessageMs,
TimeUnit.MILLISECONDS);
}
if (isNotBlank(this.encKeyFile)) {
consumerBuilder.defaultCryptoKeyReader(this.encKeyFile);
}
for (int i = 0; i < this.numTopics; i++) {
final TopicName topicName = TopicName.get(this.topics.get(i));
log.info("Adding {} consumers per subscription on topic {}", this.numConsumers, topicName);
for (int j = 0; j < this.numSubscriptions; j++) {
String subscriberName = this.subscriptions.get(j);
for (int k = 0; k < this.numConsumers; k++) {
futures.add(consumerBuilder.clone().topic(topicName.toString()).subscriptionName(subscriberName)
.subscribeAsync());
}
}
}
for (Future<Consumer<ByteBuffer>> future : futures) {
future.get();
}
log.info("Start receiving from {} consumers per subscription on {} topics", this.numConsumers,
this.numTopics);
long start = System.nanoTime();
Runtime.getRuntime().addShutdownHook(new Thread(() -> {
printAggregatedThroughput(start);
printAggregatedStats();
}));
long oldTime = System.nanoTime();
Histogram reportHistogram = null;
Histogram qHistogram = null;
HistogramLogWriter histogramLogWriter = null;
if (this.histogramFile != null) {
String statsFileName = this.histogramFile;
log.info("Dumping latency stats to {}", statsFileName);
PrintStream histogramLog = new PrintStream(new FileOutputStream(statsFileName), false);
histogramLogWriter = new HistogramLogWriter(histogramLog);
// Some log header bits
histogramLogWriter.outputLogFormatVersion();
histogramLogWriter.outputLegend();
}
while (true) {
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
break;
}
long now = System.nanoTime();
double elapsed = (now - oldTime) / 1e9;
long total = totalMessagesReceived.sum();
double rate = messagesReceived.sumThenReset() / elapsed;
double throughput = bytesReceived.sumThenReset() / elapsed * 8 / 1024 / 1024;
double rateAck = messageAck.sumThenReset() / elapsed;
long totalTxnOpSuccessNum = 0;
long totalTxnOpFailNum = 0;
double rateOpenTxn = 0;
reportHistogram = recorder.getIntervalHistogram(reportHistogram);
if (this.isEnableTransaction) {
totalTxnOpSuccessNum = totalEndTxnOpSuccessNum.sum();
totalTxnOpFailNum = totalEndTxnOpFailNum.sum();
rateOpenTxn = numTxnOpSuccess.sumThenReset() / elapsed;
log.info("--- Transaction: {} transaction end successfully --- {} transaction end failed "
+ "--- {} Txn/s --- AckRate: {} msg/s",
totalTxnOpSuccessNum,
totalTxnOpFailNum,
dec.format(rateOpenTxn),
dec.format(rateAck));
}
log.info(
"Throughput received: {} msg --- {} msg/s --- {} Mbit/s "
+ "--- Latency: mean: {} ms - med: {} "
+ "- 95pct: {} - 99pct: {} - 99.9pct: {} - 99.99pct: {} - Max: {}",
intFormat.format(total),
dec.format(rate), dec.format(throughput), dec.format(reportHistogram.getMean()),
reportHistogram.getValueAtPercentile(50), reportHistogram.getValueAtPercentile(95),
reportHistogram.getValueAtPercentile(99), reportHistogram.getValueAtPercentile(99.9),
reportHistogram.getValueAtPercentile(99.99), reportHistogram.getMaxValue());
if (this.autoScaledReceiverQueueSize && log.isDebugEnabled() && qRecorder != null) {
qHistogram = qRecorder.getIntervalHistogram(qHistogram);
log.debug("ReceiverQueueUsage: cnt={},mean={}, min={},max={},25pct={},50pct={},75pct={}",
qHistogram.getTotalCount(), dec.format(qHistogram.getMean()),
qHistogram.getMinValue(), qHistogram.getMaxValue(),
qHistogram.getValueAtPercentile(25),
qHistogram.getValueAtPercentile(50),
qHistogram.getValueAtPercentile(75)
);
qHistogram.reset();
for (Future<Consumer<ByteBuffer>> future : futures) {
ConsumerBase<?> consumerBase = (ConsumerBase<?>) future.get();
log.debug("[{}] CurrentReceiverQueueSize={}", consumerBase.getConsumerName(),
consumerBase.getCurrentReceiverQueueSize());
if (consumerBase instanceof MultiTopicsConsumerImpl) {
for (ConsumerImpl<?> consumer : ((MultiTopicsConsumerImpl<?>) consumerBase).getConsumers()) {
log.debug("[{}] SubConsumer.CurrentReceiverQueueSize={}", consumer.getConsumerName(),
consumer.getCurrentReceiverQueueSize());
}
}
}
}
if (histogramLogWriter != null) {
histogramLogWriter.outputIntervalHistogram(reportHistogram);
}
reportHistogram.reset();
oldTime = now;
if (this.testTime > 0) {
if (now > testEndTime) {
log.info("------------------- DONE -----------------------");
PerfClientUtils.exit(0);
thread.interrupt();
}
}
}
pulsarClient.close();
}