Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HADOOP-18091. S3A auditing leaks memory through ThreadLocal references #3930

Merged
merged 12 commits into from
Feb 10, 2022

Conversation

steveloughran
Copy link
Contributor

@steveloughran steveloughran commented Jan 25, 2022

Adds a new map type WeakReferenceMap, which stores weak references to values,
and a WeakReferenceThreadMap subclass to more closely resemble a thread local
type, as it is a map of thread id to value.

construct it with a factory method and optional callback
for notification on loss and regeneration.

 WeakReferenceThreadMap<WrappingAuditSpan> activeSpan =
      new WeakReferenceThreadMap<>(
          (k) -> getUnbondedSpan(),
          this::noteSpanReferenceLost);

This is used in ActiveAuditManagerS3A for span tracking.

If a calling method has a reference to the span then even with gc the reference will
be valid, it's only if no more references are held that there will be problems.

This does mean that if S3 a code keeps references around then back references to the auditor are retained.

but those classes which can get returned and which do have spans (list iterators, input and output streams, ...)
And all have callbacks into the main S3a file system anyway.

Testing this has been fun; about as hard as the production code.

The good news: We can do this in a unit test relatively quickly.
We just create a sequence of audit managers and in each one
Schedule tasks across a thread pool to create spans.
By providing an auditor implementation whose class and spans use lots of memory
We can trigger OOM fast on the original code.

With the new structure this doesn't happen. Instead, and after 100+ iterations
GC calls trigger removal of the only-weakly-referenced spans.

I have run the Itest suites against s3 london and all is well; retesting.

my system is set to fail if any operation is ever executed out of a span, other than those which happened during copy operations when the S3 SDK transfer manager invokes them.

That is the sole risk I can see in this world: that if and external reference is not held then the thread reference will be discarded prematurely.

I don't see it happening in this case but will review carefully just to make sure.

How was this patch tested?

New test which triggers oom on the old code, but works now.

For code changes:

  • Does the title or this PR starts with the corresponding JIRA issue id (e.g. 'HADOOP-17799. Your PR title ...')?
  • Object storage: have the integration tests been executed and the endpoint declared according to the connector-specific documentation?
  • If adding new dependencies to the code, are these dependencies licensed in a way that is compatible for inclusion under ASF 2.0?
  • If applicable, have you updated the LICENSE, LICENSE-binary, NOTICE-binary files?

@steveloughran
Copy link
Contributor Author

note, does not yet update the docs

@steveloughran
Copy link
Contributor Author

needs unit tests of the basic map class and its operations

Copy link
Contributor Author

@steveloughran steveloughran left a comment

Choose a reason for hiding this comment

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

got some changes todo

@apache apache deleted a comment from hadoop-yetus Jan 27, 2022
@apache apache deleted a comment from hadoop-yetus Jan 31, 2022
A map where references can be garbage collected.
This makes it a best-effort map

Change-Id: I4622f51f87cfe0fb50629e447f6828c8b5072c8c
if this is working, hope to use for iostats snapshots too

Change-Id: I808ced6dc4bfbf2b961174dbdb544636a6253592
Creates managers in a separate thread, creates spans.

runs out of memory

Change-Id: Ic4ff382e4edfa37ec7feb46265ba5a63e1abb560
no longer prunes anything, however.

Change-Id: I71f4f36dcc0900531441b870f3f5de79c64fb2ee
need to create lots of spans during the life of an auditor so the memory consumption
is enough for GC to care.

Change-Id: Iad3a350b8243031ad158c966e130bab77ab59fb3
* hadoop common TestWeakReferenceMap for map semantics and recreating of entries
  on demand.
* TestActiveAuditManagerThreadLeakage test enhanced a lot with tests of demand creation
  etc
* auditing docs brought up to date
* CommonAuditContext docs cover memory leak risks, as does audit arch.
  the put() call will log call stack if logging at trace, to provide a way
  to debug problems, if they ever surface.
* s3a committers explicitly remove jobid in commit/abort ops.
  (manifest committer should will do the same)
* auditing is still turned off for consistency with Hadoop 3.3.2
  its there for support calls, people can deploy it in production when they see
  benefits, but there's no cost/risk to others.

Change-Id: I63ec9ec35d80d25d9e3cf1eedaca3aff595a06fa
If, somehow, spans were not being deactivated from threads which where
then destroyed, then the map would fill up with weak references
to those spans.

They wouldn't stop GC-ing of the audit manager, but they would fill
up the hash table.

Now, when a span is deactivated.
1. its entry is removed from the map (not replaced with the unbounded
  one, as that will happen on demand)
2. when the unbounded span is active on a thread, its deactivate()
   call also removes it from the map.
3. every so often (PRUNE_THRESHOLD = 10000), a full prune
  of the reference map is performed. this will remove any null references.

