Skip to content

chore: add timing logs for file index partition and file listing#18417

Open
suryaprasanna wants to merge 1 commit intoapache:masterfrom
suryaprasanna:file-index-logging
Open

chore: add timing logs for file index partition and file listing#18417
suryaprasanna wants to merge 1 commit intoapache:masterfrom
suryaprasanna:file-index-logging

Conversation

@suryaprasanna
Copy link
Copy Markdown
Contributor

Describe the issue this Pull Request addresses

File index operations currently do not provide enough visibility into how much time is spent listing partitions, fetching files from metadata, and filtering files into file slices. This makes it harder to debug slow queries and identify where file-index time is being spent.

Summary and Changelog

Adds timing and context logs in BaseHoodieTableFileIndex for key file-index stages.

  • Log time taken to list partition paths with and without partition predicates
  • Log cache miss counts before fetching uncached partition files
  • Log time taken by getAllFilesInPartitions
  • Log time taken by filterFiles while building file slices
  • Include table name in partition listing failure messages

Impact

No public API or user-facing behavior change. This improves observability for file-index execution and helps diagnose performance issues in partition and file listing paths.

Risk Level

low

This change only adds logging and slightly updates an internal exception message with table context. No functional behavior is intended to change.

Documentation Update

none

Contributor's checklist

  • Read through contributor's guide
  • Enough context is provided in the sections above
  • Adequate tests were added if applicable

@github-actions github-actions bot added the size:S PR with lines of changes in (10, 100] label Mar 29, 2026
@codecov-commenter
Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 94.73684% with 1 line in your changes missing coverage. Please review.
✅ Project coverage is 68.22%. Comparing base (1eb97b3) to head (6b4efb3).
⚠️ Report is 1 commits behind head on master.

Files with missing lines Patch % Lines
...java/org/apache/hudi/BaseHoodieTableFileIndex.java 94.73% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff            @@
##             master   #18417   +/-   ##
=========================================
  Coverage     68.21%   68.22%           
+ Complexity    27709    27698   -11     
=========================================
  Files          2440     2440           
  Lines        134249   134265   +16     
  Branches      16179    16181    +2     
=========================================
+ Hits          91578    91599   +21     
+ Misses        35565    35560    -5     
  Partials       7106     7106           
Flag Coverage Δ
common-and-other-modules 44.32% <78.94%> (+<0.01%) ⬆️
hadoop-mr-java-client 45.01% <78.94%> (+0.08%) ⬆️
spark-client-hadoop-common 48.32% <78.94%> (+<0.01%) ⬆️
spark-java-tests 48.72% <94.73%> (+0.01%) ⬆️
spark-scala-tests 45.25% <94.73%> (+0.01%) ⬆️
utilities 38.40% <78.94%> (+0.02%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files with missing lines Coverage Δ
...java/org/apache/hudi/BaseHoodieTableFileIndex.java 84.54% <94.73%> (+1.06%) ⬆️

... and 14 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@hudi-bot
Copy link
Copy Markdown
Collaborator

CI report:

Bot commands @hudi-bot supports the following commands:
  • @hudi-bot run azure re-run the last Azure build

Copy link
Copy Markdown
Member

@voonhous voonhous left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Main concern here is that the logs are too noisy.

  • Are these logs only used for debugging?
  • Should we use log.debug(...) for routine timing logs instead of log.info(...)?
  • We can consider logging at info level when something is slow, i.e. if (elapsed > threshold) log.info(...) or unexpected (e.g., large cache miss ratio)

.collect(Collectors.toList())
));
} finally {
log.info("On {} with query instant as {}, it took {}ms to filter {} files into file slices across {} partitions",
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My main concern here is that the logs generated here will be too noisy.

This fires on every single query, even if it took 1ms. For a busy Spark application hitting multiple Hudi tables, this alone generates one info line per query.

Comment on lines +504 to +505
log.info("On {}, out of {} partition paths, {} are missing from cache. Loading them.",
metaClient.getTableConfig().getTableName(), partitionPaths.size(), missingPartitionPaths.size());
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

uard the "missing from cache" log with if (missingPartitionPaths.size() > 0) there is no point logging when everything is cached.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

size:S PR with lines of changes in (10, 100]

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants