apache / apache/pulsar

Pulsar Sink connectors not getting messages when input rate to pulsar is high

Open
#12,747 4 comments 0 reactions 0 assignees View on GitHub
lifecycle/stale type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

**Describe the bug**
The Pulsar Sink connector doesn't receive all the messages if the input rate to the pulsar topic is high. I tried using the inbuilt Cassandra connector and followed the instructions to try it out [here](https://pulsar.apache.org/docs/en/io-quickstart/#connect-pulsar-to-cassandra). I push 100000 messages to pulsar via a java code but I don't see all the messages there in the Sink. Topic receives all the messages but the Sink doesn't. If I send these many messages in small chunks, it reaches the sink.

**To Reproduce**
Steps to reproduce the behavior:
1. Setup Pulsar(2.8.1) standalone and Cassandra sink as described in the official docs.
2. Use the Java code given below to insert messages into the Pulsar topic.

```java
import org.apache.pulsar.client.api.BatcherBuilder;
import org.apache.pulsar.client.api.MessageId;
import org.apache.pulsar.client.api.Producer;
import org.apache.pulsar.client.api.PulsarClient;
import org.apache.pulsar.client.api.PulsarClientException;
import org.apache.pulsar.client.api.Schema;
import org.apache.pulsar.client.impl.PulsarClientImpl;
import org.apache.pulsar.client.impl.conf.ClientConfigurationData;

import java.util.concurrent.ExecutionException;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;

public class PushToCassandra {
public static void main(String[] args) throws PulsarClientException, ExecutionException, InterruptedException {
/**
* for i in {0..9}; do bin/pulsar-client produce -m "key-$i" -n 1 test_cassandra; done
*/
ClientConfigurationData clientConfigurationData = new ClientConfigurationData();
clientConfigurationData.setServiceUrl("pulsar://localhost:6650");
PulsarClient pulsarClient = new PulsarClientImpl(clientConfigurationData);
Producer producer = pulsarClient.newProducer(Schema.STRING)
.topic("test_cassandra")
.blockIfQueueFull(true)
.enableBatching(true)
.batchingMaxMessages(50_000)
.maxPendingMessages(50_000)
.batchingMaxBytes(5242880)
.batchingMaxPublishDelay(10, TimeUnit.SECONDS)
.batcherBuilder(BatcherBuilder.DEFAULT)
.create();
try (producer) {
Future future = null;
for (int i = 0; i < 100000; i++) {
future = producer.newMessage().value("key-" + i).sendAsync();
}
producer.flush();
future.get();
}
producer.close();
pulsarClient.close();
}
}

```

**Expected behavior**
A sink should receive all 100000 messages.

**Metrics**
* Topic stats (bin/pulsar-admin topics stats public/default/test_cassandra)
```json
{
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"bytesInCounter" : 1872490,
"msgInCounter" : 100000,
"bytesOutCounter" : 20293526,
"msgOutCounter" : 1100000,
"averageMsgSize" : 0.0,
"msgChunkPublished" : false,
"storageSize" : 1872490,
"backlogSize" : 1872490,
"offloadedStorageSize" : 0,
"lastOffloadLedgerId" : 0,
"lastOffloadSuccessTimeStamp" : 0,
"lastOffloadFailureTimeStamp" : 0,
"publishers" : [ ],
"waitingPublishers" : 0,
"subscriptions" : {
"public/default/cassandra-test-sink" : {
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"bytesOutCounter" : 20293526,
"msgOutCounter" : 1100000,
"msgRateRedeliver" : 0.0,
"chunkedMessageRate" : 0,
"msgBacklog" : 2,
"backlogSize" : 0,
"msgBacklogNoDelayed" : 2,
"blockedSubscriptionOnUnackedMsgs" : false,
"msgDelayed" : 0,
"unackedMessages" : 50000,
"type" : "Shared",
"msgRateExpired" : 0.0,
"totalMsgExpired" : 0,
"lastExpireTimestamp" : 0,
"lastConsumedFlowTimestamp" : 1636623672908,
"lastConsumedTimestamp" : 1636623672913,
"lastAckedTimestamp" : 0,
"lastMarkDeleteAdvancedTimestamp" : 0,
"consumers" : [ {
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"bytesOutCounter" : 20293526,
"msgOutCounter" : 1100000,
"msgRateRedeliver" : 0.0,
"chunkedMessageRate" : 0.0,
"consumerName" : "c958f",
"availablePermits" : -49000,
"unackedMessages" : 50000,
"avgMessagesPerEntry" : 45175,
"blockedConsumerOnUnackedMsgs" : true,
"lastAckedTimestamp" : 0,
"lastConsumedTimestamp" : 1636623672913,
"metadata" : {
"instance_id" : "0",
"application" : "pulsar-sink",
"instance_hostname" : "aerospike-ThinkPad-P53",
"id" : "public/default/cassandra-test-sink"
},
"connectedSince" : "2021-11-11T14:41:38.541+05:30",
"address" : "/127.0.0.1:35044",
"clientVersion" : "2.8.1"
} ],
"isDurable" : true,
"isReplicated" : false,
"consumersAfterMarkDeletePosition" : { },
"nonContiguousDeletedMessagesRanges" : 0,
"nonContiguousDeletedMessagesRangesSerializedSize" : 0,
"durable" : true,
"replicated" : false
}
},
"replication" : { },
"deduplicationStatus" : "Disabled",
"nonContiguousDeletedMessagesRanges" : 0,
"nonContiguousDeletedMessagesRangesSerializedSize" : 0,
"compaction" : {
"lastCompactionRemovedEventCount" : 0,
"lastCompactionSucceedTimestamp" : 0,
"lastCompactionFailedTimestamp" : 0,
"lastCompactionDurationTimeInMills" : 0
}
}
```
* Sink stats (bin/pulsar-admin sinks status --tenant public --namespace default --name cassandra-test-sink)
```json
{
"numInstances" : 1,
"numRunning" : 1,
"instances" : [ {
"instanceId" : 0,
"status" : {
"running" : true,
"error" : "",
"numRestarts" : 0,
"numReadFromPulsar" : 50000,
"numSystemExceptions" : 0,
"latestSystemExceptions" : [ ],
"numSinkExceptions" : 0,
"latestSinkExceptions" : [ ],
"numWrittenToSink" : 50000,
"lastReceivedTime" : 1636621993191,
"workerId" : "c-standalone-fw-localhost-8080"
}
} ]
}
```
**EDIT**
* Sink stats after 10 minutes (no change in the intermittent stat check queries)
```json
{
"numInstances" : 1,
"numRunning" : 1,
"instances" : [ {
"instanceId" : 0,
"status" : {
"running" : true,
"error" : "",
"numRestarts" : 0,
"numReadFromPulsar" : 950000,
"numSystemExceptions" : 0,
"latestSystemExceptions" : [ ],
"numSinkExceptions" : 0,
"latestSinkExceptions" : [ ],
"numWrittenToSink" : 950000,
"lastReceivedTime" : 1636623433172,
"workerId" : "c-standalone-fw-localhost-8080"
}
} ]
}
```

`availablePermits` is also a negative number in the topic stats. Isn't that wrong too? If I run the sink stats check again, the `numReadFromPulsar` and `numWrittenToSink` keep on increasing. Now I see 1400000 for them. Pulsar seems to be retrying 50k `unackedMessages`. Not sure why they are `unackedMessages`!

Contributor guide

Open the contributing guide

Research direction

Start with the Java producer reproduction and the Cassandra sink setup from the Pulsar IO quickstart. Run the topic stats and sink status commands while publishing 100000 messages, then inspect the unackedMessages, availablePermits, numReadFromPulsar, and numWrittenToSink values; done means the sink receives all messages without unexplained retries or accumulating unacked messages.

Written by the indexing model from the issue text.

Assessment

Tech stack
cassandra, java
Domain
databases, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.