Because of 1 & 2, when valid or unbound spans are deactivated, the map shrinks.
Because of 3, even if threads are destroyed with valid spans active,
after a GC the fact that they have been GC'd will surface.

This doesn't remove map entries with unbonded spans active as the
strong references held to them means they get GC'd.

We could do that with a prune() in the audit manager removing
all entries where !isValid() is true.

Change-Id: I62fc9d66216dd8fdafb22d8b57dcdd6d311915e3
Turning auditing back on.

Change-Id: I46032e467cc399a0f292f756a4bf7d1fd5e30352
Change-Id: I4af0a49cc87a0998578c3170e5199665f7f572bc
Change-Id: I6b2c76131e520081c649a89a638b03b2398780e1
@steveloughran steveloughran force-pushed the s3/HADOOP-18091-thread-map branch from 279a19c to ec7fac6 Compare January 31, 2022 11:10
Copy link
Contributor

@mukund-thakur mukund-thakur left a comment

Choose a reason for hiding this comment

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

some minor comments

// but if memory allocation in test runs increase, it
// may cease to hold. in which case: create more
// audit managers
LOG.info("Totel prune count {}", pruneCount);
Copy link
Contributor

Choose a reason for hiding this comment

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

typo in totel?

Copy link
Contributor

@mehakmeet mehakmeet left a comment

Choose a reason for hiding this comment

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

Looks good, some minor comments and doubts.

Should we have Integration tests where the span is made in the Filesystem and then we check if the ThreadLocal refs are removed after that Filesystem is closed, recreating the original problem?

@@ -111,6 +118,14 @@
public static final String NOT_A_WRAPPED_SPAN
= "Span attached to request is not a wrapped span";

