Статьи

Примеры 1 JLBH — почему код должен сравниваться в контексте

Октябрь 24, 2018

В этом посте:

  • Пример параллельного использования JMH и JLBH для сериализации дат
  • Измерение даты сериализации в микробенчмарке
  • Измерение даты сериализации как часть правильного применения
  • Как добавить зонд в свой тест JLBH
  • Понимание важности измерения кода в контексте

В последнем посте « Представление JLBH » мы представили JLBH — инструмент тестирования латентности, который Chronicle использовал для тестирования Chronicle-FIX и теперь доступен как открытый исходный код.

В следующих нескольких постах мы рассмотрим несколько примеров приложений:

Весь код для примеров можно найти здесь, в моем проекте GitHub:

Один из моментов, которые я сделал во введении к JLBH, заключался в том, что важно сопоставлять код в контексте. Это означает, что тестирование кода в среде настолько близко, насколько это возможно, в реальной жизни. Этот пост демонстрирует это на практике.

Давайте посмотрим на относительно дорогую операцию Java — сериализацию даты — и посмотрим, сколько времени это займет:

Сначала вот тест JMH:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
package org.latency.serialisation.date;
 
import net.openhft.affinity.Affinity;
import net.openhft.chronicle.core.Jvm;
import net.openhft.chronicle.core.OS;
import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
import org.openjdk.jmh.runner.options.TimeValue;
 
import java.io.*;
import java.lang.reflect.InvocationTargetException;
import java.util.Date;
import java.util.concurrent.TimeUnit;
 
/**
 * Created to show the effects of running code within more complex code.
 * Date serialisation as a micro benchmark vs date serialisation inside a TCP call.
 */
@State(Scope.Thread)
public class DateSerialiseJMH {
    private final Date date = new Date();
 
    public static void main(String[] args) throws InvocationTargetException,
            IllegalAccessException, RunnerException, IOException, ClassNotFoundException {
 
        if (OS.isLinux())
            Affinity.setAffinity(2);
 
        if(Jvm.isDebug()){
            DateSerialiseJMH jmhParse = new DateSerialiseJMH();
            jmhParse.test();
        }
        else {
            Options opt = new OptionsBuilder()
                    .include(DateSerialiseJMH.class.getSimpleName())
                    .warmupIterations(6)
                    .forks(1)
                    .measurementIterations(5)
                    .mode(Mode.SampleTime)
                    .measurementTime(TimeValue.seconds(3))
                    .timeUnit(TimeUnit.MICROSECONDS)
                    .build();
 
            new Runner(opt).run();
        }
    }
 
    @Benchmark
    public Date test() throws IOException, ClassNotFoundException {
        ByteArrayOutputStream out = new ByteArrayOutputStream();
        ObjectOutputStream oos = new ObjectOutputStream(out);
        oos.writeObject(date);
 
        ObjectInputStream ois = new ObjectInputStream(new ByteArrayInputStream(out.toByteArray()));
        return (Date)ois.readObject();
    }
}

Работая на моем ноутбуке (MBP i7), я получаю следующие результаты:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
Result "test":
  4.578 ±(99.9%) 0.046 us/op [Average]
  (min, avg, max) = (3.664, 4.578, 975.872), stdev = 6.320
  CI (99.9%): [4.533, 4.624] (assumes normal distribution)
  Samples, N = 206803
        mean =      4.578 ±(99.9%) 0.046 us/op
         min =      3.664 us/op
  p( 0.0000) =      3.664 us/op
  p(50.0000) =      4.096 us/op
  p(90.0000) =      5.608 us/op
  p(95.0000) =      5.776 us/op
  p(99.0000) =      8.432 us/op
  p(99.9000) =     24.742 us/op
  p(99.9900) =    113.362 us/op
  p(99.9990) =    847.245 us/op
  p(99.9999) =    975.872 us/op
         max =    975.872 us/op
 
 
# Run complete. Total time: 00:00:21
 
Benchmark                Mode     Cnt  Score   Error  Units
 
DateSerialiseJMH.test  sample  206803  4.578 ± 0.046  us/op

Среднее время 4.5us для операции:
Мы получаем почти такие же результаты при выполнении теста с JLBH:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
package org.latency.serialisation.date;
 
import net.openhft.chronicle.core.jlbh.JLBHOptions;
import net.openhft.chronicle.core.jlbh.JLBHTask;
import net.openhft.chronicle.core.jlbh.JLBH;
 
import java.io.*;
import java.lang.reflect.InvocationTargetException;
import java.util.Date;
 
/**
 * Created to show the effects of running code within more complex code.
 * Date serialisation as a micro benchmark vs date serialisation inside a TCP call.
 */
