Bad ZMQ latency on first 500 messages per connection

[ckohrt]

Windows 7 machine, core i7-3770 CPU @ 4.40GHz, 16 GB RAM, 64 Bit
ZMQ 4.0.4

Maybe relevant issues: #1256, #1565, #792

When sending many messages with a delay after each message a latency ramp appears
The rewritten WeatherUpdate demo of the Guide shows the behavior. It sends 1000 messages via PUB/SUB and the Sleeptime adds a sleep after each send. This results in the following times:

Average sending time in iteration 0, messages 0- 10 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 1, messages 10- 20 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 2, messages 20- 30 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 3, messages 30- 40 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 4, messages 40- 50 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 5, messages 50- 60 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 6, messages 60- 70 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 7, messages 70- 80 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 8, messages 80- 90 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 9, messages 90- 100 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 10, messages 100- 110 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 11, messages 110- 120 [ms per message]: 0.40 [ms for all messages]: 4
Average sending time in iteration 12, messages 120- 130 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 13, messages 130- 140 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 14, messages 140- 150 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 15, messages 150- 160 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 16, messages 160- 170 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 17, messages 170- 180 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 18, messages 180- 190 [ms per message]: 0.60 [ms for all messages]: 6
Average sending time in iteration 19, messages 190- 200 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 20, messages 200- 210 [ms per message]: 0.60 [ms for all messages]: 6
Average sending time in iteration 21, messages 210- 220 [ms per message]: 0.50 [ms for all messages]: 5
Average sending time in iteration 22, messages 220- 230 [ms per message]: 0.60 [ms for all messages]: 6
Average sending time in iteration 23, messages 230- 240 [ms per message]: 0.60 [ms for all messages]: 6
Average sending time in iteration 24, messages 240- 250 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 25, messages 250- 260 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 26, messages 260- 270 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 27, messages 270- 280 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 28, messages 280- 290 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 29, messages 290- 300 [ms per message]: 1.10 [ms for all messages]: 11
Average sending time in iteration 30, messages 300- 310 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 31, messages 310- 320 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 32, messages 320- 330 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 33, messages 330- 340 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 34, messages 340- 350 [ms per message]: 1.00 [ms for all messages]: 10
Average sending time in iteration 35, messages 350- 360 [ms per message]: 0.90 [ms for all messages]: 9
Average sending time in iteration 36, messages 360- 370 [ms per message]: 1.20 [ms for all messages]: 12
Average sending time in iteration 37, messages 370- 380 [ms per message]: 1.40 [ms for all messages]: 14
Average sending time in iteration 38, messages 380- 390 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 39, messages 390- 400 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 40, messages 400- 410 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 41, messages 410- 420 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 42, messages 420- 430 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 43, messages 430- 440 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 44, messages 440- 450 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 45, messages 450- 460 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 46, messages 460- 470 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 47, messages 470- 480 [ms per message]: 1.50 [ms for all messages]: 15
Average sending time in iteration 48, messages 480- 490 [ms per message]: 1.60 [ms for all messages]: 16
Average sending time in iteration 49, messages 490- 500 [ms per message]: 2.00 [ms for all messages]: 20
Average sending time in iteration 50, messages 500- 510 [ms per message]: 2.00 [ms for all messages]: 20
Average sending time in iteration 51, messages 510- 520 [ms per message]: 0.30 [ms for all messages]: 3
Average sending time in iteration 52, messages 520- 530 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 53, messages 530- 540 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 54, messages 540- 550 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 55, messages 550- 560 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 56, messages 560- 570 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 57, messages 570- 580 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 58, messages 580- 590 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 59, messages 590- 600 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 60, messages 600- 610 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 61, messages 610- 620 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 62, messages 620- 630 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 63, messages 630- 640 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 64, messages 640- 650 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 65, messages 650- 660 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 66, messages 660- 670 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 67, messages 670- 680 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 68, messages 680- 690 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 69, messages 690- 700 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 70, messages 700- 710 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 71, messages 710- 720 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 72, messages 720- 730 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 73, messages 730- 740 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 74, messages 740- 750 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 75, messages 750- 760 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 76, messages 760- 770 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 77, messages 770- 780 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 78, messages 780- 790 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 79, messages 790- 800 [ms per message]: 0.10 [ms for all messages]: 1
Average sending time in iteration 80, messages 800- 810 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 81, messages 810- 820 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 82, messages 820- 830 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 83, messages 830- 840 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 84, messages 840- 850 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 85, messages 850- 860 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 86, messages 860- 870 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 87, messages 870- 880 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 88, messages 880- 890 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 89, messages 890- 900 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 90, messages 900- 910 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 91, messages 910- 920 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 92, messages 920- 930 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 93, messages 930- 940 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 94, messages 940- 950 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 95, messages 950- 960 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 96, messages 960- 970 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 97, messages 970- 980 [ms per message]: 0.00 [ms for all messages]: 0
Average sending time in iteration 98, messages 980- 990 [ms per message]: 0.00 [ms for all messages]: 0

There is a latency ramp from message 90 on up to message 510. After 510, the latency is smaller. I had to measure 10 messages together because of the timer accuracy of 1 ms to get measurable results.

To test this on linux, you just need to modify the lines
_beginthread( StartSubscriber, 0, context );
and
#include <process.h>

Ihope this helps to reproduce the issue.

// WeatherUpdate.cpp : Defines the entry point for the console application.
//

#include "stdafx.h"
#include "zhelpers.h"
#include <process.h>


void StartSubscriber(void* context)
{
    void* subscriber = zmq_socket (context, ZMQ_SUB);

    int rc = zmq_connect (subscriber, "inproc://weather");
    assert (rc == 0);

    //  Subscribe to zipcode, default is NYC, 10001
    char *filter = "10001";
    rc = zmq_setsockopt (subscriber, ZMQ_SUBSCRIBE, filter, strlen (filter));
    assert (rc == 0);

    //  Process 1000 updates
    int update_nbr;
    long total_temp = 0;
    for (update_nbr = 0; update_nbr < 1000; update_nbr++) {
        char *string = s_recv (subscriber);

        int zipcode, temperature, relhumidity;
        sscanf (string, "%d %d %d",&zipcode, &temperature, &relhumidity);
        total_temp += temperature;
        free (string);
    }
    printf ("Average temperature for zipcode '%s' was %dF\n", filter, (int) (total_temp / update_nbr));

    zmq_close (subscriber);
}

int _tmain(int argc, _TCHAR* argv[])
{
    //  Prepare our context and publisher
    void *context = zmq_ctx_new ();
    void *publisher = zmq_socket (context, ZMQ_PUB);



    int rc = zmq_bind (publisher, "inproc://weather");
    assert (rc == 0);

    _beginthread( StartSubscriber, 0, context );

    s_sleep(1000);

    int64_t start=0;
    int64_t stop=0;

    int Sleeptime = 10;

    for(int it=0; it<100; it++)
    {
        char update [20];
        sprintf (update, "%05d %d %d", 10001, 2, 3);

        start = s_clock();

        for(int i=0; i<10; i++)
        {
            s_send (publisher, update);

            s_sleep(Sleeptime);
        }
        stop = s_clock();
        double r = int(stop-start-10*Sleeptime)/10.0;
        //double r2 = int(stop-start-10*Sleeptime)/10.0;


        printf ("Average sending time in iteration %4d, messages %4d-%4d [ms per message]: %4.2f [ms for all messages]: %3d \n", it, it*10, it*10+10, r, (stop-start-10*Sleeptime) );
    }

    s_sleep(1000000);

    zmq_close (publisher);
    zmq_ctx_destroy (context);

    return 0;
}

[hintjens]

Test case using CZMQ actors here: https://gist.github.com/hintjens/501abc0f8eddc0428ce4#file-send_sleep-c

[hintjens]

That test case sends messages from one thread to another over inproc://. It waits between sends, with a delay of 1, 8, 32, 64 msecs. The results show that the first 500 messages have increasing latency that rises to about 2 msec, before it falls down to around 100 usec again. (Latency is in usec).

[hintjens]

More updates:

We tested using client-server over tcp:// and inproc://. Over TCP we see the phenomenon. Over inproc we do not.

In all the old socket types, ZeroMQ on Windows uses a TCP socket pair for signalling between API thread and IO thread. The client/server socket type does not do this (it has a simpler threadsafe design).

So if you do dealer-router over inproc:// then you still use TCP internally. If you do client-server over inproc:// then you do not. If you do client-server over tcp:// then you do see TCP in action.

What we see from the client-server test is significant:

• the phenomenon is NOT caused by the signaler (as we see it, yet we're not using the signaler)
• the phenomenon IS caused by TCP (we do not see it in ZeroMQ over pure inproc://)

Hence it is an external effect.

So the TCP auto-tuning is a good candidate for the cause of this.