/**
* Arbritary threshold for triggering pruning on deactivation.
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: "Arbitrary"

* non-atomic and non-blocking.
* @return the number of entries pruned.
*/
public int prune() {
Copy link
Contributor

Choose a reason for hiding this comment

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

Why do we need to prune for WeakReferences, thought the point of using them was that we don't need to manually do this, and they'll be cleared automatically through the gc? Maybe I'm not understanding this right, please let me know

Copy link
Contributor Author

Choose a reason for hiding this comment

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

because the map will become full of threadId to null entries, which consumes small amounts of memory (one record per terminated thread). pruning just cleans it all out

* @param key key of lost reference
*/
private void noteLost(final K key) {
// incrment local counter
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: "increment"

return remove(curentThreadId());
}

public long curentThreadId() {
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: "current"

_Auditing was disabled by default until a fix was implemented._

The memory leak has been fixed using a new class `org.apache.hadoop.util.WeakReferenceMap`
to store a map of thread IDs to active spans. When the S3A fileystem is closed,
Copy link
Contributor

Choose a reason for hiding this comment

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

typo : "filesystem"

`org.apache.hadoop.fs.audit.CommonAuditContext` to `TRACE`
to log the origin of operations which add log entries.

This will produce a log entry whose strack trace will show the caller chain.f
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: "stack trace"

}

/**
* Verifu that pruning takes place intermittently.
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: "Verify"

@@ -82,3 +82,6 @@ log4j.logger.org.apache.hadoop.fs.s3a.S3AStorageStatistics=INFO
#log4j.logger.org.apache.hadoop.fs.s3a.audit=DEBUG
# log request creation, span lifecycle and other low-level details
#log4j.logger.org.apache.hadoop.fs.s3a.audit=TRACE

# uncomment this to trace where context entries are set
# log4j.logger.org.apache.hadoop.fs.audit.CommonAuditContext=TRACE
Copy link
Contributor

Choose a reason for hiding this comment

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

nit: Newline at eof

@apache apache deleted a comment from hadoop-yetus Feb 2, 2022
@apache apache deleted a comment from hadoop-yetus Feb 2, 2022
@steveloughran
Copy link
Contributor Author

@mehakmeet @mukund-thakur thanks for your feedback; will address this week

* typos and nits
* cleanup in test teardown
* tuning docs

Change-Id: I088f050fa34b097266b70f3e078da89e083dfdf9
@hadoop-yetus
Copy link

🎊 +1 overall

Vote Subsystem Runtime Logfile Comment
+0 🆗 reexec 0m 42s Docker mode activated.
_ Prechecks _
+1 💚 dupname 0m 0s No case conflicting files found.
+0 🆗 codespell 0m 1s codespell was not available.
+0 🆗 markdownlint 0m 1s markdownlint was not available.
+1 💚 @author 0m 0s The patch does not contain any @author tags.
+1 💚 test4tests 0m 0s The patch appears to include 5 new or modified test files.
_ trunk Compile Tests _
+0 🆗 mvndep 44m 43s Maven dependency ordering for branch
+1 💚 mvninstall 24m 27s trunk passed
+1 💚 compile 22m 20s trunk passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 compile 19m 34s trunk passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 checkstyle 3m 38s trunk passed
+1 💚 mvnsite 2m 40s trunk passed
+1 💚 javadoc 1m 55s trunk passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javadoc 2m 35s trunk passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 spotbugs 3m 48s trunk passed
+1 💚 shadedclient 20m 58s branch has no errors when building and testing our client artifacts.
-0 ⚠️ patch 21m 22s Used diff version of patch file. Binary files and potentially other changes not applied. Please rebase and squash commits if necessary.
_ Patch Compile Tests _
+0 🆗 mvndep 0m 29s Maven dependency ordering for patch
+1 💚 mvninstall 1m 35s the patch passed
+1 💚 compile 21m 42s the patch passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javac 21m 42s the patch passed
+1 💚 compile 19m 38s the patch passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 javac 19m 38s the patch passed
+1 💚 blanks 0m 0s The patch has no blanks issues.
+1 💚 checkstyle 3m 33s the patch passed
+1 💚 mvnsite 2m 38s the patch passed
+1 💚 xml 0m 2s The patch has no ill-formed XML file.
+1 💚 javadoc 1m 51s the patch passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javadoc 2m 33s the patch passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 spotbugs 4m 8s the patch passed
+1 💚 shadedclient 20m 59s patch has no errors when building and testing our client artifacts.
_ Other Tests _
+1 💚 unit 17m 29s hadoop-common in the patch passed.
+1 💚 unit 2m 31s hadoop-aws in the patch passed.
+1 💚 asflicense 1m 0s The patch does not generate ASF License warnings.
250m 58s
Subsystem Report/Notes
Docker ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/6/artifact/out/Dockerfile
GITHUB PR #3930
Optional Tests dupname asflicense compile javac javadoc mvninstall mvnsite unit shadedclient spotbugs checkstyle codespell xml markdownlint
uname Linux 5ec0c4d6faa4 4.15.0-161-generic #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/bin/hadoop.sh
git revision trunk / 06154c5
Default Java Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
Multi-JDK versions /usr/lib/jvm/java-11-openjdk-amd64:Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04 /usr/lib/jvm/java-8-openjdk-amd64:Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
Test Results https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/6/testReport/
Max. process+thread count 3020 (vs. ulimit of 5500)
modules C: hadoop-common-project/hadoop-common hadoop-tools/hadoop-aws U: .
Console output https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/6/console
versions git=2.25.1 maven=3.6.3 spotbugs=4.2.2
Powered by Apache Yetus 0.14.0-SNAPSHOT https://yetus.apache.org

This message was automatically generated.

Copy link
Contributor

@mukund-thakur mukund-thakur left a comment

Choose a reason for hiding this comment

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

+1, LGTM

@steveloughran
Copy link
Contributor Author

ok. just want to make sure i've got all those typos down

@apache apache deleted a comment from hadoop-yetus Feb 9, 2022
Change-Id: I1809cec29d9354185d759e24e65688a44d50cb89
@hadoop-yetus
Copy link

🎊 +1 overall

Vote Subsystem Runtime Logfile Comment
+0 🆗 reexec 0m 48s Docker mode activated.
_ Prechecks _
+1 💚 dupname 0m 0s No case conflicting files found.
+0 🆗 codespell 0m 1s codespell was not available.
+0 🆗 markdownlint 0m 1s markdownlint was not available.
+1 💚 @author 0m 0s The patch does not contain any @author tags.
+1 💚 test4tests 0m 0s The patch appears to include 5 new or modified test files.
_ trunk Compile Tests _
+0 🆗 mvndep 12m 50s Maven dependency ordering for branch
+1 💚 mvninstall 23m 48s trunk passed
+1 💚 compile 24m 6s trunk passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 compile 20m 21s trunk passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 checkstyle 3m 32s trunk passed
+1 💚 mvnsite 2m 46s trunk passed
+1 💚 javadoc 1m 51s trunk passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javadoc 2m 29s trunk passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 spotbugs 3m 52s trunk passed
+1 💚 shadedclient 21m 5s branch has no errors when building and testing our client artifacts.
-0 ⚠️ patch 21m 30s Used diff version of patch file. Binary files and potentially other changes not applied. Please rebase and squash commits if necessary.
_ Patch Compile Tests _
+0 🆗 mvndep 0m 29s Maven dependency ordering for patch
+1 💚 mvninstall 1m 38s the patch passed
+1 💚 compile 22m 49s the patch passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javac 22m 49s the patch passed
+1 💚 compile 20m 20s the patch passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 javac 20m 20s the patch passed
+1 💚 blanks 0m 0s The patch has no blanks issues.
+1 💚 checkstyle 3m 35s the patch passed
+1 💚 mvnsite 2m 40s the patch passed
+1 💚 xml 0m 1s The patch has no ill-formed XML file.
+1 💚 javadoc 1m 50s the patch passed with JDK Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04
+1 💚 javadoc 2m 32s the patch passed with JDK Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
+1 💚 spotbugs 4m 12s the patch passed
+1 💚 shadedclient 21m 30s patch has no errors when building and testing our client artifacts.
_ Other Tests _
+1 💚 unit 18m 0s hadoop-common in the patch passed.
+1 💚 unit 2m 31s hadoop-aws in the patch passed.
+1 💚 asflicense 0m 57s The patch does not generate ASF License warnings.
224m 14s
Subsystem Report/Notes
Docker ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/7/artifact/out/Dockerfile
GITHUB PR #3930
Optional Tests dupname asflicense compile javac javadoc mvninstall mvnsite unit shadedclient spotbugs checkstyle codespell xml markdownlint
uname Linux 750cca60ac58 4.15.0-161-generic #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Build tool maven
Personality dev-support/bin/hadoop.sh
git revision trunk / 554b55f
Default Java Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
Multi-JDK versions /usr/lib/jvm/java-11-openjdk-amd64:Ubuntu-11.0.13+8-Ubuntu-0ubuntu1.20.04 /usr/lib/jvm/java-8-openjdk-amd64:Private Build-1.8.0_312-8u312-b07-0ubuntu1~20.04-b07
Test Results https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/7/testReport/
Max. process+thread count 3158 (vs. ulimit of 5500)
modules C: hadoop-common-project/hadoop-common hadoop-tools/hadoop-aws U: .
Console output https://ci-hadoop.apache.org/job/hadoop-multibranch/job/PR-3930/7/console
versions git=2.25.1 maven=3.6.3 spotbugs=4.2.2
Powered by Apache Yetus 0.14.0-SNAPSHOT https://yetus.apache.org

This message was automatically generated.

@steveloughran steveloughran merged commit efdec92 into apache:trunk Feb 10, 2022
asfgit pushed a commit that referenced this pull request Feb 10, 2022
#3930)

Adds a new map type WeakReferenceMap, which stores weak
references to values, and a WeakReferenceThreadMap subclass
to more closely resemble a thread local type, as it is a
map of threadId to value.

Construct it with a factory method and optional callback
for notification on loss and regeneration.

 WeakReferenceThreadMap<WrappingAuditSpan> activeSpan =
      new WeakReferenceThreadMap<>(
          (k) -> getUnbondedSpan(),
          this::noteSpanReferenceLost);

This is used in ActiveAuditManagerS3A for span tracking.

Relates to
* HADOOP-17511. Add an Audit plugin point for S3A
* HADOOP-18094. Disable S3A auditing by default.

Contributed by Steve Loughran.

Change-Id: Ibf7bb082fd47298f7ebf46d92f56e80ca9b2aaf8
HarshitGupta11 pushed a commit to HarshitGupta11/hadoop that referenced this pull request Nov 28, 2022
apache#3930)


Adds a new map type WeakReferenceMap, which stores weak
references to values, and a WeakReferenceThreadMap subclass
to more closely resemble a thread local type, as it is a
map of threadId to value.

Construct it with a factory method and optional callback
for notification on loss and regeneration.

 WeakReferenceThreadMap<WrappingAuditSpan> activeSpan =
      new WeakReferenceThreadMap<>(
          (k) -> getUnbondedSpan(),
          this::noteSpanReferenceLost);

This is used in ActiveAuditManagerS3A for span tracking.

Relates to
* HADOOP-17511. Add an Audit plugin point for S3A
* HADOOP-18094. Disable S3A auditing by default.

Contributed by Steve Loughran.
jojochuang pushed a commit to jojochuang/hadoop that referenced this pull request May 23, 2023
…al references (apache#3930)

Adds a new map type WeakReferenceMap, which stores weak
references to values, and a WeakReferenceThreadMap subclass
to more closely resemble a thread local type, as it is a
map of threadId to value.

Construct it with a factory method and optional callback
for notification on loss and regeneration.

 WeakReferenceThreadMap<WrappingAuditSpan> activeSpan =
      new WeakReferenceThreadMap<>(
          (k) -> getUnbondedSpan(),
          this::noteSpanReferenceLost);

This is used in ActiveAuditManagerS3A for span tracking.

Relates to
* HADOOP-17511. Add an Audit plugin point for S3A
* HADOOP-18094. Disable S3A auditing by default.

Contributed by Steve Loughran.

Change-Id: Ibf7bb082fd47298f7ebf46d92f56e80ca9b2aaf8

 Conflicts:
	hadoop-common-project/hadoop-common/src/main/resources/core-default.xml

Change-Id: Iaa092c89ab0be16f816b56be78d795ce618a8656
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.

4 participants