kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nicolas Fouché <nfou...@onfocus.io>
Subject Streams - Got bit by log levels of the record cache
Date Thu, 09 Mar 2017 15:48:16 GMT
Hi,

I just wanted to share how we misinterpreted logs from Streams at the INFO
level. Version 0.10.1.1, I think it's the same for 0.10.2.0.

So, we configured `commit.interval.ms` and `cache.max.bytes.buffering`, and
we expected to always reach the commit interval before the maximum bytes.
It was confirmed by looking at the logs the commit interval actually
triggered commits. No logs about the maximum bytes.

But then I noticed in our monitoring graphs and by consuming output topics
that the rate of messages was way too high (thanks to pv[1]).

I checked the code of Streams to write a kinda "sequence diagram" to see
what was logged and at what level.

For `commit.interval.ms`:
- StreamThread#maybeCommit does an INFO recalling the configured duration
- then StreamThread#commitOne does one INFO per task.
- then NamedCache#flush announces the flushes at DEBUG level.

For `cache.max.bytes.buffering`:
- ThreadCache#maybeEvict does a TRACE (?!?) to announce that the cache is
too big
- then NamedCache#flush announces the flushes at DEBUG level.

So I think it makes the logs not exhaustive enough concerning the writes to
States + Changelog topics +  Output topics (Processor forwards). Thus logs
are easily misinterpreted.

Should I file a JIRA ?

[1] https://linux.die.net/man/1/pv

- Nicolas

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message