[
https://issues.apache.org/jira/browse/KAFKA-21407?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Matthias J. Sax updated KAFKA-21407:
------------------------------------
Affects Version/s: (was: 4.3.0)
(was: 4.4.0)
> 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.2.0
> Reporter: Nicholas Telford
> Priority: Minor
>
> 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)
