Skip to content

[jindo] Log Jindo stream and memory statistics - #10812

Open
sundapeng wants to merge 4 commits into
apache:masterfrom
sundapeng:jindo-io-stats
Open

sundapeng wants to merge 4 commits into
apache:masterfrom
sundapeng:jindo-io-stats

Conversation

@sundapeng

@sundapeng sundapeng commented Oct 26, 2026 •

Copy link
Copy Markdown
Member

Purpose

Containers reading through paimon-jindo, such as compaction TaskManagers, get OOMKilled while the Java heap is far from full. JindoSDK keeps a readahead cache of tens of MiB per open read stream outside the JVM, and glibc keeps most of it resident after the streams close. Nothing in the logs shows how many streams were open or how much native memory Jindo held when the container died.

This PR adds an opt-in reporter to paimon-jindo:

  • JindoIOStats counts the streams opened through a JindoFileIO that sets jindo.io-stats.interval, including multipart (two-phase) output streams: currently open, peak since the previous line, opened, closed and bytes. The counters live in the class loader of paimon-jindo, which is the whole JVM unless jobs bundle their own copy.
  • A stream closed twice, even concurrently, is counted once. A close that throws is not counted, and a retried close still reaches Jindo. Until a close succeeds, the stream stays counted as open because it may still hold native memory, so the reporter keeps logging it. A multipart stream holds no native stream and cannot retry closeForCommit(), so any attempt counts it closed.
  • With jindo.io-stats.interval set (for example 1 min), a daemon thread logs one INFO line per interval while streams are open or have been opened or closed since the previous line. Paimon does not close FileIOs, so the thread is not tied to them: it stops after an interval without stream activity, and the next open starts it again. Its context class loader is the one that loaded paimon-jindo, so it does not keep a finished job's class loader alive. When FileIOs set different intervals, the shortest is used. If the thread cannot be started, for example when no native thread can be created near the memory limit, a WARN is logged, the stream is returned as usual, and a later stream retries after one interval. The default is 0, which disables both the counting and the reporter.
  • The line combines the stream counters with:
    • JindoSDK's native metrics: prefetch cache size and capacity, open native streams, prefetch fallbacks on insufficient memory.
    • Process memory: the RSS split, heap, direct memory, metaspace, threads, and whether jemalloc is loaded.
    • The memory cgroup (v1 or v2): usage and limit, working set, peak, limit hits and OOM kills. Limits are hierarchical, so these come from the level between the process's cgroup and the mount root whose working set is closest to its limit.
  • The thread samples the cgroup every second and logs the same line at WARN when the working set of a cgroup level first crosses 80%, 90% or 95% of its limit, resetting below 70%. Each level keeps its own alarm, so a parent's WARN does not mute a child. The last line before an OOM kill therefore shows what was open.
  • Native metrics are read only through cached file systems, which are never closed. A failure is logged at DEBUG and turns that section off; it never affects reads or writes.

Example (JDK 11, 16 read streams in a 1100 MiB memory cgroup):

WARN  JindoIOStats - Container memory working set is at 85% of the limit. Jindo IO stats: input open=16 peak=16 opened=16 closed=0 read=384MiB; output open=0 peak=0 opened=0 closed=0 written=0MiB; jindo prefetchCache=346MiB/4423MiB readStreams=16 writeStreams=0 memInsufficient=0; process rss=1003MiB anon=939MiB file=63MiB shmem=0MiB threads=42 heap=69MiB/494MiB/494MiB direct=0MiB metaspace=13MiB jemalloc=false; cgroup usage=943MiB/1100MiB workingSet=943MiB peak=943MiB limitHits=0 oomKills=0

Tests

  • JindoIOStatsTest (19 tests) covers:
    • the counters and peak, and stream counting through HadoopCompliantFileIO with a mocked JindoHadoopSystem (including double close and byte counts);
    • a failed close that stays counted as open until it is retried, and streams of a FileIO with the interval unset, which are not counted;
    • multipart output streams, including one whose upload fails to start;
    • concurrent opens and closes, where every sample keeps 0 <= open <= peak, and two threads closing the same stream, which counts one close;
    • the reporter stopping once streams are idle and starting again on the next open, and a stream opened and closed between its idle check and its shutdown, which keeps it running;
    • a reporter thread that fails to start, which leaves the stream usable and is retried by a later stream, and the shortest interval winning;
    • activity detection after closes;
    • parsing the native metrics JSON;
    • cgroup v1, v2 (including a limited parent above an unlimited child) and none;
    • the alarm levels, also when a child cgroup becomes the level closest to its limit after its parent warned.
  • All 52 tests in paimon-jindo pass, and so do checkstyle and spotless.
  • I also ran it by hand on JDK 11 against OSS with jindosdk 6.10.2, in memory-limited cgroups:
    • 1100 MiB limit: 16 read streams logged the 85% WARN above. After they closed, prefetchCache was 0 MiB while anon stayed at 934 MiB, which is glibc retention rather than Jindo.
    • 960 MiB limit: the 90% WARN, with input open=16 and prefetchCache=308MiB, was the last line before the kernel OOM-killed the JVM.
  • Overhead: about 50 us per one-second sample, and about 0.2 ms per line plus about 0.4 ms for the native metrics dump.

