From 5b04e775437939d61f021981c02d82d5dd9baea8 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 13:10:59 -0400 Subject: [PATCH 01/11] fix(cost): close RequestCost instrumentation gaps and re-base the price table (#36977) Audited @RequestCost placement against Glowroot production profiles from six tenant instances. The instrumentation was concentrated on the Contentlet API while the traffic was elsewhere: a GraphQL-only customer could saturate a node and accrue almost nothing. Metering gaps closed: - findContentlets(List) - the bulk loader behind every search result (GraphQL, /api/content, /api/es/search, page render). Bypassed find(), so it was entirely uncosted. Now charged per contentlet, cache hit vs DB miss. - Background work no longer discarded. incrementCost returned before the totals when no request was on the thread, so reindexing, scheduled publishing, remote publishing and content indexing were priced correctly and then thrown away. Reported as windowJobTokens / lifetimeJobTokens. - /api/es/search bypassed ES_QUERY via enterprise ESSearchAPIImpl. - /api/vtl/* bypassed VELOCITY_MERGE by calling the engine directly. - #dotParse / #parseContainer were free, so a 30-container page priced as one. - Prerender used its own HttpClient, so HTTP_FETCH never fired. - CONTENT_INDEX, NAV_BUILD and GRAPHQL_QUERY added; CHECKIN/CHECKOUT/COPY/MOVE had prices in the enum that nothing charged. Price table re-based on resource-time, then the DB tier compressed: what is metered is capacity consumed on this node, not wall time. Cache-hit vs miss is priced because customers control caching; statements-per-miss is not, because they cannot. IMAGE_FILTER_TRANSFORM and FILE_METADATA_GENERATE were priced below a cache read and are now at the top of the scale. Reporting keeps its historical range via REQUEST_COST_DENOMINATOR 1 -> 10, and token totals stay integral so a collector parsing them as ints still works. Requires two new ingestor columns before background cost is billed. --- docs/requestcost-placement-analysis.md | 379 ++++++++++++++++++ docs/requestcost-session-summary.md | 197 +++++++++ .../enterprise/priv/ESSearchAPIImpl.java | 3 + .../business/ContentletIndexAPIImpl.java | 3 + .../business/ESContentFactoryImpl.java | 18 + .../business/ESContentletAPIImpl.java | 6 + .../com/dotcms/cost/LeakyTokenBucketImpl.java | 11 +- .../java/com/dotcms/cost/RequestCostApi.java | 14 + .../com/dotcms/cost/RequestCostApiImpl.java | 107 ++++- .../com/dotcms/cost/RequestCostPublisher.java | 2 +- .../com/dotcms/cost/RequestCostSnapshot.java | 22 +- .../java/com/dotcms/cost/RequestPrices.java | 134 +++++-- .../dotcms/graphql/DotGraphQLHttpServlet.java | 3 + .../com/dotcms/http/CircuitBreakerUrl.java | 2 +- .../prerender/PreRenderSEOWebAPIImpl.java | 3 + .../velocity/directive/DotDirective.java | 8 + .../viewtools/navigation/NavTool.java | 3 + .../dotcms/rest/api/v1/vtl/VTLResource.java | 3 + .../business/ContentletFactory.java | 5 + .../dotcms/cost/RequestCostPublisherTest.java | 2 +- .../dotcms/cost/RequestCostSnapshotTest.java | 12 +- 21 files changed, 880 insertions(+), 57 deletions(-) create mode 100644 docs/requestcost-placement-analysis.md create mode 100644 docs/requestcost-session-summary.md diff --git a/docs/requestcost-placement-analysis.md b/docs/requestcost-placement-analysis.md new file mode 100644 index 000000000000..1ffeb7753c37 --- /dev/null +++ b/docs/requestcost-placement-analysis.md @@ -0,0 +1,379 @@ +# RequestCost — profile-driven gap analysis and action list + +Glowroot main-thread profiles, 7-day windows, read 2026-08-07. + +| Tenant | Samples | Shape | Top transactions | +|---|---|---|---| +| Tenant F | 17,706 | traditional site | page renders, `/dA/` binaries | +| Tenant A | 68,378 | write-heavy API | workflow fire 54%, graphql 23%, es/search 16% | +| Tenant B | 12,126 | read-heavy API | graphql 60%, `/api/vtl/*` 31%, page render 7% | +| Tenant C | 8,781 | velocity + remote API | product browse pages | +| Tenant D | 893 | graphql | graphql 54%, es/search 12%, page render 10%, content 20% | +| Tenant E | 53 | — | **ignored — 53 samples is noise** | + +## Headline + +Six instances, six different cost centres. The model's prices are the dominant +cost for exactly one of them. + +| Tenant | Where the time actually goes | Costed? | +|---|---|---| +| Tenant F | filter chain (DB), velocity render, binaries | partly | +| Tenant A | `addContentToIndex` — ~10% of all samples, blocking | **no** | +| Tenant B | prerender park 36%, `NavTool.getNav` 11% | **no** | +| Tenant C | `CircuitBreakerUrl` outbound HTTP ~50% | yes — but was priced 4, now 100 | +| Tenant D | GraphQL execute + transform + relationship N+1 | **no** | + +Standing caveat: a sampled profile gives **time share, not invocation counts**. +It reliably shows where instrumentation is *missing*; it cannot set per-call +prices. Only the cost model itself, once placed, produces the counts you need. + +--- + +# Ranked + +Ordered by (currently-invisible, client-controllable cost made visible) ÷ effort. + +**All items are resolved.** #14 was decided in favour of the **estimate model**, with +the line drawn at what the customer can influence — see §4. + +| # | Do | Effort | Why here | +|---|---|---|---| +| 1 | ✅ Charge `CONTENT_FROM_CACHE` per contentlet + `CONTENT_FROM_DB` per miss in `findContentlets(List)` | 2 lines + 1 API overload | Universal: GraphQL, `/api/content`, `/api/es/search`, page render all bulk-load here. Makes cost scale with **rows returned** — the main lever a client has. §1.1 | +| 2 | ✅ `CONTENT_INDEX` on `addContentToIndex` | 1 annotation + funnel check | ~10% of the largest tenant's samples, blocking, and no indexing price exists at all. §2 | +| 3 | ✅ Reprice `HTTP_FETCH` (4 → 100) | one number | ~50% of Tenant C's samples. Was barely above `VELOCITY_MERGE`. §3 | +| 4 | ✅ Reprice `CONTENT_GET_RELATED` (1 → 10) | one number | Hottest priced constant in API traffic, and it recurses. One `?depth=` bump multiplies work at no cost. §3 | +| 5 | ✅ `HTTP_FETCH` on `PreRenderSEOWebAPIImpl` | 1 annotation | 36.2% of Tenant B parked in `Unsafe.park`; own HttpClient means the existing charge never fires. §1.7 | +| 6 | ✅ `NAV_BUILD` on `NavTool.getNav` | 1 annotation + funnel check | 11% of Tenant B's total samples, DB-blocked, recursive. §2 | +| 7 | ✅ `ES_QUERY` on `enterprise.priv.ESSearchAPIImpl.esSearchRaw` | 1 annotation | `/api/es/search` = 12% Tenant D, 16% Tenant A, currently free. §1.6 | +| 8 | ✅ `VELOCITY_MERGE` on `DotDirective.render` (miss branch) | 1 annotation | Biggest *relative* distortion for velocity tenants — 30 containers price like 1. §1.4 | +| 9 | ✅ `VELOCITY_MERGE` on `VTLResource.processRequest` | 1 annotation | 31% of Tenant B's transactions charge no merge. §1.5 | +| 10 | ✅ `CONTENT_FROM_DB` on **both** `findInDb` variants | 2 annotations | The cache-miss surcharge on the single-contentlet path. Not a delete — the two are not duplicates, see §1.2. | +| 11 | ✅ `find()` charges the `CONTENT_FROM_CACHE` base fee | comment | Correct as-is once the miss surcharge lands in `findInDb`. §1.3 | +| 12 | ✅ Guard the unconditional log concat in `RequestCostApiImpl` | 1 line | Done by the author. §6.4 | +| 13 | ✅ `GRAPHQL_QUERY` on `DotGraphQLHttpServlet.handleRequest` | 1 annotation | ~4% in parse+validate, and the only charge that scales with **query size** rather than rows. §2 | +| 14 | ✅ **Decided: estimate, split on what the customer controls** | design call | Cache-vs-DB is priced (theirs); statements-per-miss is not (ours). `DB_QUERY` retired. §4 | +| 15 | ~~`LANGUAGE_VARIABLE`~~ — **dropped, already metered** | — | The ES query it triggers is charged as `ES_QUERY` on the cache-miss branch. Adding it would double-charge. See below. | +| 16 | ~~per-fetcher `GRAPHQL_FIELD_FETCH`~~ — **dropped** | — | The fetchers resolve content, now charged per row by #1, and parse/validate by #13. Adding it would count the same work twice at a different altitude. | +| — | ✅ Filed as [#36970](https://github.com/dotCMS/core/issues/36970) | — | ~20–25× per request-profile, pure waste. Not a costing item. §7.1 | +| — | ✅ Filed as [#36971](https://github.com/dotCMS/core/issues/36971) | — | One user query per response row. §7.2 | +| — | **Don't** charge the filter chain | — | ~15% of the velocity profile but fixed per request and not client-controllable. §5 | + +Rows 1–4 are where the return is concentrated: they are four small changes that +cover every tenant archetype in the sample. + +# Action list + +## 0. Applied + +16 files, +218/−46. Compiles clean — verified with `javac` against the built +classpath, error count identical to the HEAD baseline. (The full `mvn` build +fails in `dotcms-core-web`'s nx step and `dotCMS/target/classes` is stale +relative to HEAD; both pre-existing and unrelated.) + +**Content-op terminals** (`ESContentletAPIImpl`) — each verified as the method +its overload chain funnels into: + +| Price | Method | Why this one | +|---|---|---| +| `CONTENT_CHECKIN` | `internalCheckin` (private terminal) | 12 `checkin` overloads chain into it | +| `CONTENT_CHECKOUT` | `checkout(String, User, boolean)` | list variants loop over it → per-contentlet | +| `CONTENT_COPY` | 7-arg `copyContentlet(…, ContentType, Host, Folder, …)` | 8 overloads funnel here | +| `CONTENT_MOVE` | 4-arg `move(…, Host, Folder, boolean)` | 3 overloads funnel here | + +Copy calls checkin internally, so a copy costs 25+50=75 — a composite, worth +knowing when reading traces. + +**Per-contentlet content charge** — `ESContentFactoryImpl.findContentlets(List)` +charges `inodes.size()` × `CONTENT_FROM_CACHE` as a base fee, plus +`missingCons.size()` × `CONTENT_FROM_DB` as a cache-miss surcharge. The surcharge +is per missed **row**, not per SQL statement — the 200-row batching is ours, not +the customer's. Uses a new +`incrementCost(Price, Class, String, Object[], int times)` on `RequestCostApi` +(the 4-arg form delegates with `times = 1`; the HTML accounting entry and the log +line report the multiplied cost). + +**New terminals annotated:** + +| Price | Method | File | +|---|---|---| +| `CONTENT_INDEX` (new, 25) | `addContentToIndex(List)` | `ContentletIndexAPIImpl` | +| `NAV_BUILD` (new, 10) | `getNav(Host, String, long, User)` — terminal of 5 overloads | `NavTool` | +| `ES_QUERY` | private `esSearchRaw(JSONObject, …)` — terminal of both public paths | `enterprise.priv.ESSearchAPIImpl` | +| `HTTP_FETCH` | `proxyPrerenderedPageResponse` — the actual HTTP call, not the eligibility check | `PreRenderSEOWebAPIImpl` | +| `VELOCITY_MERGE` | private `evalVelocity` | `VTLResource` | +| `VELOCITY_MERGE` | `DotDirective.render`, imperative, **past** the `getFromCache()` short-circuit | `DotDirective` | + +**The whole price table was re-based on resource-time.** A price is now an +order-of-magnitude estimate of the CPU, heap, or parked-thread time an operation +consumes. Cache reads are the unit; everything is a ratio to that: + +``` + 1 in-memory cache read CONTENT_FROM_CACHE, ES_CACHE, FILE_METADATA_FROM_CACHE + 2 per-item work in memory VELOCITY_BUILD_CONTEXT, BLOCK_EDITOR_HYDRATION + 5 render a template fragment VELOCITY_MERGE + 10 CPU parse/compile, or one DB hop VELOCITY_PARSE, XSLT_PARSE, GRAPHQL_QUERY, CONTENT_FROM_DB, CONTENT_GET_RELATED, NAV_BUILD, … + 25 one ES round trip, multi-qry write ES_QUERY, ES_COUNT, CONTENT_INDEX, CONTENT_MOVE, CONTENT_COPY + 50 heavy CPU + heap, or a write txn IMAGE_FILTER_TRANSFORM, FILE_METADATA_GENERATE, CONTENT_CHECKIN, CONTENT_DELETE +100 one remote HTTP round trip HTTP_FETCH, XML/XSLT_FETCH_AND_PARSE +``` + +**Why a DB query is only 10x a cache read when it is ~1000x the latency:** what +is metered is capacity consumed *on this node*, not wall time. A query parks the +thread and burns the cycles on Postgres. The Velocity-tenant profile bears this +out — template rendering dominates those requests, not DB frames — and at an +earlier `DB_QUERY` of 25 the price table told a story the profile contradicted +(DB 50% of a page render vs. merges 37%). At 10 the same page is merges 59%, DB +31%, ES 10%, which matches. **If a node ever exhausts request threads before CPU, +this reasoning inverts and the DB / ES / HTTP tiers should go back up.** + +The two biggest corrections this forced: `IMAGE_FILTER_TRANSFORM` and +`FILE_METADATA_GENERATE` were priced 2 and 3 — decoding/re-encoding an image and +running Tika over a binary burn a core and a large buffer, so they are 50. + +**Content pricing took three passes to land** — worth recording, because two of +the three looked right at the time: + +1. A full `CONTENT_FROM_DB` per missed row. **Wrong on units:** misses are fetched + in batches of 200, so 1,000 rows priced as 1,000 queries when it is 5. +2. Cache-hit / miss-row / per-batch-query split. **Right on resource-time, wrong + commercially:** charging per batch prices our implementation detail. +3. Base fee per contentlet + surcharge per missed row, no per-statement charge. + **The one that shipped** — see §4 for why the line sits there. + +**Reported tokens stay in their old range, and stay integral.** The larger +internal scale is divided back out on the way to anyone outside the JVM: + +- `REQUEST_COST_DENOMINATOR` default 1.0 → **10.0**, so one reported token ≈ one + DB round trip, which is roughly what a token meant under the old table. +- The `x-dotrequest-cost` header is **rounded** but still formatted `"%.2f"` — it + has always looked like `"23.00"` and has always been a whole number, so neither + the format nor the integrality changes for anything parsing it. +- `windowTokens` / `lifetimeTokens` in the pushed `RequestCostSnapshot` are + rounded for the same reason: the field is typed `double` but has only ever + carried whole numbers, and a collector parsing them as ints would break on a + fractional value. The per-request *averages* are left fractional — they always + were (`sum / count`). + +Worked examples at denominator 10: + +| Request | raw | reported | +|---|---|---| +| page: 30 containers, 8 DB queries, 1 ES query | 255 | 26 | +| the same page plus one remote API call | 355 | 36 | +| workflow fire (checkin + index) | 75 | 8 | +| single image resize | 50 | 5 | +| 1000-row cached GraphQL response | 1010 | 101 | +| the same 1000 rows cold (2/row + 5 batched queries) | 2060 | 206 | + +**Rate-limit defaults scaled with the table** (`LeakyTokenBucketImpl`): +`RATE_LIMIT_REFILL_PER_SECOND` 500 → 5000, `RATE_LIMIT_MAX_BUCKET_SIZE` +10000 → 100000, preserving the old ratio. `RATE_LIMIT_ENABLED` still defaults +false. These knobs are undocumented and unset everywhere, so the defaults are the +only values in play — but note for whenever the limiter is turned on that **the +bucket drains in raw units, not denominated ones**: a limit is expressed on the +Price scale (one remote HTTP call = 100), not on the reported-token scale. + +## 1. Metering holes on prices that already exist (no new constants) + +**1.1 — `ESContentFactoryImpl.findContentlets(List)` is the big one. FIXED.** +This is the bulk loader behind every search result: GraphQL, `/api/content`, +`/api/es/search`, page render. It reads `contentletCache` per inode, then +batch-SELECTs the misses 200 at a time. It was **uncosted**, and it bypasses +`ESContentletAPIImpl.find()` entirely — so the content annotation there never +fired for a search result. A GraphQL query returning 100 contentlets charged +zero for the content. + +Now charged in two parts — base fee for everything asked for, surcharge for the +rows that missed: + +```java +incrementCost(Price.CONTENT_FROM_CACHE, …, inodes.size()); // base +incrementCost(Price.CONTENT_FROM_DB, …, missingCons.size()); // surcharge +``` + +The surcharge is per missed **row**, not per SQL statement — the 200-row batching +is ours, not the customer's. + +Required one new API surface: a count-taking +`incrementCost(Price, Class, String, Object[], int times)` on `RequestCostApi`. +This makes cost scale with **rows returned** — the lever the client actually +controls — and with nothing else. + +**1.2 — the single-contentlet DB path. Now deliberately unpriced.** `CONTENT_FROM_DB` +used to sit on `ContentletFactory.findInDb(String, String variant)`, an **interface +default method**. Java doesn't inherit method annotations and ByteBuddy matches +declared methods, so it only fired for `find(inode, variant)`; the common path +landed on `ESContentFactoryImpl.findInDb(String, boolean)` and charged nothing. + +An early recommendation to "delete the duplicate override" was also wrong: the two +run the same SQL but differ in post-processing — the interface default filters by +`variantId`, the impl honours `ignoreStoryBlock` — so neither can delegate to the +other as written. The duplicated SQL is still a real smell and deserves its own +issue. + +Both now carry `@RequestCost(Price.CONTENT_FROM_DB)` — reaching either method *is* +the cache miss, and `find()` has already charged the base fee, so a warm find +costs 1 and a cold one 11. + +**1.3 — `find()` charges `CONTENT_FROM_CACHE` unconditionally, and that is +correct.** It reads as a bug in isolation, but it is the base fee; the miss +surcharge is added deeper, in `findInDb`. Warm 1, cold 11, without this method +needing to know which happened. + +**1.4 — `#dotParse` / `#parseContainer` are free.** `DotDirective.render` → +`renderTemplate()` → `((SimpleNode) t.getData()).render(...)`, never through the +annotated `VelocityUtil.mergeTemplate`. A page with 30 containers charges the +same `VELOCITY_MERGE` as a page with 1. The velocity profile shows +`ASTDirective.render` nesting 5–6 deep at 7–11% — that nesting *is* the container +tree. `getFromCache()` already short-circuits, so mirror the `cachedIndexCount` +pattern: cheap on hit, full price on miss. + +**1.5 — `/api/vtl/*` merges are free.** `VTLResource.processRequest:552` calls +`VelocityUtil.getEngine().evaluate(...)` directly, not the annotated +`VelocityUtil.eval`. 31% of Tenant B's transactions. + +**1.6 — `/api/es/search` bypasses `ES_QUERY`.** `ESContentResourcePortlet.searchPost` +→ `com.dotcms.enterprise.priv.ESSearchAPIImpl.esSearchRaw` → +`RestHighLevelClient.performRequest`, never touching +`ContentFactoryIndexOperationsES.cachedIndexSearch` where the imperative +`ES_QUERY` charge lives. 12% of Tenant D, 16% of Tenant A. The class is at +`dotCMS/src/enterprise/java/...` and `com.dotcms.*` is in the ByteBuddy +whitelist, so a plain annotation works. + +**1.7 — Prerender holds a request thread for free.** `PreRenderSEOWebAPIImpl` +uses its own `CloseableHttpClient`, not `CircuitBreakerUrl`, so `HTTP_FETCH` +never fires. Tenant B: `SimpleWebInterceptorDelegateImpl.intercept` → +`Unsafe.park` TIMED_WAITING at **36.2%**. Content-dependent (bot UA + eligible +page), so unlike the rest of the filter chain it *is* chargeable. + +## 2. New prices + +| Price | Placement | Evidence | +|---|---|---| +| `CONTENT_INDEX` | `ContentletIndexAPIImpl.addContentToIndex` — 3 overloads (`:2265/:2270/:2325`), find the terminal | Tenant A: `Object.wait0` WAITING at 9.9 / 9.5 / 9.3 / 8.3% ≈ **10% of all samples**. No indexing price exists at all. | +| `GRAPHQL_QUERY` | `DotGraphQLHttpServlet.handleRequest` | Tenant D: `parseInvocationInput` 1.8% + `ParseAndValidate.validate` / `LanguageTraversal.traverseImpl` ~2.5%. Real CPU **before any field is fetched** — this is the only charge that scales with query size rather than row count. | +| `NAV_BUILD` | `NavTool.getNav` — 4 overloads (`:319/:343/:347/:363`), terminal only | Tenant B: → `BrowserAPIImpl.getFolderContentList` → `Net.poll` = **11.4% + 10.3% of all samples**, DB-blocked, recursive via `NavResultHydrated.getChildren`. | +| ~~`LANGUAGE_VARIABLE`~~ | **dropped — already metered** | The profile frames are real (Tenant D: `getLanguageVariable` → `ESContentletAPIImpl.search` → `indexSearch` at 1.0 / 0.8 / 0.7 / 0.6 / 0.4%), but the path is `KeyValueAPIImpl.get` (own cache) → on miss → `indexSearch` → `searchHits` → `internalSearchHits` → `cachedIndexSearch`, which already charges `ES_QUERY` on **its** miss branch. Two cache layers, both already respected. A price here would double-charge. The N+1 shape is still real and is now *visible*: 50 language-variable misses on a page cost 50 × `ES_QUERY`. | + +**Dropped from an earlier draft:** `CONTENT_TRANSFORM` on +`AbstractTransformStrategy.apply`. Once 1.1 charges per row, this is largely +redundant — it scales with the same row count, and it fires per-*strategy* +(several run per contentlet), so it would triple-count. + +**Optional:** per-fetcher `GRAPHQL_FIELD_FETCH` on the 7 data fetchers +(`ContentletDataFetcher`, `ContentMapDataFetcher`, `FileFieldDataFetcher`, +`SiteFieldDataFetcher`, `UserDataFetcher`, `page.PageDataFetcher`, +`page.ContainersDataFetcher`). Only worth it if you want query *depth* priced +separately from rows — 1.1 + `GRAPHQL_QUERY` covers most of it. Note +`ContainersDataFetcher` → `PageRenderUtil.` at 2.9%: a GraphQL page query +runs the full container pipeline. + +## 3. Repricing — the strongest evidence in the set + +- **`HTTP_FETCH` = 4 is far too low.** Tenant C: `CircuitBreakerUrl` → + `ProtocolExec.execute` → `Net.poll` across branches sums to roughly **half of + all samples**. A template makes a handful of these per request while doing many + merges, yet `HTTP_FETCH`(4) sits barely above `VELOCITY_MERGE`(3). +- **`CONTENT_GET_RELATED` = 1 is the cheapest non-free price and the hottest one + in API traffic.** Tenant D: `ContentHelper.addRelationshipsToJSON` **recurses** + (`:537` → `:600` → `addRelatedContentToJsonArray:782` → `toMaps` → transform → …) + at 3.9 / 3.8 / 3.7 / 3.0 / 2.9 / 2.7%, bottoming out in + `RelationshipFactoryImpl.dbRelatedContent` → `DotConnect.loadResult` → poll. + One `?depth=` bump multiplies this without touching the cost. + +## 4. The pricing model — DECIDED + +Two coherent models, and they double-count if combined: + +- **Choke-point** — meter primitives: every SQL statement at + `DotConnect.executeQuery`, every cache miss. Physically accurate. +- **Estimate** — meter customer-visible operations at a published price. + +**Chosen: estimate, with the line drawn at what the customer can influence** — +which is not the same as the API boundary. Two things that look alike sit on +opposite sides: + +| | Whose? | Priced? | +|---|---|---| +| Did this need the database at all? | **theirs** — cacheable containers/pages, TTLs, query shape | **yes** | +| How many statements, what batch size, which plan? | ours | **no** | + +So content is priced in two parts — `CONTENT_FROM_CACHE`(1) as a base fee per +contentlet asked for, plus `CONTENT_FROM_DB`(10) as a surcharge on the ones that +had to be read from Postgres. Warm is 1, cold is 11. There is deliberately **no +generic `DB_QUERY` price**: the 200-row batching in `findContentlets` is our +implementation detail, so the surcharge is per missed *row*, not per statement. + +The same shape already existed elsewhere and is now consistent across the model: + +| Cheap (cache hit) | Expensive (miss) | +|---|---| +| `CONTENT_FROM_CACHE` 1 | `CONTENT_FROM_DB` 10 | +| `ES_CACHE` 1 | `ES_QUERY` 25 / `ES_COUNT` 25 | +| `FILE_METADATA_FROM_CACHE` 1 | `FILE_METADATA_FROM_DB` 10 / `GENERATE` 50 | +| `DotDirective` cache hit — free | `VELOCITY_MERGE` 5 past `getFromCache()` | + +**Hibernate remains a blind spot** either way: +`PermissionBitAPIImpl.getPermissionsByRole` goes through +`net.sf.hibernate.loader.Loader` → `QueryExecutorImpl.execute` (1.7 / 1.8% in +Tenant D), never touching `DotConnect`. + +## 5. Base fee — probably do NOT charge + +`PageMode.get`, `HostWebAPIImpl.getCurrentHost`, `VanityURLFilter`, +`VisitorFilter`, `DefaultAutoLoginWebInterceptor`. DB-blocked and uncosted, +~15% of the velocity profile — but fixed per request and not client-controllable. +Charging them adds a constant and tells you nothing. `RequestCostFilter` is #2 in +`web.xml`, so they stay attributable if you later decide otherwise. + +## 6. Verify before annotating — five ways to silently ship a zero + +1. **Request-thread assumption.** `RequestCostApiImpl.incrementCost` opens with + `HttpServletRequestThreadLocal.INSTANCE.getRequest(); if (request == null) return;` + — charges on any other thread are **dropped silently, no error**. The Tenant D + profile puts the GraphQL fetchers on the servlet thread today, but graphql-java + goes async the moment a fetcher returns a `CompletableFuture` or DataLoader + batching lands. Same question for whatever `addContentToIndex` blocks on. +2. **Funnel rule.** ByteBuddy weaves bytecode, so **self-invocation fires the + advice** (unlike CDI proxies). Annotating two methods in one overload chain + double-charges. Verify the terminal for `addContentToIndex` and `NavTool.getNav` + the way §0 did for checkin/copy/move. +3. **Cache-wrapper trap.** Charge the miss branch, not the wrapper — the + `indexCount` → `cachedIndexCount` pattern. Applies to `LANGUAGE_VARIABLE` and + `DotDirective.render`. +4. **Hot-path cost.** `RequestCostApiImpl` used to build the log string with + unconditional concatenation *before* checking whether debug was on — since + fixed with suppliers. Worth re-checking if the number of charges per request + ever grows by an order of magnitude. +5. **Annotations don't inherit.** §1.2 is the live example — an annotation on an + interface/abstract method does nothing for an override. + +## 7. Bugs the profiles exposed — not costing items + +1. **Config reads round-trip Postgres.** `AppsAPIImpl.getSecrets` / + `hasEnvBackedSecrets` → `Config.getSystemTableValue` → + `SystemTableConfigSource.getValue` → `SystemTableFactoryImpl.find` → DB. + ~20× in Tenant B, ~25× in Tenant D, several times per request from several + interceptors. Should be cached. Worth its own issue. +2. **Per-row owner lookup.** `DefaultTransformStrategy` → + `UserAPIImpl.loadUserById` → `DotConnect.executeQuery` → poll, 1.0% in Tenant D. + One user query per row in the response. +3. **Duplicate SQL.** `ESContentFactoryImpl.findInDb(String, boolean)` re-implements + the interface default's query verbatim (§1.2). + +## 8. Not a bug — closing an earlier claim + +The bare `@RequestCost` in `ImageFilterApiImpl` (`:116`, `:243`) is **not** +mispriced. `IMAGE_FILTER_TRANSFORM` is charged imperatively at +`ImageFilter.overwrite():158`, once per filter that regenerates; the bare +annotations are a deliberate second layer at 1 each. Only the default constant's +*name* (`COSTING_INIT`) is misleading. Same story for `ES_QUERY`, `ES_COUNT` and +`WORKFLOW_ACTION_RUN` — all charged imperatively, invisible to a `@RequestCost` +grep. + +## 9. Calibration loop + +Place §1 and §2, run a week, then per endpoint compare Glowroot's mean response +time against the model's mean cost. Endpoints where that ratio is an outlier are +the mispriced constants. Do not set prices from the profile alone. diff --git a/docs/requestcost-session-summary.md b/docs/requestcost-session-summary.md new file mode 100644 index 000000000000..24ab794abd3b --- /dev/null +++ b/docs/requestcost-session-summary.md @@ -0,0 +1,197 @@ +# RequestCost — instrumentation review and pricing model + +**Status:** implemented, uncommitted, on branch `issue-36947-core-web-cacheable`. +**Companion doc:** [requestcost-placement-analysis.md](requestcost-placement-analysis.md) — the full evidence and the ranked backlog. +**Date:** 2026-08-10. + +--- + +## What this was + +`@RequestCost` exists to score the "heaviness" of a request, token-style, so that +usage can be metered and rate-limited. This session audited **where the annotation +is actually placed** against real production behaviour, using Glowroot main-thread +profiles from six tenant instances (7-day windows), and then reworked the price +table. + +Tenants are anonymised as A–F below. Shapes, not names, are what matter — and the +shapes turned out to be the whole story. + +## The finding that framed everything + +Six production instances, six different cost centres. The model's prices were the +dominant cost for exactly one of them. + +| Tenant | Shape | Where the time actually went | Metered before? | +|---|---|---|---| +| A | write-heavy API | `addContentToIndex` — ~10% of all samples, blocking | **no** | +| B | GraphQL 60% / VTL 31% | prerender park 36%, `NavTool.getNav` 11% | **no** | +| C | Velocity + remote API | `CircuitBreakerUrl` outbound HTTP ~50% | yes, priced 4 | +| D | GraphQL 54% | GraphQL execute, transform, relationship N+1 | **no** | +| F | traditional Velocity | filter chain, render, binaries | partly | +| E | — | 53 samples, discarded as noise | — | + +A GraphQL-only customer could saturate a node and accrue almost nothing. The +instrumentation was concentrated on the Contentlet API; the traffic was not. + +## The decision that matters most + +Midway through, the question surfaced as: **should cost track what the server +actually did, or what the customer asked for?** + +Two coherent models: + +- **Choke-point** — meter primitives (every SQL statement, every cache miss). + Accurate to real resource use, but the customer's bill then moves with *our* + cache hit rate, batch sizes and query plans. +- **Estimate** — meter customer-visible operations at a flat, published price. + Less physically precise, stable and optimisable. + +**We chose estimate — but the line is drawn at what the customer can influence, +not at the API boundary.** Two things that look similar are on opposite sides: + +- **Did this need the database?** — theirs. Customers control caching through + cacheable containers and pages, cache TTLs, and how they shape their queries. + Cached content is priced at a tenth of uncached content, so the optimisation + visibly pays off. +- **How did we ask the database?** — ours. Batch sizes, query plans, how many SQL + statements a miss took. A customer cannot see or change any of it, so there is + deliberately **no generic per-statement `DB_QUERY` price**. + +Content is therefore priced in two parts: `CONTENT_FROM_CACHE` (1) as a base fee +per contentlet asked for, plus `CONTENT_FROM_DB` (10) as a surcharge on the ones +that had to be read from Postgres. One contentlet costs 1 warm and 11 cold; a +thousand cost 1,000 warm and 11,000 cold. + +The same shape already existed for ES queries (`ES_CACHE` 1 / `ES_QUERY` 25) and +file metadata (`FILE_METADATA_FROM_CACHE` 1 / `FROM_DB` 10 / `GENERATE` 50), and +was extended to Velocity directives — `#dotParse` is charged past the +`getFromCache()` short-circuit, so cacheable containers are cheaper than +uncacheable ones. The model is consistent across all four. + +What that looks like, at the default denominator of 10: + +| Scenario | raw | reported | +|---|---|---| +| 1,000 contentlets, all cached | 1,000 | **100** | +| 1,000 contentlets, 90% cached | 2,000 | 200 | +| 1,000 contentlets, all from DB | 11,000 | **1,100** | + +An 11× spread between fully warm and fully cold — large enough that tuning cache +config is worth a customer's time, which is the whole point. + +The reasoning is written into `RequestPrices.Price` so the next person doesn't +"simplify" it away. + +## The price table + +Re-based twice. First onto **resource-time** — a price is an order-of-magnitude +estimate of the CPU, heap or parked-thread time an operation consumes. Then the DB +tier was compressed after a challenge that it was too high: + +``` + 1 in-memory cache read CONTENT_FROM_CACHE, FILE_METADATA_FROM_CACHE, ES_CACHE + 2 per-item work in memory VELOCITY_BUILD_CONTEXT, BLOCK_EDITOR_HYDRATION + 5 render a template fragment VELOCITY_MERGE + 10 CPU parse/compile, or one DB hop VELOCITY_PARSE, XSLT_PARSE, GRAPHQL_QUERY, CONTENT_FROM_DB, CONTENT_GET_RELATED, NAV_BUILD + 25 one ES round trip, or a write ES_QUERY, ES_COUNT, CONTENT_INDEX, CONTENT_MOVE, CONTENT_COPY + 50 heavy CPU + heap, or a write txn IMAGE_FILTER_TRANSFORM, FILE_METADATA_GENERATE, CONTENT_CHECKIN, CONTENT_DELETE +100 one remote HTTP round trip HTTP_FETCH, XML/XSLT_FETCH_AND_PARSE +``` + +**Why a DB query is only 10× a cache read when it is ~1000× the latency:** what is +metered is capacity consumed *on this node*, not wall time. A query parks the +thread and burns the cycles on Postgres. Tenant F's profile bore this out — +template rendering dominated, not DB frames. At a DB price of 25 the table said DB +was 50% of a page render; the profile said otherwise. At 10 it reads merges 59% / +DB 31% / ES 10%, which matches. + +**If a node ever exhausts request threads before CPU, that reasoning inverts** and +the DB/ES/HTTP tiers should go back up. That caveat is in the code. + +Two prices were badly wrong and are worth calling out: `IMAGE_FILTER_TRANSFORM` +was **2** and `FILE_METADATA_GENERATE` was **3**. Decoding and re-encoding an +image, or running Tika over a binary, burns a core and a large buffer — both are +now 50. + +## What shipped + +16 files, ~+220/−50. Compiles clean (verified with `javac` against the built +classpath; error count identical to the HEAD baseline). + +**Placement gaps closed** + +| Price | Where | Why it mattered | +|---|---|---| +| `CONTENT_FROM_CACHE` + `CONTENT_FROM_DB` | `ESContentFactoryImpl.findContentlets(List)` | The bulk loader behind *every* search result — GraphQL, `/api/content`, `/api/es/search`, page render. It bypasses `find()`, so nothing metered it. Base fee per contentlet, surcharge per missed row. | +| `CONTENT_FROM_CACHE` | `ESContentletAPIImpl.find(...)` | Base fee, single-contentlet path | +| `CONTENT_FROM_DB` | both `findInDb` variants | The miss surcharge. Annotations aren't inherited, so the interface default and the impl override each need their own | +| `CONTENT_INDEX` (new) | `ContentletIndexAPIImpl.addContentToIndex(List)` | ~10% of Tenant A's samples, blocking, no price existed | +| `NAV_BUILD` (new) | `NavTool.getNav(Host, String, long, User)` | 11% of Tenant B's samples, DB-blocked, recursive | +| `GRAPHQL_QUERY` (new) | `DotGraphQLHttpServlet.handleRequest` | Parse + validate, before any field is fetched — the only charge that scales with *query size* | +| `ES_QUERY` | `enterprise.priv.ESSearchAPIImpl.esSearchRaw` | `/api/es/search` bypassed the existing charge entirely | +| `HTTP_FETCH` | `PreRenderSEOWebAPIImpl.proxyPrerenderedPageResponse` | Own `HttpClient`, so `CircuitBreakerUrl`'s charge never fired. 36% of Tenant B parked here | +| `VELOCITY_MERGE` | `DotDirective.render` | `#dotParse` / `#parseContainer` were free — a 30-container page priced like a 1-container page | +| `VELOCITY_MERGE` | `VTLResource.evalVelocity` | `/api/vtl/*` bypassed the annotated merge. 31% of Tenant B's transactions | +| `CONTENT_CHECKIN` / `CHECKOUT` / `COPY` / `MOVE` | `ESContentletAPIImpl` terminals | Prices existed in the enum, nothing charged them | + +**API change:** `RequestCostApi` gained +`incrementCost(Price, Class, String, Object[], int times)` so a charge can scale +with result-set size. The 4-arg form delegates with `times = 1`. + +**Reporting:** internal scale grew, so `REQUEST_COST_DENOMINATOR` now defaults to +10 to keep reported tokens in their historical range. The `x-dotrequest-cost` +header and the pushed snapshot totals are **rounded** — both have only ever +carried whole numbers, and a collector parsing them as ints would break on a +fractional value. Per-request averages stay fractional, as they always were. + +**Rate limiting:** `LeakyTokenBucketImpl` defaults scaled with the table +(500→5000 refill, 10000→100000 bucket). Still disabled by default, and confirmed +that nothing overrides these anywhere. + +## Three traps for whoever extends this + +1. **The enum is not an index of what is metered.** Four prices — `ES_QUERY`, + `ES_COUNT`, `WORKFLOW_ACTION_RUN`, `IMAGE_FILTER_TRANSFORM` — are charged with + direct `incrementCost(...)` calls, invisible to a `@RequestCost` grep. This + caused three wrong conclusions during the session before it was caught. Grep + for **both** forms. +2. **ByteBuddy weaves bytecode, so self-invocation fires the advice** — unlike CDI + proxies. `checkin` has 12 overloads chaining into each other; annotating two in + one chain double-charges. Always find the terminal. +3. **Charges are silently dropped off the request thread.** `incrementCost` opens + with `if (request == null) return;`. Anything that moves to a + `CompletableFuture` or a worker pool stops being metered with no error. Relevant + if GraphQL DataLoader batching ever lands. + +Also: annotations are **not inherited**, so a `@RequestCost` on an interface or +abstract method does nothing for an override. This had already made +`CONTENT_FROM_DB` dead on the common single-find path. + +## Open + +- **Deliberately not charged:** the pre-render filter chain (`PageMode.get`, + `HostWebAPIImpl.getCurrentHost`, Vanity/Visitor filters). ~15% of Tenant F's + profile, but fixed per request and not client-controllable — charging it adds a + constant and tells you nothing. +- **Hibernate is a blind spot.** `PermissionBitAPIImpl.getPermissionsByRole` goes + through `net.sf.hibernate.loader.Loader`, never touching `DotConnect`. Any + future DB-level metering would miss permission loading entirely. +- **Nothing is validated against a running instance.** Prices are + order-of-magnitude estimates from sampled time-share; placements were verified by + reading call chains, not by watching a request. The calibration loop — run a + week, compare per-endpoint mean response time against mean cost, investigate + outlier ratios — is what turns these into measured numbers. + +## Bugs filed + +Two performance defects surfaced by the profiles, neither a costing issue: + +- [#36970](https://github.com/dotCMS/core/issues/36970) — Config and App-secret + reads round-trip Postgres on every request, several times per request from + several interceptors. +- [#36971](https://github.com/dotCMS/core/issues/36971) — N+1: one + `loadUserById` per row of every REST/GraphQL response. + +Both are `Team : Platform`. The Technology project field is unset on both — that +needs a `gh auth refresh -s read:project -s project` from someone with the scope. diff --git a/dotCMS/src/enterprise/java/com/dotcms/enterprise/priv/ESSearchAPIImpl.java b/dotCMS/src/enterprise/java/com/dotcms/enterprise/priv/ESSearchAPIImpl.java index a35195ef2d07..51184e072f1c 100644 --- a/dotCMS/src/enterprise/java/com/dotcms/enterprise/priv/ESSearchAPIImpl.java +++ b/dotCMS/src/enterprise/java/com/dotcms/enterprise/priv/ESSearchAPIImpl.java @@ -9,6 +9,8 @@ package com.dotcms.enterprise.priv; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.content.elasticsearch.business.ESContentFactoryImpl; import com.dotcms.content.elasticsearch.business.ESSearchResults; import com.dotcms.content.elasticsearch.business.IndiciesInfo; @@ -204,6 +206,7 @@ public SearchResponse esSearchRelated(final Contentlet contentlet, * @throws DotDataException * An error occurred when retrieving the data. */ + @RequestCost(Price.ES_QUERY) private SearchResponse esSearchRaw(JSONObject jsonObject, boolean live, User user, boolean respectFrontendRoles, int limit, int offset, String sortBy) throws DotSecurityException, DotDataException { diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ContentletIndexAPIImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ContentletIndexAPIImpl.java index 71b311b6e70e..8adbd693e363 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ContentletIndexAPIImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ContentletIndexAPIImpl.java @@ -1,5 +1,7 @@ package com.dotcms.content.elasticsearch.business; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import static com.dotcms.content.index.IndexConfigHelper.haltMigration; import static com.dotcms.content.index.IndexConfigHelper.isMigrationComplete; import static com.dotcms.content.index.IndexConfigHelper.isMigrationNotStarted; @@ -2321,6 +2323,7 @@ public void stopFullReindexation() throws DotDataException { } } + @RequestCost(Price.CONTENT_INDEX) @Override public void addContentToIndex(final List contentToIndex) { diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java index 3208210f690f..eb0deb21761b 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java @@ -42,6 +42,8 @@ import com.dotcms.variant.model.Variant; import com.dotmarketing.beans.Host; import com.dotmarketing.beans.Identifier; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotmarketing.business.APILocator; import com.dotmarketing.business.CacheLocator; import com.dotmarketing.business.DotStateException; @@ -755,6 +757,11 @@ public Optional findInDb(final String inode) { * @param ignoreStoryBlock if it is true then the StoryBlock are not hydrated * @return */ + // The cache-miss surcharge for the single-contentlet path. Reaching this method IS the + // miss - find() has already charged the CONTENT_FROM_CACHE base fee, so a warm find + // costs 1 and a cold one costs 11. Annotations are not inherited, so the @RequestCost on + // ContentletFactory's findInDb default does nothing here; this needs its own. + @RequestCost(Price.CONTENT_FROM_DB) public Optional findInDb(final String inode, final boolean ignoreStoryBlock) { try { if (inode != null) { @@ -1282,10 +1289,21 @@ public List findContentlets(final List inodes) throws DotDat } } + // This is the bulk loader behind every search result (GraphQL, /api/content, + // /api/es/search, page render) and it bypasses ESContentletAPIImpl.find(), so nothing + // else meters it. Base fee per contentlet asked for; the cache misses pay a surcharge + // below. Note the surcharge is per missed ROW, not per SQL statement - the 200-row + // batching is our implementation detail and is deliberately not priced. + APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_CACHE, + ESContentFactoryImpl.class, "findContentlets", new Object[]{}, inodes.size()); + if (conMap.size() != inodes.size()) { final List missingCons = new ArrayList<>( CollectionUtils.subtract(inodes, conMap.keySet())); + APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_DB, + ESContentFactoryImpl.class, "findContentlets", new Object[]{}, missingCons.size()); + final String contentletBase = "select contentlet.*, contentlet_1_.owner from contentlet join inode contentlet_1_ " + " on contentlet_1_.inode = contentlet.inode and contentlet_1_.type = 'contentlet' where contentlet.inode in ('"; diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java index 3efef9b2b695..3f2af49da324 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java @@ -432,6 +432,8 @@ public Contentlet find(final String inode, final User user, final boolean respec * @throws DotDataException * @throws DotSecurityException */ + // Base fee for asking for one contentlet. If the factory misses cache and falls through + // to findInDb, that adds the CONTENT_FROM_DB surcharge - so warm is 1, cold is 11. @RequestCost(Price.CONTENT_FROM_CACHE) @CloseDBIfOpened @Override @@ -575,6 +577,7 @@ private Folder createFolder(final String folderPath, final Contentlet contentlet } @WrapInTransaction + @RequestCost(Price.CONTENT_MOVE) @Override public Contentlet move(final Contentlet contentlet, final User incomingUser, final Host host, final Folder folder, @@ -5718,6 +5721,7 @@ private boolean isWorkflowInProgress(final Contentlet contentlet) { return contentlet.isWorkflowInProgress(); } + @RequestCost(Price.CONTENT_CHECKIN) private Contentlet internalCheckin(Contentlet contentlet, ContentletRelationships contentRelationships, List categories, final User incomingUser, @@ -7100,6 +7104,7 @@ public List checkout(String luceneQuery, User user, boolean respectF } @WrapInTransaction + @RequestCost(Price.CONTENT_CHECKOUT) @Override public Contentlet checkout(final String contentletInode, final User user, final boolean respectFrontendRoles) @@ -9464,6 +9469,7 @@ public Contentlet copyContentlet(final Contentlet sourceContentlet, final Host h } @WrapInTransaction + @RequestCost(Price.CONTENT_COPY) @Override @SuppressWarnings("unchecked") public Contentlet copyContentlet(final Contentlet sourceContentlet, diff --git a/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java b/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java index d30ee3d00f2e..38f9162ce7b9 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java +++ b/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java @@ -66,8 +66,15 @@ public class LeakyTokenBucketImpl implements LeakyTokenBucket { LeakyTokenBucketImpl() { this( Config.getBooleanProperty("RATE_LIMIT_ENABLED", false), - Config.getLongProperty("RATE_LIMIT_REFILL_PER_SECOND", 500), - Config.getLongProperty("RATE_LIMIT_MAX_BUCKET_SIZE", 10000) + // Scaled with the Price table when it was re-based on resource-time + // (see RequestPrices.Price): one DB round trip is 10 units, one remote + // HTTP call is 100, so the old 500/10000 defaults would now throttle a + // handful of requests per second. Ratio to the old defaults is unchanged. + // NOTE: the bucket drains in RAW Price units, not the denominated ones + // reported in the x-dotrequest-cost header - a limit set here is on the + // Price scale (remote HTTP = 100), not the reported-token scale. + Config.getLongProperty("RATE_LIMIT_REFILL_PER_SECOND", 5000), + Config.getLongProperty("RATE_LIMIT_MAX_BUCKET_SIZE", 100000) ); } diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApi.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApi.java index 7849d05f520b..794d14560246 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApi.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApi.java @@ -92,6 +92,20 @@ public static Accounting fromString(String text) { */ void incrementCost(Price price, @NotNull Class clazz, @NotNull String method, @NotNull Object[] args); + /** + * Increments the cost for the current request by {@code price * times}. Used where the work + * scales with the size of a result set (e.g. loading N contentlets) and charging once would + * make a 1-row and a 1000-row response cost the same. + * + * @param price the unit price + * @param clazz calling class + * @param method calling method + * @param args arguments, for the HTML accounting report + * @param times how many units of work were done; values <= 0 are a no-op + */ + void incrementCost(Price price, @NotNull Class clazz, @NotNull String method, + @NotNull Object[] args, int times); + /** * Returns the current cost for the current request. * diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java index 5401e5951c89..0b1198374c86 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java @@ -41,6 +41,13 @@ public class RequestCostApiImpl implements RequestCostApi { final LongAdder requestCostForWindow = new LongAdder(); private final LongAdder requestCountTotal = new LongAdder(); private final LongAdder requestCostTotal = new LongAdder(); + // Cost incurred with no HttpServletRequest on the thread: site-search reindexing, + // scheduled publishing, remote/push publishing, content indexing, embedding generation. + // This is real, billable work - it just has no request to attach to. Before these + // counters existed incrementCost returned early and the cost vanished from the totals + // entirely, so none of it reached the collector. + private final LongAdder jobCostForWindow = new LongAdder(); + private final LongAdder jobCostTotal = new LongAdder(); private final Optional enableForTests; //log an accounting every X seconds private int requestCostTimeWindowSeconds; @@ -62,11 +69,15 @@ public RequestCostApiImpl(Boolean enable) { @PostConstruct public void init() { - this.requestCostTimeWindowSeconds = Config.getIntProperty("REQUEST_COST_TIME_WINDOW_SECONDS", 60); + this.requestCostTimeWindowSeconds = Config.getIntProperty("REQUEST_COST_TIME_WINDOW_SECONDS", 300); // Clamp to >= 1.0 so a misconfigured 0 doesn't produce Infinity/NaN in the snapshot — // those serialize as JSON-invalid literals and break strict parsers on the collector side. + // Default of 10 keeps reported tokens in the range they were before the Price table + // was re-based on resource-time: internally 1 unit is now an in-memory cache read and + // one DB round trip is 10, so dividing by 10 makes a reported token ~= one DB query, + // which is roughly what a token meant under the old table. this.requestCostDenominator = Math.max(1.0d, - Config.getFloatProperty("REQUEST_COST_DENOMINATOR", 1.0f)); + Config.getFloatProperty("REQUEST_COST_DENOMINATOR", 10.0f)); this.scheduler = Executors.newSingleThreadScheduledExecutor( r -> { @@ -97,35 +108,57 @@ private void logRequestCost() { // the lifetime totals — Σ(window) can briefly trail lifetime by a few requests. // Intentional: observational telemetry, atomic snapshot would need a lock. final long totalRequestsForDuration = this.requestCountForWindow.sumThenReset(); - final double totalCostForDuration = this.requestCostForWindow.sumThenReset() / getRequestCostDenominator(); + // Token totals are rounded to whole numbers. They were always integral while the + // denominator was 1, and a collector that has been parsing them as ints would break + // on a fractional value. The per-request averages stay fractional — they always were. + final double requestCostForDuration = Math.round( + this.requestCostForWindow.sumThenReset() / getRequestCostDenominator()); + final double jobCostForDuration = Math.round( + this.jobCostForWindow.sumThenReset() / getRequestCostDenominator()); + + // windowTokens stays request-only, exactly as it has always been. Background work + // is reported alongside it in windowJobTokens rather than folded in, so every + // field keeps a single meaning and windowTokens / windowRequests still agrees with + // windowAvgTokensPerRequest. Total cluster consumption is the sum of the two, and + // the collector is where that sum belongs. + final double totalCostForDuration = requestCostForDuration; + final double costPerRequestForDuration = totalRequestsForDuration == 0 ? 0 - : totalCostForDuration / totalRequestsForDuration; + : requestCostForDuration / totalRequestsForDuration; final long totalRequestsTotal = requestCountTotal.longValue(); - final double totalCostTotal = requestCostTotal.longValue() / getRequestCostDenominator(); + final double requestCostTotalValue = Math.round( + requestCostTotal.longValue() / getRequestCostDenominator()); + final double jobCostTotalValue = Math.round( + jobCostTotal.longValue() / getRequestCostDenominator()); + final double totalCostTotal = requestCostTotalValue; final double costPerRequestTotal = totalRequestsTotal == 0 ? 0 - : totalCostTotal / totalRequestsTotal; + : requestCostTotalValue / totalRequestsTotal; // The log line is throttled on consecutive idle windows so dev consoles stay quiet. // The publisher is NOT throttled — telemetry must emit a point every tick so an idle // cluster and a downed cluster are distinguishable on the receiving side. - final boolean idleWindow = totalRequestsForDuration == 0; + // An idle window is one with no requests AND no background work - a node doing + // nothing but reindexing is not idle and should still log. + final boolean idleWindow = totalRequestsForDuration == 0 && jobCostForDuration == 0; final boolean suppressLog = idleWindow && skipZeroRequests; skipZeroRequests = idleWindow; if (!suppressLog) { Logger.info("REQUEST TOKEN MONITOR >", String.format( - "Last %ds: Reqs: %d, Tokens: %.2f, Avg Tokens: %.2f | Totals: Reqs: %d, Tokens: %.2f, Avg Tokens: %.2f", + "Last %ds: Reqs: %d, Tokens: %.2f, Avg Tokens: %.2f, Job Tokens: %.2f | Totals: Reqs: %d, Tokens: %.2f, Avg Tokens: %.2f, Job Tokens: %.2f", requestCostTimeWindowSeconds, totalRequestsForDuration, totalCostForDuration, costPerRequestForDuration, + jobCostForDuration, totalRequestsTotal, totalCostTotal, - costPerRequestTotal)); + costPerRequestTotal, + jobCostTotalValue)); } if (publisher.isEnabled()) { @@ -141,7 +174,9 @@ private void logRequestCost() { costPerRequestForDuration, totalRequestsTotal, totalCostTotal, - costPerRequestTotal)); + costPerRequestTotal, + jobCostForDuration, + jobCostTotalValue)); } } catch (Exception e) { Logger.warnAndDebug(this.getClass(), "Error logging request tokens:" + e.getMessage(), e); @@ -246,26 +281,50 @@ public void incrementCost(Price price, Method method, Object[] args) { @Override public void incrementCost(Price price, Class clazz, String method, Object[] args) { + incrementCost(price, clazz, method, args, 1); + } + + + @Override + public void incrementCost(Price price, Class clazz, String method, Object[] args, + final int times) { + if (times <= 0) { + return; + } + final int cost = price.price * times; HttpServletRequest request = HttpServletRequestThreadLocal.INSTANCE.getRequest(); if (request == null) { + // Background work - reindex, scheduled publish, push publish, embedding + // generation. It has no request to attach to, but it is still the customer's + // work and still consumes the cluster, so it is counted here rather than + // discarded. Deliberately NOT drained from the rate-limit bucket: a reindex + // must never be able to throttle live traffic into 429s. + jobCostForWindow.add(cost); + jobCostTotal.add(cost); + Logger.debug(RequestCostApiImpl.class, + () -> "REQUESTCOST job cost:" + cost + " , thread:" + Thread.currentThread().getName() + + " , method:" + clazz.getSimpleName() + "." + method); return; } Accounting accounting = resolveAccounting(request); if (accounting == Accounting.HTML) { - Map load = createAccountingEntry(price, clazz, method, args, accounting); + Map load = createAccountingEntry(cost, clazz, method, args, accounting); getAccountList(request).add(load); } - String logMessage = - "<--- REQUESTCOST price:" + price.price + " , method:" + clazz.getSimpleName() + "." + method; // log requests if a fuller accounting is enabled // Note: Cannot use lambdas with inline=true due to synthetic method access issues if (accounting.ordinal() > Accounting.HEADER.ordinal()) { - Logger.info(RequestCostAdvice.class, logMessage); + Logger.info(RequestCostAdvice.class, ()->{ + return "<--- REQUESTCOST price:" + cost + " , method:" + clazz.getSimpleName() + "." + method; + }); } else { - Logger.debug(RequestCostAdvice.class, logMessage); + Logger.debug(RequestCostAdvice.class, ()-> { + return "<--- REQUESTCOST price:" + cost + " , method:" + clazz.getSimpleName() + "." + method; + + }); } int currentCost = getRequestCost(request); if (currentCost == 0) { @@ -273,16 +332,16 @@ public void incrementCost(Price price, Class clazz, String method, Object[] args this.requestCountTotal.increment(); } - request.setAttribute(REQUEST_COST_RUNNING_TOTAL_ATTRIBUTE, currentCost + price.price); - requestCostForWindow.add(price.price); - requestCostTotal.add(price.price); - bucket.drainFromBucket(price.price); + request.setAttribute(REQUEST_COST_RUNNING_TOTAL_ATTRIBUTE, currentCost + cost); + requestCostForWindow.add(cost); + requestCostTotal.add(cost); + bucket.drainFromBucket(cost); } - private Map createAccountingEntry(Price price, Class clazz, String method, + private Map createAccountingEntry(int cost, Class clazz, String method, Object[] args, Accounting accounting) { - return Map.of(COST, price.price, METHOD, method, CLASS, clazz.getCanonicalName(), ARGS, args); + return Map.of(COST, cost, METHOD, method, CLASS, clazz.getCanonicalName(), ARGS, args); } @@ -336,8 +395,12 @@ public void addCostHeader(HttpServletRequest request, HttpServletResponse respon } Integer currentCost = getRequestCost(request); + // Rounded, but still formatted "%.2f": the header has always looked like "23.00" and + // has always been a whole number. Keeping both the format and the integrality means + // nothing downstream has to change when the internal Price scale moves. response.setHeader(REQUEST_COST_HEADER_NAME, - String.format("%.2f", currentCost.doubleValue() / requestCostDenominator)); + String.format("%.2f", + (double) Math.round(currentCost.doubleValue() / requestCostDenominator))); } diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java index 0ee3445f0960..4c5da6eecacf 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java @@ -42,7 +42,7 @@ public boolean isEnabled() { } private String getUrl() { - return Config.getStringProperty("REQUEST_COST_PUSH_URL", null); + return Config.getStringProperty("REQUEST_COST_PUSH_URL", "https://t0.dotcms.dev/api/v1/tokens"); } private String getToken() { diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostSnapshot.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostSnapshot.java index deec0addee02..a1055e49f4ac 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostSnapshot.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostSnapshot.java @@ -23,6 +23,22 @@ public final class RequestCostSnapshot { public final long lifetimeRequests; public final double lifetimeTokens; public final double lifetimeAvgTokensPerRequest; + /** + * Tokens consumed by work that ran outside any HTTP request — site-search reindexing, + * scheduled publishing, remote/push publishing, content indexing, embedding generation. + *

+ * Reported separately from {@code windowTokens} / {@code lifetimeTokens}, + * which remain request-only. Total cluster consumption is the sum of the two. Keeping them + * apart means every field has one meaning: {@code windowTokens} still divides by + * {@code windowRequests} to give {@code windowAvgTokensPerRequest}, which it would not if + * background work were folded in. + *

+ * Before these fields existed this cost was not merely unattributed, it was discarded — + * {@code incrementCost} returned early when no request was on the thread, so reindexing and + * scheduled publishing reached the collector as zero. + */ + public final double windowJobTokens; + public final double lifetimeJobTokens; public RequestCostSnapshot( final String clusterId, @@ -34,7 +50,9 @@ public RequestCostSnapshot( final double windowAvgTokensPerRequest, final long lifetimeRequests, final double lifetimeTokens, - final double lifetimeAvgTokensPerRequest) { + final double lifetimeAvgTokensPerRequest, + final double windowJobTokens, + final double lifetimeJobTokens) { this.clusterId = clusterId; this.serverId = serverId; this.timestamp = timestamp; @@ -45,5 +63,7 @@ public RequestCostSnapshot( this.lifetimeRequests = lifetimeRequests; this.lifetimeTokens = lifetimeTokens; this.lifetimeAvgTokensPerRequest = lifetimeAvgTokensPerRequest; + this.windowJobTokens = windowJobTokens; + this.lifetimeJobTokens = lifetimeJobTokens; } } diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestPrices.java b/dotCMS/src/main/java/com/dotcms/cost/RequestPrices.java index a64d59dcc8a4..1a00dbe1e3d5 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestPrices.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestPrices.java @@ -21,35 +21,117 @@ public enum Price { TEN_THOUSAND(10000), - // PRICED ITEMS - DB_QUERY(1), + /* + * PRICED ITEMS + * + * A price is an order-of-magnitude estimate of the *resource-time* an operation + * consumes — CPU, heap, or a request thread parked on a socket. Reading from an + * in-memory cache is microseconds and is the unit; a remote HTTP call parks the + * thread for hundreds of milliseconds and is priced ~250x that. What matters is + * the ratio between tiers, not the absolute numbers. + * + * 1 in-memory cache read + * 2 per-row hydrate / small alloc + * 5 render a template fragment + * 10 parse/compile CPU-bound, or one DB round trip + * 25 one ES round trip, or a multi-query write + * 50 heavy CPU + heap (image, Tika), or a write transaction + * 100 one remote HTTP round trip + * + * Rule of thumb when adding one: what does this hold a thread (or a core, or a + * chunk of heap) for? Price that, not how important the operation feels. + * + * On why a DB query is only 10x a cache read when it is ~1000x the latency: what + * is being metered is capacity consumed *on this node*, not wall time. A query + * parks the thread and burns the cycles on Postgres, so it costs this JVM far less + * than its latency suggests. The Velocity-tenant profiles bear that out - template + * rendering dominates those requests, not the DB frames. If a node ever runs out + * of request threads before it runs out of CPU, that reasoning inverts and the DB + * and HTTP tiers should go back up. + */ + + // --- tier 1: memory reads. Deliberately near-free; these must not dominate a + // response just because it returned a lot of rows. COSTING_INIT(1), - CONTENT_FROM_CACHE(1), - CONTENT_FROM_DB(3), - CONTENT_GET_RELATED(1), - CONTENT_GET_REFERENCES(2), - CONTENT_MOVE(2), - CONTENT_COPY(2), - CONTENT_DELETE(2), - CONTENT_CHECKOUT(1), - CONTENT_CHECKIN(5), - WORKFLOW_ACTION_RUN(1), - BLOCK_EDITOR_HYDRATION(1), FILE_METADATA_FROM_CACHE(1), - FILE_METADATA_FROM_DB(2), - FILE_METADATA_GENERATE(3), - HTTP_FETCH(4), - VELOCITY_BUILD_CONTEXT(1), - VELOCITY_MERGE(3), - VELOCITY_PARSE(5), - LOGIN_USERNAME_PASS(3), - XML_FETCH_AND_PARSE(5), - XSLT_PARSE(3), - XSLT_FETCH_AND_PARSE(6), - IMAGE_FILTER_TRANSFORM(2), ES_CACHE(1), - ES_QUERY(3), - ES_COUNT(3); + + // --- tier 2: per-item work in memory (allocate, transform, hydrate one object). + VELOCITY_BUILD_CONTEXT(2), + BLOCK_EDITOR_HYDRATION(2), + + /* + * Content is priced per contentlet, in two parts: + * + * CONTENT_FROM_CACHE base fee, charged for every contentlet asked for + * CONTENT_FROM_DB surcharge, added only when we had to read it from Postgres + * + * So one contentlet costs 1 warm and 11 cold; a thousand cost 1,000 warm and 11,000 + * cold. The 10x gap is the point: caching is something customers control - through + * cacheable containers and pages, cache TTLs, and how they shape their queries - so + * it should visibly pay off in their bill. + * + * What is NOT priced is how we service a miss: batch size, query plan, how many SQL + * statements it took. That is our implementation detail and a customer cannot + * optimise against it, which is why there is no generic DB_QUERY price. The line is + * between "did this need the database" (theirs) and "how did we ask the database" + * (ours). + */ + CONTENT_FROM_CACHE(1), + + // --- tier 5-10: CPU-bound work, no I/O. + VELOCITY_MERGE(5), + VELOCITY_PARSE(10), + XSLT_PARSE(10), + // Parsing and validating an incoming GraphQL document, before a single field is + // fetched. This is the only charge that scales with the size of the *query* rather + // than the size of the result, so a deeply nested document is not free. + GRAPHQL_QUERY(10), + + // --- tier 10: one round trip to Postgres. Deliberately only 10x a cache read - + // see the note above on capacity vs latency. + // + // There is intentionally no generic DB_QUERY here. Charging per SQL statement would + // make a customer's cost depend on batch sizes and query plans they cannot see or + // change. Whether the database was needed at all is theirs to influence and IS + // priced; how many statements it took to satisfy is ours and is not. + // + // Surcharge added to CONTENT_FROM_CACHE when a contentlet had to be read from + // Postgres. Charged in ESContentFactoryImpl.findContentlets (per missed row) and on + // both findInDb variants (single-contentlet path). + CONTENT_FROM_DB(10), + FILE_METADATA_FROM_DB(10), + CONTENT_GET_REFERENCES(10), + LOGIN_USERNAME_PASS(10), + CONTENT_CHECKOUT(10), + WORKFLOW_ACTION_RUN(10), + // Recurses through ContentHelper.addRelationshipsToJSON, one DB query per level; + // a single ?depth= bump multiplies the work, so it is priced as the query it is. + CONTENT_GET_RELATED(10), + // Folder-tree walk, DB-blocked and recursive through NavResultHydrated.getChildren. + NAV_BUILD(10), + + // --- tier 25: one round trip to Elasticsearch, or a multi-query write. + ES_QUERY(25), + ES_COUNT(25), + // Blocking ES write on the request thread after every checkin. + CONTENT_INDEX(25), + CONTENT_MOVE(25), + CONTENT_COPY(25), + + // --- tier 50: heavy CPU and heap, or a write transaction spanning many queries. + // Decoding, resizing and re-encoding an image, or running Tika over a binary, + // burns a core and a large buffer for a long time - it is not a "2". + IMAGE_FILTER_TRANSFORM(50), + FILE_METADATA_GENERATE(50), + CONTENT_CHECKIN(50), + CONTENT_DELETE(50), + + // --- tier 100: outbound HTTP. The thread is parked for the whole remote + // round-trip, which is unbounded and outside our control. + HTTP_FETCH(100), + XML_FETCH_AND_PARSE(100), + XSLT_FETCH_AND_PARSE(100); final public int price; diff --git a/dotCMS/src/main/java/com/dotcms/graphql/DotGraphQLHttpServlet.java b/dotCMS/src/main/java/com/dotcms/graphql/DotGraphQLHttpServlet.java index b199368be8fd..baae5c772ed7 100644 --- a/dotCMS/src/main/java/com/dotcms/graphql/DotGraphQLHttpServlet.java +++ b/dotCMS/src/main/java/com/dotcms/graphql/DotGraphQLHttpServlet.java @@ -1,5 +1,7 @@ package com.dotcms.graphql; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rest.api.CorsFilter; import com.dotmarketing.util.Config; import com.dotmarketing.util.Logger; @@ -74,6 +76,7 @@ protected void doOptions(final HttpServletRequest request, final HttpServletResp * @param request * @param response */ + @RequestCost(Price.GRAPHQL_QUERY) protected void handleRequest(HttpServletRequest request, HttpServletResponse response) { corsHeaders.get().forEach(response::setHeader); try { diff --git a/dotCMS/src/main/java/com/dotcms/http/CircuitBreakerUrl.java b/dotCMS/src/main/java/com/dotcms/http/CircuitBreakerUrl.java index ad8c415a0f3f..90f8515b7958 100644 --- a/dotCMS/src/main/java/com/dotcms/http/CircuitBreakerUrl.java +++ b/dotCMS/src/main/java/com/dotcms/http/CircuitBreakerUrl.java @@ -75,7 +75,7 @@ public class CircuitBreakerUrl { private static final Lazy circuitBreakerMaxConnTotal = Lazy.of(() -> Config.getIntProperty("CIRCUIT_BREAKER_MAX_CONN_TOTAL", 100)); private static final Lazy allowAccessToPrivateSubnets = - Lazy.of(() -> Config.getBooleanProperty("ALLOW_ACCESS_TO_PRIVATE_SUBNETS", false)); + Lazy.of(() -> Config.getBooleanProperty("ALLOW_ACCESS_TO_PRIVATE_SUBNETS", false)); private static final CircuitBreakerConnectionControl circuitBreakerConnectionControl = new CircuitBreakerConnectionControl(circuitBreakerMaxConnTotal.get()); diff --git a/dotCMS/src/main/java/com/dotcms/prerender/PreRenderSEOWebAPIImpl.java b/dotCMS/src/main/java/com/dotcms/prerender/PreRenderSEOWebAPIImpl.java index a5d7aebd56ce..4ba38a6c33da 100644 --- a/dotCMS/src/main/java/com/dotcms/prerender/PreRenderSEOWebAPIImpl.java +++ b/dotCMS/src/main/java/com/dotcms/prerender/PreRenderSEOWebAPIImpl.java @@ -1,5 +1,7 @@ package com.dotcms.prerender; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.concurrent.ConditionalSubmitter; import com.dotcms.concurrent.DotConcurrentFactory; import com.dotcms.security.apps.AppSecrets; @@ -256,6 +258,7 @@ private PreRenderEventHandler getEventHandler(final AppConfig appConfig) { return null; } + @RequestCost(Price.HTTP_FETCH) private boolean proxyPrerenderedPageResponse(final HttpServletRequest request, final HttpServletResponse response, final PreRenderEventHandler preRenderEventHandler, final PrerenderConfig prerenderConfig) { diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java index 9391cceb27ad..0eafe4f710ef 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java @@ -1,5 +1,7 @@ package com.dotcms.rendering.velocity.directive; +import com.dotcms.cost.RequestPrices.Price; +import com.dotmarketing.business.APILocator; import java.io.IOException; import java.io.StringWriter; import java.io.Writer; @@ -117,6 +119,12 @@ final public boolean render(InternalContextAdapter context, Writer writer, Node } Template t = loadTemplate(context, templatePath); + // Charged here, past the getFromCache() short-circuit above, so a directive served from + // cache stays cheap. Without this every #dotParse/#parseContainer on a page is free and + // a 30-container page costs the same as a 1-container page. + APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, DotDirective.class, + "render", new Object[]{templatePath}); + final Writer innerWriter = new StringWriter(); final boolean result = this.renderTemplate(context, innerWriter, t, templatePath); this.afterRender(innerWriter.toString(), arguments, context); diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/viewtools/navigation/NavTool.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/viewtools/navigation/NavTool.java index 59d0b1d2fbff..ecd895463561 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/viewtools/navigation/NavTool.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/viewtools/navigation/NavTool.java @@ -1,6 +1,8 @@ package com.dotcms.rendering.velocity.viewtools.navigation; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rest.api.v1.browsertree.BrowserTreeHelper; import com.dotmarketing.beans.Host; import com.dotmarketing.beans.Identifier; @@ -86,6 +88,7 @@ protected void setItemLinkValues(NavResult nav,Link itemLink, List ch children.add(nav); } + @RequestCost(Price.NAV_BUILD) protected NavResultHydrated getNav(final Host host, String path, final long languageId, final User systemUserParam) throws DotDataException, DotSecurityException { diff --git a/dotCMS/src/main/java/com/dotcms/rest/api/v1/vtl/VTLResource.java b/dotCMS/src/main/java/com/dotcms/rest/api/v1/vtl/VTLResource.java index 02d1ab9d8eae..71dc33c83089 100644 --- a/dotCMS/src/main/java/com/dotcms/rest/api/v1/vtl/VTLResource.java +++ b/dotCMS/src/main/java/com/dotcms/rest/api/v1/vtl/VTLResource.java @@ -1,5 +1,7 @@ package com.dotcms.rest.api.v1.vtl; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.api.vtl.model.DotJSON; import com.dotcms.cache.DotJSONCache; import com.dotcms.cache.DotJSONCacheFactory; @@ -538,6 +540,7 @@ private Response processRequest(final HttpServletRequest request, final HttpServ } } + @RequestCost(Price.VELOCITY_MERGE) private Response evalVelocity(final HttpServletRequest request, final HttpServletResponse response, final Reader velocityReader, final Map contextParams, final User user, final DotJSONCache cache) diff --git a/dotCMS/src/main/java/com/dotmarketing/portlets/contentlet/business/ContentletFactory.java b/dotCMS/src/main/java/com/dotmarketing/portlets/contentlet/business/ContentletFactory.java index a1df0f0059d3..1a61d9ad9d26 100644 --- a/dotCMS/src/main/java/com/dotmarketing/portlets/contentlet/business/ContentletFactory.java +++ b/dotCMS/src/main/java/com/dotmarketing/portlets/contentlet/business/ContentletFactory.java @@ -70,6 +70,11 @@ public interface ContentletFactory { * @param variant the variant ID to filter the contentlet from the database results * @return an {@code Optional} containing the contentlet if found, or an empty {@code Optional} if not found */ + // The cache-miss surcharge for the single-contentlet path - reaching this method IS the + // miss. Only fires for find(inode, variant); the other paths land on + // ESContentFactoryImpl.findInDb(String, boolean), which carries its own copy of both the + // SQL and this annotation. (The two differ: this one filters by variantId, that one + // honours ignoreStoryBlock, so neither can delegate to the other as written.) @RequestCost(Price.CONTENT_FROM_DB) default Optional findInDb(final String inode, final String variant) { try { diff --git a/dotCMS/src/test/java/com/dotcms/cost/RequestCostPublisherTest.java b/dotCMS/src/test/java/com/dotcms/cost/RequestCostPublisherTest.java index fde57fb008de..2c5f3ba0e4d8 100644 --- a/dotCMS/src/test/java/com/dotcms/cost/RequestCostPublisherTest.java +++ b/dotCMS/src/test/java/com/dotcms/cost/RequestCostPublisherTest.java @@ -31,7 +31,7 @@ public void clearConfig() { private RequestCostSnapshot anySnapshot() { return new RequestCostSnapshot( "c", "e", "2026-05-19T00:00:00Z", - 60, 0L, 0d, 0d, 0L, 0d, 0d); + 60, 0L, 0d, 0d, 0L, 0d, 0d, 0d, 0d); } @Test diff --git a/dotCMS/src/test/java/com/dotcms/cost/RequestCostSnapshotTest.java b/dotCMS/src/test/java/com/dotcms/cost/RequestCostSnapshotTest.java index 873e60e6440a..68904feab62d 100644 --- a/dotCMS/src/test/java/com/dotcms/cost/RequestCostSnapshotTest.java +++ b/dotCMS/src/test/java/com/dotcms/cost/RequestCostSnapshotTest.java @@ -28,7 +28,9 @@ private RequestCostSnapshot sample() { 4.6d, 999_999L, 12_345_678.25d, - 12.35d); + 12.35d, + 42.5d, + 86_400.75d); } @Test @@ -47,6 +49,8 @@ public void test_serialization_includesAllExpectedFields() throws Exception { assertTrue("missing lifetimeRequests", json.has("lifetimeRequests")); assertTrue("missing lifetimeTokens", json.has("lifetimeTokens")); assertTrue("missing lifetimeAvgTokensPerRequest", json.has("lifetimeAvgTokensPerRequest")); + assertTrue("missing windowJobTokens", json.has("windowJobTokens")); + assertTrue("missing lifetimeJobTokens", json.has("lifetimeJobTokens")); } @Test @@ -65,15 +69,17 @@ public void test_serialization_preservesValues() throws Exception { assertEquals(999_999L, json.get("lifetimeRequests").asLong()); assertEquals(12_345_678.25d, json.get("lifetimeTokens").asDouble(), 0.0001d); assertEquals(12.35d, json.get("lifetimeAvgTokensPerRequest").asDouble(), 0.0001d); + assertEquals(42.5d, json.get("windowJobTokens").asDouble(), 0.0001d); + assertEquals(86_400.75d, json.get("lifetimeJobTokens").asDouble(), 0.0001d); } @Test - public void test_serialization_emitsExactlyTenFields() throws Exception { + public void test_serialization_emitsExactlyTwelveFields() throws Exception { // When final JsonNode json = MAPPER.readTree(MAPPER.writeValueAsString(sample())); // Then — guard against accidental leakage of internal fields if someone adds private // helpers later without updating the @JsonAutoDetect visibility - assertEquals("unexpected fields on the wire", 10, json.size()); + assertEquals("unexpected fields on the wire", 12, json.size()); } } From 268359583fcf687cefec6be3ac10b5f78575a967 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 13:21:29 -0400 Subject: [PATCH 02/11] fix(cost): charge VELOCITY_MERGE for the page's own template merge (#36977) Velocity rendering was not metered anywhere on the page path. All three mode handlers call Template.merge() directly rather than an annotated VelocityUtil method, so neither the page nor its nested directives charged a merge - the annotated VelocityUtil.merge/mergeTemplate/eval only ever fired for AI prompt evaluation and SAML relay state. Charged at the merge itself rather than on serve(): - LiveMode: on writePage(), which the two page-cache hit paths return before reaching - so a cached page correctly pays no merge. - Edit/Preview: immediately before the merge call. serve() also does permission checks and context building, and would have billed a merge that never ran. Nested #dotParse / #parseContainer continue to charge separately in DotDirective.render, past its own cache short-circuit. --- .../rendering/velocity/servlet/VelocityEditMode.java | 6 ++++++ .../rendering/velocity/servlet/VelocityLiveMode.java | 7 +++++++ .../rendering/velocity/servlet/VelocityPreviewMode.java | 6 ++++++ 3 files changed, 19 insertions(+) diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java index 2f59ece0ecb1..4a7443c70866 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java @@ -1,5 +1,6 @@ package com.dotcms.rendering.velocity.servlet; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rendering.velocity.events.PreviewEditParseErrorException; import com.dotcms.rendering.velocity.services.PageRenderUtil; import com.dotcms.rendering.velocity.util.VelocityUtil; @@ -62,6 +63,11 @@ public void serve(final OutputStream out) throws DotDataException, IOException, try(final Writer outStr = new BufferedWriter(new OutputStreamWriter(out))){ + // Charged at the merge itself, not on serve(): serve() also does permission + // checks and context building, and would bill a merge that never happened. + // Nested #dotParse / #parseContainer charge separately in DotDirective.render. + APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, + VelocityEditMode.class, "serve", new Object[]{}); this.getTemplate(htmlPage, mode).merge(context, outStr); } catch (PreviewEditParseErrorException e) { this.processException(user, htmlPage.getName(), e); diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityLiveMode.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityLiveMode.java index c3d0a7bec477..54ea180384db 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityLiveMode.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityLiveMode.java @@ -1,5 +1,7 @@ package com.dotcms.rendering.velocity.servlet; +import com.dotcms.cost.RequestCost; +import com.dotcms.cost.RequestPrices.Price; import static com.dotmarketing.filters.Constants.VANITY_URL_OBJECT; import com.dotcms.api.web.HttpServletRequestThreadLocal; @@ -265,6 +267,11 @@ PageCacheParameters buildCacheParameters(final long langId, final IHTMLPage html * @param out * @param htmlPage */ + // The page's own template merge. The three call sites above are mutually exclusive + // branches, so this charges exactly once per render - and notably NOT at all when the + // page is served from the page cache, which never reaches here. Nested #dotParse / + // #parseContainer directives charge separately in DotDirective.render. + @RequestCost(Price.VELOCITY_MERGE) private void writePage(final Writer out, final IHTMLPage htmlPage) { final Context context = VelocityUtil.getInstance().getContext(request, response); this.getTemplate(htmlPage, mode).merge(context, out); diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java index ab31cced2273..9411bcd5c2a7 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java @@ -1,5 +1,6 @@ package com.dotcms.rendering.velocity.servlet; +import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rendering.velocity.events.PreviewEditParseErrorException; import com.dotcms.rendering.velocity.services.PageRenderUtil; import com.dotcms.rendering.velocity.util.VelocityUtil; @@ -69,6 +70,11 @@ public void serve(final OutputStream out) throws DotDataException, IOException, request.setAttribute("velocityContext", context); try(final Writer outStr = new BufferedWriter(new OutputStreamWriter(out))){ + // Charged at the merge itself, not on serve(): serve() also does permission + // checks and context building, and would bill a merge that never happened. + // Nested #dotParse / #parseContainer charge separately in DotDirective.render. + APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, + VelocityPreviewMode.class, "serve", new Object[]{}); this.getTemplate(htmlPage, mode).merge(context, outStr); } catch (PreviewEditParseErrorException e) { this.processException(user, htmlPage.getName(), e); From 23e48c6046a89c903c6b6aaa61f8357cac06a1db Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 13:50:58 -0400 Subject: [PATCH 03/11] perf(content): collect cache misses in the existing loop in findContentlets (#36977) The cache lookup already visits every inode and already knows which ones missed, but the misses were re-derived afterwards with CollectionUtils.subtract(inodes, conMap.keySet()) - which builds a HashBag of the hit keys, walks the inodes against it, and returns a list that was then copied into a second ArrayList. Two passes and three allocations to recompute something the first loop knew. Also fixes a latent duplicate-handling wart: subtract has multiset semantics, so a repeated inode that WAS in cache would fall out of the bag on its second occurrence and be queried from the database anyway. Filtering on the cache result cannot do that. Behaviour is otherwise identical for the normal case where an inode maps to a contentlet with the same inode. --- .../business/ESContentFactoryImpl.java | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java index eb0deb21761b..fdd482c3bbd5 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java @@ -117,7 +117,6 @@ import java.util.Optional; import java.util.Set; import java.util.stream.Collectors; -import org.apache.commons.collections.CollectionUtils; import org.apache.commons.lang.StringUtils; /** @@ -1281,11 +1280,19 @@ public Contentlet findContentletForLanguage(long languageId, Identifier identifi @Override public List findContentlets(final List inodes) throws DotDataException { + // Single pass: the cache lookup already knows which inodes missed, so collect them here + // rather than re-deriving the difference afterwards. CollectionUtils.subtract built a + // HashBag of the hit keys, walked the inodes against it and returned a list that was then + // copied into a second list - three allocations and an extra pass to recompute something + // this loop already knew. final HashMap conMap = new HashMap<>(); - for (String i : inodes) { + final List missingCons = new ArrayList<>(); + for (final String i : inodes) { final Contentlet contentlet = contentletCache.get(i); if (contentlet != null && InodeUtils.isSet(contentlet.getInode())) { conMap.put(contentlet.getInode(), processCachedContentlet(contentlet)); + } else { + missingCons.add(i); } } @@ -1297,10 +1304,7 @@ public List findContentlets(final List inodes) throws DotDat APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_CACHE, ESContentFactoryImpl.class, "findContentlets", new Object[]{}, inodes.size()); - if (conMap.size() != inodes.size()) { - final List missingCons = new ArrayList<>( - CollectionUtils.subtract(inodes, conMap.keySet())); - + if (!missingCons.isEmpty()) { APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_DB, ESContentFactoryImpl.class, "findContentlets", new Object[]{}, missingCons.size()); From 876c4c0bb655cbf7468ff1de4358ad8f0fd71843 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 14:18:31 -0400 Subject: [PATCH 04/11] fix(cost): drop the hardcoded REQUEST_COST_PUSH_URL default (#36977) Reverts the push URL default to null. isEnabled() gates on url AND token, so a default URL could not activate the publisher on its own - but it meant anyone who set only REQUEST_COST_PUSH_TOKEN would silently start posting usage data to a dotcms.dev endpoint they never named. The collector has to be opted into explicitly. The collection interval default stays at 300s (up from 60s): a five-minute window is enough resolution for billing and cuts the push volume fivefold. --- dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java index 4c5da6eecacf..0ee3445f0960 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostPublisher.java @@ -42,7 +42,7 @@ public boolean isEnabled() { } private String getUrl() { - return Config.getStringProperty("REQUEST_COST_PUSH_URL", "https://t0.dotcms.dev/api/v1/tokens"); + return Config.getStringProperty("REQUEST_COST_PUSH_URL", null); } private String getToken() { From b67dee1f6373b98c20d8458bff2a40bb4ab5b392 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 14:47:30 -0400 Subject: [PATCH 05/11] =?UTF-8?q?fix(cost):=20address=20review=20=E2=80=94?= =?UTF-8?q?=20guard=20direct=20charges,=20floor=20the=20header,=20document?= =?UTF-8?q?=20stacking=20(#36977)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three findings from the automated review, all valid. 1. The four direct incrementCost(..) calls ran unguarded on page-render and content-load paths. The annotation path is protected - RequestCostAdvice.enter is @Advice.OnMethodEnter(suppress = Throwable.class) - so a failure in the cost API can never break the metered method there. The direct calls had no such protection: a transient locator or init failure would have propagated out of DotDirective.render and ESContentFactoryImpl.findContentlets and broken the page or the search result. Metering must never take down serving. Routed all four through RequestCostHandler, which already wraps exactly this for the advice and CDI paths, rather than scattering try/catch. 2. The x-dotrequest-cost header rounded to "0.00" for any request costing less than half the denominator - at the default of 10, every request reading a single warm contentlet. A request that did real work reported as free. Now floored at 1 whenever the raw cost is non-zero; only a genuinely zero-cost request reports 0.00. Window and lifetime totals are unaffected, they sum raw units and divide once. 3. CONTENT_MOVE and CONTENT_COPY are not terminals and stack with CHECKIN and INDEX. That is deliberate - a copy really does check in each version and a move really does reindex - and is not the double-charge trap, which is about one operation counted twice rather than two operations each counted once. Documented on both so a future reader does not "fix" it. --- .../interceptor/RequestCostHandler.java | 36 +++++++++++++++++++ .../business/ESContentFactoryImpl.java | 5 +-- .../business/ESContentletAPIImpl.java | 6 ++++ .../com/dotcms/cost/RequestCostApiImpl.java | 13 +++++-- .../velocity/directive/DotDirective.java | 3 +- .../velocity/servlet/VelocityEditMode.java | 3 +- .../velocity/servlet/VelocityPreviewMode.java | 3 +- 7 files changed, 61 insertions(+), 8 deletions(-) diff --git a/dotCMS/src/main/java/com/dotcms/business/interceptor/RequestCostHandler.java b/dotCMS/src/main/java/com/dotcms/business/interceptor/RequestCostHandler.java index 04a8a4a3b25c..4fa51da1803e 100644 --- a/dotCMS/src/main/java/com/dotcms/business/interceptor/RequestCostHandler.java +++ b/dotCMS/src/main/java/com/dotcms/business/interceptor/RequestCostHandler.java @@ -32,4 +32,40 @@ public static void incrementCost(final Price price, final Method method, "Error in RequestCostHandler.incrementCost(): " + t.getMessage(), t); } } + + /** + * Increments the request cost by {@code price * times} from a call site that charges + * directly rather than through the {@code @RequestCost} annotation. + *

+ * Use this rather than calling {@code APILocator.getRequestCostAPI().incrementCost(..)} + * inline. The annotation path is protected — {@code RequestCostAdvice.enter} is declared + * {@code @Advice.OnMethodEnter(suppress = Throwable.class)} — so a failure in the cost API + * can never break the method being metered. A direct call has no such protection, and + * these charge points sit on page rendering and content loading: metering must never be + * able to take down serving. + * + * @param price the unit price + * @param clazz calling class + * @param method calling method + * @param args arguments, for the HTML accounting report + * @param times how many units of work were done + */ + public static void incrementCost(final Price price, final Class clazz, final String method, + final Object[] args, final int times) { + try { + APILocator.getRequestCostAPI().incrementCost(price, clazz, method, args, times); + } catch (Throwable t) { + Logger.warnAndDebug(RequestCostHandler.class, + "Error in RequestCostHandler.incrementCost(): " + t.getMessage(), t); + } + } + + /** + * Convenience overload charging a single unit. See + * {@link #incrementCost(Price, Class, String, Object[], int)}. + */ + public static void incrementCost(final Price price, final Class clazz, final String method, + final Object[] args) { + incrementCost(price, clazz, method, args, 1); + } } \ No newline at end of file diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java index fdd482c3bbd5..93ce40ea0f23 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java @@ -42,6 +42,7 @@ import com.dotcms.variant.model.Variant; import com.dotmarketing.beans.Host; import com.dotmarketing.beans.Identifier; +import com.dotcms.business.interceptor.RequestCostHandler; import com.dotcms.cost.RequestCost; import com.dotcms.cost.RequestPrices.Price; import com.dotmarketing.business.APILocator; @@ -1301,11 +1302,11 @@ public List findContentlets(final List inodes) throws DotDat // else meters it. Base fee per contentlet asked for; the cache misses pay a surcharge // below. Note the surcharge is per missed ROW, not per SQL statement - the 200-row // batching is our implementation detail and is deliberately not priced. - APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_CACHE, + RequestCostHandler.incrementCost(Price.CONTENT_FROM_CACHE, ESContentFactoryImpl.class, "findContentlets", new Object[]{}, inodes.size()); if (!missingCons.isEmpty()) { - APILocator.getRequestCostAPI().incrementCost(Price.CONTENT_FROM_DB, + RequestCostHandler.incrementCost(Price.CONTENT_FROM_DB, ESContentFactoryImpl.class, "findContentlets", new Object[]{}, missingCons.size()); final String contentletBase = diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java index 3f2af49da324..470b52bf34ca 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentletAPIImpl.java @@ -577,6 +577,12 @@ private Folder createFolder(final String folderPath, final Contentlet contentlet } @WrapInTransaction + // Deliberately NOT a terminal, and the stacking is intended: move() calls + // indexAPI.addContentToIndex(..) below, which reaches the annotated + // addContentToIndex(List) and adds CONTENT_INDEX on top of this CONTENT_MOVE. A move + // really does reindex, so it really should cost both. This is not the "annotating two + // methods in one chain double-charges" trap - that is about one operation being counted + // twice, this is two distinct operations each counted once. Do not remove either. @RequestCost(Price.CONTENT_MOVE) @Override public Contentlet move(final Contentlet contentlet, final User incomingUser, final Host host, diff --git a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java index 0b1198374c86..3783c8c0ae51 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java +++ b/dotCMS/src/main/java/com/dotcms/cost/RequestCostApiImpl.java @@ -398,9 +398,16 @@ public void addCostHeader(HttpServletRequest request, HttpServletResponse respon // Rounded, but still formatted "%.2f": the header has always looked like "23.00" and // has always been a whole number. Keeping both the format and the integrality means // nothing downstream has to change when the internal Price scale moves. - response.setHeader(REQUEST_COST_HEADER_NAME, - String.format("%.2f", - (double) Math.round(currentCost.doubleValue() / requestCostDenominator))); + // + // Floored at 1 when the request cost anything at all. Without this, any request under + // half the denominator rounds to "0.00" - at the default of 10 that is every request + // reading a single warm contentlet - and a request that did real work would report as + // free. Only a genuinely zero-cost request reports 0.00. Window and lifetime totals + // are unaffected: they sum raw units and divide once, so no resolution is lost there. + final long reported = currentCost > 0 + ? Math.max(1L, Math.round(currentCost.doubleValue() / requestCostDenominator)) + : 0L; + response.setHeader(REQUEST_COST_HEADER_NAME, String.format("%.2f", (double) reported)); } diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java index 0eafe4f710ef..df7a04311449 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/directive/DotDirective.java @@ -1,5 +1,6 @@ package com.dotcms.rendering.velocity.directive; +import com.dotcms.business.interceptor.RequestCostHandler; import com.dotcms.cost.RequestPrices.Price; import com.dotmarketing.business.APILocator; import java.io.IOException; @@ -122,7 +123,7 @@ final public boolean render(InternalContextAdapter context, Writer writer, Node // Charged here, past the getFromCache() short-circuit above, so a directive served from // cache stays cheap. Without this every #dotParse/#parseContainer on a page is free and // a 30-container page costs the same as a 1-container page. - APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, DotDirective.class, + RequestCostHandler.incrementCost(Price.VELOCITY_MERGE, DotDirective.class, "render", new Object[]{templatePath}); final Writer innerWriter = new StringWriter(); diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java index 4a7443c70866..c2e85f8169d4 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityEditMode.java @@ -1,5 +1,6 @@ package com.dotcms.rendering.velocity.servlet; +import com.dotcms.business.interceptor.RequestCostHandler; import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rendering.velocity.events.PreviewEditParseErrorException; import com.dotcms.rendering.velocity.services.PageRenderUtil; @@ -66,7 +67,7 @@ public void serve(final OutputStream out) throws DotDataException, IOException, // Charged at the merge itself, not on serve(): serve() also does permission // checks and context building, and would bill a merge that never happened. // Nested #dotParse / #parseContainer charge separately in DotDirective.render. - APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, + RequestCostHandler.incrementCost(Price.VELOCITY_MERGE, VelocityEditMode.class, "serve", new Object[]{}); this.getTemplate(htmlPage, mode).merge(context, outStr); } catch (PreviewEditParseErrorException e) { diff --git a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java index 9411bcd5c2a7..af9a6e567d49 100644 --- a/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java +++ b/dotCMS/src/main/java/com/dotcms/rendering/velocity/servlet/VelocityPreviewMode.java @@ -1,5 +1,6 @@ package com.dotcms.rendering.velocity.servlet; +import com.dotcms.business.interceptor.RequestCostHandler; import com.dotcms.cost.RequestPrices.Price; import com.dotcms.rendering.velocity.events.PreviewEditParseErrorException; import com.dotcms.rendering.velocity.services.PageRenderUtil; @@ -73,7 +74,7 @@ public void serve(final OutputStream out) throws DotDataException, IOException, // Charged at the merge itself, not on serve(): serve() also does permission // checks and context building, and would bill a merge that never happened. // Nested #dotParse / #parseContainer charge separately in DotDirective.render. - APILocator.getRequestCostAPI().incrementCost(Price.VELOCITY_MERGE, + RequestCostHandler.incrementCost(Price.VELOCITY_MERGE, VelocityPreviewMode.class, "serve", new Object[]{}); this.getTemplate(htmlPage, mode).merge(context, outStr); } catch (PreviewEditParseErrorException e) { From 1b7b245841508d27e11288f18676a7960d8da2fe Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 20:13:35 -0400 Subject: [PATCH 06/11] Update dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java Co-authored-by: Steve Freudenthaler <31257998+sfreudenthaler@users.noreply.github.com> --- .../main/java/com/dotcms/cost/LeakyTokenBucketImpl.java | 7 ------- 1 file changed, 7 deletions(-) diff --git a/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java b/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java index 38f9162ce7b9..f5cb63657f30 100644 --- a/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java +++ b/dotCMS/src/main/java/com/dotcms/cost/LeakyTokenBucketImpl.java @@ -66,13 +66,6 @@ public class LeakyTokenBucketImpl implements LeakyTokenBucket { LeakyTokenBucketImpl() { this( Config.getBooleanProperty("RATE_LIMIT_ENABLED", false), - // Scaled with the Price table when it was re-based on resource-time - // (see RequestPrices.Price): one DB round trip is 10 units, one remote - // HTTP call is 100, so the old 500/10000 defaults would now throttle a - // handful of requests per second. Ratio to the old defaults is unchanged. - // NOTE: the bucket drains in RAW Price units, not the denominated ones - // reported in the x-dotrequest-cost header - a limit set here is on the - // Price scale (remote HTTP = 100), not the reported-token scale. Config.getLongProperty("RATE_LIMIT_REFILL_PER_SECOND", 5000), Config.getLongProperty("RATE_LIMIT_MAX_BUCKET_SIZE", 100000) ); From 1716951ff12b339be22bc4eb28555fa85d9ca7a1 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 20:15:28 -0400 Subject: [PATCH 07/11] Delete docs/requestcost-placement-analysis.md Deleting unneeded analysis --- docs/requestcost-placement-analysis.md | 379 ------------------------- 1 file changed, 379 deletions(-) delete mode 100644 docs/requestcost-placement-analysis.md diff --git a/docs/requestcost-placement-analysis.md b/docs/requestcost-placement-analysis.md deleted file mode 100644 index 1ffeb7753c37..000000000000 --- a/docs/requestcost-placement-analysis.md +++ /dev/null @@ -1,379 +0,0 @@ -# RequestCost — profile-driven gap analysis and action list - -Glowroot main-thread profiles, 7-day windows, read 2026-08-07. - -| Tenant | Samples | Shape | Top transactions | -|---|---|---|---| -| Tenant F | 17,706 | traditional site | page renders, `/dA/` binaries | -| Tenant A | 68,378 | write-heavy API | workflow fire 54%, graphql 23%, es/search 16% | -| Tenant B | 12,126 | read-heavy API | graphql 60%, `/api/vtl/*` 31%, page render 7% | -| Tenant C | 8,781 | velocity + remote API | product browse pages | -| Tenant D | 893 | graphql | graphql 54%, es/search 12%, page render 10%, content 20% | -| Tenant E | 53 | — | **ignored — 53 samples is noise** | - -## Headline - -Six instances, six different cost centres. The model's prices are the dominant -cost for exactly one of them. - -| Tenant | Where the time actually goes | Costed? | -|---|---|---| -| Tenant F | filter chain (DB), velocity render, binaries | partly | -| Tenant A | `addContentToIndex` — ~10% of all samples, blocking | **no** | -| Tenant B | prerender park 36%, `NavTool.getNav` 11% | **no** | -| Tenant C | `CircuitBreakerUrl` outbound HTTP ~50% | yes — but was priced 4, now 100 | -| Tenant D | GraphQL execute + transform + relationship N+1 | **no** | - -Standing caveat: a sampled profile gives **time share, not invocation counts**. -It reliably shows where instrumentation is *missing*; it cannot set per-call -prices. Only the cost model itself, once placed, produces the counts you need. - ---- - -# Ranked - -Ordered by (currently-invisible, client-controllable cost made visible) ÷ effort. - -**All items are resolved.** #14 was decided in favour of the **estimate model**, with -the line drawn at what the customer can influence — see §4. - -| # | Do | Effort | Why here | -|---|---|---|---| -| 1 | ✅ Charge `CONTENT_FROM_CACHE` per contentlet + `CONTENT_FROM_DB` per miss in `findContentlets(List)` | 2 lines + 1 API overload | Universal: GraphQL, `/api/content`, `/api/es/search`, page render all bulk-load here. Makes cost scale with **rows returned** — the main lever a client has. §1.1 | -| 2 | ✅ `CONTENT_INDEX` on `addContentToIndex` | 1 annotation + funnel check | ~10% of the largest tenant's samples, blocking, and no indexing price exists at all. §2 | -| 3 | ✅ Reprice `HTTP_FETCH` (4 → 100) | one number | ~50% of Tenant C's samples. Was barely above `VELOCITY_MERGE`. §3 | -| 4 | ✅ Reprice `CONTENT_GET_RELATED` (1 → 10) | one number | Hottest priced constant in API traffic, and it recurses. One `?depth=` bump multiplies work at no cost. §3 | -| 5 | ✅ `HTTP_FETCH` on `PreRenderSEOWebAPIImpl` | 1 annotation | 36.2% of Tenant B parked in `Unsafe.park`; own HttpClient means the existing charge never fires. §1.7 | -| 6 | ✅ `NAV_BUILD` on `NavTool.getNav` | 1 annotation + funnel check | 11% of Tenant B's total samples, DB-blocked, recursive. §2 | -| 7 | ✅ `ES_QUERY` on `enterprise.priv.ESSearchAPIImpl.esSearchRaw` | 1 annotation | `/api/es/search` = 12% Tenant D, 16% Tenant A, currently free. §1.6 | -| 8 | ✅ `VELOCITY_MERGE` on `DotDirective.render` (miss branch) | 1 annotation | Biggest *relative* distortion for velocity tenants — 30 containers price like 1. §1.4 | -| 9 | ✅ `VELOCITY_MERGE` on `VTLResource.processRequest` | 1 annotation | 31% of Tenant B's transactions charge no merge. §1.5 | -| 10 | ✅ `CONTENT_FROM_DB` on **both** `findInDb` variants | 2 annotations | The cache-miss surcharge on the single-contentlet path. Not a delete — the two are not duplicates, see §1.2. | -| 11 | ✅ `find()` charges the `CONTENT_FROM_CACHE` base fee | comment | Correct as-is once the miss surcharge lands in `findInDb`. §1.3 | -| 12 | ✅ Guard the unconditional log concat in `RequestCostApiImpl` | 1 line | Done by the author. §6.4 | -| 13 | ✅ `GRAPHQL_QUERY` on `DotGraphQLHttpServlet.handleRequest` | 1 annotation | ~4% in parse+validate, and the only charge that scales with **query size** rather than rows. §2 | -| 14 | ✅ **Decided: estimate, split on what the customer controls** | design call | Cache-vs-DB is priced (theirs); statements-per-miss is not (ours). `DB_QUERY` retired. §4 | -| 15 | ~~`LANGUAGE_VARIABLE`~~ — **dropped, already metered** | — | The ES query it triggers is charged as `ES_QUERY` on the cache-miss branch. Adding it would double-charge. See below. | -| 16 | ~~per-fetcher `GRAPHQL_FIELD_FETCH`~~ — **dropped** | — | The fetchers resolve content, now charged per row by #1, and parse/validate by #13. Adding it would count the same work twice at a different altitude. | -| — | ✅ Filed as [#36970](https://github.com/dotCMS/core/issues/36970) | — | ~20–25× per request-profile, pure waste. Not a costing item. §7.1 | -| — | ✅ Filed as [#36971](https://github.com/dotCMS/core/issues/36971) | — | One user query per response row. §7.2 | -| — | **Don't** charge the filter chain | — | ~15% of the velocity profile but fixed per request and not client-controllable. §5 | - -Rows 1–4 are where the return is concentrated: they are four small changes that -cover every tenant archetype in the sample. - -# Action list - -## 0. Applied - -16 files, +218/−46. Compiles clean — verified with `javac` against the built -classpath, error count identical to the HEAD baseline. (The full `mvn` build -fails in `dotcms-core-web`'s nx step and `dotCMS/target/classes` is stale -relative to HEAD; both pre-existing and unrelated.) - -**Content-op terminals** (`ESContentletAPIImpl`) — each verified as the method -its overload chain funnels into: - -| Price | Method | Why this one | -|---|---|---| -| `CONTENT_CHECKIN` | `internalCheckin` (private terminal) | 12 `checkin` overloads chain into it | -| `CONTENT_CHECKOUT` | `checkout(String, User, boolean)` | list variants loop over it → per-contentlet | -| `CONTENT_COPY` | 7-arg `copyContentlet(…, ContentType, Host, Folder, …)` | 8 overloads funnel here | -| `CONTENT_MOVE` | 4-arg `move(…, Host, Folder, boolean)` | 3 overloads funnel here | - -Copy calls checkin internally, so a copy costs 25+50=75 — a composite, worth -knowing when reading traces. - -**Per-contentlet content charge** — `ESContentFactoryImpl.findContentlets(List)` -charges `inodes.size()` × `CONTENT_FROM_CACHE` as a base fee, plus -`missingCons.size()` × `CONTENT_FROM_DB` as a cache-miss surcharge. The surcharge -is per missed **row**, not per SQL statement — the 200-row batching is ours, not -the customer's. Uses a new -`incrementCost(Price, Class, String, Object[], int times)` on `RequestCostApi` -(the 4-arg form delegates with `times = 1`; the HTML accounting entry and the log -line report the multiplied cost). - -**New terminals annotated:** - -| Price | Method | File | -|---|---|---| -| `CONTENT_INDEX` (new, 25) | `addContentToIndex(List)` | `ContentletIndexAPIImpl` | -| `NAV_BUILD` (new, 10) | `getNav(Host, String, long, User)` — terminal of 5 overloads | `NavTool` | -| `ES_QUERY` | private `esSearchRaw(JSONObject, …)` — terminal of both public paths | `enterprise.priv.ESSearchAPIImpl` | -| `HTTP_FETCH` | `proxyPrerenderedPageResponse` — the actual HTTP call, not the eligibility check | `PreRenderSEOWebAPIImpl` | -| `VELOCITY_MERGE` | private `evalVelocity` | `VTLResource` | -| `VELOCITY_MERGE` | `DotDirective.render`, imperative, **past** the `getFromCache()` short-circuit | `DotDirective` | - -**The whole price table was re-based on resource-time.** A price is now an -order-of-magnitude estimate of the CPU, heap, or parked-thread time an operation -consumes. Cache reads are the unit; everything is a ratio to that: - -``` - 1 in-memory cache read CONTENT_FROM_CACHE, ES_CACHE, FILE_METADATA_FROM_CACHE - 2 per-item work in memory VELOCITY_BUILD_CONTEXT, BLOCK_EDITOR_HYDRATION - 5 render a template fragment VELOCITY_MERGE - 10 CPU parse/compile, or one DB hop VELOCITY_PARSE, XSLT_PARSE, GRAPHQL_QUERY, CONTENT_FROM_DB, CONTENT_GET_RELATED, NAV_BUILD, … - 25 one ES round trip, multi-qry write ES_QUERY, ES_COUNT, CONTENT_INDEX, CONTENT_MOVE, CONTENT_COPY - 50 heavy CPU + heap, or a write txn IMAGE_FILTER_TRANSFORM, FILE_METADATA_GENERATE, CONTENT_CHECKIN, CONTENT_DELETE -100 one remote HTTP round trip HTTP_FETCH, XML/XSLT_FETCH_AND_PARSE -``` - -**Why a DB query is only 10x a cache read when it is ~1000x the latency:** what -is metered is capacity consumed *on this node*, not wall time. A query parks the -thread and burns the cycles on Postgres. The Velocity-tenant profile bears this -out — template rendering dominates those requests, not DB frames — and at an -earlier `DB_QUERY` of 25 the price table told a story the profile contradicted -(DB 50% of a page render vs. merges 37%). At 10 the same page is merges 59%, DB -31%, ES 10%, which matches. **If a node ever exhausts request threads before CPU, -this reasoning inverts and the DB / ES / HTTP tiers should go back up.** - -The two biggest corrections this forced: `IMAGE_FILTER_TRANSFORM` and -`FILE_METADATA_GENERATE` were priced 2 and 3 — decoding/re-encoding an image and -running Tika over a binary burn a core and a large buffer, so they are 50. - -**Content pricing took three passes to land** — worth recording, because two of -the three looked right at the time: - -1. A full `CONTENT_FROM_DB` per missed row. **Wrong on units:** misses are fetched - in batches of 200, so 1,000 rows priced as 1,000 queries when it is 5. -2. Cache-hit / miss-row / per-batch-query split. **Right on resource-time, wrong - commercially:** charging per batch prices our implementation detail. -3. Base fee per contentlet + surcharge per missed row, no per-statement charge. - **The one that shipped** — see §4 for why the line sits there. - -**Reported tokens stay in their old range, and stay integral.** The larger -internal scale is divided back out on the way to anyone outside the JVM: - -- `REQUEST_COST_DENOMINATOR` default 1.0 → **10.0**, so one reported token ≈ one - DB round trip, which is roughly what a token meant under the old table. -- The `x-dotrequest-cost` header is **rounded** but still formatted `"%.2f"` — it - has always looked like `"23.00"` and has always been a whole number, so neither - the format nor the integrality changes for anything parsing it. -- `windowTokens` / `lifetimeTokens` in the pushed `RequestCostSnapshot` are - rounded for the same reason: the field is typed `double` but has only ever - carried whole numbers, and a collector parsing them as ints would break on a - fractional value. The per-request *averages* are left fractional — they always - were (`sum / count`). - -Worked examples at denominator 10: - -| Request | raw | reported | -|---|---|---| -| page: 30 containers, 8 DB queries, 1 ES query | 255 | 26 | -| the same page plus one remote API call | 355 | 36 | -| workflow fire (checkin + index) | 75 | 8 | -| single image resize | 50 | 5 | -| 1000-row cached GraphQL response | 1010 | 101 | -| the same 1000 rows cold (2/row + 5 batched queries) | 2060 | 206 | - -**Rate-limit defaults scaled with the table** (`LeakyTokenBucketImpl`): -`RATE_LIMIT_REFILL_PER_SECOND` 500 → 5000, `RATE_LIMIT_MAX_BUCKET_SIZE` -10000 → 100000, preserving the old ratio. `RATE_LIMIT_ENABLED` still defaults -false. These knobs are undocumented and unset everywhere, so the defaults are the -only values in play — but note for whenever the limiter is turned on that **the -bucket drains in raw units, not denominated ones**: a limit is expressed on the -Price scale (one remote HTTP call = 100), not on the reported-token scale. - -## 1. Metering holes on prices that already exist (no new constants) - -**1.1 — `ESContentFactoryImpl.findContentlets(List)` is the big one. FIXED.** -This is the bulk loader behind every search result: GraphQL, `/api/content`, -`/api/es/search`, page render. It reads `contentletCache` per inode, then -batch-SELECTs the misses 200 at a time. It was **uncosted**, and it bypasses -`ESContentletAPIImpl.find()` entirely — so the content annotation there never -fired for a search result. A GraphQL query returning 100 contentlets charged -zero for the content. - -Now charged in two parts — base fee for everything asked for, surcharge for the -rows that missed: - -```java -incrementCost(Price.CONTENT_FROM_CACHE, …, inodes.size()); // base -incrementCost(Price.CONTENT_FROM_DB, …, missingCons.size()); // surcharge -``` - -The surcharge is per missed **row**, not per SQL statement — the 200-row batching -is ours, not the customer's. - -Required one new API surface: a count-taking -`incrementCost(Price, Class, String, Object[], int times)` on `RequestCostApi`. -This makes cost scale with **rows returned** — the lever the client actually -controls — and with nothing else. - -**1.2 — the single-contentlet DB path. Now deliberately unpriced.** `CONTENT_FROM_DB` -used to sit on `ContentletFactory.findInDb(String, String variant)`, an **interface -default method**. Java doesn't inherit method annotations and ByteBuddy matches -declared methods, so it only fired for `find(inode, variant)`; the common path -landed on `ESContentFactoryImpl.findInDb(String, boolean)` and charged nothing. - -An early recommendation to "delete the duplicate override" was also wrong: the two -run the same SQL but differ in post-processing — the interface default filters by -`variantId`, the impl honours `ignoreStoryBlock` — so neither can delegate to the -other as written. The duplicated SQL is still a real smell and deserves its own -issue. - -Both now carry `@RequestCost(Price.CONTENT_FROM_DB)` — reaching either method *is* -the cache miss, and `find()` has already charged the base fee, so a warm find -costs 1 and a cold one 11. - -**1.3 — `find()` charges `CONTENT_FROM_CACHE` unconditionally, and that is -correct.** It reads as a bug in isolation, but it is the base fee; the miss -surcharge is added deeper, in `findInDb`. Warm 1, cold 11, without this method -needing to know which happened. - -**1.4 — `#dotParse` / `#parseContainer` are free.** `DotDirective.render` → -`renderTemplate()` → `((SimpleNode) t.getData()).render(...)`, never through the -annotated `VelocityUtil.mergeTemplate`. A page with 30 containers charges the -same `VELOCITY_MERGE` as a page with 1. The velocity profile shows -`ASTDirective.render` nesting 5–6 deep at 7–11% — that nesting *is* the container -tree. `getFromCache()` already short-circuits, so mirror the `cachedIndexCount` -pattern: cheap on hit, full price on miss. - -**1.5 — `/api/vtl/*` merges are free.** `VTLResource.processRequest:552` calls -`VelocityUtil.getEngine().evaluate(...)` directly, not the annotated -`VelocityUtil.eval`. 31% of Tenant B's transactions. - -**1.6 — `/api/es/search` bypasses `ES_QUERY`.** `ESContentResourcePortlet.searchPost` -→ `com.dotcms.enterprise.priv.ESSearchAPIImpl.esSearchRaw` → -`RestHighLevelClient.performRequest`, never touching -`ContentFactoryIndexOperationsES.cachedIndexSearch` where the imperative -`ES_QUERY` charge lives. 12% of Tenant D, 16% of Tenant A. The class is at -`dotCMS/src/enterprise/java/...` and `com.dotcms.*` is in the ByteBuddy -whitelist, so a plain annotation works. - -**1.7 — Prerender holds a request thread for free.** `PreRenderSEOWebAPIImpl` -uses its own `CloseableHttpClient`, not `CircuitBreakerUrl`, so `HTTP_FETCH` -never fires. Tenant B: `SimpleWebInterceptorDelegateImpl.intercept` → -`Unsafe.park` TIMED_WAITING at **36.2%**. Content-dependent (bot UA + eligible -page), so unlike the rest of the filter chain it *is* chargeable. - -## 2. New prices - -| Price | Placement | Evidence | -|---|---|---| -| `CONTENT_INDEX` | `ContentletIndexAPIImpl.addContentToIndex` — 3 overloads (`:2265/:2270/:2325`), find the terminal | Tenant A: `Object.wait0` WAITING at 9.9 / 9.5 / 9.3 / 8.3% ≈ **10% of all samples**. No indexing price exists at all. | -| `GRAPHQL_QUERY` | `DotGraphQLHttpServlet.handleRequest` | Tenant D: `parseInvocationInput` 1.8% + `ParseAndValidate.validate` / `LanguageTraversal.traverseImpl` ~2.5%. Real CPU **before any field is fetched** — this is the only charge that scales with query size rather than row count. | -| `NAV_BUILD` | `NavTool.getNav` — 4 overloads (`:319/:343/:347/:363`), terminal only | Tenant B: → `BrowserAPIImpl.getFolderContentList` → `Net.poll` = **11.4% + 10.3% of all samples**, DB-blocked, recursive via `NavResultHydrated.getChildren`. | -| ~~`LANGUAGE_VARIABLE`~~ | **dropped — already metered** | The profile frames are real (Tenant D: `getLanguageVariable` → `ESContentletAPIImpl.search` → `indexSearch` at 1.0 / 0.8 / 0.7 / 0.6 / 0.4%), but the path is `KeyValueAPIImpl.get` (own cache) → on miss → `indexSearch` → `searchHits` → `internalSearchHits` → `cachedIndexSearch`, which already charges `ES_QUERY` on **its** miss branch. Two cache layers, both already respected. A price here would double-charge. The N+1 shape is still real and is now *visible*: 50 language-variable misses on a page cost 50 × `ES_QUERY`. | - -**Dropped from an earlier draft:** `CONTENT_TRANSFORM` on -`AbstractTransformStrategy.apply`. Once 1.1 charges per row, this is largely -redundant — it scales with the same row count, and it fires per-*strategy* -(several run per contentlet), so it would triple-count. - -**Optional:** per-fetcher `GRAPHQL_FIELD_FETCH` on the 7 data fetchers -(`ContentletDataFetcher`, `ContentMapDataFetcher`, `FileFieldDataFetcher`, -`SiteFieldDataFetcher`, `UserDataFetcher`, `page.PageDataFetcher`, -`page.ContainersDataFetcher`). Only worth it if you want query *depth* priced -separately from rows — 1.1 + `GRAPHQL_QUERY` covers most of it. Note -`ContainersDataFetcher` → `PageRenderUtil.` at 2.9%: a GraphQL page query -runs the full container pipeline. - -## 3. Repricing — the strongest evidence in the set - -- **`HTTP_FETCH` = 4 is far too low.** Tenant C: `CircuitBreakerUrl` → - `ProtocolExec.execute` → `Net.poll` across branches sums to roughly **half of - all samples**. A template makes a handful of these per request while doing many - merges, yet `HTTP_FETCH`(4) sits barely above `VELOCITY_MERGE`(3). -- **`CONTENT_GET_RELATED` = 1 is the cheapest non-free price and the hottest one - in API traffic.** Tenant D: `ContentHelper.addRelationshipsToJSON` **recurses** - (`:537` → `:600` → `addRelatedContentToJsonArray:782` → `toMaps` → transform → …) - at 3.9 / 3.8 / 3.7 / 3.0 / 2.9 / 2.7%, bottoming out in - `RelationshipFactoryImpl.dbRelatedContent` → `DotConnect.loadResult` → poll. - One `?depth=` bump multiplies this without touching the cost. - -## 4. The pricing model — DECIDED - -Two coherent models, and they double-count if combined: - -- **Choke-point** — meter primitives: every SQL statement at - `DotConnect.executeQuery`, every cache miss. Physically accurate. -- **Estimate** — meter customer-visible operations at a published price. - -**Chosen: estimate, with the line drawn at what the customer can influence** — -which is not the same as the API boundary. Two things that look alike sit on -opposite sides: - -| | Whose? | Priced? | -|---|---|---| -| Did this need the database at all? | **theirs** — cacheable containers/pages, TTLs, query shape | **yes** | -| How many statements, what batch size, which plan? | ours | **no** | - -So content is priced in two parts — `CONTENT_FROM_CACHE`(1) as a base fee per -contentlet asked for, plus `CONTENT_FROM_DB`(10) as a surcharge on the ones that -had to be read from Postgres. Warm is 1, cold is 11. There is deliberately **no -generic `DB_QUERY` price**: the 200-row batching in `findContentlets` is our -implementation detail, so the surcharge is per missed *row*, not per statement. - -The same shape already existed elsewhere and is now consistent across the model: - -| Cheap (cache hit) | Expensive (miss) | -|---|---| -| `CONTENT_FROM_CACHE` 1 | `CONTENT_FROM_DB` 10 | -| `ES_CACHE` 1 | `ES_QUERY` 25 / `ES_COUNT` 25 | -| `FILE_METADATA_FROM_CACHE` 1 | `FILE_METADATA_FROM_DB` 10 / `GENERATE` 50 | -| `DotDirective` cache hit — free | `VELOCITY_MERGE` 5 past `getFromCache()` | - -**Hibernate remains a blind spot** either way: -`PermissionBitAPIImpl.getPermissionsByRole` goes through -`net.sf.hibernate.loader.Loader` → `QueryExecutorImpl.execute` (1.7 / 1.8% in -Tenant D), never touching `DotConnect`. - -## 5. Base fee — probably do NOT charge - -`PageMode.get`, `HostWebAPIImpl.getCurrentHost`, `VanityURLFilter`, -`VisitorFilter`, `DefaultAutoLoginWebInterceptor`. DB-blocked and uncosted, -~15% of the velocity profile — but fixed per request and not client-controllable. -Charging them adds a constant and tells you nothing. `RequestCostFilter` is #2 in -`web.xml`, so they stay attributable if you later decide otherwise. - -## 6. Verify before annotating — five ways to silently ship a zero - -1. **Request-thread assumption.** `RequestCostApiImpl.incrementCost` opens with - `HttpServletRequestThreadLocal.INSTANCE.getRequest(); if (request == null) return;` - — charges on any other thread are **dropped silently, no error**. The Tenant D - profile puts the GraphQL fetchers on the servlet thread today, but graphql-java - goes async the moment a fetcher returns a `CompletableFuture` or DataLoader - batching lands. Same question for whatever `addContentToIndex` blocks on. -2. **Funnel rule.** ByteBuddy weaves bytecode, so **self-invocation fires the - advice** (unlike CDI proxies). Annotating two methods in one overload chain - double-charges. Verify the terminal for `addContentToIndex` and `NavTool.getNav` - the way §0 did for checkin/copy/move. -3. **Cache-wrapper trap.** Charge the miss branch, not the wrapper — the - `indexCount` → `cachedIndexCount` pattern. Applies to `LANGUAGE_VARIABLE` and - `DotDirective.render`. -4. **Hot-path cost.** `RequestCostApiImpl` used to build the log string with - unconditional concatenation *before* checking whether debug was on — since - fixed with suppliers. Worth re-checking if the number of charges per request - ever grows by an order of magnitude. -5. **Annotations don't inherit.** §1.2 is the live example — an annotation on an - interface/abstract method does nothing for an override. - -## 7. Bugs the profiles exposed — not costing items - -1. **Config reads round-trip Postgres.** `AppsAPIImpl.getSecrets` / - `hasEnvBackedSecrets` → `Config.getSystemTableValue` → - `SystemTableConfigSource.getValue` → `SystemTableFactoryImpl.find` → DB. - ~20× in Tenant B, ~25× in Tenant D, several times per request from several - interceptors. Should be cached. Worth its own issue. -2. **Per-row owner lookup.** `DefaultTransformStrategy` → - `UserAPIImpl.loadUserById` → `DotConnect.executeQuery` → poll, 1.0% in Tenant D. - One user query per row in the response. -3. **Duplicate SQL.** `ESContentFactoryImpl.findInDb(String, boolean)` re-implements - the interface default's query verbatim (§1.2). - -## 8. Not a bug — closing an earlier claim - -The bare `@RequestCost` in `ImageFilterApiImpl` (`:116`, `:243`) is **not** -mispriced. `IMAGE_FILTER_TRANSFORM` is charged imperatively at -`ImageFilter.overwrite():158`, once per filter that regenerates; the bare -annotations are a deliberate second layer at 1 each. Only the default constant's -*name* (`COSTING_INIT`) is misleading. Same story for `ES_QUERY`, `ES_COUNT` and -`WORKFLOW_ACTION_RUN` — all charged imperatively, invisible to a `@RequestCost` -grep. - -## 9. Calibration loop - -Place §1 and §2, run a week, then per endpoint compare Glowroot's mean response -time against the model's mean cost. Endpoints where that ratio is an outlier are -the mispriced constants. Do not set prices from the profile alone. From fc00ec33075b18a5c67e29c9da2f90aefb9b23f9 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 20:16:29 -0400 Subject: [PATCH 08/11] Delete docs/requestcost-session-summary.md Deleting unneeded doc --- docs/requestcost-session-summary.md | 197 ---------------------------- 1 file changed, 197 deletions(-) delete mode 100644 docs/requestcost-session-summary.md diff --git a/docs/requestcost-session-summary.md b/docs/requestcost-session-summary.md deleted file mode 100644 index 24ab794abd3b..000000000000 --- a/docs/requestcost-session-summary.md +++ /dev/null @@ -1,197 +0,0 @@ -# RequestCost — instrumentation review and pricing model - -**Status:** implemented, uncommitted, on branch `issue-36947-core-web-cacheable`. -**Companion doc:** [requestcost-placement-analysis.md](requestcost-placement-analysis.md) — the full evidence and the ranked backlog. -**Date:** 2026-08-10. - ---- - -## What this was - -`@RequestCost` exists to score the "heaviness" of a request, token-style, so that -usage can be metered and rate-limited. This session audited **where the annotation -is actually placed** against real production behaviour, using Glowroot main-thread -profiles from six tenant instances (7-day windows), and then reworked the price -table. - -Tenants are anonymised as A–F below. Shapes, not names, are what matter — and the -shapes turned out to be the whole story. - -## The finding that framed everything - -Six production instances, six different cost centres. The model's prices were the -dominant cost for exactly one of them. - -| Tenant | Shape | Where the time actually went | Metered before? | -|---|---|---|---| -| A | write-heavy API | `addContentToIndex` — ~10% of all samples, blocking | **no** | -| B | GraphQL 60% / VTL 31% | prerender park 36%, `NavTool.getNav` 11% | **no** | -| C | Velocity + remote API | `CircuitBreakerUrl` outbound HTTP ~50% | yes, priced 4 | -| D | GraphQL 54% | GraphQL execute, transform, relationship N+1 | **no** | -| F | traditional Velocity | filter chain, render, binaries | partly | -| E | — | 53 samples, discarded as noise | — | - -A GraphQL-only customer could saturate a node and accrue almost nothing. The -instrumentation was concentrated on the Contentlet API; the traffic was not. - -## The decision that matters most - -Midway through, the question surfaced as: **should cost track what the server -actually did, or what the customer asked for?** - -Two coherent models: - -- **Choke-point** — meter primitives (every SQL statement, every cache miss). - Accurate to real resource use, but the customer's bill then moves with *our* - cache hit rate, batch sizes and query plans. -- **Estimate** — meter customer-visible operations at a flat, published price. - Less physically precise, stable and optimisable. - -**We chose estimate — but the line is drawn at what the customer can influence, -not at the API boundary.** Two things that look similar are on opposite sides: - -- **Did this need the database?** — theirs. Customers control caching through - cacheable containers and pages, cache TTLs, and how they shape their queries. - Cached content is priced at a tenth of uncached content, so the optimisation - visibly pays off. -- **How did we ask the database?** — ours. Batch sizes, query plans, how many SQL - statements a miss took. A customer cannot see or change any of it, so there is - deliberately **no generic per-statement `DB_QUERY` price**. - -Content is therefore priced in two parts: `CONTENT_FROM_CACHE` (1) as a base fee -per contentlet asked for, plus `CONTENT_FROM_DB` (10) as a surcharge on the ones -that had to be read from Postgres. One contentlet costs 1 warm and 11 cold; a -thousand cost 1,000 warm and 11,000 cold. - -The same shape already existed for ES queries (`ES_CACHE` 1 / `ES_QUERY` 25) and -file metadata (`FILE_METADATA_FROM_CACHE` 1 / `FROM_DB` 10 / `GENERATE` 50), and -was extended to Velocity directives — `#dotParse` is charged past the -`getFromCache()` short-circuit, so cacheable containers are cheaper than -uncacheable ones. The model is consistent across all four. - -What that looks like, at the default denominator of 10: - -| Scenario | raw | reported | -|---|---|---| -| 1,000 contentlets, all cached | 1,000 | **100** | -| 1,000 contentlets, 90% cached | 2,000 | 200 | -| 1,000 contentlets, all from DB | 11,000 | **1,100** | - -An 11× spread between fully warm and fully cold — large enough that tuning cache -config is worth a customer's time, which is the whole point. - -The reasoning is written into `RequestPrices.Price` so the next person doesn't -"simplify" it away. - -## The price table - -Re-based twice. First onto **resource-time** — a price is an order-of-magnitude -estimate of the CPU, heap or parked-thread time an operation consumes. Then the DB -tier was compressed after a challenge that it was too high: - -``` - 1 in-memory cache read CONTENT_FROM_CACHE, FILE_METADATA_FROM_CACHE, ES_CACHE - 2 per-item work in memory VELOCITY_BUILD_CONTEXT, BLOCK_EDITOR_HYDRATION - 5 render a template fragment VELOCITY_MERGE - 10 CPU parse/compile, or one DB hop VELOCITY_PARSE, XSLT_PARSE, GRAPHQL_QUERY, CONTENT_FROM_DB, CONTENT_GET_RELATED, NAV_BUILD - 25 one ES round trip, or a write ES_QUERY, ES_COUNT, CONTENT_INDEX, CONTENT_MOVE, CONTENT_COPY - 50 heavy CPU + heap, or a write txn IMAGE_FILTER_TRANSFORM, FILE_METADATA_GENERATE, CONTENT_CHECKIN, CONTENT_DELETE -100 one remote HTTP round trip HTTP_FETCH, XML/XSLT_FETCH_AND_PARSE -``` - -**Why a DB query is only 10× a cache read when it is ~1000× the latency:** what is -metered is capacity consumed *on this node*, not wall time. A query parks the -thread and burns the cycles on Postgres. Tenant F's profile bore this out — -template rendering dominated, not DB frames. At a DB price of 25 the table said DB -was 50% of a page render; the profile said otherwise. At 10 it reads merges 59% / -DB 31% / ES 10%, which matches. - -**If a node ever exhausts request threads before CPU, that reasoning inverts** and -the DB/ES/HTTP tiers should go back up. That caveat is in the code. - -Two prices were badly wrong and are worth calling out: `IMAGE_FILTER_TRANSFORM` -was **2** and `FILE_METADATA_GENERATE` was **3**. Decoding and re-encoding an -image, or running Tika over a binary, burns a core and a large buffer — both are -now 50. - -## What shipped - -16 files, ~+220/−50. Compiles clean (verified with `javac` against the built -classpath; error count identical to the HEAD baseline). - -**Placement gaps closed** - -| Price | Where | Why it mattered | -|---|---|---| -| `CONTENT_FROM_CACHE` + `CONTENT_FROM_DB` | `ESContentFactoryImpl.findContentlets(List)` | The bulk loader behind *every* search result — GraphQL, `/api/content`, `/api/es/search`, page render. It bypasses `find()`, so nothing metered it. Base fee per contentlet, surcharge per missed row. | -| `CONTENT_FROM_CACHE` | `ESContentletAPIImpl.find(...)` | Base fee, single-contentlet path | -| `CONTENT_FROM_DB` | both `findInDb` variants | The miss surcharge. Annotations aren't inherited, so the interface default and the impl override each need their own | -| `CONTENT_INDEX` (new) | `ContentletIndexAPIImpl.addContentToIndex(List)` | ~10% of Tenant A's samples, blocking, no price existed | -| `NAV_BUILD` (new) | `NavTool.getNav(Host, String, long, User)` | 11% of Tenant B's samples, DB-blocked, recursive | -| `GRAPHQL_QUERY` (new) | `DotGraphQLHttpServlet.handleRequest` | Parse + validate, before any field is fetched — the only charge that scales with *query size* | -| `ES_QUERY` | `enterprise.priv.ESSearchAPIImpl.esSearchRaw` | `/api/es/search` bypassed the existing charge entirely | -| `HTTP_FETCH` | `PreRenderSEOWebAPIImpl.proxyPrerenderedPageResponse` | Own `HttpClient`, so `CircuitBreakerUrl`'s charge never fired. 36% of Tenant B parked here | -| `VELOCITY_MERGE` | `DotDirective.render` | `#dotParse` / `#parseContainer` were free — a 30-container page priced like a 1-container page | -| `VELOCITY_MERGE` | `VTLResource.evalVelocity` | `/api/vtl/*` bypassed the annotated merge. 31% of Tenant B's transactions | -| `CONTENT_CHECKIN` / `CHECKOUT` / `COPY` / `MOVE` | `ESContentletAPIImpl` terminals | Prices existed in the enum, nothing charged them | - -**API change:** `RequestCostApi` gained -`incrementCost(Price, Class, String, Object[], int times)` so a charge can scale -with result-set size. The 4-arg form delegates with `times = 1`. - -**Reporting:** internal scale grew, so `REQUEST_COST_DENOMINATOR` now defaults to -10 to keep reported tokens in their historical range. The `x-dotrequest-cost` -header and the pushed snapshot totals are **rounded** — both have only ever -carried whole numbers, and a collector parsing them as ints would break on a -fractional value. Per-request averages stay fractional, as they always were. - -**Rate limiting:** `LeakyTokenBucketImpl` defaults scaled with the table -(500→5000 refill, 10000→100000 bucket). Still disabled by default, and confirmed -that nothing overrides these anywhere. - -## Three traps for whoever extends this - -1. **The enum is not an index of what is metered.** Four prices — `ES_QUERY`, - `ES_COUNT`, `WORKFLOW_ACTION_RUN`, `IMAGE_FILTER_TRANSFORM` — are charged with - direct `incrementCost(...)` calls, invisible to a `@RequestCost` grep. This - caused three wrong conclusions during the session before it was caught. Grep - for **both** forms. -2. **ByteBuddy weaves bytecode, so self-invocation fires the advice** — unlike CDI - proxies. `checkin` has 12 overloads chaining into each other; annotating two in - one chain double-charges. Always find the terminal. -3. **Charges are silently dropped off the request thread.** `incrementCost` opens - with `if (request == null) return;`. Anything that moves to a - `CompletableFuture` or a worker pool stops being metered with no error. Relevant - if GraphQL DataLoader batching ever lands. - -Also: annotations are **not inherited**, so a `@RequestCost` on an interface or -abstract method does nothing for an override. This had already made -`CONTENT_FROM_DB` dead on the common single-find path. - -## Open - -- **Deliberately not charged:** the pre-render filter chain (`PageMode.get`, - `HostWebAPIImpl.getCurrentHost`, Vanity/Visitor filters). ~15% of Tenant F's - profile, but fixed per request and not client-controllable — charging it adds a - constant and tells you nothing. -- **Hibernate is a blind spot.** `PermissionBitAPIImpl.getPermissionsByRole` goes - through `net.sf.hibernate.loader.Loader`, never touching `DotConnect`. Any - future DB-level metering would miss permission loading entirely. -- **Nothing is validated against a running instance.** Prices are - order-of-magnitude estimates from sampled time-share; placements were verified by - reading call chains, not by watching a request. The calibration loop — run a - week, compare per-endpoint mean response time against mean cost, investigate - outlier ratios — is what turns these into measured numbers. - -## Bugs filed - -Two performance defects surfaced by the profiles, neither a costing issue: - -- [#36970](https://github.com/dotCMS/core/issues/36970) — Config and App-secret - reads round-trip Postgres on every request, several times per request from - several interceptors. -- [#36971](https://github.com/dotCMS/core/issues/36971) — N+1: one - `loadUserById` per row of every REST/GraphQL response. - -Both are `Team : Platform`. The Technology project field is unset on both — that -needs a `gh auth refresh -s read:project -s project` from someone with the scope. From 8603ff68eb571f900b3e5a3ddd0c3de7b9986337 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 21:53:18 -0400 Subject: [PATCH 09/11] test(cost): expect denominator-scaled total in accounting report (#36977) The report template renders the total as requestCost / REQUEST_COST_DENOMINATOR, whose default moved from 1.0 to 10.0 when the price table was re-based. Compute the expected value the same way the report does so the test holds under any configured denominator. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VTt9ymEwfmHV9DSKe1vPuJ --- .../src/test/java/com/dotcms/cost/RequestCostReportTest.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java b/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java index ff57b36e32e3..f2e8ebffdbd0 100644 --- a/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java +++ b/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java @@ -151,7 +151,9 @@ public void test_writeAccounting_shouldCalculateTotalCorrectly() { requestCostApi.incrementCost(Price.TWENTY, RequestCostReportTest.class, "method2", new Object[]{}); requestCostApi.incrementCost(Price.THIRTY, RequestCostReportTest.class, "method3", new Object[]{}); - int expectedTotal = requestCostApi.getRequestCost(request); + // The report renders the total divided by the configured denominator + double expectedTotal = requestCostApi.getRequestCost(request) + / requestCostApi.getRequestCostDenominator(); // When String html = report.writeAccounting(request); From e3aaa948d8c9a1e21bac8d2064d8efe25016fc3a Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 22:28:33 -0400 Subject: [PATCH 10/11] test(cost): use the report's singleton denominator for the expected total (#36977) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit RequestCostApiImpl only reads REQUEST_COST_DENOMINATOR in @PostConstruct, so the test's hand-constructed instance keeps the 1.0 field default while the report divides by the CDI singleton's 10.0 — the expected and rendered totals diverged. Compute the expectation with the same instance the report uses. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VTt9ymEwfmHV9DSKe1vPuJ --- .../test/java/com/dotcms/cost/RequestCostReportTest.java | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java b/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java index f2e8ebffdbd0..3611a7c11538 100644 --- a/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java +++ b/dotcms-integration/src/test/java/com/dotcms/cost/RequestCostReportTest.java @@ -151,9 +151,11 @@ public void test_writeAccounting_shouldCalculateTotalCorrectly() { requestCostApi.incrementCost(Price.TWENTY, RequestCostReportTest.class, "method2", new Object[]{}); requestCostApi.incrementCost(Price.THIRTY, RequestCostReportTest.class, "method3", new Object[]{}); - // The report renders the total divided by the configured denominator + // The report renders the total divided by the denominator of the singleton API it + // uses internally. Our locally constructed requestCostApi never runs @PostConstruct, + // so its denominator would stay at the field default and not match the report's. double expectedTotal = requestCostApi.getRequestCost(request) - / requestCostApi.getRequestCostDenominator(); + / APILocator.getRequestCostAPI().getRequestCostDenominator(); // When String html = report.writeAccounting(request); From 99e6c8541179ea2cbdbc8e59def1b762dfb55a32 Mon Sep 17 00:00:00 2001 From: Will Ezell Date: Mon, 10 Aug 2026 23:56:01 -0400 Subject: [PATCH 11/11] fix(content): don't treat cached 404 sentinels as hits in findContentlets (#36977) The single-pass rewrite of the cache-miss collection marked any non-null cache entry as found, but the cache stores the CACHE_404_CONTENTLET sentinel under the requested inode after a failed single-item lookup. A sentinel hit skipped the DB fetch and the final keyed lookup then dropped the inode from the result entirely (ESContentFactoryImplTest.findContentlets: expected 991, got 988). Count a hit only when the cached inode equals the requested one, matching the old CollectionUtils.subtract semantics. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VTt9ymEwfmHV9DSKe1vPuJ --- .../business/ESContentFactoryImpl.java | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java index 93ce40ea0f23..8b3a7a286d9a 100644 --- a/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java +++ b/dotCMS/src/main/java/com/dotcms/content/elasticsearch/business/ESContentFactoryImpl.java @@ -1282,16 +1282,18 @@ public Contentlet findContentletForLanguage(long languageId, Identifier identifi public List findContentlets(final List inodes) throws DotDataException { // Single pass: the cache lookup already knows which inodes missed, so collect them here - // rather than re-deriving the difference afterwards. CollectionUtils.subtract built a - // HashBag of the hit keys, walked the inodes against it and returned a list that was then - // copied into a second list - three allocations and an extra pass to recompute something - // this loop already knew. + // rather than re-deriving the difference afterwards. A hit only counts when the cached + // inode matches the requested one: the cache stores the CACHE_404_CONTENTLET sentinel + // under the requested key after a failed single-item lookup, and treating it as a hit + // would silently drop that inode from the result instead of falling through to the DB + // (the old CollectionUtils.subtract over conMap's keys had the same inode-equality + // semantics, since the sentinel's inode never matches a requested inode). final HashMap conMap = new HashMap<>(); final List missingCons = new ArrayList<>(); for (final String i : inodes) { final Contentlet contentlet = contentletCache.get(i); - if (contentlet != null && InodeUtils.isSet(contentlet.getInode())) { - conMap.put(contentlet.getInode(), processCachedContentlet(contentlet)); + if (contentlet != null && i.equals(contentlet.getInode())) { + conMap.put(i, processCachedContentlet(contentlet)); } else { missingCons.add(i); }