Alexander Belyak created IGNITE-23564:
-----------------------------------------
Summary: Critical threads may be blocked by disc operations for
logging
Key: IGNITE-23564
URL: https://issues.apache.org/jira/browse/IGNITE-23564
Project: Ignite
Issue Type: Improvement
Components: general
Affects Versions: 3.0
Reporter: Alexander Belyak
The critical thread could be blocked by disk operation when writing logs. It
could happen any time, but in my case:
# Start 1 node AI3 cluster (from main)
# Run TPC-H benchmark
Got exception:
{code:java}
2024-10-29 08:42:11:048 +0000
[WARNING][%poc-tester-SERVER-172.24.1.2-id-0%common-scheduler-0][FailureManager]
Possible failure suppressed according to a configured handler
[hnd=NoOpFailureHandler [super=AbstractFailureHandler
[ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED,
SYSTEM_CRITICAL_OPERATION_TIMEOUT]]], failureCtx=SYSTEM_WORKER_BLOCKED]
org.apache.ignite.lang.IgniteException: IGN-WORKERS-1
TraceId:1c340c5a-bc99-4c84-b16a-b98296b676f8 A critical thread is blocked for
6862 ms that is more than the allowed 500 ms, it is
"poc-tester-SERVER-172.24.1.2-id-0-srv-worker-13" prio=10 Id=47 RUNNABLE
at [email protected]/java.io.FileOutputStream.writeBytes(Native Method)
at
[email protected]/java.io.FileOutputStream.write(FileOutputStream.java:354)
at
[email protected]/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81)
at
[email protected]/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142)
- locked java.io.BufferedOutputStream@78d7618b
at [email protected]/java.io.PrintStream.flush(PrintStream.java:417)
- locked java.io.PrintStream@2b55b478
at
[email protected]/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:318)
at
[email protected]/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:153)
- locked java.io.OutputStreamWriter@3d0ebea5
at
[email protected]/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:251)
at
[email protected]/java.util.logging.StreamHandler.flush(StreamHandler.java:247)
- locked org.gridgain.poc.framework.utils.OutConsoleHandler@12544ea2
at
app//org.gridgain.poc.framework.utils.OutConsoleHandler.publish(OutConsoleHandler.java:33)
at [email protected]/java.util.logging.Logger.log(Logger.java:979)
at [email protected]/java.util.logging.Logger.doLog(Logger.java:1006)
at [email protected]/java.util.logging.Logger.log(Logger.java:1029)
at
[email protected]/sun.util.logging.internal.LoggingProviderImpl$JULWrapper.log(LoggingProviderImpl.java:230)
at
app//org.apache.ignite.internal.logger.IgniteLogger.logInternal(IgniteLogger.java:266)
at
app//org.apache.ignite.internal.logger.IgniteLogger.info(IgniteLogger.java:49)
at
app//org.apache.ignite.client.handler.ClientInboundMessageHandler.writeFlags(ClientInboundMessageHandler.java:844)
at
app//org.apache.ignite.client.handler.ClientInboundMessageHandler.processOperation(ClientInboundMessageHandler.java:600)
at
app//org.apache.ignite.client.handler.ClientInboundMessageHandler.channelRead(ClientInboundMessageHandler.java:330)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at
app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at
app//io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
at
app//io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at
app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at
app//io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at
app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at
app//io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868)
at
app//io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at
app//io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at
app//io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at
app//io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at
app//io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at
app//io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at
app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at [email protected]/java.lang.Thread.run(Thread.java:829)
{code}
because the
[ClientInboundMessageHandler|https://github.com/apache/ignite-3/blob/e68e435dd6600770f596f394823495114a699c92/modules/client-handler/src/main/java/org/apache/ignite/client/handler/ClientInboundMessageHandler.java#L916]
tries to log:
{code:java}
LOG.info("Partition primary replica changed, notifying client [connectionId=" +
connectionId + ", remoteAddress="
+ ctx.channel().remoteAddress() + ']'); {code}
We should either:
# Recommend moving logs to the separate drive
# Change the logger or wrap it to use some in-memory buffer to write the logs
asynchronously
to avoid blocking critical threads with not mandatory disk operations.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