Compaction TaskManagers reading through paimon-jindo are OOMKilled by
the container while the Java heap is far from full: JindoSDK keeps a
readahead cache of tens of MiB per open read stream outside the JVM, and
glibc keeps most of it resident after the streams close. Nothing in the
logs tells how many streams were open or how much native memory Jindo
held when the container died.

JindoIOStats keeps JVM-wide counters of the streams opened through
JindoFileIO (open, peak since the previous line, opened, closed, bytes).
When jindo.io-stats.interval is set, a daemon thread logs one INFO line
per interval while streams are open or have opened/closed since the
previous line:

  Jindo IO stats: input open=16 peak=16 opened=16 closed=0 read=384MiB;
  output open=0 ...; jindo prefetchCache=346MiB/4423MiB readStreams=16
  writeStreams=0 memInsufficient=0; process rss=1003MiB anon=939MiB
  file=63MiB shmem=0MiB threads=42 heap=69MiB/494MiB/494MiB direct=0MiB
  metaspace=13MiB jemalloc=false; cgroup usage=943MiB/1100MiB
  workingSet=943MiB peak=943MiB limitHits=0 oomKills=0

The jindo section comes from the native metrics dump (STATIC_ONLY JSON,
about 0.4 ms), read only through cached file systems, which are never
closed. The thread also samples the memory cgroup (v1 or v2) every
second and logs the same line at WARN when the working set (usage minus
inactive file) first crosses 80%, 90% and 95% of the limit, resetting
below 70%, so the last line before an OOM kill shows what was open.

The reporter is off by default (interval 0), to be turned on, for
example with 1 min, for jobs that keep getting OOMKilled. A sample costs
about 50 us and a full line about 0.2 ms plus the dump.

Verified on JDK 11 against OSS with jindosdk 6.10.2: 16 streams in a
960 MiB memcg logged "working set is at 90% of the limit" with
prefetchCache=308MiB right before the kernel OOM-killed the JVM; after
all streams closed, prefetchCache dropped to 0 MiB while anon stayed at
934 MiB, which is glibc retention rather than Jindo.
- Always delegate close() again and count a stream closed only after the
  delegate close succeeds, so a cleanup retry after a failed close still
  reaches Jindo (e.g. BTreeIndexWriter calls closeQuietly after close fails).
- Paimon never closes FileIOs, so the reporter cannot be tied to their
  lifecycle. It now starts on the first counted stream open, stops after an
  interval without stream activity, and is restarted by the next open. Its
  context class loader is the one that loaded paimon-jindo, so it no longer
  pins the loader of whichever job opened the first stream.
- Keep a single active counter and reset the peak with a CAS loop, so a log
  line never shows a negative open count or a peak below the open count.
- Cgroup limits are hierarchical: walk from the process's cgroup to the mount
  root and report and alarm on the level whose working set is closest to its
  limit, reading limit, usage and events from that same level.
- An interval of 0 now also skips counting. Each stream captures its counter
  when it is opened, so its open and close stay balanced.
- Guard the one-time close accounting with an AtomicBoolean. Two concurrent
  successful closes of one stream could both see it open and decrement the
  active count twice, leaving open at -1 and keeping the reporter running.
- A stream opened between the reporter's idle check and its shutdown saw it
  running and started no replacement, so its events were never reported.
  After clearing the running flag, stop() now also checks for events since
  the idle check and keeps running when there are any, logging them at the
  next interval.
- Starting the reporter must not fail I/O: the stream is already open when
  it is counted, so a failure to create the thread (e.g. no native thread
  near the memory limit) is now logged, the running flag is cleared, and a
  later stream retries after one interval.
- Use the shortest interval set by any FileIO instead of the first one, and
  read it on every sample so that a running reporter picks it up.
- Keep one alarm level per cgroup level. With a single level, a parent's
  95% WARN muted a child that later became the level closest to its limit.
- Count Jindo multipart (two-phase) output streams, which bypassed the
  output counters. Such a stream holds no native stream and cannot retry
  closeForCommit(), so even a failed attempt counts it closed.
- Say that the counters cover the class loader of paimon-jindo rather than
  the whole JVM, which differs when jobs bundle their own copy.
@sundapeng sundapeng changed the title [jindo] Log JVM-wide Jindo stream and memory statistics [jindo] Log Jindo stream and memory statistics Oct 26, 2026
@sundapeng
sundapeng marked this pull request as ready for review October 29, 2026 18:19
@sundapeng sundapeng closed this Oct 29, 2026
@sundapeng sundapeng reopened this Oct 29, 2026
@sundapeng sundapeng closed this Oct 30, 2026
@sundapeng sundapeng reopened this Oct 30, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant