Initial latency observed up to 5 minutes with JCSMP clients

rdesoju

Hi,
I have a performance test setup in which ingesting 100 messages per second from 10 threads at 100 ms interval.
As per my observation, the initial Producer to Consumer latency (Producer -> Broker -> Consumer) is observed as 5 minutes. And, it keeps decreasing and reaches to nano seconds latency within 5 minutes. However, it is taking around 5 minutes to reach the optimal nano seconds optimal point.

Is this a valid observation? Any thoughts on debugging what's causing the initial delay?

Please note that Producer, Consumer and Broker in HA Group are running with default settings.

Thanks,
Raghu

amackenzie

This is definitely not expected. If you are a Solace customer, I would certainly log a Support ticket and our smart techs can help out.
If not, are you able to share your code?

Aaron

Are your publishers and consumers on the same host? How are you measuring the time deltas? It should be impossible to have a 5 minute delay. It should also be impossible to have nanosecond latency... microseconds at least. Can you explain what your "performance test setup" is?

Thanks!

rdesoju

Hi @amackenzie,
I am using the code samples mentioned here: https://solace.com/samples/solace-samples-java/persistence-with-queues/
Only difference in my Producer code is I am creating objects such as Session, Producer, Message outside the loop and setting message and sending repeatedly inside the loop:

String queueName = "Q/tutorial";
final Queue queue = JCSMPFactory.onlyInstance().createQueue(queueName);
TextMessage msg = JCSMPFactory.onlyInstance().createMessage(TextMessage.class);
msg.setDeliveryMode(DeliveryMode.PERSISTENT);

XMLMessageProducer prod = session.getMessageProducer(new JCSMPStreamingPublishEventHandler() {

@Override
public void responseReceived(String messageID) {
System.out.println("Producer received response for msg: " + messageID);
}

@Override
public void handleError(String messageID, JCSMPException e, long timestamp) {
    System.out.printf("Producer received error for msg: %s@%s - %s%n",messageID,timestamp,e);
}

});
while(true) {
String text = "Persistent Queue Tutorial! " + DateFormat.getDateTimeInstance().format(new Date());
msg.setText(text);
prod.send(msg, queue);
sleep(100); //ms
}

Consumer is exactly same as mentioned in the above link. Also, queue has been provisioned with appropriate permissions from CLI.
@Aaron - I am running both Producer and Consumer on the same host. Also, the minimum latency that is observed is 1.1 ms NOT in nano seconds as you mentioned.

amackenzie

If you could post your code, that would be great since the samples you mention do not show such latency. As @Aaron mentions, 5 min latency is so far off the norm that it's unlikely to be basic functionality of the broker with clients.

Aaron

Ok... some quick thoughts off the top of my head:

• Is the queue empty before your start your tests?
• Rather than creating new Date objects and using DateTimeInstance inside your tight loop, just use System.currentTimeMillis() in the payload
• Rather than 10 threads, practice with just one thread until your values are as expected. Simpler.
• Instead of publishing forever, run a test with 1000 messages. Or 10,000 at a higher rate.
• When doing proper latency tests, typically you're building a histogram of results, putting latency deltas into a number of buckets, and then calculating the relative percentage of each bucket. What you DON'T want to do is any kind of I/O (write to console, screen, DB, etc.) when you receive the message in your consumer. You didn't post your consumer code, but hopefully your onReceive() callback simply calculates the delta between "now" and the payload of the message, and stores that away for later calculations. Do not PRINT or DUMP the message to the console in the callback.
• sleep() is not very accurate... as your message rates increase, you may prefer to use a "busy wait" where you spin in a tight loop until the current system time has advanced by x milliseconds, or x microseconds.
• Please confirm you've removed the "latch" from the receiver code to ensure the receiver continues to run

Still, even without these improvements, you should never be seeing 5 minute delays. So I'm still wondering if there is some sort of timestamp / clock issue..?

Thanks!

rdesoju

@Aaron ,
Both producer and consumer are running on the same machine which eliminates the clock skew issue while calculating the latency. Also, queue is empty before the launch of the test.
I have System.currentTimeMillis() and System.nanoTime() calls in both producer and consumer and calculating the delta from the consumer using the same timestamps. Also, I removed the latch to ensure consumer runs forever.
I will reproduce the issue and share my observations.
Thanks for your thoughts.

Aaron

Yeah, please post up all your code and I'll take a look. Both publisher and subscriber.