public class DateSerialisedJLBHTask implements JLBHTask {
    private Date date = new Date();
    private JLBH lth;
 
    public static void main(String[] args) throws InvocationTargetException, IllegalAccessException, IOException, ClassNotFoundException {
        JLBHOptions jlbhOptions = new JLBHOptions()
                .warmUpIterations(400_000)
                .iterations(1_000_000)
                .throughput(100_000)
                .runs(3)
                .recordOSJitter(true)
                .accountForCoordinatedOmmission(true)
                .jlbhTask(new DateSerialisedJLBHTask());
        new JLBH(jlbhOptions).start();
    }
 
    @Override
    public void run(long startTimeNS) {
        try {
            ByteArrayOutputStream out = new ByteArrayOutputStream();
            ObjectOutputStream oos = new ObjectOutputStream(out);
            oos.writeObject(date);
 
            ObjectInputStream ois = new ObjectInputStream(new ByteArrayInputStream(out.toByteArray()));
            date = (Date)ois.readObject();
            lth.sample(System.nanoTime() - startTimeNS);
        } catch (IOException | ClassNotFoundException e) {
            e.printStackTrace();
        }
    }
 
    @Override
    public void init(JLBH lth) {
        this.lth = lth;
    }
}

Вот результаты:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
Warm up complete (400000 iterations took 2.934s)
-------------------------------- BENCHMARK RESULTS (RUN 1) ---------
Run time: 10.0s
Correcting for co-ordinated:true
Target throughput:100000/s = 1 message every 10us
End to End: (1,000,000)                         50/90 99/99.9 99.99/99.999 - worst was 4.2 / 5.8  352 / 672  803 / 901 - 934
OS Jitter (13,939)                              50/90 99/99.9 99.99 - worst was 8.4 / 17  639 / 4,130  12,850 - 20,450
--------------------------------------------------------------------
-------------------------------- BENCHMARK RESULTS (RUN 2) ---------
Run time: 10.0s
Correcting for co-ordinated:true
Target throughput:100000/s = 1 message every 10us
End to End: (1,000,000)                         50/90 99/99.9 99.99/99.999 - worst was 4.2 / 5.8  434 / 705  836 / 934 - 967
OS Jitter (11,016)                              50/90 99/99.9 99.99 - worst was 8.4 / 17  606 / 770  868 - 1,340
--------------------------------------------------------------------
-------------------------------- BENCHMARK RESULTS (RUN 3) ---------
Run time: 10.0s
Correcting for co-ordinated:true
Target throughput:100000/s = 1 message every 10us
End to End: (1,000,000)                         50/90 99/99.9 99.99/99.999 - worst was 4.2 / 5.8  434 / 737  901 / 999 - 1,030
OS Jitter (12,319)                              50/90 99/99.9 99.99 - worst was 8.4 / 15  573 / 737  803 - 901
---------------------------------------------------------------------------------------------------- SUMMARY (end to end)---------------Percentile   run1         run2         run3      % Variation  
50:             4.22         4.22         4.22         0.00   
90:             5.76         5.76         5.76         0.00   
99:           352.26       434.18       434.18         0.00   
99.9:         671.74       704.51       737.28         3.01   
99.99:        802.82       835.58       901.12         4.97   
worst:        901.12       933.89       999.42         4.47   
--------------------------------------------------------------------

Среднее время работы 4,2 с:

Примечание. Это тот случай, когда использование JLBH не является преимуществом перед JMH. Я просто включил код для сравнения.
Теперь мы собираемся выполнить точно такую ​​же операцию, но внутри вызова TCP код будет работать так:

  1. Клиент отправляет серверу сообщение об исправлении через TCP loopback (localhost)
  2. Сервер читает сообщение
  3. Сервер выполняет сериализацию даты
  4. Сервер возвращает сообщение клиенту

Как объяснялось в предыдущем посте, JLBH позволяет нам создавать профиль задержки для любой части кода. Мы добавим зонд для стадии 3.

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
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
package org.latency.serialisation.date;
 
import net.openhft.affinity.Affinity;
import net.openhft.chronicle.core.Jvm;
import net.openhft.chronicle.core.jlbh.JLBHOptions;
import net.openhft.chronicle.core.jlbh.JLBHTask;
import net.openhft.chronicle.core.jlbh.JLBH;
import net.openhft.chronicle.core.util.NanoSampler;
 
import java.io.*;
import java.net.InetSocketAddress;
import java.nio.ByteBuffer;
import java.nio.ByteOrder;
import java.nio.channels.ServerSocketChannel;
import java.nio.channels.SocketChannel;
import java.util.Date;
 
