Initial latency observed up to 5 minutes with JCSMP clients

rdesoju
rdesoju Member Posts: 66
edited January 2020 in PubSub+ Event Broker #1

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

Tagged:

Comments

  • amackenzie
    amackenzie Member, Employee Posts: 262 Solace Employee

    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
    Aaron Member, Administrator, Moderator, Employee Posts: 595 admin

    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
    rdesoju Member Posts: 66
    edited January 2020 #4

    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
    amackenzie Member, Employee Posts: 262 Solace Employee

    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
    Aaron Member, Administrator, Moderator, Employee Posts: 595 admin

    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
    rdesoju Member Posts: 66

    @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
    Aaron Member, Administrator, Moderator, Employee Posts: 595 admin

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