Performance test improvements

.gitignore

@@ -21,3 +21,5 @@ coverage
 .nyc_output/
 *lcov.info
 **/lcov-report
+examples/performance/*.json
+*.log

.semaphore/semaphore.yml

@@ -191,7 +191,7 @@ blocks:
             - export NODE_OPTIONS='--max-old-space-size=1536'
             - cd examples/performance
             - npm install
-            - bash -c '../../ci/tests/run_perf_test.sh'
+            - node '../../ci/tests/run_perf_test.js'
             - rm -rf ./node_modules
 
   - name: "Linux amd64: Release"

CHANGELOG.md

@@ -9,6 +9,7 @@ v1.6.1 is a maintenance release. It is supported for all usage.
    property (#393).
 2. Fix for at-least-once guarantee not ensured in case a seek happens on one
 partition and there are messages being fetched about other partitions (#393).
+3. Messages passed to the producer `send` method are kept constant (#394).
 
 
 # confluent-kafka-javascript 1.6.0

examples/performance/performance-consolidated.js

@@ -1,84 +1,246 @@
+const fs = require('fs');
 const mode = process.env.MODE ? process.env.MODE : 'confluent';
 
-let runProducer, runConsumer, runConsumeTransformProduce, runCreateTopics, runProducerConsumerTogether;
+let runProducer, runConsumer, runConsumeTransformProduce, runCreateTopics, runProducerConsumerTogether, runProducerCKJS;
 if (mode === 'confluent') {
-    ({ runProducer, runConsumer, runConsumeTransformProduce, runCreateTopics, runProducerConsumerTogether } = require('./performance-primitives'));
+    ({ runProducer, runConsumer, runConsumeTransformProduce,
+        runCreateTopics, runLagMonitoring,
+        runProducerConsumerTogether } = require('./performance-primitives'));
+    runProducerCKJS = runProducer;
 } else {
-    ({ runProducer, runConsumer, runConsumeTransformProduce, runCreateTopics, runProducerConsumerTogether } = require('./performance-primitives-kafkajs'));
+    ({ runProducer, runConsumer, runConsumeTransformProduce, runProducerConsumerTogether } = require('./performance-primitives-kafkajs'));
+    /* createTopics is more reliable in CKJS */
+    ({ runCreateTopics, runLagMonitoring, runProducer: runProducerCKJS } = require('./performance-primitives'));
 }
 
 const brokers = process.env.KAFKA_BROKERS || 'localhost:9092';
-const topic = process.env.KAFKA_TOPIC || 'test-topic';
-const topic2 = process.env.KAFKA_TOPIC2 || 'test-topic2';
+const securityProtocol = process.env.SECURITY_PROTOCOL;
+const saslUsername = process.env.SASL_USERNAME;
+const saslPassword = process.env.SASL_PASSWORD;
+const topic = process.env.KAFKA_TOPIC || `test-topic-${mode}`;
+const topic2 = process.env.KAFKA_TOPIC2 || `test-topic2-${mode}`;
 const messageCount = process.env.MESSAGE_COUNT ? +process.env.MESSAGE_COUNT : 1000000;
-const messageSize = process.env.MESSAGE_SIZE ? +process.env.MESSAGE_SIZE : 256;
-const batchSize = process.env.BATCH_SIZE ? +process.env.BATCH_SIZE : 100;
+const messageSize = process.env.MESSAGE_SIZE ? +process.env.MESSAGE_SIZE : 4096;
+const batchSize = process.env.PRODUCER_BATCH_SIZE ? +process.env.PRODUCER_BATCH_SIZE : 100;
 const compression = process.env.COMPRESSION || 'None';
+// Between 0 and 1, percentage of random bytes in each message
+const randomness = process.env.RANDOMNESS ? +process.env.RANDOMNESS : 0.5;
+const initialDelayMs = process.env.INITIAL_DELAY_MS ? +process.env.INITIAL_DELAY_MS : 0;
+const numPartitions = process.env.PARTITIONS ? +process.env.PARTITIONS : 3;
+const partitionsConsumedConcurrently = process.env.PARTITIONS_CONSUMED_CONCURRENTLY ? +process.env.PARTITIONS_CONSUMED_CONCURRENTLY : 1;
 const warmupMessages = process.env.WARMUP_MESSAGES ? +process.env.WARMUP_MESSAGES : (batchSize * 10);
 const messageProcessTimeMs = process.env.MESSAGE_PROCESS_TIME_MS ? +process.env.MESSAGE_PROCESS_TIME_MS : 5;
 const ctpConcurrency = process.env.CONSUME_TRANSFORM_PRODUCE_CONCURRENCY ? +process.env.CONSUME_TRANSFORM_PRODUCE_CONCURRENCY : 1;
 const consumerProcessingTime = process.env.CONSUMER_PROCESSING_TIME ? +process.env.CONSUMER_PROCESSING_TIME : 100;
 const producerProcessingTime = process.env.PRODUCER_PROCESSING_TIME ? +process.env.PRODUCER_PROCESSING_TIME : 100;
