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 Wed, 07 Dec 2016 19:12:59 GMT

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

Steve Loughran edited comment on HADOOP-13871 at 12/7/16 7:12 PM:
------------------------------------------------------------------

good news, I've been able to replicate it on the new SDK too, meaning its a network/load balance problem, not SDK related

{code}
2016-12-07 18:42:22,553 [Thread-1] DEBUG s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:22,913 [Thread-1] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from BasicAWSCredentialsProvider
2016-12-07 18:42:22,921 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-us-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 787e1df3-9887-fd11-ec8d-801a7836e20d, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:23,927 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service: null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID: 0D2990D655FE6CDD), S3 Extended Request ID: zam+lWQRapkEc17mnHEoLgeWBuFXGGLncQaxBi/a12Y3uohpoEAzRS1frsGb81AnU1HDJn2b7IU=
2016-12-07 18:42:23,978 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: f9fabf3f-9809-ad08-7c2f-1683f6d593cf, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,163 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: null
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: not available
2016-12-07 18:42:24,165 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:24,166 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:24,169 [Thread-1] INFO  contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:setup(184)) - Test filesystem = s3a://hwdev-steve-ireland-new implemented by S3AFileSystem{uri=s3a://hwdev-steve-ireland-new, workingDir=s3a://hwdev-steve-ireland-new/user/stevel, inputPolicy=normal, partSize=8000000, enableMultiObjectsDelete=true, maxKeys=5000, readAhead=65536, blockSize=33554432, multiPartThreshold=2147483647, blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@51dffc97, executor=BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=30, available=30, waiting=0}, activeCount=0}, statistics {0 bytes read, 0 bytes written, 0 read ops, 0 large read ops, 0 write ops}, metrics {{Context=S3AFileSystem} {FileSystemId=461d5b68-e18f-4e9b-b88f-ee6cee6196ac-hwdev-steve-ireland-new} {fsURI=s3a://hwdev-steve-ireland-new/} {files_created=0} {files_copied=0} {files_copied_bytes=0} {files_deleted=0} {fake_directories_deleted=0} {directories_created=0} {directories_deleted=0} {ignored_errors=0} {op_copy_from_local_file=0} {op_exists=0} {op_get_file_status=0} {op_glob_status=0} {op_is_directory=0} {op_is_file=0} {op_list_files=0} {op_list_located_status=0} {op_list_status=0} {op_mkdirs=0} {op_rename=0} {object_copy_requests=0} {object_delete_requests=0} {object_list_requests=0} {object_continue_list_requests=0} {object_metadata_requests=0} {object_multipart_aborted=0} {object_put_bytes=0} {object_put_requests=0} {object_put_requests_completed=0} {stream_write_failures=0} {stream_write_block_uploads=0} {stream_write_block_uploads_committed=0} {stream_write_block_uploads_aborted=0} {stream_write_total_time=0} {stream_write_total_data=0} {object_put_requests_active=0} {object_put_bytes_pending=0} {stream_write_block_uploads_active=0} {stream_write_block_uploads_pending=0} {stream_write_block_uploads_data_pending=0} {stream_read_fully_operations=0} {stream_opened=0} {stream_bytes_skipped_on_seek=0} {stream_closed=0} {stream_bytes_backwards_on_seek=0} {stream_bytes_read=0} {stream_read_operations_incomplete=0} {stream_bytes_discarded_in_abort=0} {stream_close_operations=0} {stream_read_operations=0} {stream_aborted=0} {stream_forward_seek_operations=0} {stream_backward_seek_operations=0} {stream_seek_operations=0} {stream_bytes_read_in_close=0} {stream_read_exceptions=0} }}
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerMkdirs(1478)) - Making directory: /test
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_mkdirs += 1  ->  1
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  1
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://hwdev-steve-ireland-new/test  (test)
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  1
2016-12-07 18:42:24,174 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 57239941-1812-a15f-736a-f3da7727b192, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,225 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null; Status Code: 404; Error Code: 404 Not Found; Request ID: 2B1E6AAB5BB13A50), S3 Extended Request ID: 37X2RRn7nQAt5RDTbO8jazu8ltPGdiUZ+OmvP0cPPtYaaoEGeI/qZ5sv4fEH3xFZOb+d5+wu/w4=
2016-12-07 18:42:24,225 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  2
2016-12-07 18:42:24,226 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 52c578b8-6d85-49e9-d148-2db3079cc239, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,274 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null; Status Code: 404; Error Code: 404 Not Found; Request ID: 4B7CD9CADDF086A7), S3 Extended Request ID: 9AR/mRdKgwAnb8SnWzLSqrM8K/DWFK1utzFqKXZihDtTN9UXPsxGFGN2GoBHgHNTqY41YBBptn8=
2016-12-07 18:42:24,274 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1  ->  1
2016-12-07 18:42:24,289 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters: ({"prefix":["test/"],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5cb39b7e-4fb2-5401-25d5-0fdc15db05ad, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,364 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1616)) - Not Found: s3a://hwdev-steve-ireland-new/test
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  2
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://hwdev-steve-ireland-new/  ()
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1  ->  2
2016-12-07 18:42:24,366 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters: ({"prefix":[""],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: d68ca495-6dee-8f17-0ff8-008f25a75702, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1591)) - Found path as directory (with /): 1/0
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1599)) - Prefix: Users/
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutStartStatistics(1116)) - PUT start 0 bytes
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests += 1  ->  1
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutCompletedStatistics(1133)) - PUT completed success=true; 0 bytes
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests_completed += 1  ->  1
2016-12-07 18:42:24,440 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: PUT https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102 com.amazonaws.services.s3.transfer.TransferManager/1.11.45, amz-sdk-invocation-id: fad23d78-a104-156a-81ed-f3e29d668cd8, Content-Length: 0, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,514 [Thread-1] DEBUG S3AFileSystem.Progress (S3AFileSystem.java:incrementPutProgressStatistics(1151)) - PUT test/: 0 bytes
2016-12-07 18:42:24,514 [Thread-1] DEBUG scale.S3AScaleTestBase (S3AScaleTestBase.java:setup(94)) - Scale test operation count = 1
2016-12-07 18:42:24,516 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:24,519 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from BasicAWSCredentialsProvider
2016-12-07 18:42:24,520 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 40808c03-5cf7-c960-4c97-353313df657b, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:25,338 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service: null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID: 58DECB0934A6428C), S3 Extended Request ID: QQxGx+1eyQEbD/skrLYpaXg+XuW8EvgwtCkpqqTJttl/ONjzD1xC1jVX6IqFCQZdfrSsup85pTM=
2016-12-07 18:42:25,339 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5eb0baa1-d0f0-1825-27c1-4c122afb0d72, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: null
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: not available
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  3
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://landsat-pds/scene_list.gz  (scene_list.gz)
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  3
2016-12-07 18:42:26,227 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 33d34c3d-ead9-809a-af05-257b905fede7, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file: normal file
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(87)) - 

