[
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)
