Java Flight Recorder, и в сегодняшней статье я собираюсь использовать его, чтобы понять, как
Sockets ведет себя в вашем Java-приложении.
Многие люди используют API-интерфейсы HTTP для связи между своими службами (давайте напишем еще одну статью о том, является ли это хорошим решением или нет), и в большинстве случаев он работает нормально. Тем не менее, мы можем попасть в ситуации, когда производительность действительно имеет значение, и особенно для разработчиков библиотек, JFR может быть очень полезным инструментом, чтобы увидеть работу ввода-вывода в их коде.
Вам также может понравиться:
Использование Java Flight Recorder с OpenJDK 11
Эта статья не является введением в Flight Recorder, она более практична. Если вы хотите узнать больше об этой технологии, вы можете начать с JEP 328: Flight Recorder .
Введение в наше приложение Netty
В качестве примера я решил использовать отличный проект под названием Netty, который упрощает реализацию JDK NIO и предоставляет множество приемов, которые мы можем использовать для оптимизации нашего приложения. Давайте углубимся в то, что мы собираемся использовать для наших экспериментов.
Не стесняйтесь проверить мой проект jfr-sockets на GitHub и попробовать все со мной. Проект фактически содержит два приложения на основе TCP. Первый в простом пакете — это просто дамп TCP Client / Server, и клиент отправляет каждую 1-ю строку my-message, которая занимает ровно 10 байтов. И второе — это клиент-серверное приложение на базе Netty, где сервер отправляет каждые 1 ту же строку, что и раньше, но с использованием WebSocket. Я сознательно выбрал эти типы приложений, и мы рассмотрим детали того, почему я это сделал.
Вы также можете заметить строковую константу с именем CONFIG . Я использую трюк, в котором файл с правильной конфигурацией создается таким образом, вместо изменения обычного файла конфигурации JFR. Если вы хотите увидеть файлы конфигурации в JDK, пожалуйста, откройте эту папку ${JAVA_HOME}/lib/jfr. Скорее всего, вы заметили два файла default.jfc и profile.jfc . Если вы откроете его, вы увидите XML-конфигурацию событий JFR. Эта конфигурация говорит, когда событие должно быть отправлено. По умолчанию файл конфигурации имеет меньшие издержки (~ 1%) и полезен для непрерывного профилирования, тогда как конфигурация профиля очень агрессивна и генерирует больше событий с более низкими порогами (накладные расходы ~ 2%).
Нам нужно было создать наши собственные настройки, потому что по умолчанию существует порог 20 мс для чтения и записи, но мы хотим видеть каждую операцию.
Обратите внимание, что я использую новую функцию, которая доступна с Java 14 JEP 349: Потоковая передача событий JFR , а это означает, что если вы хотите попробовать ее, вам нужно скачать ее с https://jdk.java.net/14/ .
Запустите простое блокирующее приложение
Самый первый пример — это класс pbouda.jfr.sockets.simple.Start . Если вы попробуете это, вы увидите вывод, похожий на приведенный ниже. Как мы упоминали ранее, приложение записывает UTF String my-message (10 байт), и если вы посмотрите внутрь методов, мы фактически попали в stacktrace поле, 10-байтовая строка кодируется в 12-байтовое сообщение.
Поскольку TCP основан на потоках, нам нужен хорошо известный разделитель между двумя сообщениями, или нам нужно как-то кодировать размер сообщения. Реализация JDK writeUTFи readUTF основана на втором варианте. JDK использует первые два байта как короткий тип, который определяет количество байтов в самом сообщении.
Джава
1
[0, 10, 109, 121, 45, 109, 101, 115, 115, 97, 103, 101]
Согласно событию jdk.SocketWrite мы видим, что мы записали 12-байтовый массив (2 байта для длины, 10 байтов для полезной нагрузки).
С точки зрения jdk.SocketRead мы можем заметить два события, принадлежащих DataInputStream#readUnsignedShort. Как мы упоминали выше, во-первых, нам нужно прочитать размер полезной нагрузки (беззнаковый шорт). Эта операция вызвала два события, потому что она всегда вызывает SocketInputStream#readдважды, чтобы прочитать короткое значение (один байт на операцию). Самое последнее событие уже содержит полезные данные и вызовы DataInputStream#readFully.
Джава
xxxxxxxxxx
1
jdk.SocketWrite {
2
startTime = 20:03:57.651
3
duration = 0.185 ms
4
host = "localhost"
5
address = "127.0.0.1"
6
port = 52960
7
bytesWritten = 12 bytes
8
eventThread = "Thread-0" (javaThreadId = 18)
9
stackTrace = [
10
java.net.Socket$SocketOutputStream.write(byte[], int, int) line: 65
11
java.io.DataOutputStream.write(byte[], int, int) line: 106
12
java.io.DataOutputStream.writeUTF(String, DataOutput) line: 397
13
java.io.DataOutputStream.writeUTF(String) line: 325
14
pbouda.jfr.sockets.simple.Start$ClientHandler.run() line: 67
15
...
16
]
17
}
18
jdk.SocketRead {
20
startTime = 20:03:56.558
21
duration = 1.09 s
22
host = "localhost"
23
address = "127.0.0.1"
24
port = 5000
25
timeout = 0 s
26
bytesRead = 1 byte
27
endOfStream = false
28
eventThread = "main" (javaThreadId = 1)
29
stackTrace = [
30
java.net.Socket$SocketInputStream.read(byte[], int, int) line: 68
31
java.net.Socket$SocketInputStream.read() line: 977
32
java.io.DataInputStream.readUnsignedShort() line: 341
33
java.io.DataInputStream.readUTF(DataInput) line: 593
34
java.io.DataInputStream.readUTF() line: 568
35
...
36
]
37
}
38
jdk.SocketRead {
40
startTime = 20:03:57.651
41
duration = 0.0617 ms
42
host = "localhost"
43
address = "127.0.0.1"
44
port = 5000
45
timeout = 0 s
46
bytesRead = 1 byte
47
endOfStream = false
48
eventThread = "main" (javaThreadId = 1)
49
stackTrace = [
50
java.net.Socket$SocketInputStream.read(byte[], int, int) line: 68
51
java.net.Socket$SocketInputStream.read() line: 977
52
java.io.DataInputStream.readUnsignedShort() line: 342
53
java.io.DataInputStream.readUTF(DataInput) line: 593
54
java.io.DataInputStream.readUTF() line: 568
55
...
56
]
57
}
58
jdk.SocketRead {
60
startTime = 20:03:57.652
61
duration = 0.0699 ms
62
host = "localhost"
63
address = "127.0.0.1"
64
port = 5000
65
timeout = 0 s
66
bytesRead = 10 bytes
67
endOfStream = false
68
eventThread = "main" (javaThreadId = 1)
69
stackTrace = [
70
java.net.Socket$SocketInputStream.read(byte[], int, int) line: 68
71
java.io.DataInputStream.readFully(byte[], int, int) line: 199
72
java.io.DataInputStream.readUTF(DataInput) line: 613
73
java.io.DataInputStream.readUTF() line: 568
74
pbouda.jfr.sockets.simple.Start.main(String[]) line: 49
75
...
76
]
77
}
78
my-message
Если вы хотите увидеть, как эти события представлены в JDK, вот подсказка:
Джава
xxxxxxxxxx
1
jdk.jfr.events.SocketReadEvent
2
jdk.jfr.events.SocketWriteEvent
Не стесняйтесь перемещаться туда, где эти события испускаются. События JFR обычно кэшируются и используются позже. В этом случае мы можем видеть, что объект хранится в ThreadLocalпеременной. Поля всегда переустанавливаются, событие генерируется, и затем объект может снова использоваться тем же потоком. Все сделано ради дружелюбия GC.
Какие интересные вещи мы можем увидеть?
События сокетов очень богаты, и мы можем увидеть много интересной информации. Большинство из этих полей очень описательны, только примечание об адресе / имени хоста / порте. Мы можем очень легко увидеть, с какими другими приложениями мы общаемся, разве мы не называем какие-либо подозрительные конечные точки?
Тем не менее, мое любимое поле - продолжительность. Мы видим большие различия между SocketReadсобытиями в приведенном выше фрагменте. Почему самые первые события заняли более 1 секунды и что это на самом деле означает?
Мы уже знаем, что клиент имеет задержку в 1 секунду между сообщениями. Однако поле длительности невероятно ценно, потому что теперь мы можем видеть, что что-то блокирует наш поток (конечно, мы можем видеть это даже из трассировки стека, потому что InputStreamэто блокирует по своей природе). На самом деле поток делает то, что он ожидает, пока какие-либо данные не поступят в Receive Socket Buffer, чтобы иметь возможность скопировать их во внутреннюю временную память DirectBuffer. Мы можем заметить, что другие операции были намного быстрее, потому что байты уже были в буфере сокета, и мы просто читаем точное количество байтов, которое нам нужно.
Почему я вижу такую большую продолжительность?
Если вы используете Java Mission Control для визуализации событий JFR, то, скорее всего, вы заметили, что секция Socket I / O содержит невероятную длительность и общее время ввода-вывода. Это результат того, что некоторые блокирующие TCP-соединения открыты и ожидают данных. В приведенном ниже случае это RMI TCP Connection, но вы можете столкнуться с очень похожей проблемой, если, скажем, RabbitMQ и не принимаете никаких сообщений.
Где события отправляются с моей конечной точки?
Вы также можете быть удивлены: почему я не вижу другого трафика? Допустим, у нас есть приложение с конечной точкой HTTP, которое используется очень часто. Причина в том, что вы, вероятно, работаете в конфигурации JFR по умолчанию, которая гласит: только операции длительностью более 20 мсек будут генерировать событие . Это означает, что вы можете праздновать, потому что ваше приложение, скорее всего, не пострадает от серьезных (я знаю, что это относительно, 20 мс - это не маленькая задержка) проблем с сокетом ввода-вывода.
Запустите приложение NetSucket WebSocket
Давайте продолжим со вторым приложением. Как мы уже упоминали, это приложение WebSocket, в котором сервер передает сообщения всем подключенным клиентам. Для этого эксперимента мы собираемся подключить только одного клиента и посмотреть, какие сообщения получает клиент.
Если вы знаете проект Netty, вы, вероятно, заметили, что Netty содержит несколько реализаций SocketChannel. Давайте начнем с сокета NIO на основе JDK.
Запустите класс, который автоматически запускает клиент и сервер: pbouda.jfr.sockets.netty.Start .
Во-первых, мы видим четыре события, относящиеся к установлению соединения WebSocket. Обратите внимание, что у нас уже есть значимое eventThread поле, которое может помочь нам, когда мы начнем исследовать любые проблемы.
Джава
xxxxxxxxxx
1
jdk.SocketWrite {
2
startTime = 21:21:27.135
3
duration = 0.677 ms
4
host = ""
5
address = "127.0.0.1"
6
port = 8080
7
bytesWritten = 292 bytes
8
eventThread = "client-nioEventLoopGroup-0" (javaThreadId = 26)
9
stackTrace = [ sun.nio.ch.SocketChannelImpl.write(ByteBuffer) line: 138
10
io.netty.channel.socket.nio.NioSocketChannel.doWrite(ChannelOutboundBuffer) line: 405
11
io.netty.channel.AbstractChannel$AbstractUnsafe.flush0() line: 931
12
io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0() line: 354
13
io.netty.channel.AbstractChannel$AbstractUnsafe.flush() line: 898
14
...
15
]
16
}
17
jdk.SocketRead {
19
startTime = 21:21:27.149
20
duration = 0.0479 ms
21
host = ""
22
address = "127.0.0.1"
23
port = 41244
24
timeout = 0 s
25
bytesRead = 292 bytes
26
endOfStream = false
27
eventThread = "server-nioEventLoopGroup-1" (javaThreadId = 27)
28
stackTrace = [
29
sun.nio.ch.SocketChannelImpl.read(ByteBuffer) line: 73
30
io.netty.buffer.PooledByteBuf.setBytes(int, ScatteringByteChannel, int) line: 247
31
io.netty.buffer.AbstractByteBuf.writeBytes(ScatteringByteChannel, int) line: 1147
32
io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(ByteBuf) line: 347
33
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read() line: 148
34
...
35
]
36
}
37
jdk.SocketWrite {
39
startTime = 21:21:27.177
40
duration = 0.102 ms
41
host = ""
42
address = "127.0.0.1"
43
port = 41244
44
bytesWritten = 129 bytes
45
eventThread = "server-nioEventLoopGroup-1" (javaThreadId = 27)
46
stackTrace = [
47
sun.nio.ch.SocketChannelImpl.write(ByteBuffer) line: 138
48
io.netty.channel.socket.nio.NioSocketChannel.doWrite(ChannelOutboundBuffer) line: 405
49
io.netty.channel.AbstractChannel$AbstractUnsafe.flush0() line: 931
50
io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0() line: 354
51
io.netty.channel.AbstractChannel$AbstractUnsafe.flush() line: 898
52
...
53
]
54
}
55
jdk.SocketRead {
57
startTime = 21:21:27.183
58
duration = 0.0394 ms
59
host = ""
60
address = "127.0.0.1"
61
port = 8080
62
timeout = 0 s
63
bytesRead = 129 bytes
64
endOfStream = false
65
eventThread = "client-nioEventLoopGroup-0" (javaThreadId = 26)
66
stackTrace = [
67
sun.nio.ch.SocketChannelImpl.read(ByteBuffer) line: 73
68
io.netty.buffer.PooledByteBuf.setBytes(int, ScatteringByteChannel, int) line: 247
69
io.netty.buffer.AbstractByteBuf.writeBytes(ScatteringByteChannel, int) line: 1147
70
io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(ByteBuf) line: 347
71
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read() line: 148
72
...
73
]
74
}
Давайте посмотрим события, связанные с нашей полезной нагрузкой (не так просто выяснить, какие события относятся к какой записи журнала, но сейчас это не так важно).
Мы можем заметить, что у нас очень часто есть одно событие для чтения и одно для записи, которые содержат 12 байтов (это также может быть разным, мы можем прочитать только часть сообщения, а затем поддержка WebSocket в Netty должна ждать другого чтения / буфера чтобы иметь возможность анализировать весь кадр WebSocket).
Кому-то может быть любопытно, почему мы передали 12 байтов в случае 10-байтового сообщения? В случае сообщений размером менее 126 байт накладные расходы составляют 2 байта, это связано с механизмом кадрирования WebSocket.
Кто-то также может быть удивлен тем, что в случае SocketReadсобытий у нас не было никаких длительностей, превышающих 1 секунду, как в первом примере. Причина в том, что NIO сконфигурирован в неблокирующем режиме, что означает, что он не ожидает входящие данные (просто копирует то, что в данный момент находится в буфере сокета, в JDK DirectBufferи передает его Netty и не заботится о количестве байтов). ), и текущий поток просто пытается сделать что-то другое (он может читать из другого канала, если у нас есть несколько соединений для одного цикла обработки событий). Итак, мы видим, что наше приложение, скорее всего, исправно с точки зрения блокировки потоков; это может быть проблемой, если вы хотите пропустить проблему C10K (параллельная обработка тысяч соединений).
Джава
xxxxxxxxxx
1
Broadcaster-Server 2020-01-14 21:21:29,181 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
2
jdk.SocketWrite {
4
startTime = 21:21:29.454
5
duration = 0.0644 ms
6
host = ""
7
address = "127.0.0.1"
8
port = 41244
9
bytesWritten = 12 bytes
10
eventThread = "server-nioEventLoopGroup-1" (javaThreadId = 27)
11
stackTrace = [
12
sun.nio.ch.SocketChannelImpl.write(ByteBuffer) line: 138
13
io.netty.channel.socket.nio.NioSocketChannel.doWrite(ChannelOutboundBuffer) line: 405
14
io.netty.channel.AbstractChannel$AbstractUnsafe.flush0() line: 931
15
io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0() line: 354
16
io.netty.channel.AbstractChannel$AbstractUnsafe.flush() line: 898
17
...
18
]
19
}
20
jdk.SocketRead {
22
startTime = 21:21:29.454
23
duration = 0.0197 ms
24
host = ""
25
address = "127.0.0.1"
26
port = 8080
27
timeout = 0 s
28
bytesRead = 12 bytes
29
endOfStream = false
30
eventThread = "client-nioEventLoopGroup-0" (javaThreadId = 26)
31
stackTrace = [
32
sun.nio.ch.SocketChannelImpl.read(ByteBuffer) line: 73
33
io.netty.buffer.PooledByteBuf.setBytes(int, ScatteringByteChannel, int) line: 247
34
io.netty.buffer.AbstractByteBuf.writeBytes(ScatteringByteChannel, int) line: 1147
35
io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(ByteBuf) line: 347
36
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read() line: 148
37
...
38
]
39
}
Покажите мне некоторые возможные оптимизации с Netty!
Netty позволяет нам эффективно управлять нашей связью, принадлежащей одному соединению. Я подготовил один пример, показывающий, что мы можем очень легко уменьшить количество системных вызовов, используя кеш сообщений в Netty. Просто мы решили пожертвовать задержкой одного сообщения и сделать наше серверное приложение намного более эффективным, удалив системные вызовы. Допустим, мы хотим сбросить не каждое сообщение, а каждое пятое сообщение для данного клиента.
Нам нужно сделать два небольших изменения:
Джава
xxxxxxxxxx
1
pbouda.jfr.sockets.netty.server.SlowConsumerDisconnectHandler
2
- we need to comment out flushing of every message and use simple write instead
3
- write method does not automatically write data into the socket, it waits for a flush context.writeAndFlush(obj) -> context.write(obj)
Джава
xxxxxxxxxx
1
pbouda.jfr.sockets.netty.Start#main
2
- uncomment the section at the end of the method `Flush a bulk of 5 messages`
Теперь мы можем снова запустить приложение Netty. Мы можем видеть, что мы получили пять сообщений в массе и передали 60 байтов вместо 12, используя один системный вызов / вызов.
Джава
xxxxxxxxxx
1
Broadcaster-Server 2020-01-14 22:12:00,937 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
2
Broadcaster-Server 2020-01-14 22:12:00,937 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
3
Broadcaster-Server 2020-01-14 22:12:00,938 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
4
Broadcaster-Server 2020-01-14 22:12:00,938 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
5
Broadcaster-Server 2020-01-14 22:12:00,939 [client-nioEventLoopGroup-0] INFO p.j.s.n.c.WebSocketClientHandler - Received message: my-message (10 bytes)
6
jdk.SocketWrite {
8
startTime = 22:12:01.603
9
duration = 2.23 ms
10
host = ""
11
address = "127.0.0.1"
12
port = 42556
13
bytesWritten = 60 bytes
14
eventThread = "server-nioEventLoopGroup-1" (javaThreadId = 27)
15
stackTrace = [
16
sun.nio.ch.SocketChannelImpl.write(ByteBuffer[], int, int) line: 167
17
io.netty.channel.socket.nio.NioSocketChannel.doWrite(ChannelOutboundBuffer) line: 420
18
io.netty.channel.AbstractChannel$AbstractUnsafe.flush0() line: 931
19
io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0() line: 354
20
io.netty.channel.AbstractChannel$AbstractUnsafe.flush() line: 898
21
...
22
]
23
}
24
jdk.SocketRead {
26
startTime = 22:12:01.605
27
duration = 0.0757 ms
28
host = ""
29
address = "127.0.0.1"
30
port = 8080
31
timeout = 0 s
32
bytesRead = 60 bytes
33
endOfStream = false
34
eventThread = "client-nioEventLoopGroup-0" (javaThreadId = 26)
35
stackTrace = [
36
sun.nio.ch.SocketChannelImpl.read(ByteBuffer) line: 73
37
io.netty.buffer.PooledByteBuf.setBytes(int, ScatteringByteChannel, int) line: 247
38
io.netty.buffer.AbstractByteBuf.writeBytes(ScatteringByteChannel, int) line: 1147
39
io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(ByteBuf) line: 347
40
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read() line: 148
41
...
42
]
43
}
Я пользуюсь Netty и не вижу событий! Почему?
Есть много причин, но одна из них немного сложнее. Если вы работаете в Linux и хотите быть очень эффективным, вы можете включить транспорт электронного опроса. Это неблокирующий собственный транспорт, который можно использовать только в Linux. Большим преимуществом этого транспорта является то, что если у нас есть приложение, обрабатывающее десятки тысяч соединений параллельно, то, в случае JDK NIO, мы должны выполнить итерацию по всем соединениям, чтобы попытаться найти какие-либо данные для чтения - у нас есть O (N), чтобы прочитать данные. Простой электронный опрос позволяет получить информацию о читаемых соединениях - O (1).
Проблема в том, что поддержка электронного опроса полностью разработана командой Netty и не генерирует никаких событий JFR. Если вы хотите попробовать это, то:
Джава
xxxxxxxxxx
1
pbouda.jfr.sockets.netty.server.Server
2
- uncomment EpollEventLoopGroup instead of NioEventLoopGroup
3
- uncomment EpollServerSocketChannel instead of NioServerSocketChannel
Резюме
События JFR могут быть очень мощным инструментом для поиска слабых мест в наших приложениях. Стоит изучить, что он нам предлагает, и быть готовым использовать его, когда мы сталкиваемся с любой проблемой. В общем, это означает:
SocketRead События: Ждем поступающих данных. Наш буфер получаемых сокетов, скорее всего, пуст. В случае неблокирующего транспорта мы не получаем никаких событий из-за неблокирующего характера реализации. В случае блокировки транспорта мы можем получать события, но это может быть какое-то соединение, которое просто находится в режиме ожидания и ожидает каких-либо данных.
SocketWrite События: ситуация просто обратная. Мы можем заблокировать в случае блокирования транспорта, если буфер отправки сокета заполнен. В случае неблокирующей передачи мы можем выполнить частичную запись (запись только байтов, которые подходят для Send Socket Buffer), а остальные байты должны быть кэшированы нашим приложением.
Если вы хотите попробовать больше событий (даже других типов), тогда посмотрите репозиторий jfr-playstation . В противном случае, спасибо за чтение моей статьи и, пожалуйста, оставьте комментарии ниже. Если вы хотите получать уведомления о новых сообщениях, тогда начните подписываться на меня в Twitter !