[
https://issues.apache.org/jira/browse/GROOVY-12354?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18111963#comment-18111963
]
ASF GitHub Bot commented on GROOVY-12354:
-----------------------------------------
paulk-asert opened a new pull request, #2883:
URL: https://github.com/apache/groovy/pull/2883
…for AOT-linked sites
While a call site is on the reflective cold tier, reflection and Groovy
runtime frames sit between caller and target, so logging frameworks,
StackWalker and stack traces report the wrong caller until the site promotes,
or forever for rarely hit sites. Groovy 5 reported the caller correctly from
the first call, so the on-by-default tier was a regression.
An explicit groovy.indy.cold.reflection setting still wins. When unset, only
AOT-linked sites (GraalVM native image, or groovy.indy.aot.link) use the tier,
where it is the steady state. The JMH A/B forks now enable the tier rather than
disable it, and the invokedynamic docs describe the property, its defaults, and
the logger-side workarounds for JVM and native-image users.
> 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 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)
