Nicholas Telford created KAFKA-21407:
----------------------------------------
Summary: StreamTask spams "not ready for processing" at INFO every
2 minutes for every idle task
Key: KAFKA-21407
URL: https://issues.apache.org/jira/browse/KAFKA-21407
Project: Kafka
Issue Type: Bug
Components: streams
Affects Versions: 4.4.0, 4.3.0, 4.2.0
Reporter: Nicholas Telford
h3. Problem
KAFKA-19682 (#20693, first released in 4.2.0) made {{StreamTask#isProcessable}}
log the reason when a task is not ready to process.
{{StreamTask#maybeLogNotReady}} writes this reason at INFO, one time in each
{{NOT_READY_LOG_INTERVAL_MS}} (120 s) while the task stays not ready:
{code:java}
private void maybeLogNotReady(final long wallClockTime, final String
logMessage) {
final long timeSinceLastLog = lastNotReadyLogTime.map(aLong ->
wallClockTime - aLong).orElse(-1L);
if (timeSinceLastLog >= NOT_READY_LOG_INTERVAL_MS) {
log.info(logMessage);
lastNotReadyLogTime = Optional.of(wallClockTime);
}
}
{code}
The most frequent reason is the last branch of
{{{}PartitionGroup#readyToProcess{}}}: "No partitions were buffered locally, so
this task is not ready for processing." A task gets this result when none of
its input partitions has buffered records. This is the normal state of a task
whose input topics receive no new data, for example a task of a low-volume or a
bursty topic.
So an application logs one INFO line every 2 minutes for each idle task, for as
long as the task stays idle. The line tells the operator nothing that needs an
action. Before 4.2.0, {{PartitionGroup}} logged the same states at TRACE.
h3. Impact
We upgraded a Kafka Streams application from 3.8 to 4.4.0. It runs 12 instances
with about 1,800 active tasks in total. Many of its source topics have a low
volume.
* On 3.8, the application logged about 2,160 INFO lines per hour in steady
state, almost all of them the {{StreamThread}} "Processed ... total records"
summary.
* On 4.4.0, it logs about {*}58,000 INFO lines per hour{*}. 53,800 of them
(93%) are the "not ready for processing" line from {{{}StreamTask{}}}.
The count agrees with one line for each task every 2 minutes. The volume
increases the cost of log storage, and the line hides the useful INFO lines of
{{{}StreamTask{}}}.
An operator cannot raise the level of the {{StreamTask}} logger to WARN to
remove the line, because the same logger writes the task lifecycle at INFO:
"Initialized", "Restored and ready to run", "Suspended", "Closed clean" and
"Closed dirty". These lines are necessary to diagnose restores and rebalances.
The only workaround is a filter on the message text in the logging backend.
h3. Proposed fix
Keep the diagnostic, but write it at INFO only when the task waits for a reason
that is not normal. Possible approaches:
# Log the "no partitions were buffered locally" reason at DEBUG. Keep INFO for
the reasons that mean the task waits for data that the broker has, or waits for
a pending transaction commit.
# Log at INFO only when the task stayed not ready for longer than a threshold,
for example {{max.task.idle.ms}} or a new configuration, and log at DEBUG
before that.
# Use a separate logger name for the not-ready diagnostic, so that an operator
can set its level without a change to the task lifecycle lines.
If KAFKA-21372 changes {{ReadyToProcessResult}} to carry the reason as
structured data, {{StreamTask}} can select the level from the reason with no
text match.
h3. Workaround
A filter in the logging backend that denies INFO events of the
{{org.apache.kafka.streams.processor.internals.StreamTask}} logger when the
message ends with "not ready for processing.". This depends on the exact
message text.
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
