Skip to content

MINOR: improve StreamThread periodic processing log #18430

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ableegoldman merged 1 commit into from
Jan 9, 2025
Merged

MINOR: improve StreamThread periodic processing log #18430

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 7 additions & 3 deletions streams/src/main/java/org/apache/kafka/streams/processor/internals/StreamThread.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -311,6 +311,7 @@ public boolean isStartingRunningOrPartitionAssigned() {
private long lastLogSummaryMs = -1L;
private long totalRecordsProcessedSinceLastSummary = 0L;
private long totalPunctuatorsSinceLastSummary = 0L;
private long totalPolledSinceLastSummary = 0L;
private long totalCommittedSinceLastSummary = 0L;

private long now;
Expand Down Expand Up @@ -960,6 +961,7 @@ void runOnceWithoutProcessingThreads() {
final long pollLatency;
taskManager.resumePollingForPartitionsWithAvailableSpace();
pollLatency = pollPhase();
totalPolledSinceLastSummary += 1;

// Shutdown hook could potentially be triggered and transit the thread state to PENDING_SHUTDOWN during #pollRequests().
// The task manager internal states could be uninitialized if the state transition happens during #onPartitionsAssigned().
Expand Down Expand Up @@ -1075,12 +1077,14 @@ void runOnceWithoutProcessingThreads() {
pollRatioSensor.record((double) pollLatency / runOnceLatency, now);
commitRatioSensor.record((double) totalCommitLatency / runOnceLatency, now);

if (logSummaryIntervalMs > 0 && now - lastLogSummaryMs > logSummaryIntervalMs) {
log.info("Processed {} total records, ran {} punctuators, and committed {} total tasks since the last update",
totalRecordsProcessedSinceLastSummary, totalPunctuatorsSinceLastSummary, totalCommittedSinceLastSummary);
final long timeSinceLastLog = now - lastLogSummaryMs;
if (logSummaryIntervalMs > 0 && timeSinceLastLog > logSummaryIntervalMs) {
log.info("Processed {} total records, ran {} punctuators, polled {} times and committed {} total tasks since the last update {}ms ago",

@ableegoldman ableegoldman Jan 8, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oxford comma 😭

@ableegoldman ableegoldman Jan 8, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can we also log how long it's been since the last update? we just merged a KIP to allow configuring this interval, and anyways the time can vary and the logging interval is just a minimum not exact interval

@ableegoldman ableegoldman Jan 8, 2025

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oh my bad...you already did...

(great minds think alike...?)

totalRecordsProcessedSinceLastSummary, totalPunctuatorsSinceLastSummary, totalPolledSinceLastSummary, totalCommittedSinceLastSummary, timeSinceLastLog);

totalRecordsProcessedSinceLastSummary = 0L;
totalPunctuatorsSinceLastSummary = 0L;
totalPolledSinceLastSummary = 0L;
totalCommittedSinceLastSummary = 0L;
lastLogSummaryMs = now;
}
Expand Down