+const limitRPS = process.env.LIMIT_RPS ? +process.env.LIMIT_RPS : null;
+const useCKJSProducerEverywhere = process.env.USE_CKJS_PRODUCER_EVERYWHERE === 'true';
+const parameters = {
+    brokers,
+    securityProtocol,
+    saslUsername,
+    saslPassword,
+}
+
+function logParameters(parameters) {
+    console.log(`  Brokers: ${parameters.brokers}`);
+    if (parameters.securityProtocol && parameters.saslUsername && parameters.saslPassword) {
+        console.log(`  Security Protocol: ${parameters.securityProtocol}`);
+        console.log(`  SASL Username: ${parameters.saslUsername ? parameters.saslUsername : 'not set'}`);
+        console.log(`  SASL Password: ${parameters.saslPassword ? '******' : 'not set'}`);
+    } else {
+        console.log("  No security protocol configured");
+    }
+}
+
+function printPercentiles(percentiles, type) {
+    for (const { percentile, value, count, total } of percentiles) {
+        const percentileStr = `P${percentile}`.padStart(6, ' ');
+        console.log(`=== Consumer ${percentileStr} E2E latency ${type}: ${value.toFixed(2)} ms (${count}/${total})`);
+    }
+}
 
 (async function () {
     const producer = process.argv.includes('--producer');
     const consumer = process.argv.includes('--consumer');
+    const consumerEachMessage = process.argv.includes('--consumer-each-message');
+    const consumerEachBatch = process.argv.includes('--consumer-each-batch');
+    const produceToSecondTopic = process.argv.includes('--produce-to-second-topic');
     const ctp = process.argv.includes('--ctp');
     const produceConsumeLatency = process.argv.includes('--latency');
     const all = process.argv.includes('--all');
     const createTopics = process.argv.includes('--create-topics');
+    const monitorLag = process.argv.includes('--monitor-lag');
+    let maxAverageRSSKB, maxMaxRSSKB;
+    const stats = {};
+
+    let measures = [];
+    let interval;
+    const startTrackingMemory = () => {
+        interval = setInterval(() => {
+            measures.push({ rss: process.memoryUsage().rss,
+                            timestamp: Date.now() });
+        }, 100);
+    };
+
+    const datapointToJSON = (m) =>
+        ({ rss: m.rss.toString(), timestamp: m.timestamp.toString() });
+
+    const endTrackingMemory = (name, fileName) => {
+        clearInterval(interval);
+        interval = null;
+        const averageRSS = measures.reduce((sum, m) => sum + m.rss, 0) / measures.length;
+        const averageRSSKB = averageRSS / 1024;
+        maxAverageRSSKB = !maxAverageRSSKB ? averageRSSKB : Math.max(averageRSSKB, maxAverageRSSKB);
+        console.log(`=== Average ${name} RSS KB: ${averageRSSKB}`);
+        const max = measures.reduce((prev, current) => (prev.rss > current.rss) ? prev : current);
+        const maxRSSKB = max.rss / 1024;
+        maxMaxRSSKB = !maxMaxRSSKB ? maxRSSKB : Math.max(maxRSSKB, maxMaxRSSKB);
+        console.log(`=== Max ${name} RSS KB: ${maxRSSKB}`);
+        if (fileName) {
+            const measuresJSON = JSON.stringify({
+                measures: measures.map(datapointToJSON),
+                averageRSS: averageRSS.toString(),
+                maxRSS: datapointToJSON(max)
+            }, null, 2);
+            fs.writeFileSync(fileName, measuresJSON);
+        }
+        measures = [];
+    }
+
+    console.log(`=== Starting Performance Tests - Mode ${mode} ===`);
+    if (initialDelayMs > 0) {
+        console.log(`=== Initial delay of ${initialDelayMs}ms before starting tests ===`);
+        await new Promise(resolve => setTimeout(resolve, initialDelayMs));
+    }
 
     if (createTopics || all) {
         console.log("=== Creating Topics (deleting if they exist already):");
-        console.log(`  Brokers: ${brokers}`);
+        logParameters(parameters);
         console.log(`  Topic: ${topic}`);
         console.log(`  Topic2: ${topic2}`);
-        await runCreateTopics(brokers, topic, topic2);
+        console.log(`  Partitions: ${numPartitions}`);
+        await runCreateTopics(parameters, topic, topic2, numPartitions);
+    }
+
+    if (monitorLag) {
+        console.log("=== Starting Lag Monitoring:");
+        logParameters(parameters);
+        console.log(`  Topic: ${topic}`);
+        const {
+            averageLag,
+            maxLag,
+            totalMeasurements
+        } = await runLagMonitoring(parameters, topic);
+        const monitoredGroupId = process.env.GROUPID_MONITOR;
+        console.log(`=== Average broker lag (${monitoredGroupId}): `, averageLag);
+        console.log(`=== Max broker lag (${monitoredGroupId}): `, maxLag);
+        console.log(`=== Sample size for broker lag measurement (${monitoredGroupId}): `, totalMeasurements);
     }
 
     if (producer || all) {
         console.log("=== Running Basic Producer Performance Test:")
-        console.log(`  Brokers: ${brokers}`);
+        logParameters(parameters);
         console.log(`  Topic: ${topic}`);
         console.log(`  Message Count: ${messageCount}`);
         console.log(`  Message Size: ${messageSize}`);
         console.log(`  Batch Size: ${batchSize}`);
         console.log(`  Compression: ${compression}`);
+        console.log(`  Limit RPS: ${limitRPS}`);
         console.log(`  Warmup Messages: ${warmupMessages}`);
-        const producerRate = await runProducer(brokers, topic, batchSize, warmupMessages, messageCount, messageSize, compression);
+        console.log(`  Use CKJS Producer Everywhere: ${useCKJSProducerEverywhere}`);
+        startTrackingMemory();
+        let runProducerFunction = runProducer;
+        if (useCKJSProducerEverywhere) {
+            runProducerFunction = runProducerCKJS;
+        }
+        const producerRate = await runProducerFunction(parameters, topic, batchSize,
+            warmupMessages, messageCount, messageSize, compression,
+            randomness, limitRPS);
+        endTrackingMemory('producer', `producer-memory-${mode}.json`);
         console.log("=== Producer Rate: ", producerRate);
     }
 
-    if (consumer || all) {
+    if (consumer || consumerEachMessage || all) {
         // If user runs this without --producer then they are responsible for seeding the topic.
-        console.log("=== Running Basic Consumer Performance Test:")
-        console.log(`  Brokers: ${brokers}`);
+        console.log("=== Running Basic Consumer Performance Test (eachMessage):")
+        logParameters(parameters);
         console.log(`  Topic: ${topic}`);
         console.log(`  Message Count: ${messageCount}`);
-        const consumerRate = await runConsumer(brokers, topic, messageCount);
-        console.log("=== Consumer Rate: ", consumerRate);
+        console.log(`  Partitions consumed concurrently: ${partitionsConsumedConcurrently}`);
+        startTrackingMemory();
+        const consumerRate = await runConsumer(parameters, topic,
+            warmupMessages, messageCount,
+            false, partitionsConsumedConcurrently, stats,
+            produceToSecondTopic ? topic2 : null, compression, useCKJSProducerEverywhere);
+        endTrackingMemory('consumer-each-message', `consumer-memory-message-${mode}.json`);
+        console.log("=== Consumer Rate MB/s (eachMessage): ", consumerRate);
+        console.log("=== Consumer Rate msg/s (eachMessage): ", stats.messageRate);
+        printPercentiles(stats.percentilesTOT1, 'T0-T1 (eachMessage)');
+        console.log("=== Consumer max E2E latency T0-T1 (eachMessage): ", stats.maxLatencyT0T1);
+        if (produceToSecondTopic) {
+            console.log("=== Consumer average E2E latency T0-T2 (eachMessage): ", stats.avgLatencyT0T2);
+            printPercentiles(stats.percentilesTOT2, 'T0-T2 (eachMessage)');
+            console.log("=== Consumer max E2E latency T0-T2 (eachMessage): ", stats.maxLatencyT0T2);
+        }
+        console.log("=== Consumption time (eachMessage): ", stats.durationSeconds);
+    }
+
+    if (consumer || consumerEachBatch || all) {
+        // If user runs this without --producer then they are responsible for seeding the topic.
+        console.log("=== Running Basic Consumer Performance Test (eachBatch):")
+        logParameters(parameters);
+        console.log(`  Topic: ${topic}`);
+        console.log(`  Message Count: ${messageCount}`);
+        console.log(`  Partitions consumed concurrently: ${partitionsConsumedConcurrently}`);
+        startTrackingMemory();
+        const consumerRate = await runConsumer(parameters, topic,
+            warmupMessages, messageCount,
+            true, partitionsConsumedConcurrently, stats,
+            produceToSecondTopic ? topic2 : null, compression, useCKJSProducerEverywhere);
+        endTrackingMemory('consumer-each-batch', `consumer-memory-batch-${mode}.json`);
+        console.log("=== Consumer Rate MB/s (eachBatch): ", consumerRate);
+        console.log("=== Consumer Rate msg/s (eachBatch): ", stats.messageRate);
+        console.log("=== Average eachBatch lag: ", stats.averageOffsetLag);
+        console.log("=== Max eachBatch lag: ", stats.maxOffsetLag);
+        console.log("=== Average eachBatch size: ", stats.averageBatchSize);
+        console.log("=== Consumer average E2E latency T0-T1 (eachBatch): ", stats.avgLatencyT0T1);
+        printPercentiles(stats.percentilesTOT1, 'T0-T1 (eachBatch)');
+        console.log("=== Consumer max E2E latency T0-T1 (eachBatch): ", stats.maxLatencyT0T1);
+        if (produceToSecondTopic) {
+            console.log("=== Consumer average E2E latency T0-T2 (eachBatch): ", stats.avgLatencyT0T2);
+            printPercentiles(stats.percentilesTOT2, 'T0-T2 (eachBatch)');
+            console.log("=== Consumer max E2E latency T0-T2 (eachBatch): ", stats.maxLatencyT0T2);
+        }
+        console.log("=== Consumption time (eachBatch): ", stats.durationSeconds);
     }
 
     if (ctp || all) {
         console.log("=== Running Consume-Transform-Produce Performance Test:")
-        console.log(`  Brokers: ${brokers}`);
+        logParameters(parameters);
         console.log(`  ConsumeTopic: ${topic}`);
         console.log(`  ProduceTopic: ${topic2}`);
         console.log(`  Message Count: ${messageCount}`);
         // Seed the topic with messages
-        await runProducer(brokers, topic, batchSize, warmupMessages, messageCount, messageSize, compression);
-        const ctpRate = await runConsumeTransformProduce(brokers, topic, topic2, warmupMessages, messageCount, messageProcessTimeMs, ctpConcurrency);
+        await runProducerCKJS(parameters, topic, batchSize,
+            warmupMessages, messageCount, messageSize, compression,
+            randomness, limitRPS);
+        startTrackingMemory();
+        const ctpRate = await runConsumeTransformProduce(parameters, topic, topic2, warmupMessages, messageCount, messageProcessTimeMs, ctpConcurrency);
+        endTrackingMemory('consume-transform-produce', `consume-transform-produce-${mode}.json`);
         console.log("=== Consume-Transform-Produce Rate: ", ctpRate);
     }
 
     if (produceConsumeLatency || all) {
         console.log("=== Running Produce-To-Consume Latency Performance Test:")
-        console.log(`  Brokers: ${brokers}`);
+        logParameters(parameters);
         console.log(`  Topic: ${topic}`);
         console.log(`  Message Count: ${messageCount}`);
         console.log(`  Consumer Processing Time: ${consumerProcessingTime}`);
         console.log(`  Producer Processing Time: ${producerProcessingTime}`);
-        const { mean, p50, p90, p95, outliers } = await runProducerConsumerTogether(brokers, topic, messageCount, messageSize, producerProcessingTime, consumerProcessingTime);
+        startTrackingMemory();
+        const { mean, p50, p90, p95, outliers } = await runProducerConsumerTogether(parameters, topic, messageCount, messageSize, producerProcessingTime, consumerProcessingTime);
+        endTrackingMemory('producer-consumer-together', `producer-consumer-together-${mode}.json`);
         console.log(`=== Produce-To-Consume Latency (ms): Mean: ${mean}, P50: ${p50}, P90: ${p90}, P95: ${p95}`);
 
         // The presence of outliers invalidates the mean measurement, and rasies concerns as to why there are any.
@@ -87,4 +249,9 @@ const producerProcessingTime = process.env.PRODUCER_PROCESSING_TIME ? +process.e
             console.log("=== Outliers (ms): ", outliers);
         }
     }
+
+    if (maxAverageRSSKB !== undefined && maxMaxRSSKB !== undefined) {
+        console.log(`=== Max Average RSS across tests: `, maxAverageRSSKB);
+        console.log(`=== Max RSS across tests: `, maxMaxRSSKB);
+    }
 })();