/**
 * Created to show the effects of running code within more complex code.
 * Date serialisation as a micro benchmark vs date serialisation inside a TCP call.
 */
public class DateSerialiseJLBHTcpTask implements JLBHTask {
    private final static int port = 8007;
    private static final boolean BLOCKING = false;
    private final int SERVER_CPU = Integer.getInteger("server.cpu", 0);
    private Date date = new Date();
    private JLBH lth;
 
    private ByteBuffer bb;
    private SocketChannel socket;
    private byte[] fixMessageBytes;
    private NanoSampler dateProbe;
 
    public static void main(String[] args) {
        JLBHOptions lth = new JLBHOptions()
                .warmUpIterations(50_000)
                .iterations(100_000)
                .throughput(20_000)
                .runs(3)
                .recordOSJitter(true)
                .accountForCoordinatedOmmission(true)
                .jlbhTask(new DateSerialiseJLBHTcpTask());
        new JLBH(lth).start();
    }
 
    @Override
    public void init(JLBH lth) {
        this.lth = lth;
        dateProbe = lth.addProbe("date serialisation ");
        try {
            runServer(port);
            Jvm.pause(200);
 
            socket = SocketChannel.open(new InetSocketAddress(port));
            socket.socket().setTcpNoDelay(true);
            socket.configureBlocking(BLOCKING);
 
        } catch (IOException e) {
            e.printStackTrace();
        }
 
        String fixMessage = "8=FIX.4.2\u00019=211\u000135=D\u000134=3\u000149=MY-INITIATOR-SERVICE\u000152=20160229-" +
                "09:04:14.459\u000156=MY-ACCEPTOR-SERVICE\u00011=ABCTEST1\u000111=863913604164909\u000121=3\u000122=5" +
                "\u000138=1\u000140=2\u000144=200\u000148=LCOM1\u000154=1\u000155=LCOM1\u000159=0\u000160=20160229-09:" +
                "04:14.459\u0001167=FUT\u0001200=201106\u000110=144\u0001\n";
 
        fixMessageBytes = fixMessage.getBytes();
        int length = fixMessageBytes.length;
        bb = ByteBuffer.allocateDirect(length).order(ByteOrder.nativeOrder());
        bb.put(fixMessageBytes);
    }
 
    private void runServer(int port) throws IOException {
 
        new Thread(() -> {
            if (SERVER_CPU > 0) {
                System.out.println("server cpu: " + SERVER_CPU);
                Affinity.setAffinity(SERVER_CPU);
            }
            ServerSocketChannel ssc = null;
            SocketChannel socket = null;
            try {
                ssc = ServerSocketChannel.open();
                ssc.bind(new InetSocketAddress(port));
                System.out.println("listening on " + ssc);
 
                socket = ssc.accept();
                socket.socket().setTcpNoDelay(true);
                socket.configureBlocking(BLOCKING);
 
                System.out.println("Connected " + socket);
 
                ByteBuffer bb = ByteBuffer.allocateDirect(32 * 1024).order(ByteOrder.nativeOrder());
                for (; ; ) {
                    bb.limit(12);
                    do {
                        if (socket.read(bb) < 0)
                            throw new EOFException();
                    } while (bb.remaining() > 0);
                    int length = bb.getInt(0);
                    bb.limit(length);
                    do {
                        if (socket.read(bb) < 0)
                            throw new EOFException();
                    } while (bb.remaining() > 0);
 
                    long now = System.nanoTime();
                    try {
                        //Running the date serialisation but this time inside the TCP callback.
                        ByteArrayOutputStream out = new ByteArrayOutputStream();
                        ObjectOutputStream oos = new ObjectOutputStream(out);
                        oos.writeObject(date);
 
                        ObjectInputStream ois = new ObjectInputStream(new ByteArrayInputStream(out.toByteArray()));
                        date = (Date)ois.readObject();
                        dateProbe.sampleNanos(System.nanoTime() - now);
                    } catch (IOException | ClassNotFoundException e) {
                        e.printStackTrace();
                    }
 
                    bb.flip();
 
                    if (socket.write(bb) < 0)
                        throw new EOFException();
 
                    bb.clear();
                }
            } catch (IOException e) {
                e.printStackTrace();
            } finally {
                System.out.println("... disconnected " + socket);
                try {
                    if (ssc != null)
                        ssc.close();
                } catch (IOException ignored) {
                }
                try {
                    if (socket != null)
                        socket.close();
                } catch (IOException ignored) {
                }
            }
        }, "server").start();
 
    }
 
