feat: split the SQL log into a performance log and a slow statement log - #521
Merged
Conversation
The kotlin-maven-plugin was declared with extensions=true in storm-ktor, storm-ktor-test and storm-kotlin-spring, which contributes a lifecycle mapping on top of the executions the modules declare: default-compile, default-kapt, default-test-kapt and default-test-compile ran alongside compile, test-kapt and test-compile, so the sources compiled twice and kapt ran over main sources with no annotation processors. default-compile carried no sourceDirs and fell back to src/main/java, which the Ktor modules do not have, and reported the missing directory as an error on every build. storm-kotlin and storm-kotlinx-serialization never set the flag, so this also brings the modules into line. Dokka needed two fixes in the same two modules. Its default source roots are the project's compile roots, which include src/main/java whether it exists or not, so the Kotlin root is now named explicitly. Dokka 2.0 analyses with a Kotlin 2.0 frontend and cannot read the Kotlin 2.3 metadata these modules and their stdlib carry, which filled every build with metadata errors and left the API documentation resolved against nothing; 2.2 reads it. The rest of the framework stays on Dokka 2.0 with its own compiler generation.
The SQL log writes to two loggers that answer different questions, but it was configured as one flat section, so storm.sql-log.enabled read as "turn the SQL log on" while it only ever switched on the summaries. Each log now has its own section, named after the logger it writes to. storm.sql-log.call-site-skip shared by both logs storm.sql-log.performance.* st.orm.sql.perf, what work cost storm.sql-log.slow.* st.orm.sql.slow, which execution did enabled, limit, call-sites, line-width, entry-points and threshold.* move under performance; slow-statement and slow-statement-limit become slow.threshold and slow.limit. call-site-skip stays at the top, since both logs attribute a frame the same way. The Ktor DSL and HOCON keys follow, and the system properties become storm.sql_log.performance.line_width, storm.sql_log.slow.threshold and storm.sql_log.slow.limit. The Spring types follow too: StormPerformanceLogFilter, StormPerformanceLogEntryPointPostProcessor and PerformanceLog. SqlLog.Summary keeps its name, since a summary is what the performance log reports rather than the log itself. Three behavioural changes come with it. The slow statement log takes its threshold from the performance log when it has none of its own. A unit of work that exceeds a duration holds at least one execution, so a statement threshold no lower than the work's can only fire inside work that reports anyway: the derived default names the statement behind a warning instead of adding warnings of its own. Both logs are retunable while the application runs. Every setting either log reports with is read per unit of work, so a replacement takes effect on the next one, and where the actuator is present the stormsqllog endpoint reads and sets both halves. What a threshold should be is a question a degraded deployment answers better than a configuration file written months earlier, and that is the deployment a restart costs the most. Only enabled stays a startup decision: it installs the request filter and the entry-point proxies, which a refreshed context cannot be given. The slow log's per-shape rate limit now covers the executions it has no shape for. A statement whose shape cannot be derived, and every shape past the four thousand tracked, skipped the limit entirely and reported on every slow execution, so the limit stopped applying exactly where the log knew the least and a degraded database could flood it. Those executions share one reporting budget; they still carry no baseline, since there is none.
Codecov Report❌ Patch coverage is 📢 Thoughts on this report? Let us know! |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The SQL log writes to two loggers that answer different questions, but it was configured as one flat section.
storm.sql-log.enabledreads as "turn the SQL log on" while it only ever switched on the summaries, and the slow statement log stayed off with nothing said about it. Each log now has its own section, named after the logger it writes to.The Ktor DSL and HOCON keys follow (
sqlLogPerformance,sqlLogPerformanceLimit,sqlLogSlowThreshold, ...), and the system properties becomestorm.sql_log.performance.line_width,storm.sql_log.slow.thresholdandstorm.sql_log.slow.limit. The Spring types follow too:StormPerformanceLogFilter,StormPerformanceLogEntryPointPostProcessorandPerformanceLog.SqlLog.Summarykeeps its name, since a summary is what the performance log reports rather than the log itself.Three behavioural changes come with the split.
The slow threshold derives from the performance log
storm.sql-log.slow.thresholdunset alongside an enabled performance log followsperformance.threshold.duration. A unit of work that exceeds a duration holds at least one execution, so a statement threshold no lower than the work's can only fire inside work that reports anyway: the derived default names the statement behind a warning instead of adding warnings of its own. An explicit threshold still wins, and with neither set there is no slow log.Both logs are retunable while the application runs
Every setting either log reports with is read per unit of work, so a replacement takes effect on the next one. Where the actuator is on the class path, the
stormsqllogendpoint reads and sets both halves:What a threshold should be is a question a degraded deployment answers better than a configuration file written months earlier, and that is the deployment a restart costs the most. Only
enabledstays a startup decision: it installs the request filter and the entry-point proxies, which a refreshed context cannot be given.spring-boot-actuatoris aprovideddependency behind@ConditionalOnClass, so it costs nothing where the actuator is absent.The slow log's rate limit covers executions with no shape
SlowStatementLogskippedclaim()entirely when a shape had noShapeStats, soslowwas set unconditionally. That happens for a statement whose shape cannot be derived (any element whose processor returns no compilation key) and for every shape past the four thousand tracked, so the per-shape limit stopped applying exactly where the log knew the least, and a degraded database could flood it. Those executions now share one reporting budget; they still carry no baseline, since there is none to carry.Not backward compatible
The old flat keys are removed rather than mapped. A configuration still on them binds to nothing and starts with the performance log off and no message, so this wants a line in the release notes.
Build
Separate commit, unrelated to the log.
kotlin-maven-pluginwas declared withextensions=truein three modules, which contributes a lifecycle mapping on top of the declared executions: sources compiled twice, kapt ran over main sources with no processors, anddefault-compilefell back tosrc/main/javaand reported the missing directory as an error on every build of the Ktor modules. Dokka needed its source root named for the same reason, and Dokka 2.0 cannot read the Kotlin 2.3 metadata those modules carry, which filled their builds with metadata errors; 2.2 reads it.Verification
storm-core2659,storm-spring113,storm-kotlin-spring250,storm-ktor89,storm-ktor-test6, all passing; spotless clean; every Spring and Kotlin dependent module builds. Six new tests cover the derived default, explicit-wins, no-derivation-without-the-performance-log, a limit configured without a threshold, both endpoint paths, and the untracked rate limit.One pre-existing test was made robust rather than left flaky:
testAStreamedReadReportsDatabaseTimeApartFromConsumptionasserts database time under 50 ms absolute, and adding a method to the class reshuffled JUnit's order so it ran cold and measured 83 ms. Its claim is that the two figures are kept apart, not that the database is fast, so the read is warmed before the one that is measured.