hadoop-common-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Steve Loughran (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (HADOOP-13871) ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks performance on branch-2.8 awful
Date Thu, 08 Dec 2016 13:32:58 GMT

    [ https://issues.apache.org/jira/browse/HADOOP-13871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15732215#comment-15732215
] 

Steve Loughran edited comment on HADOOP-13871 at 12/8/16 1:32 PM:
------------------------------------------------------------------

Logging org.apache.http 
{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}


was (Author: stevel@apache.org):
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-unsubscribe@hadoop.apache.org
For additional commands, e-mail: common-issues-help@hadoop.apache.org


Mime
View raw message