    @Override
    public void run(long startTimeNs) {
        bb.position(0);
        bb.putInt(bb.remaining());
        bb.putLong(startTimeNs);
        bb.position(0);
        writeAll(socket, bb);
 
        bb.position(0);
        try {
            readAll(socket, bb);
        } catch (IOException e) {
            e.printStackTrace();
        }
 
        bb.flip();
        if (bb.getInt(0) != fixMessageBytes.length) {
            throw new AssertionError("read error");
        }
 
        lth.sample(System.nanoTime() - startTimeNs);
    }
 
    private static void readAll(SocketChannel socket, ByteBuffer bb) throws IOException {
        bb.clear();
        do {
            if (socket.read(bb) < 0)
                throw new EOFException();
        } while (bb.remaining() > 0);
    }
 
    private static void writeAll(SocketChannel socket, ByteBuffer bb) {
        try {
            while (bb.remaining() > 0 && socket.write(bb) >= 0) ;
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
}

На этот раз результаты выглядят так:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
Warm up complete (50000 iterations took 3.83s)
-------------------------------- BENCHMARK RESULTS (RUN 1) ------------------------
Run time: 6.712s
Correcting for co-ordinated:true
Target throughput:20000/s = 1 message every 50us
End to End: (100,000)                           50/90 99/99.9 99.99 - worst was 822,080 / 1,509,950  1,711,280 / 1,711,280  1,711,280 - 1,711,280
date serialisation  (100,000)                   50/90 99/99.9 99.99 - worst was 11 / 19  31 / 50  901 - 2,420
OS Jitter (64,973)                              50/90 99/99.9 99.99 - worst was 8.1 / 16  40 / 1,540  4,850 - 18,350
--------------------------------------------------------------------
-------------------------------- BENCHMARK RESULTS (RUN 2) ---------
Run time: 6.373s
Correcting for co-ordinated:true
Target throughput:20000/s = 1 message every 50us
End to End: (100,000)                           50/90 99/99.9 99.99 - worst was 1,107,300 / 1,375,730  1,375,730 / 1,375,730  1,375,730 - 1,375,730
date serialisation  (100,000)                   50/90 99/99.9 99.99 - worst was 11 / 19  29 / 52  901 - 1,670
OS Jitter (40,677)                              50/90 99/99.9 99.99 - worst was 8.4 / 16  34 / 209  934 - 1,470
--------------------------------------------------------------------
-------------------------------- BENCHMARK RESULTS (RUN 3) ---------
Run time: 5.333s
Correcting for co-ordinated:true
Target throughput:20000/s = 1 message every 50us
End to End: (100,000)                           50/90 99/99.9 99.99 - worst was 55,570 / 293,600  343,930 / 343,930  343,930 - 343,930
date serialisation  (100,000)                   50/90 99/99.9 99.99 - worst was 9.0 / 16  26 / 38  770 - 1,030
OS Jitter (32,042)                              50/90 99/99.9 99.99 - worst was 9.0 / 13  22 / 58  737 - 934
--------------------------------------------------------------------
-------------------------------- SUMMARY (end to end)---------------
Percentile   run1         run2         run3      % Variation  
50:        822083.58   1107296.26     55574.53        92.66   
90:       1509949.44   1375731.71    293601.28        71.07   
99:       1711276.03   1375731.71    343932.93        66.67   
99.9:     1711276.03   1375731.71    343932.93        66.67   
99.99:    1711276.03   1375731.71    343932.93        66.67   
worst:    1711276.03   1375731.71    343932.93        66.67   
--------------------------------------------------------------------
-------------------------------- SUMMARY (date serialisation )------
Percentile   run1         run2         run3      % Variation  
50:            11.01        11.01         8.96        13.22   
90:            18.94        18.94        15.62        12.44   
99:            31.23        29.18        26.11         7.27   
99.9:          50.18        52.22        37.89        20.14   
99.99:        901.12       901.12       770.05        10.19   
worst:       2424.83      1671.17      1032.19        29.21   
 
--------------------------------------------------------------------

Как видно, одна и та же сериализация даты занимает в два раза больше времени — от ~ 4,5 до ~ 10 у.

Здесь не место вдаваться в подробности о том, почему выполнение кода занимает больше времени в контексте, но это связано с заполнением кэшей ЦП между вызовами сериализации даты.

Когда все, что мы запускаем (как в микро-бенчмарке), — это Сериализация Даты, тогда она может хорошо вписаться в кэш ЦП и не нуждается в очистке. Однако когда между вызовами сериализации Date возникает разрыв, код операции очищается и его необходимо перезагрузить.

JLBH позволяет вам тестировать код в контексте, и это важная часть сравнительного анализа задержки.

Ссылка: Примеры 1 JLBH — почему код должен сравниваться в контексте с нашим партнером по JCG Дэниелом Шая из блога Rational Java .
37
Share: