Bad ZMQ latency on first 500 messages per connection #1608

ckohrt · 2015-10-13T09:27:47Z

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 · 2015-10-28T12:41:01Z

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

hintjens · 2015-10-28T12:45:18Z

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 · 2015-10-30T08:34:59Z

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.

See issue zeromq#1608. This is an old issue with Windows 7. The effect is that we see a latency ramp on the first 500 messages. * The ramp is unaffected by message size. * Sleeping up to 100msec between sends has no effect except to switch off ZeroMQ batching so making the ramp more visible. * After 500 messages, latency falls back down to ~10-40 usec. * Over inproc:// the ramp happens when we use the signaler class. * Client-server over inproc:// does not show the ramp. * Client-server over tcp:// shows a similar ramp. We know that the signaller is using TCP on Windows. We can 'prime' the connection by doing 500 dummy sends. This potentially causes new sockets to be delayed on creation, which is not a good solution. Note that the signaller sends zero-byte messages. This may also be confusing TCP. Solution: flood the receive buffer when creating a new FD pair; send a 1M buffer and discard it. ** THIS IS SPECULATIVE **

See issue zeromq#1608. This is an old issue with Windows 7. The effect is that we see a latency ramp on the first 500 messages. * The ramp is unaffected by message size. * Sleeping up to 100msec between sends has no effect except to switch off ZeroMQ batching so making the ramp more visible. * After 500 messages, latency falls back down to ~10-40 usec. * Over inproc:// the ramp happens when we use the signaler class. * Client-server over inproc:// does not show the ramp. * Client-server over tcp:// shows a similar ramp. We know that the signaller is using TCP on Windows. We can 'prime' the connection by doing 500 dummy sends. This potentially causes new sockets to be delayed on creation, which is not a good solution. Note that the signaller sends zero-byte messages. This may also be confusing TCP. Solution: flood the receive buffer when creating a new FD pair; send a 1M buffer and discard it. Fixes zeromq#1608

…ignaler.cpp:524 ("Bad address") Solution: remove the workaround for zeromq#1608

hintjens mentioned this issue Nov 1, 2015

Problem: Windows 7 TCP slow start #1629

Merged

c-rack closed this as completed in #1629 Nov 1, 2015

ghost mentioned this issue Aug 28, 2016

4.1.2: Assertion failed: Connection reset by peer (zeromq\src\signaler.cpp:298) #1808

Closed

reunanen added a commit to outotec/libzmq that referenced this issue Jan 9, 2017

Problem: workaround for zeromq#1608 causes wsa_assert to trigger at s…

e6cc462

…ignaler.cpp:524 ("Bad address") Solution: remove the workaround for zeromq#1608

reunanen added a commit to reunanen/Numcore_messaging_library that referenced this issue Jan 9, 2017

Update libzmq (remove workaround for zeromq/libzmq#1608)

dfb89f0

reunanen added a commit to reunanen/libzmq that referenced this issue Jan 15, 2017

Problem: workaround for zeromq#1608 causes wsa_assert to trigger at s…

2ced431

…ignaler.cpp:524 ("Bad address") Solution: remove the workaround for zeromq#1608

reunanen added a commit to reunanen/libzmq that referenced this issue Jan 21, 2017

Problem: workaround for zeromq#1608 causes wsa_assert to trigger at s…

99119dd

…ignaler.cpp:524 ("Bad address") Solution: remove the workaround for zeromq#1608

glaure mentioned this issue Dec 7, 2017

use poll in router dealer pattern, the speed is very slow, why? #2835

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bad ZMQ latency on first 500 messages per connection #1608

Bad ZMQ latency on first 500 messages per connection #1608

ckohrt commented Oct 13, 2015

hintjens commented Oct 28, 2015

hintjens commented Oct 28, 2015

hintjens commented Oct 30, 2015

Bad ZMQ latency on first 500 messages per connection #1608

Bad ZMQ latency on first 500 messages per connection #1608

Comments

ckohrt commented Oct 13, 2015

hintjens commented Oct 28, 2015

hintjens commented Oct 28, 2015

hintjens commented Oct 30, 2015