linliu-code opened a new issue, #20061:
URL: https://github.com/apache/hudi/issues/20061
## Bug Description
In a long-running Spark Thrift Server, `EmbeddedTimelineService` instances
accumulate over the
life of the driver JVM. Each retained instance keeps a live Javalin/Jetty
server and its
`TimelineService-JettyScheduler` thread pool, so threads and heap grow
without bound over
weeks of uptime.
The great majority of timeline services are closed correctly. The problem is
a small,
persistent fraction that never are.
**Measured over ~9 days on one driver:**
| Log line | Count |
| --- | --- |
| `Starting Timeline server` | 4,664 |
| `Closing Timeline server` (close attempted) | 4,637 |
| `Closed Timeline server` (close completed) | 4,635 |
So of 4,664 starts, **27 never had close attempted at all**, and 2 more
began closing without
finishing — about **0.6%**, roughly 3.2 leaked per day.
(The driver is live, so counts in this report were sampled a few minutes
apart and drift by a
handful between sections. The gaps, which are what matter, are stable.)
**Confirmed on the heap of that driver** (JVM uptime 29 days), via `jmap
-histo`:
171 io.javalin.Javalin
171 io.javalin.jetty.JettyServer
171 org.apache.hudi.timeline.service.TimelineService$Config
342
org.apache.hudi.org.apache.jetty.util.thread.ScheduledExecutorScheduler
1 org.apache.hudi.timeline.service.TimelineService
1 org.apache.hudi.client.embedded.EmbeddedTimelineService
and 1,361 live threads named `TimelineService-JettyScheduler`.
Two things worth noting there. Only **one** `TimelineService` /
`EmbeddedTimelineService` object
survives, so the wrappers are being dereferenced normally — it is the
Javalin/Jetty servers they
started that stay alive, rooted by their own running threads. And 1361/171 ≈
**7.96 threads per
retained server**, matching the hardcoded `8` in
`TimelineService.createApp()`:
ScheduledExecutorScheduler scheduler =
new ScheduledExecutorScheduler("TimelineService-JettyScheduler",
true, 8);
which confirms each retained `Javalin` corresponds to one `createApp()` call.
The leak scales with write activity. Three drivers of identical age in the
same deployment:
| Driver | write activity | `io.javalin.Javalin` | scheduler threads |
| --- | --- | --- | --- |
| A | none (read-only) | 0 | 0 |
| B | light | 4 | 32 |
| C | heavy | 171 | 1361 |
## What I was able to rule out
Sharing these so nobody re-walks them:
- **Not the port-binding retry loop.** `startServiceOnPort` creates a fresh
`Javalin` per attempt,
which looked like an obvious candidate. Across all 4,664 starts there were
**zero**
`could not bind on port` and **zero** `Timeline server start failed` log
lines.
- **Not a missing close path.** `TimelineService.close()` does call
`app.stop()`, and
`EmbeddedTimelineService.stopForBasePath` does close the server once its
last base path is
removed — the wiring is there. (It is however unguarded, which causes a
separate and much
smaller failure; see "A second, narrower defect" below.)
- **Not a missing `writeClient.close()` in the SQL write path.**
`HoodieSparkSqlWriter` calls `handleWriteClientClosure` in a `finally`,
plus in a
`catch (HoodieException)`.
- **Not the metadata-table writer.** `BaseActionExecutor.writeTableMetadata`
uses
try-with-resources; `HoodieBackedTableMetadataWriter.close()` closes its
write client.
- **Not an injected-and-unowned server.** `BaseHoodieClient` sets
`shouldStopTimelineServer = !timelineServer.isPresent()`, so an injected
server would not be
stopped by the client — but no production construction site of
`SparkRDDWriteClient` passes a
non-empty `Option<EmbeddedTimelineService>`; they all pass
`Option.empty()`.
- **Not correlated with logged failures.** Over the same window: 0
`SparkException`,
0 `HoodieException`, 0 `Job aborted` in that driver's logs.
## The one lead I could not close out
Over the same 9-day window on the same driver:
| Log line | Count |
| --- | --- |
| `Starting Timeline server` | 4,664 |
| `Closing write client` | 4,484 |
a gap of **180**, which is much closer to the 171 retained servers than the
29-line gap in the
timeline-service close counts. That suggests the missing close is one level
up — a write client
that is never closed, rather than a timeline service specifically — and that
it happens without
throwing anything that gets logged.
**I could not identify which caller skips the close.** I am reporting the
observation and the
eliminations rather than guessing at a mechanism; someone who knows the
write-client lifecycle
will likely see it quickly.
## How to reproduce / measure
On any long-running driver that performs Hudi writes:
# leak rate, from the driver's own logs
grep -c "Starting Timeline server" <driver log>
grep -c "Closing Timeline server" <driver log>
grep -c "Closed Timeline server" <driver log>
# retained servers and their threads
jmap -histo <pid> | grep -E
"io\.javalin\.Javalin$|jetty\.JettyServer$|TimelineService"
jcmd <pid> Thread.print | grep -c "TimelineService-JettyScheduler"
A driver doing no writes shows zero of everything, which is a useful control.
## A second, narrower defect found in the same data
Splitting the close counts by stage localises a distinct failure.
`TimelineService.close()` logs
`Closing Timeline Service` / `Closed Timeline Service` (capital S), while
`EmbeddedTimelineService.stopForBasePath` logs `Closing Timeline server` /
`Closed Timeline server`
(lowercase). Over the same window on the same driver:
| Log line | Count |
| --- | --- |
| `Closing Timeline Service` (enters `TimelineService.close()`) | 4,644 |
| `Closed Timeline Service` (completes it) | 4,641 |
| `Closing Timeline server` (enters the `stopForBasePath` close block) |
4,642 |
| `Closed Timeline server` (completes it) | 4,640 |
So **3 calls entered `TimelineService.close()` and never came out**, 2 of
which propagated up into
`stopForBasePath`. (The count of 4,644 > 4,642 also shows `close()` has a
second caller — the
`RUNNING_SERVICES` sweep.)
`TimelineService.close()` has no exception handling:
public void close() {
LOG.info("Closing Timeline Service");
if (requestHandler != null) this.requestHandler.stop();
if (this.app != null) { this.app.stop(); this.app = null; }
this.fsViewsManager.close();
LOG.info("Closed Timeline Service");
}
If any of `requestHandler.stop()`, `app.stop()` or `fsViewsManager.close()`
throws:
- `app = null` never executes, so the Javalin server stays both running and
referenced
- `fsViewsManager.close()` is skipped
- in the caller, `this.server = null` never executes, so **that instance can
never be closed
again** — there is no retry path
And it is silent: there were **zero** ERROR-level lines from
`TimelineService` or
`EmbeddedTimelineService` across the whole window (the 397 ERROR lines
present all come from
`SparkExecuteStatementOperation` and unrelated components). A close failure
today leaves a
permanently unclosable server and emits nothing.
This accounts for only ~0.06% of starts, so it is not the main leak above —
but it is narrow,
independently fixable, and arguably worse per occurrence because the
resulting instance is
unrecoverable. A try/finally that nulls `app` and `server` regardless, plus
a logged warning,
would close it.
## Suggested direction
No fix is proposed for the main leak, since the caller that skips the close
is unidentified.
Two adjacent things look worth doing regardless:
1. `startServiceOnPort` leaves the final `app` unstopped if every retry
fails: `createApp()`
only stops the previous app at the *start* of the next attempt, and there
is no cleanup after
the loop before it throws `IOException`. This was not the cause here
(zero bind failures) but
it is a real leak on a path that can be hit.
2. `NUM_SERVERS_RUNNING` is already maintained and registered as
`numEmbeddedTimelineServers`.
Surfacing it, or logging it periodically, would make this class of leak
visible without a
heap dump.
## Proposed fix for the narrow defect
The close path is unobservable and non-idempotent. Over ~9 days on this
driver there were
**14,354 captured stack traces** and **zero** of them contained
`TimelineService`,
`EmbeddedTimelineService`, `javalin`, `jetty`, `stopForBasePath` or
`BaseHoodieClient.close` —
so the exception aborting these closes leaves no trace anywhere, because
none of the four frames
in the call chain catches or logs it. (`HoodieSparkSqlWriter` calls
`handleWriteClientClosure`
from a `finally`, so the throw also replaces any in-flight exception on its
way out.)
Two changes make the failure visible and the instance releasable.
`TimelineService.close()` — never skip the field nulling, and say when a
stage failed:
public void close() {
LOG.info("Closing Timeline Service");
try {
if (requestHandler != null) {
this.requestHandler.stop();
}
} catch (Exception e) {
LOG.warn("Failed to stop the timeline request handler; continuing
shutdown", e);
}
try {
if (this.app != null) {
this.app.stop();
}
} catch (Exception e) {
LOG.warn("Failed to stop the Javalin app; continuing shutdown", e);
} finally {
this.app = null;
}
try {
this.fsViewsManager.close();
} catch (Exception e) {
LOG.warn("Failed to close the file system view manager", e);
}
LOG.info("Closed Timeline Service");
}
`EmbeddedTimelineService.stopForBasePath()` — release the reference even
when the close throws,
so the instance cannot end up permanently unclosable:
if (basePaths.isEmpty() && null != server) {
LOG.info("Closing Timeline server");
try {
this.server.close();
} catch (Exception e) {
LOG.warn("Timeline server did not close cleanly; releasing the
reference anyway", e);
} finally {
METRICS_REGISTRY.set(NUM_EMBEDDED_TIMELINE_SERVERS,
NUM_SERVERS_RUNNING.decrementAndGet());
this.server = null;
this.viewManager = null;
}
LOG.info("Closed Timeline server");
}
**What this does and does not achieve.** It removes the unrecoverable state
— today, if
`app.stop()` throws, `this.app` and `this.server` stay set and that instance
can never be closed
again — and it makes the failure visible for the first time. It does **not**
guarantee the
underlying Jetty threads are reclaimed: nulling a reference does not stop a
server that failed to
stop. So this converts a silent, unrecoverable leak into a visible one,
which is what is needed
to diagnose the remainder. A forced-stop or retry path would be the
follow-up, and is better
designed once the WARN above shows what actually throws.
## Affected lines
The unguarded close is present, unchanged, on every line checked:
| Line | Version | `TimelineService.close()` | `stopForBasePath` |
| --- | --- | --- | --- |
| apache/hudi `master` | 1.3.0-SNAPSHOT | no try/catch | no try/catch |
| 0.x line | 0.x | no try/catch | no try/catch |
| 1.x line | 1.1.0-SNAPSHOT | no try/catch | no try/catch |
| 1.2 line | 1.2.0 | no try/catch | no try/catch |
| 1.3-pre line | 1.3 pre-release | no try/catch | no try/catch |
Only the log formatting differs: newer lines use `log.info("Closing Timeline
Service with port {}", serverPort)`
and parameterised SLF4J, older ones use `LOG.info("Closing Timeline
Service")` or string concatenation.
Anyone grepping for these lines should match on `Closing Timeline Service` /
`Closed Timeline Service`
without assuming the trailing text.
Note also that `EmbeddedTimelineService` has a **second** call site for
`server.close()` — the
`RUNNING_SERVICES` sweep — which is equally unguarded on every line. In the
data above this shows
up as `Closing Timeline Service` (4,644) exceeding `Closing Timeline server`
(4,642).
## Environment
- Hudi: observed on a 0.x-line build; the same code is present on every line
checked (see Affected lines)
- Spark 3.5, Scala 2.12, JDK 17
- Deployment: Spark Thrift Server on Kubernetes, driver uptime 29 days
- Table type: COW and MOR, metadata table enabled
- `hoodie.embed.timeline.server.reuse.enabled`: default (`false`)
## Logs and Stack Trace
No exception — this is a retention issue rather than a failure. The relevant
lines are the
INFO-level `Starting Timeline server on port: {}`
(`TimelineService.startService`) and
`Closing Timeline server` / `Closed Timeline server`
(`EmbeddedTimelineService.stopForBasePath`), counted above.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
