Статьи

Эффект координированного пропуска — Измерьте задержку обратной связи, используя простой клиент / сервер NIO

Февраль 1, 2019

В этом посте я демонстрирую ряд идей и приемов:

  1. Как написать простой неблокирующий клиент / сервер NIO
  2. Эффекты скоординированного упущения
  3. Как измерить задержки в процентилях (в отличие от простого среднего)
  4. Как рассчитать время ожидания петли на вашем компьютере

Недавно я разрабатывал эталон с малой задержкой для клиент-серверного приложения. Первоначально я имитировал эталонный тест на одной машине, используя TCP over loopback. Первая мера, которую я хотел измерить, состояла в том, сколько из зарегистрированной задержки мне нужно было учесть для простой обратной петли. Тогда я смог бы более четко понять задержку, добавленную моим фактическим приложением.

Для этого я создал программу (код в конце поста), которая передает один байт от клиента на сервер и обратно. Это делается неоднократно и результаты обрабатываются.

Программа написана с использованием неблокирующего java NIO, чтобы максимально оптимизировать задержки в петле.

Что важнее, чем запись среднего времени, процентильные задержки записываются. (См. Предыдущий пост здесь для обсуждения того, как измерить задержку). Критически, кодовые факторы для скоординированного упущения. (Чтобы узнать больше об этом см. Здесь от Gil Tene). Короче говоря, вы не определяете время с того момента, когда оно началось, а с того, что оно должно было начаться.

Это результаты моего 2-летнего MBP.

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
Starting latency test rate: 80000
Average time 2513852
Loop back echo latency was 2514247.3/3887258.6 4,196,487/4,226,913 4,229,987/4230294 4,230,294 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 70000
Average time 2327041
Loop back echo latency was 2339701.6/3666542.5 3,957,860/3,986,626 3,989,404/3989763 3,989,763 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 50000
Average time 1883303
Loop back echo latency was 1881621.0/2960104.0 3,203,771/3,229,260 3,231,809/3232046 3,232,046 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 30000
Average time 1021576
Loop back echo latency was 1029566.5/1599881.0 1,726,326/1,739,626 1,741,098/1741233 1,741,233 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 20000
Average time 304
Loop back echo latency was 65.6/831.2 3,632/4,559 4,690/4698 4,698 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 10000
Average time 50
Loop back echo latency was 47.8/57.9 89/120 152/182 182 us for 50/90 99/99.9 99.99/99.999 worst %tile

Сравните эти результаты с тем, когда я не исправил согласованное упущение:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
Starting latency test rate: 80000
Average time 45
Loop back echo latency was 44.1/48.8 71/105 124/374 374 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 70000
Average time 45
Loop back echo latency was 44.1/48.9 76/106 145/358 358 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 50000
Average time 45
Loop back echo latency was 43.9/48.8 74/105 123/162 162 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 30000
Average time 45
Loop back echo latency was 44.0/48.8 73/104 129/147 147 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 20000
Average time 45
Loop back echo latency was 44.7/49.6 78/107 135/311 311 us for 50/90 99/99.9 99.99/99.999 worst %tile
Starting latency test rate: 10000
Average time 46
Loop back echo latency was 45.1/50.8 81/112 144/184 184 us for 50/90 99/99.9 99.99/99.999 worst %tile

Как видите, эффекты пропускной способности полностью игнорируются! Может показаться, что даже при скорости 80 000 сообщений в секунду ваш 99,99 процентиль составляет 374 мкс, хотя на самом деле он намного больше этого.

На самом деле вы можете достичь заданных задержек только тогда, когда ваша пропускная способность приближается к 10000 в секунду. Как вы понимаете интуитивно, существует компромисс между пропускной способностью и задержкой.

Код для этого теста ниже:

001
002
003
004
005
006
007
008
009
010
011
012
013
014
015
016
017
018
019
020
021
022
023
024
025
026
027
028
029
030
031
032
033
034
035
036
037
038
039
040
041
042
043
044
045
046
047
048
049
050
051
052
053
054
055
056
057
058
059
060
061
062
063
064
065
066
067
068
069
070
071
072
073
074
075
076
077
078
079
080
081
082
083
084
085
086
087
088
089
090
091
092
093
094
095
096
097
098
099
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
package util;
  
  
import java.io.EOFException;
import java.io.IOException;
import java.net.InetSocketAddress;
import java.net.Socket;
import java.nio.ByteBuffer;
import java.nio.channels.ServerSocketChannel;
import java.nio.channels.SocketChannel;
import java.util.Arrays;
  
/**
 * Created by daniel on 02/07/2015.
 * Simple program to test loopback speeds and latencies.
 */
public class LoopBackPingPong {
    public final static int PORT = 8007;
  
    public void runServer(int port) throws IOException {
        ServerSocketChannel ssc = ServerSocketChannel.open();
        ssc.bind(new InetSocketAddress(port));
        System.out.println("listening on " + ssc);
  
        final SocketChannel socket = ssc.accept();
        socket.socket().setTcpNoDelay(true);
        socket.configureBlocking(false);
        new Thread(() -> {
            long totalTime = 0;
            int count = 0;
            try {
                System.out.println("Connected " + socket);
  
                ByteBuffer bb = ByteBuffer.allocateDirect(1);
                int length;
                while ((length = socket.read(bb)) >= 0) {
                    if (length > 0) {
                        long time = System.nanoTime();
                        bb.flip();
                        bb.position(0);
                        count++;
  
                        if (socket.write(bb) < 0)
                            throw new EOFException();
  
                        bb.clear();
                        totalTime += System.nanoTime() - time;
                    }
                }
            } catch (IOException ignored) {
            } finally {
                System.out.println("Total server time " + (totalTime / count) / 1000);
                System.out.println("... disconnected " + socket);
                try {
                    socket.close();
                } catch (IOException ignored) {
                }
            }
        }).start();
  
    }
  
    public void testLatency(int targetThroughput, SocketChannel socket) throws IOException {
        System.out.println("Starting latency test rate: " + targetThroughput);
        int tests = Math.min(18 * targetThroughput, 100_000);
        long[] times = new long[tests];
        int count = 0;
        long now = System.nanoTime();
        long rate = (long) (1e9 / targetThroughput);
  
        ByteBuffer bb = ByteBuffer.allocateDirect(4);
        bb.putInt(0, 0x12345678);
  
        for (int i = -20000; i < tests; i++) {
            //now += rate;
            //while (System.nanoTime() < now)
            //    ;
            now = System.nanoTime();
  
            bb.position(0);
            while (bb.remaining() > 0)
                if (socket.write(bb) < 0)
                    throw new EOFException();
  
            bb.position(0);
            while (bb.remaining() > 0)
                if (socket.read(bb) < 0)
                    throw new EOFException();
  
            if (bb.getInt(0) != 0x12345678)
                throw new AssertionError("read error");
  
            if (i >= 0)
                times[count++] = System.nanoTime() - now;
        }
        System.out.println("Average time " + (Arrays.stream(times).sum() / times.length) / 1000);
        Arrays.sort(times);
        System.out.printf("Loop back echo latency was %.1f/%.1f %,d/%,d %,d/%d %,d us for 50/90 99/99.9 99.99/99.999 worst %%tile%n",
                times[times.length / 2] / 1e3,
                times[times.length * 9 / 10] / 1e3,
                times[times.length - times.length / 100] / 1000,
                times[times.length - times.length / 1000] / 1000,
                times[times.length - times.length / 10000] / 1000,
                times[times.length - times.length / 100000] / 1000,
                times[times.length - 1] / 1000
        );
    }
  
  
    public static void main(String... args) throws Exception {
        int port = args.length < 1 ? PORT : Integer.parseInt(args[0]);
        LoopBackPingPong lbpp = new LoopBackPingPong();
  
        new Thread(() -> {
            try {
                lbpp.runServer(port);
            } catch (IOException e) {
                Jvm.rethrow(e);
            }
        }).start();
        //give the server a chance to start
        Thread.sleep(1000);
  
        SocketChannel socket = SocketChannel.open(new InetSocketAddress("localhost", port));
        socket.socket().setTcpNoDelay(true);
        socket.configureBlocking(false);
  
        for (int i : new int[]{80_000, 70_000, 50_000, 30_000, 20_000, 10_000})
            lbpp.testLatency(i, socket);
        System.exit(0);
    }
  
}
Ссылка: Эффект координированного пропуска — Измерьте задержку обратной связи, используя простой клиент / сервер NIO от нашего партнера JCG Дэниела Шая в блоге Rational Java .
35
Share: