[HADOOP-18416] ITestS3AIOStatisticsContext failure

• Type: Sub-task
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.3.5
• Fix Version/s: 3.3.5
• Component/s: fs/s3, test
• Labels: pull-request-available
• Assignee: Mehakmeet Singh
• Reporter: Steve Loughran
• Created: 23/Aug/22 17:18
• Updated: 28/Apr/23 11:44
• Resolved: 28/Sep/22 08:48

Description

test failure running the new ITestS3AIOStatisticsContext. attaching the stack and log file.

This happened on a large (12 thread) test run, but i can get it to come back intermittently on repeated runs of the whole suite, but never when i just run the single test case.

[ERROR] testThreadIOStatisticsForDifferentThreads(org.apache.hadoop.fs.s3a.ITestS3AIOStatisticsContext)  Time elapsed: 3.616 s  <<< FAILURE!
java.lang.AssertionError: 
[Counter named stream_write_bytes] 
Expecting actual not to be null
        at org.apache.hadoop.fs.statistics.IOStatisticAssertions.lookupStatistic(IOStatisticAssertions.java:160)
        at org.apache.hadoop.fs.statistics.IOStatisticAssertions.assertThatStatisticLong(IOStatisticAssertions.java:291)
        at org.apache.hadoop.fs.statistics.IOStatisticAssertions.assertThatStatisticCounter(IOStatisticAssertions.java:306)
        at org.apache.hadoop.fs.s3a.ITestS3AIOStatisticsContext.assertThreadStatisticsForThread(ITestS3AIOStatisticsContext.java:367)
        at org.apache.hadoop.fs.s3a.ITestS3AIOStatisticsContext.testThreadIOStatisticsForDifferentThreads(ITestS3AIOStatisticsContext.java:260)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
        at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:288)
        at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:282)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.lang.Thread.run(Thread.java:750)

I'm suspecting some race condition or gc pressure is releasing that reference in the worker thread.

proposed test changes

• worker thread changes its thread ID for the logs
• stores its thread context into a field, so there's guarantee of no GC
• logs more as it goes along.

Issue Links

• is broken by: HADOOP-17461 Add thread-level IOStatistics Context
• links to: GitHub Pull Request #4806
• links to: GitHub Pull Request #4931