steveloughran commented on PR #4766:
URL: https://github.com/apache/hadoop/pull/4766#issuecomment-1220968467
The async stream draining only executes (in the other thread) if the
original invoker waits for the result.
this is not caused by some synchronized conflict -I made the method being
invoked static to ensure this.
And the logging of the start/finish of the call are present. just not the
bit in the middle.
## test run with the {{join()}} to make it blocking.
the `[JUnit-testUnbufferDraining]` thread is the one doing the
unbuffer()/read() calls; the `[s3a-transfer-stevel-london-unbounded-pool]`
threads are the unbounded pool into which work
is queued. it is the unbounded pool; so that is not the limit.
That would appear to leave some aspect of CompletableFuture, possibly
related to how things are being wrapped in duration tracking, audit spans etc.
But I can't see this, and they all seem to work everywhere else.
```
{code}
2022-08-19 18:52:50,102 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(663)) - Closing stream
unbuffer(): soft
2022-08-19 18:52:50,102 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(676)) - initiating
asynchronous drain of 998 bytes
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$null$0(1609)) - Starting
submitted operation in ec003fc0-e885-4793-b9b9-34296cc34f3a-00000010
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AInputStream (S3AInputStream.java:drainOrAbortHttpStream(761)) -
drain or abort reason unbuffer() remaining=998 abort=false
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AInputStream (S3AInputStream.java:drainOrAbortHttpStream(771)) -
draining 998 bytes
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AInputStream (S3AInputStream.java:drainOrAbortHttpStream(789)) -
Drained stream of 998 bytes
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AInputStream (S3AInputStream.java:drainOrAbortHttpStream(801)) -
Closing stream
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AInputStream (S3AInputStream.java:drainOrAbortHttpStream(826)) -
Stream s3a://stevel-london/test/testUnbufferDraining closed: unbuffer();
remaining=0
2022-08-19 18:52:50,102 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$null$0(1613)) - Completed
submitted operation in ec003fc0-e885-4793-b9b9-34296cc34f3a-00000010
2022-08-19 18:52:50,104 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInstrumentation (S3AInstrumentation.java:merge(1172)) - Merging
statistics into FS statistics in unbuffer(): ...
2022-08-19 18:52:50,104 [JUnit-testUnbufferDraining] INFO
s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(219)) -
testUnbufferDraining: Starting read/unbuffer #2
{code}
```
## no waiting
But without the join, no joy. even though the log above shows the drain is
being executed in the new thread.
```
2022-08-19 18:36:56,109 [JUnit-testUnbufferDraining] DEBUG s3a.Invoker
(DurationInfo.java:close(101)) - read: duration 0:00.000s
2022-08-19 18:36:56,109 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(663)) - Closing stream
unbuffer(): soft
2022-08-19 18:36:56,109 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(676)) - initiating
asynchronous drain of 998 bytes
2022-08-19 18:36:56,109 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$null$0(1609)) - Starting
submitted operation in 54f63eab-e0d8-48b5-a0c1-9a877576a450-00000010
2022-08-19 18:36:56,109 [s3a-transfer-stevel-london-unbounded-pool5-t3]
DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$null$0(1613)) - Completed
submitted operation in 54f63eab-e0d8-48b5-a0c1-9a877576a450-00000010
2022-08-19 18:36:56,110 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInstrumentation (S3AInstrumentation.java:merge(1172)) - Merging
statistics into FS statistics in unbuffer(): ...
2022-08-19 18:36:56,111 [JUnit-testUnbufferDraining] INFO
s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(219)) -
testUnbufferDraining: Starting read/unbuffer #2
2022-08-19 18:36:56,111 [JUnit-testUnbufferDraining] DEBUG s3a.Invoker
(DurationInfo.java:<init>(80)) - Starting: lazySeek
2022-08-19 18:36:56,111 [JUnit-testUnbufferDraining] DEBUG
s3a.S3AInputStream (S3AInputStream.java:reopen(263)) -
reopen(s3a://stevel-london/test/testUnbufferDraining) for read from new offset
range[49001-50000], length=1, streamPosition=49002, nextReadPosition=49001,
policy=random
2022-08-19 18:36:56,111 [JUnit-testUnbufferDraining] DEBUG
impl.ChangeDetectionPolicy
(ChangeDetectionPolicy.java:applyRevisionConstraint(430)) - Restricting get
request to version RFW1GsJZAc_mL5eKKWRnB7tX2K9B3I98
2022-08-19 18:36:56,112 [JUnit-testUnbufferDraining] DEBUG
impl.LoggingAuditor (LoggingAuditor.java:beforeExecution(327)) - [11]
54f63eab-e0d8-48b5-a0c1-9a877576a450-00000010 Executing op_open with
{action_http_get_request 'test/testUnbufferDraining' size=998, mutating=false};
https://audit.example.org/hadoop/1/op_open/54f63eab-e0d8-48b5-a0c1-9a877576a450-00000010/?op=op_open&p1=test/testUnbufferDraining&pr=stevel&ps=6cd73b0d-cfa1-41ec-ba5a-305b3abff0b0&id=54f63eab-e0d8-48b5-a0c1-9a877576a450-00000010&t0=30&fs=54f63eab-e0d8-48b5-a0c1-9a877576a450&t1=11&ts=1660930615787
2022-08-19 18:36:58,223 [JUnit-testUnbufferDraining] DEBUG s3a.Invoker
(DurationInfo.java:close(101)) - lazySeek: duration 0:02.112s
```
then the timeout surfaces on the next read()
```
org.apache.hadoop.net.ConnectTimeoutException: re-open
s3a://stevel-london/test/testUnbufferDraining at 49001 on
s3a://stevel-london/test/testUnbufferDraining:
com.amazonaws.SdkClientException: Unable to execute HTTP request: Timeout
waiting for connection from pool
at
org.apache.hadoop.fs.s3a.S3AUtils.translateInterruptedException(S3AUtils.java:385)
at
org.apache.hadoop.fs.s3a.S3AUtils.translateException(S3AUtils.java:198)
at
org.apache.hadoop.fs.s3a.Invoker.onceTrackingDuration(Invoker.java:149)
at
org.apache.hadoop.fs.s3a.S3AInputStream.reopen(S3AInputStream.java:276)
at
org.apache.hadoop.fs.s3a.S3AInputStream.lambda$lazySeek$1(S3AInputStream.java:429)
at
org.apache.hadoop.fs.s3a.Invoker.lambda$maybeRetry$3(Invoker.java:284)
at org.apache.hadoop.fs.s3a.Invoker.once(Invoker.java:122)
at org.apache.hadoop.fs.s3a.Invoker.maybeRetry(Invoker.java:410)
at org.apache.hadoop.fs.s3a.Invoker.maybeRetry(Invoker.java:282)
at org.apache.hadoop.fs.s3a.Invoker.maybeRetry(Invoker.java:326)
at
org.apache.hadoop.fs.s3a.S3AInputStream.lazySeek(S3AInputStream.java:421)
at org.apache.hadoop.fs.s3a.S3AInputStream.read(S3AInputStream.java:455)
at java.io.FilterInputStream.read(FilterInputStream.java:83)
at
org.apache.hadoop.fs.s3a.performance.ITestUnbufferDraining.testUnbufferDraining(ITestUnbufferDraining.java:141)
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:299)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
Caused by: com.amazonaws.SdkClientException: Unable to execute HTTP request:
Timeout waiting for connection from pool
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleRetryableException(AmazonHttpClient.java:1219)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1165)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:814)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:781)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:755)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:715)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:697)
at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:561)
at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:541)
at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:5456)
at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:5403)
at
com.amazonaws.services.s3.AmazonS3Client.getObject(AmazonS3Client.java:1524)
at
org.apache.hadoop.fs.s3a.S3AFileSystem$InputStreamCallbacksImpl.getObject(S3AFileSystem.java:1600)
at
org.apache.hadoop.fs.s3a.S3AInputStream.lambda$reopen$0(S3AInputStream.java:278)
at
org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.invokeTrackingDuration(IOStatisticsBinding.java:547)
at org.apache.hadoop.fs.s3a.Invoker.onceTrackingDuration(Invoker.java:147)
... 26 more
Caused by:
com.amazonaws.thirdparty.apache.http.conn.ConnectionPoolTimeoutException:
Timeout waiting for connection from pool
at
com.amazonaws.thirdparty.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:316)
at
com.amazonaws.thirdparty.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282)
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
com.amazonaws.http.conn.ClientConnectionRequestFactory$Handler.invoke(ClientConnectionRequestFactory.java:70)
at com.amazonaws.http.conn.$Proxy22.get(Unknown Source)
at
com.amazonaws.thirdparty.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
at
com.amazonaws.thirdparty.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at
com.amazonaws.thirdparty.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at
com.amazonaws.thirdparty.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at
com.amazonaws.thirdparty.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
at
com.amazonaws.http.apache.client.impl.SdkHttpClient.execute(SdkHttpClient.java:72)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1346)
at
com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1157)
... 40 more
```
--
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]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
