[jira] [Updated] (KAFKA-21407) StreamTask spams "not ready for processing" at INFO every 2 minutes for every idle task

["Matthias J. Sax (Jira) via jira" <ji...@kafka.apache.org>]

     [ 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)