{"record":{"id":"25977b785e9fee90","repo":"apache/cassandra","slug":"out-of-journal-flushes-over-the-past-s-wit","errorCode":null,"errorMessage":"Out of {} {} journal flushes over the past {}s with average duration of {}ms, {} have exceeded the configured flush period by an average of {}ms","messagePattern":"Out of (.+?) (.+?) journal flushes over the past (.+?)s with average duration of (.+?)ms, (.+?) have exceeded the configured flush period by an average of (.+?)ms","errorType":"console","errorClass":null,"httpStatus":null,"severity":"warning","filePath":"src/java/org/apache/cassandra/journal/Flusher.java","lineNumber":382,"sourceCode":"\n        private void processDuration(long startedFlushAt, long finishedFsyncAt)\n        {\n            fsyncCount++;\n            duration += (finishedFsyncAt - startedFlushAt);\n\n            long flushPeriodNanos = flushPeriodNanos();\n            long lag = finishedFsyncAt - (startedFlushAt + flushPeriodNanos);\n            if (flushPeriodNanos <= 0 || lag <= 0)\n                return;\n\n            lagCount++;\n            lagDuration += lag;\n\n            if (firstLaggedAt == Long.MIN_VALUE)\n                firstLaggedAt = finishedFsyncAt;\n\n            boolean logged =\n            noSpamLogger.warn(finishedFsyncAt,\n                              \"Out of {} {} journal flushes over the past {}s with average duration of {}ms, \" +\n                              \"{} have exceeded the configured flush period by an average of {}ms\",\n                              fsyncCount,\n                              journal.name,\n                              format(\"%.2f\", (finishedFsyncAt - firstLaggedAt) * 1e-9d),\n                              format(\"%.2f\", duration * 1e-6d / fsyncCount),\n                              lagCount,\n                              format(\"%.2f\", lagDuration * 1e-6d / lagCount));\n\n            if (logged) // reset metrics for next log statement\n            {\n                firstLaggedAt = Long.MIN_VALUE;\n                fsyncCount = lagCount = 0;\n                duration = lagDuration = 0;\n            }\n        }\n\n        private void afterFSync(long startedAt, long segment, int position)","sourceCodeStart":364,"sourceCodeEnd":400,"githubUrl":"https://github.com/apache/cassandra/blob/88fd0f6a0eaed8943f05ac9e8f947882b8ddc8f1/src/java/org/apache/cassandra/journal/Flusher.java#L364-L400","documentation":"Journal's Flusher tracks fsync durations; after each fsync (afterFSync -> processDuration) it detects flushes that overran the configured flush period. When enough flushes lag, it emits this rate-limited (noSpamLogger) warning summarizing how many of the recent flushes exceeded the period and by how much on average. It signals the journal cannot keep up with its flush interval, typically due to slow disk.","triggerScenarios":"Periodic journal flusher runs where fsync latency pushes average flush duration past the configured flush period; sustained fsync counts with average duration exceeding the target interval trigger the warning once per no-spam window.","commonSituations":"Disk saturation from compaction or other I/O on the same volume; journal and data sharing a slow EBS/network disk; fsync latency spikes; flush period tuned too aggressively for the storage.","solutions":["Check disk latency (iostat -x) for the journal volume; move journal/commitlog to dedicated fast storage.","Reduce concurrent I/O (throttle compaction throughput) competing with fsyncs.","Increase the journal flush period so it matches achievable fsync latency.","Verify the filesystem supports fast fsync (avoid overlays/network mounts).","If the warning is sparse and average lag is small, treat as informational and monitor."],"exampleFix":"// before (cassandra.yaml)\n# flush_period: 1000ms  # fsyncs take ~50ms, unrealistic\n// after\n# flush_period: 10000ms  # headroom above measured avg fsync duration","handlingStrategy":"validation","validationCode":"// before tuning: measure achievable fsync latency on the journal volume\nlong start = System.nanoTime();\ntry (java.io.FileChannel ch = java.io.FileChannel.open(journalDir.resolve(\"f.dat\"), java.nio.file.StandardOpenOption.WRITE)) {\n    ch.force(true);\n}\nlong fsyncMs = (System.nanoTime() - start) / 1_000_000;\nif (fsyncMs > configuredFlushPeriodMs) reconfigureFlushPeriod(fsyncMs * 2);","typeGuard":null,"tryCatchPattern":null,"preventionTips":["Monitor disk utilization and fsync latency (iostat -x, nodetool tpstats) continuously.","Isolate journal/commitlog on a dedicated low-latency volume.","Set flush period with headroom above measured fsync latency.","Throttle compaction and streaming to reduce I/O contention."],"tags":["disk","fsync","performance","journal"],"backgroundTag":"flush-latency-exceeded","analyzedSha":"88fd0f6a0eaed8943f05ac9e8f947882b8ddc8f1","analyzedAt":"2026-09-10T07:29:22.284Z","contentChangedAt":"2026-09-10T07:29:22.284Z","schemaVersion":2},"datasetVersion":"2026-09-17T15:17:12.973Z"}