[
https://issues.apache.org/jira/browse/GROOVY-12354?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Paul King updated GROOVY-12354:
-------------------------------
Description:
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, 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}
> 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
>
> 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, 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)
