我有一个相对较短的 Netty 管道,其中包含一个ByteToMessageDecoder
和一个LoggingHandler
. 在进行分析以了解为什么我对遥控器的请求/响应时间如此之长,并且我能够对事情进行相当多的优化。但是,完成阻塞 writeAndFlush 似乎仍然需要花费过多的时间。这个多余的时间似乎是在出站数据从 my 传播ByteToMessageDecoder
到 my LoggingHandler
。
“就在发送之前”和“就在发送之后”的日志时间包括数据在线路上发出所需的时间,但是“就在发送之前”和LoggingHandler
命中之间的日志时间消除了实际硬件的任何开销传播。
在下面的一种情况下,我们看到“就在发送之前”发生在 59.550 并且在 00.150LoggingHandler
被击中......整整 600 毫秒后。完全在内存中操作的 600ms 似乎相当长。
额外上下文:这使用构建在 JSerialComm 之上的 OioByteStreamChannel 抽象。
private void sendRequest(String command, String payload) throws InterruptedException {
log.info("allocating buffer");
ByteBuf buffer = Unpooled.buffer();
log.info("done allocating buffer");
String commandPlusPayload = format("%s%s", command, payload);
buffer.writeByte(STX);
buffer.writeBytes(commandPlusPayload.getBytes(StandardCharsets.US_ASCII));
buffer.writeByte(ETX);
buffer.writeByte(calcChecksum(commandPlusPayload.getBytes(StandardCharsets.US_ASCII)));
log.info("just before send");
context.writeAndFlush(buffer).sync();
log.info("just after send");
}
2021-03-31_07:35:59.550 INFO [pipe-pie:stop 1] pie.device - just before send
2021-03-31_07:36:00.150 TRACE [pool-23-thread-1] pie.device.serial - [id: 0x62e4a0a4, L:localhost - R:tty.usbserial-FTCASQQV] WRITE: 6B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 02 43 30 31 03 57 |.C01.W |
+--------+-------------------------------------------------+----------------+
2021-03-31_07:36:00.150 TRACE [pool-23-thread-1] pie.device.serial - [id: 0x62e4a0a4, L:localhost - R:tty.usbserial-FTCASQQV] FLUSH
2021-03-31_07:36:00.151 INFO [pipe-pie:stop 1] pie.device - just after send
ChannelInitializer<T> initializer = new ChannelInitializer<T>() {
@Override
protected void initChannel(Channel channel) {
channel.pipeline().addLast(new LoggingHandler(logName, LogLevel.TRACE)); // logs traffic
channel.pipeline().addLast(PiePipelineManager.class.getName(), broker);
}
};