testTimeToOpenAndReadWholeFileBlocks: Open the test file s3a://landsat-pds/scene_list.gz and read it in blocks of size 1048576

2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input strategy: normal
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:open(503)) - Opening 's3a://landsat-pds/scene_list.gz' for reading.
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  4
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://landsat-pds/scene_list.gz  (scene_list.gz)
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  4
2016-12-07 18:42:26,790 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5d20098b-a1cc-a15d-7cf6-959355ceda8c, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file: normal file
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input strategy: normal
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) - reopen(s3a://landsat-pds/scene_list.gz) for read from new offset range[0-38939342], length=1048576, streamPosition=0, nextReadPosition=0
2016-12-07 18:42:26,969 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 6489ce83-1f56-b833-15dc-f78d8eed429f, Range: bytes=0-38939342, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 206, AWS Request ID: 7BB5413C293FE587
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 7BB5413C293FE587
2016-12-07 18:43:32,677 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 0 in 121 reads: 65,708,704,300 nS
2016-12-07 18:44:50,868 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 1 in 121 reads: 78,191,068,156 nS
2016-12-07 18:48:57,544 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(334)) - Got exception while trying to read from stream s3a://landsat-pds/scene_list.gz trying to recover: java.net.SocketTimeoutException: Read timed out
2016-12-07 18:48:57,546 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(336)) - While trying to read from stream s3a://landsat-pds/scene_list.gz
java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
	at sun.security.ssl.InputRecord.readV3Record(InputRecord.java:593)
	at sun.security.ssl.InputRecord.read(InputRecord.java:532)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
	at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:200)
	at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
	at org.apache.hadoop.fs.s3a.S3AInputStream.read(S3AInputStream.java:373)
	at java.io.DataInputStream.read(DataInputStream.java:149)
	at org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks(ITestS3AInputStreamPerformance.java:225)
	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:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	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:55)
	at org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream s3a://landsat-pds/scene_list.gz aborted: reopen(failure recovery); streamPos=2575953, nextReadPos=2575953, request range 0-38939342 length=38939342
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) - reopen(s3a://landsat-pds/scene_list.gz) for failure recovery range[2575953-38939342], length=569775, streamPosition=2575953, nextReadPosition=2575953
2016-12-07 18:48:57,554 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 4ae4b351-3374-49e5-fa73-81cff322f56c, Range: bytes=2575953-38939342, Content-Type: application/octet-stream, ) 
2016-12-07 18:48:58,358 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 206, AWS Request ID: 773084E647B9C370
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 773084E647B9C370
2016-12-07 18:48:59,397 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 2 in 121 reads: 248,531,807,139 nS
2016-12-07 18:48:59,988 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 3 in 122 reads: 590,226,556 nS
2016-12-07 18:49:00,346 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 4 in 122 reads: 357,777,268 nS
2016-12-07 18:49:00,635 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 5 in 121 reads: 288,089,615 nS
2016-12-07 18:49:00,869 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 6 in 89 reads: 233,918,422 nS
2016-12-07 18:49:01,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 7 in 69 reads: 224,188,050 nS
2016-12-07 18:49:01,270 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 8 in 69 reads: 175,089,680 nS
2016-12-07 18:49:01,508 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 9 in 69 reads: 237,915,953 nS
2016-12-07 18:49:03,203 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 10 in 69 reads: 1,694,581,186 nS
2016-12-07 18:49:03,562 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 11 in 69 reads: 358,629,013 nS
2016-12-07 18:49:03,814 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 12 in 69 reads: 251,512,010 nS
2016-12-07 18:49:04,080 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 13 in 69 reads: 265,251,582 nS
2016-12-07 18:49:04,284 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 14 in 69 reads: 203,401,204 nS
2016-12-07 18:49:04,488 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 15 in 69 reads: 203,355,837 nS
2016-12-07 18:49:04,682 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 16 in 69 reads: 193,974,256 nS
2016-12-07 18:49:04,902 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 17 in 69 reads: 219,901,121 nS
2016-12-07 18:49:05,089 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 18 in 69 reads: 186,285,604 nS
2016-12-07 18:49:05,323 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 19 in 69 reads: 233,165,569 nS
2016-12-07 18:49:06,021 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 20 in 69 reads: 698,049,891 nS
2016-12-07 18:49:06,350 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 21 in 69 reads: 328,816,127 nS
2016-12-07 18:49:06,571 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 22 in 69 reads: 220,920,300 nS
2016-12-07 18:49:06,785 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 23 in 69 reads: 213,269,165 nS
2016-12-07 18:49:07,044 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 24 in 69 reads: 258,383,769 nS
2016-12-07 18:49:07,260 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 25 in 69 reads: 215,997,541 nS
2016-12-07 18:49:07,472 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 26 in 69 reads: 210,871,191 nS
2016-12-07 18:49:07,675 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 27 in 69 reads: 203,160,739 nS
2016-12-07 18:49:07,905 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 28 in 69 reads: 229,260,978 nS
2016-12-07 18:49:08,107 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 29 in 69 reads: 202,102,165 nS
2016-12-07 18:49:08,387 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 30 in 69 reads: 279,023,912 nS
2016-12-07 18:49:08,751 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 31 in 69 reads: 363,367,889 nS
2016-12-07 18:49:09,066 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 32 in 69 reads: 315,399,466 nS
2016-12-07 18:49:09,312 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 33 in 69 reads: 245,392,893 nS
2016-12-07 18:49:09,566 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 34 in 69 reads: 253,079,462 nS
2016-12-07 18:49:09,813 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 35 in 69 reads: 246,456,730 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 36 in 69 reads: 279,688,361 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Time to read 38939342 bytes in 37 blocks: 403,130,941,090 nS
2016-12-07 18:49:10,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:bandwidth(963)) - Bandwidth = 0.091782  MB/S
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  scale.ITestS3AInputStreamPerformance (ITestS3AInputStreamPerformance.java:logStreamStatistics(324)) - Stream Statistics
StreamStatistics{OpenOperations=2, CloseOperations=1, Closed=0, Aborted=1, SeekOperations=0, ReadExceptions=1, ForwardSeekOperations=0, BackwardSeekOperations=0, BytesSkippedOnSeek=0, BytesBackwardsOnSeek=0, BytesRead=38797312, BytesRead excluding skipped=38797312, ReadOperations=2887, ReadFullyOperations=0, ReadsIncomplete=2850, BytesReadInClose=0, BytesDiscardedInAbort=36363389}
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:describe(255)) - cleanup
2016-12-07 18:49:10,096 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream s3a://landsat-pds/scene_list.gz aborted: close() operation; streamPos=38797312, nextReadPos=38797312, request range 2575953-38939342 length=38939342
{code}


