You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@groovy.apache.org by "Daniel Sun (Jira)" <ji...@apache.org> on 2026/09/06 03:53:00 UTC
[jira] [Resolved] (GROOVY-12354) Indy: investigate making the reflective cold tier opt-in (groovy.indy.cold.reflection) — it hides the real caller from loggers and StackWalker
[ https://issues.apache.org/jira/browse/GROOVY-12354?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Daniel Sun resolved GROOVY-12354.
---------------------------------
Fix Version/s: 6.0.0-RC-2
Resolution: Fixed
> Indy: investigate making the reflective cold tier opt-in (groovy.indy.cold.reflection) — it hides the real caller from loggers and StackWalker
> ----------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: GROOVY-12354
> URL: https://issues.apache.org/jira/browse/GROOVY-12354
> Project: Groovy
> Issue Type: Improvement
> Reporter: Paul King
> Assignee: Paul King
> Priority: Major
> Fix For: 6.0.0-RC-2
>
>
> h2. Summary
> The reflective cold tier for indy dispatch (GROOVY-12137, merged as 3c58690c39 on 2026-07-11, first shipped in 6.0.0-beta-1) is *on by default*. While a call site is cold it dispatches plain instance calls through {{CachedMethod.invokeReflective}} → {{Method.invoke}}, and only promotes to the MethodHandle chain after {{groovy.indy.optimize.threshold}} (1000) reflective hits. Every consumer that inspects the call stack therefore sees Groovy or JDK reflection frames where the caller used to be. Reported on dev@ by Matt (Sep 2026) after Logback started attributing all log statements to {{jdk.internal.reflect.DirectMethodHandleAccessor.invoke}}.
> This issue is to investigate making the tier opt-in for 6.0.0 (or on only under AOT link mode), and to document the flag either way. (GROOVY-12137's summary was already changed from "experimental" to "configurable reflective cold tier" on 2026-09-04.)
> h2. Default value vs PR description
> * The PR/commit text for GROOVY-12137 says "Behind the groovy.indy.cold.reflection flag (default: off)".
> * The code has defaulted to {{true}} since that same merge commit; the Javadoc beside it says "On by default … set -Dgroovy.indy.cold.reflection=false to disable (opt-out)". No later commit touched the line.
> * The flag is documented nowhere: not in the language spec, and not in the 6.0 release notes' System Property Reference table, which has rows for {{groovy.indy.setproperty}}, {{groovy.indy.invalidation.stats}} and {{groovy.indy.aot.link}} but none for {{groovy.indy.cold.reflection}} (checked in the release-notes source, groovy-6.0.adoc). The notes mention the tier only inside the "Dynamic Groovy in GraalVM Native Images (incubating)" section, as the AOT steady state.
> h2. Reproduction (6.0.0-RC-1 candidate, JDK 25)
> A Groovy method {{Svc.work()}} calling a logger, executed 1500 times; JUL and Log4j2 statements executed only at call 1 and call 1500.
> || Observer, called from a Groovy method || flag on, cold site || flag off, or Groovy 5.1.2 ||
> | Logback {{%C.%M:%L}} | {{DirectMethodHandleAccessor.invoke:104}} (JDK 18+; {{NativeMethodAccessorImpl}} on 17) | {{Svc.work:19}} |
> | java.util.logging source class/method | {{org.codehaus.groovy.reflection.CachedMethod.invokeReflective}} | {{Svc.work}} |
> | Log4j2 {{%C.%M:%L}} | {{CachedMethod.invokeReflective:505}} | {{Svc.work:20}} |
> | {{StackWalker.getCallerClass()}} inside a Java library | {{org.codehaus.groovy.reflection.CachedMethod}} | {{Svc}} |
> Observations:
> * JUL and Log4j2 are affected as well as Logback. They use {{StackWalker}}, which hides the JDK reflection frames, but Groovy's own {{CachedMethod.invokeReflective}} frame is not hidden and becomes the reported caller. Registering Groovy packages as "framework packages" in Logback would not be a complete workaround.
> * Promotion is per call site after 1000 reflective hits (measured: call 1000 reflective, call 1001 clean; {{-Dgroovy.indy.optimize.threshold=10}} moves it to call 11). A hot {{log.info}} self-corrects; a {{log.warn}}/{{log.error}} that fires a few times a day reports the wrong location forever. Under AOT link mode sites never promote.
> * The frame users see does not depend on GROOVY-12325: the cold tier always goes through {{CachedMethod.invokeReflective}} → {{Method.invoke}}, so even when the target method is hot via other call sites (and would use the generated trampoline on the MOP path) a cold logging site still reports the JDK reflection frame. Verified with one site called 1500 times and a second site for the same {{Logger.info}} called once.
> * The existing guard ({{ColdReflectiveMethodHandleWrapper.isCallerSensitive}}, {{CachedMethod.isCallerSensitive}}) keeps {{@CallerSensitive}} targets and the serialization cases on the full path, and its Javadoc already notes that promotion "would then change the observed caller mid-run". Logger location and {{StackWalker.getCallerClass()}} in user/library code are ordinary methods, so there is nothing to probe.
> h2. Benchmark impact of the default (from https://apache.github.io/groovy/ gh-pages data, checked 2026-09-05)
> The merge commit added {{*_groovyColdReflect}} variants that run with the flag off in the same JMH job, so every daily run since 2026-07-12 is a paired comparison. Over all 55 runs of the indy suite (ratio ON/OFF, median and range):
> || Benchmark || ON/OFF median || range || reading ||
> | DynamicDispatchColdBench.dynamicMono_groovy n=20000 (us/op) | 1.017 | 0.99–1.07 | ON ~2% slower |
> | DynamicDispatchColdBench.dynamicMono_groovy n=500 (us/op) | 0.998 | 0.97–1.07 | no difference |
> | DynamicDispatchColdBench.dynamicPoly_groovy n=20000 (us/op) | 1.010 | 0.99–1.06 | ON ~1% slower |
> | DynamicDispatchColdBench.dynamicPoly_groovy n=500 (us/op) | 0.998 | 0.98–1.03 | no difference |
> | CallsiteBench.dispatch_1_monomorphic_groovy (ops/ms) | 1.000 | 0.96–1.10 | identical |
> | CallsiteBench.dispatch_3_polymorphic_groovy (ops/ms) | 0.979 | 0.87–1.06 | ON ~2% slower, noisy |
> Deterministic {{:perf:dispatchMetrics}} (512 cold iterations per scenario, so the workload stays on the reflective tier), run locally on the RC-1 parent commit e9375984eb as a 2x2 with the GROOVY-12138 property-write flag that landed in the same window:
> || groovy.indy.cold.reflection || groovy.indy.setproperty || LambdaForms || classes loaded ||
> | on (default) | on (default) | 402 | 3962 |
> | off | on | 419 | 3973 |
> | on | off | 379 | 3938 |
> | off | off | 400 | 3953 |
> So the tier saves ~17–21 LambdaForms (~4%) on this workload. The dashboard's +30 LambdaForms on 2026-07-12 was the sum of GROOVY-12138 (+~21), this tier (−~17) and other commits in the 9d01e177d8..6047948849 window; nothing in the compiler, core or Grails-pattern suites moved in a way attributable to this flag (host calibration benches swung 40–90% in the same three days).
> The PR's measurement ("~2/3 of per-shape LambdaForm cost removed, 1.34–1.40x faster cold dispatch with many cold sites") is not reproduced by any published series; the dashboard workloads have few call-site shapes. There was also experimentation against real Grails applications that reportedly showed a real benefit, but those results do not appear to be recorded anywhere. If they can be found or re-run, they belong here before a decision is made, since a real-app cold-start benefit is the strongest argument for keeping the tier on.
> h2. Options
> # Flip the default to {{false}} for 6.0.0 (matches the PR's stated intent; the tier stays available for native-image work). No measurable cost on any published series.
> # Keep on by default only under AOT link mode (where there is no alternative and sites never promote anyway); opt-in on a normal JVM.
> # Keep on by default, but add a {{groovy.indy.cold.reflection}} row (default {{true}}, {{false}} restores MethodHandle dispatch for cold sites and correct caller frames) to the release notes' System Property Reference, and the caller-location caveat to the native-image section.
> Whichever is chosen, the flag needs documenting, and the PR/commit wording "default: off" should be corrected in the release notes so the record matches the code.
> h2. Reproduction scripts
> {code:title=logtest2.groovy (run with logback-classic, log4j-core on the classpath)}
> class Svc {
> static final log = org.slf4j.LoggerFactory.getLogger(Svc)
> static final jul = java.util.logging.Logger.getLogger('jul')
> static final l4j = org.apache.logging.log4j.LogManager.getLogger(Svc)
> void work(int n) {
> log.info("call $n")
> if (n == 1 || n == 1500) { jul.info("call $n"); l4j.info("call $n") }
> }
> }
> def s = new Svc()
> (1..1500).each { s.work(it) }
> // Logback pattern: 'LOGBACK %C{0}.%M:%L - %msg%n'; Log4j2 pattern: '%C{1}.%M:%L - %msg%n'
> // compare: groovy logtest2.groovy vs JAVA_OPTS=-Dgroovy.indy.cold.reflection=false groovy logtest2.groovy
> {code}
> {code:title=probe3.groovy (finds the promotion point)}
> class Service {
> boolean reflective() {
> def st = new Throwable().stackTrace
> int end = 0
> while (end < st.length && !st[end].className.startsWith('probe3')) end++
> (0..<end).any { st[it].className.contains('reflect') }
> }
> }
> def s = new Service()
> def firstClean = -1; def lastReflective = -1
> for (int n = 1; n <= 3000; n++) { if (s.reflective()) lastReflective = n; else if (firstClean < 0) firstClean = n }
> println "first clean call: $firstClean, last reflective call: $lastReflective" // default: 1001 / 1000
> {code}
> {code:title=CallerLib.java + sw.groovy (StackWalker)}
> public class CallerLib {
> private static final StackWalker SW = StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE);
> public Class<?> whoCalledMe() { return SW.getCallerClass(); }
> }
> // sw.groovy
> class Svc { def lib = new CallerLib(); Class who() { lib.whoCalledMe() } }
> println new Svc().who().name // on: org.codehaus.groovy.reflection.CachedMethod off: Svc
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)