[
https://issues.apache.org/jira/browse/HADOOP-13871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15732215#comment-15732215
]
Steve Loughran commented on HADOOP-13871:
-----------------------------------------
Logging org.apache.http shows why things are taking just over 60s: something is
pausing and its only when the connection is closed that things return
{code}
2016-12-08 13:26:20,458 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[0-39234217], length=1048576, streamPosition=0, nextReadPosition=0
2016-12-08 13:26:20,460 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(671)) - Sending
Request: GET https://landsat-pds.s3.amazonaws.com /scene_list.gz Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.10.6 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, Range:
bytes=0-39234217, Content-Type: application/x-www-form-urlencoded;
charset=utf-8, )
2016-12-08 13:26:20,460 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:requestConnection(184)) - Connection
request: [route: {s}->https://landsat-pds.s3.amazonaws.com:443][total kept
alive: 1; route allocated: 1 of 25; total allocated: 1 of 25]
2016-12-08 13:26:20,461 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:leaseConnection(218)) - Connection leased:
[id: 1][route: {s}->https://landsat-pds.s3.amazonaws.com:443][total kept alive:
0; route allocated: 1 of 25; total allocated: 1 of 25]
2016-12-08 13:26:20,462 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
protocol.RequestAddCookies (RequestAddCookies.java:process(122)) - CookieSpec
selected: default
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
protocol.RequestAuthCache (RequestAuthCache.java:process(76)) - Auth cache not
set in the context
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
protocol.RequestProxyAuthentication
(RequestProxyAuthentication.java:process(88)) - Proxy auth state: UNCHALLENGED
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
conn.DefaultClientConnection
(DefaultClientConnection.java:sendRequestHeader(276)) - Sending request: GET
/scene_list.gz HTTP/1.1
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(280)) - >> GET
/scene_list.gz HTTP/1.1
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >> Host:
landsat-pds.s3.amazonaws.com
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >>
Authorization: *REMOVED*
2016-12-08 13:26:20,463 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >>
User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.10.6 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102
2016-12-08 13:26:20,464 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >> Range:
bytes=0-39234217
2016-12-08 13:26:20,464 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >> Date:
Thu, 08 Dec 2016 13:26:20 GMT
2016-12-08 13:26:20,464 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >>
Content-Type: application/x-www-form-urlencoded; charset=utf-8
2016-12-08 13:26:20,464 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:sendRequestHeader(283)) - >>
Connection: Keep-Alive
2016-12-08 13:26:20,643 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
conn.DefaultClientConnection
(DefaultClientConnection.java:receiveResponseHeader(261)) - Receiving response:
HTTP/1.1 206 Partial Content
2016-12-08 13:26:20,643 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(264)) - <<
HTTP/1.1 206 Partial Content
2016-12-08 13:26:20,643 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
x-amz-id-2:
cZjR9+rI+ZlDKmRWEkFmnCQmj0p7jeF9c5/kXVKeM5oKLTQRf0rQOfR1ipw5r0lnmPbfknnj+o8=
2016-12-08 13:26:20,643 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
x-amz-request-id: 71429013F16577FD
2016-12-08 13:26:20,643 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Date: Thu, 08 Dec 2016 13:26:21 GMT
2016-12-08 13:26:20,644 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Last-Modified: Thu, 08 Dec 2016 11:32:05 GMT
2016-12-08 13:26:20,644 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
ETag: "00585bfc6fa4c4295c5a0073f7fa6922"
2016-12-08 13:26:20,644 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Accept-Ranges: bytes
2016-12-08 13:26:20,644 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Content-Range: bytes 0-39234216/39234217
2016-12-08 13:26:20,644 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Content-Type: application/octet-stream
2016-12-08 13:26:20,645 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Content-Length: 39234217
2016-12-08 13:26:20,645 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (DefaultClientConnection.java:receiveResponseHeader(267)) - <<
Server: AmazonS3
2016-12-08 13:26:20,645 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:logHeaderRequestId(836)) -
x-amzn-RequestId: not available
2016-12-08 13:26:20,646 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:handleResponse(1091)) - Received
successful response: 206, AWS Request ID: 71429013F16577FD
2016-12-08 13:26:20,647 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:logResponseRequestId(856)) - AWS
Request ID: 71429013F16577FD
2016-12-08 13:27:16,428 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 0 in 121 reads: 55,968,522,151 nS
2016-12-08 13:27:18,158 [java-sdk-http-connection-reaper] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:closeIdleConnections(293)) - Closing
connections idle longer than 60 SECONDS
2016-12-08 13:27:18,159 [java-sdk-http-connection-reaper] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:closeIdleConnections(293)) - Closing
connections idle longer than 60 SECONDS
2016-12-08 13:28:18,165 [java-sdk-http-connection-reaper] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:closeIdleConnections(293)) - Closing
connections idle longer than 60 SECONDS
2016-12-08 13:28:18,169 [java-sdk-http-connection-reaper] DEBUG
conn.DefaultClientConnection (DefaultClientConnection.java:close(182)) -
Connection 0.0.0.0:50399<->52.218.16.241:443 closed
2016-12-08 13:28:18,170 [java-sdk-http-connection-reaper] DEBUG
conn.PoolingClientConnectionManager
(PoolingClientConnectionManager.java:closeIdleConnections(293)) - Closing
connections idle longer than 60 SECONDS
2016-12-08 13:28:19,931 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 1 in 121 reads: 63,503,155,385 nS
{code}
> ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks
> performance on branch-2.8 awful
> ---------------------------------------------------------------------------------------------------
>
> Key: HADOOP-13871
> URL: https://issues.apache.org/jira/browse/HADOOP-13871
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Affects Versions: 2.8.0
> Environment: landsat bucket from the UK
> Reporter: Steve Loughran
> Assignee: Steve Loughran
>
> The ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks takes
> 15s on branch-2, but is now taking minutes on branch-2.8.
> This is a regression, and it's surfacing on some internal branches too. Even
> where the code hasn't changed. It does not happen on branch-2, which has a
> later SDK.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