was (Author: stevel@apache.org):
good news, I've been able to replicate it on the new SDK too, meaning its a network/load balance problem, not SDK related
{code}
2016-12-07 18:42:22,553 [Thread-1] DEBUG s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:22,913 [Thread-1] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from BasicAWSCredentialsProvider
2016-12-07 18:42:22,921 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-us-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 787e1df3-9887-fd11-ec8d-801a7836e20d, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:23,927 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service: null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID: 0D2990D655FE6CDD), S3 Extended Request ID: zam+lWQRapkEc17mnHEoLgeWBuFXGGLncQaxBi/a12Y3uohpoEAzRS1frsGb81AnU1HDJn2b7IU=
2016-12-07 18:42:23,978 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: f9fabf3f-9809-ad08-7c2f-1683f6d593cf, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,163 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: null
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: not available
2016-12-07 18:42:24,165 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:24,166 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:24,169 [Thread-1] INFO  contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:setup(184)) - Test filesystem = s3a://hwdev-steve-ireland-new implemented by S3AFileSystem{uri=s3a://hwdev-steve-ireland-new, workingDir=s3a://hwdev-steve-ireland-new/user/stevel, inputPolicy=normal, partSize=8000000, enableMultiObjectsDelete=true, maxKeys=5000, readAhead=65536, blockSize=33554432, multiPartThreshold=2147483647, blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@51dffc97, executor=BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=30, available=30, waiting=0}, activeCount=0}, statistics {0 bytes read, 0 bytes written, 0 read ops, 0 large read ops, 0 write ops}, metrics {{Context=S3AFileSystem} {FileSystemId=461d5b68-e18f-4e9b-b88f-ee6cee6196ac-hwdev-steve-ireland-new} {fsURI=s3a://hwdev-steve-ireland-new/} {files_created=0} {files_copied=0} {files_copied_bytes=0} {files_deleted=0} {fake_directories_deleted=0} {directories_created=0} {directories_deleted=0} {ignored_errors=0} {op_copy_from_local_file=0} {op_exists=0} {op_get_file_status=0} {op_glob_status=0} {op_is_directory=0} {op_is_file=0} {op_list_files=0} {op_list_located_status=0} {op_list_status=0} {op_mkdirs=0} {op_rename=0} {object_copy_requests=0} {object_delete_requests=0} {object_list_requests=0} {object_continue_list_requests=0} {object_metadata_requests=0} {object_multipart_aborted=0} {object_put_bytes=0} {object_put_requests=0} {object_put_requests_completed=0} {stream_write_failures=0} {stream_write_block_uploads=0} {stream_write_block_uploads_committed=0} {stream_write_block_uploads_aborted=0} {stream_write_total_time=0} {stream_write_total_data=0} {object_put_requests_active=0} {object_put_bytes_pending=0} {stream_write_block_uploads_active=0} {stream_write_block_uploads_pending=0} {stream_write_block_uploads_data_pending=0} {stream_read_fully_operations=0} {stream_opened=0} {stream_bytes_skipped_on_seek=0} {stream_closed=0} {stream_bytes_backwards_on_seek=0} {stream_bytes_read=0} {stream_read_operations_incomplete=0} {stream_bytes_discarded_in_abort=0} {stream_close_operations=0} {stream_read_operations=0} {stream_aborted=0} {stream_forward_seek_operations=0} {stream_backward_seek_operations=0} {stream_seek_operations=0} {stream_bytes_read_in_close=0} {stream_read_exceptions=0} }}
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerMkdirs(1478)) - Making directory: /test
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_mkdirs += 1  ->  1
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  1
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://hwdev-steve-ireland-new/test  (test)
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  1
2016-12-07 18:42:24,174 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 57239941-1812-a15f-736a-f3da7727b192, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,225 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null; Status Code: 404; Error Code: 404 Not Found; Request ID: 2B1E6AAB5BB13A50), S3 Extended Request ID: 37X2RRn7nQAt5RDTbO8jazu8ltPGdiUZ+OmvP0cPPtYaaoEGeI/qZ5sv4fEH3xFZOb+d5+wu/w4=
2016-12-07 18:42:24,225 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  2
2016-12-07 18:42:24,226 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 52c578b8-6d85-49e9-d148-2db3079cc239, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,274 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null; Status Code: 404; Error Code: 404 Not Found; Request ID: 4B7CD9CADDF086A7), S3 Extended Request ID: 9AR/mRdKgwAnb8SnWzLSqrM8K/DWFK1utzFqKXZihDtTN9UXPsxGFGN2GoBHgHNTqY41YBBptn8=
2016-12-07 18:42:24,274 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1  ->  1
2016-12-07 18:42:24,289 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters: ({"prefix":["test/"],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5cb39b7e-4fb2-5401-25d5-0fdc15db05ad, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,364 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1616)) - Not Found: s3a://hwdev-steve-ireland-new/test
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  2
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://hwdev-steve-ireland-new/  ()
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1  ->  2
2016-12-07 18:42:24,366 [Thread-1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters: ({"prefix":[""],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: d68ca495-6dee-8f17-0ff8-008f25a75702, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1591)) - Found path as directory (with /): 1/0
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1599)) - Prefix: Users/
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutStartStatistics(1116)) - PUT start 0 bytes
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests += 1  ->  1
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutCompletedStatistics(1133)) - PUT completed success=true; 0 bytes
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests_completed += 1  ->  1
2016-12-07 18:42:24,440 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: PUT https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102 com.amazonaws.services.s3.transfer.TransferManager/1.11.45, amz-sdk-invocation-id: fad23d78-a104-156a-81ed-f3e29d668cd8, Content-Length: 0, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,514 [Thread-1] DEBUG S3AFileSystem.Progress (S3AFileSystem.java:incrementPutProgressStatistics(1151)) - PUT test/: 0 bytes
2016-12-07 18:42:24,514 [Thread-1] DEBUG scale.S3AScaleTestBase (S3AScaleTestBase.java:setup(94)) - Scale test operation count = 1
2016-12-07 18:42:24,516 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:24,519 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from BasicAWSCredentialsProvider
2016-12-07 18:42:24,520 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-1.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 40808c03-5cf7-c960-4c97-353313df657b, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:25,338 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service: null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID: 58DECB0934A6428C), S3 Extended Request ID: QQxGx+1eyQEbD/skrLYpaXg+XuW8EvgwtCkpqqTJttl/ONjzD1xC1jVX6IqFCQZdfrSsup85pTM=
2016-12-07 18:42:25,339 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com / Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5eb0baa1-d0f0-1825-27c1-4c122afb0d72, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: null
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: not available
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  3
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://landsat-pds/scene_list.gz  (scene_list.gz)
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  3
2016-12-07 18:42:26,227 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 33d34c3d-ead9-809a-af05-257b905fede7, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file: normal file
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(87)) - 

testTimeToOpenAndReadWholeFileBlocks: Open the test file s3a://landsat-pds/scene_list.gz and read it in blocks of size 1048576

2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input strategy: normal
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:open(503)) - Opening 's3a://landsat-pds/scene_list.gz' for reading.
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1  ->  4
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path status for s3a://landsat-pds/scene_list.gz  (scene_list.gz)
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests += 1  ->  4
2016-12-07 18:42:26,790 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 5d20098b-a1cc-a15d-7cf6-959355ceda8c, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 200, AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file: normal file
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input strategy: normal
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) - reopen(s3a://landsat-pds/scene_list.gz) for read from new offset range[0-38939342], length=1048576, streamPosition=0, nextReadPosition=0
2016-12-07 18:42:26,969 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 6489ce83-1f56-b833-15dc-f78d8eed429f, Range: bytes=0-38939342, Content-Type: application/octet-stream, ) 
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 206, AWS Request ID: 7BB5413C293FE587
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 7BB5413C293FE587
2016-12-07 18:43:32,677 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 0 in 121 reads: 65,708,704,300 nS
2016-12-07 18:44:50,868 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 1 in 121 reads: 78,191,068,156 nS
2016-12-07 18:48:57,544 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(334)) - Got exception while trying to read from stream s3a://landsat-pds/scene_list.gz trying to recover: java.net.SocketTimeoutException: Read timed out
2016-12-07 18:48:57,546 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(336)) - While trying to read from stream s3a://landsat-pds/scene_list.gz
java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
	at sun.security.ssl.InputRecord.readV3Record(InputRecord.java:593)
	at sun.security.ssl.InputRecord.read(InputRecord.java:532)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
	at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:200)
	at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
	at org.apache.hadoop.fs.s3a.S3AInputStream.read(S3AInputStream.java:373)
	at java.io.DataInputStream.read(DataInputStream.java:149)
	at org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks(ITestS3AInputStreamPerformance.java:225)
	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:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	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:55)
	at org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream s3a://landsat-pds/scene_list.gz aborted: reopen(failure recovery); streamPos=2575953, nextReadPos=2575953, request range 0-38939342 length=38939342
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) - reopen(s3a://landsat-pds/scene_list.gz) for failure recovery range[2575953-38939342], length=569775, streamPosition=2575953, nextReadPosition=2575953
2016-12-07 18:48:57,554 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id: 4ae4b351-3374-49e5-fa73-81cff322f56c, Range: bytes=2575953-38939342, Content-Type: application/octet-stream, ) 
2016-12-07 18:48:58,358 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received successful response: 206, AWS Request ID: 773084E647B9C370
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId: not available
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID: 773084E647B9C370
2016-12-07 18:48:59,397 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 2 in 121 reads: 248,531,807,139 nS
2016-12-07 18:48:59,988 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 3 in 122 reads: 590,226,556 nS
2016-12-07 18:49:00,346 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 4 in 122 reads: 357,777,268 nS
2016-12-07 18:49:00,635 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 5 in 121 reads: 288,089,615 nS
2016-12-07 18:49:00,869 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 6 in 89 reads: 233,918,422 nS
2016-12-07 18:49:01,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 7 in 69 reads: 224,188,050 nS
2016-12-07 18:49:01,270 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 8 in 69 reads: 175,089,680 nS
2016-12-07 18:49:01,508 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 9 in 69 reads: 237,915,953 nS
2016-12-07 18:49:03,203 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 10 in 69 reads: 1,694,581,186 nS
2016-12-07 18:49:03,562 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 11 in 69 reads: 358,629,013 nS
2016-12-07 18:49:03,814 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 12 in 69 reads: 251,512,010 nS
2016-12-07 18:49:04,080 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 13 in 69 reads: 265,251,582 nS
2016-12-07 18:49:04,284 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 14 in 69 reads: 203,401,204 nS
2016-12-07 18:49:04,488 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 15 in 69 reads: 203,355,837 nS
2016-12-07 18:49:04,682 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 16 in 69 reads: 193,974,256 nS
2016-12-07 18:49:04,902 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 17 in 69 reads: 219,901,121 nS
2016-12-07 18:49:05,089 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 18 in 69 reads: 186,285,604 nS
2016-12-07 18:49:05,323 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 19 in 69 reads: 233,165,569 nS
2016-12-07 18:49:06,021 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 20 in 69 reads: 698,049,891 nS
2016-12-07 18:49:06,350 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 21 in 69 reads: 328,816,127 nS
2016-12-07 18:49:06,571 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 22 in 69 reads: 220,920,300 nS
2016-12-07 18:49:06,785 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 23 in 69 reads: 213,269,165 nS
2016-12-07 18:49:07,044 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 24 in 69 reads: 258,383,769 nS
2016-12-07 18:49:07,260 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 25 in 69 reads: 215,997,541 nS
2016-12-07 18:49:07,472 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 26 in 69 reads: 210,871,191 nS
2016-12-07 18:49:07,675 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 27 in 69 reads: 203,160,739 nS
2016-12-07 18:49:07,905 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 28 in 69 reads: 229,260,978 nS
2016-12-07 18:49:08,107 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 29 in 69 reads: 202,102,165 nS
2016-12-07 18:49:08,387 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 30 in 69 reads: 279,023,912 nS
2016-12-07 18:49:08,751 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 31 in 69 reads: 363,367,889 nS
2016-12-07 18:49:09,066 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 32 in 69 reads: 315,399,466 nS
2016-12-07 18:49:09,312 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 33 in 69 reads: 245,392,893 nS
2016-12-07 18:49:09,566 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 34 in 69 reads: 253,079,462 nS
2016-12-07 18:49:09,813 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 35 in 69 reads: 246,456,730 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Reading block 36 in 69 reads: 279,688,361 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of Time to read 38939342 bytes in 37 blocks: 403,130,941,090 nS
2016-12-07 18:49:10,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.ContractTestUtils (ContractTestUtils.java:bandwidth(963)) - Bandwidth = 0.091782  MB/S
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  scale.ITestS3AInputStreamPerformance (ITestS3AInputStreamPerformance.java:logStreamStatistics(324)) - Stream Statistics
StreamStatistics{OpenOperations=2, CloseOperations=1, Closed=0, Aborted=1, SeekOperations=0, ReadExceptions=1, ForwardSeekOperations=0, BackwardSeekOperations=0, BytesSkippedOnSeek=0, BytesBackwardsOnSeek=0, BytesRead=38797312, BytesRead excluding skipped=38797312, ReadOperations=2887, ReadFullyOperations=0, ReadsIncomplete=2850, BytesReadInClose=0, BytesDiscardedInAbort=36363389}
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO  contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:describe(255)) - cleanup
2016-12-07 18:49:10,096 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream s3a://landsat-pds/scene_list.gz aborted: close() operation; streamPos=38797312, nextReadPos=38797312, request range 2575953-38939342 length=38939342
{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