[
https://issues.apache.org/jira/browse/HADOOP-13871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15732357#comment-15732357
]
Steve Loughran commented on HADOOP-13871:
-----------------------------------------
And it is replicable with the latest SDK. This at least implies its not an SDK
problem; some local environment or networking issue
{code}
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(135))
- http-outgoing-3 >> GET /scene_list.gz HTTP/1.1
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> Host: landsat-pds.s3-us-west-2.amazonaws.com
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> x-amz-content-sha256: UNSIGNED-PAYLOAD
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> Authorization: AWS4-HMAC-SHA256
Credential=AKIAIYZ5JQOW3N5H6NPA/20161208/us-west-2/s3/aws4_request,
SignedHeaders=amz-sdk-invocation-id;amz-sdk-retry;content-type;host;range;user-agent;x-amz-content-sha256;x-amz-date,
Signature=26e0566a3ef87493309d56eac330d20d2a071010ded7cbff9886e7c7cef1bd86
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> X-Amz-Date: 20161208T142321Z
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> 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
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> amz-sdk-invocation-id: ddf8d5b5-96a3-57a4-96d6-fbb66f63f6fa
2016-12-08 14:23:21,981 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> amz-sdk-retry: 0/0/500
2016-12-08 14:23:21,982 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> Range: bytes=0-39234217
2016-12-08 14:23:21,982 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> Content-Type: application/octet-stream
2016-12-08 14:23:21,982 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onRequestSubmitted(138))
- http-outgoing-3 >> Connection: Keep-Alive
2016-12-08 14:23:22,301 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(124))
- http-outgoing-3 << HTTP/1.1 206 Partial Content
2016-12-08 14:23:22,301 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << x-amz-id-2:
SykItR7JBcTf1TsNkVK58VYN2164t1IDsMa+ZpLUBGuJW+Bxb9ONEAHFvi85JhhGvLZJxXlwc3k=
2016-12-08 14:23:22,301 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << x-amz-request-id: 0AE8E8AD401F45D6
2016-12-08 14:23:22,301 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Date: Thu, 08 Dec 2016 14:23:23 GMT
2016-12-08 14:23:22,301 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Last-Modified: Thu, 08 Dec 2016 11:32:05 GMT
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << ETag: "00585bfc6fa4c4295c5a0073f7fa6922"
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Accept-Ranges: bytes
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Content-Range: bytes 0-39234216/39234217
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Content-Type: application/octet-stream
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Content-Length: 39234217
2016-12-08 14:23:22,302 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
http.headers (LoggingManagedHttpClientConnection.java:onResponseReceived(127))
- http-outgoing-3 << Server: AmazonS3
2016-12-08 14:23:22,303 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
execchain.MainClientExec (MainClientExec.java:execute(284)) - Connection can be
kept alive for 60000 MILLISECONDS
2016-12-08 14:23:22,304 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 206, AWS Request ID: 0AE8E8AD401F45D6
2016-12-08 14:23:22,304 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-08 14:23:22,304 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 0AE8E8AD401F45D6
2016-12-08 14:23:22,486 - Bytes in read #1: 16347 , block bytes: 16347,
remaining in block: 1032229 duration=501762710 nS; ns/byte: 30694,
bandwidth=0.031070 MB/s
2016-12-08 14:23:22,487 - Bytes in read #2: 630 , block bytes: 16977,
remaining in block: 1031599 duration=160825 nS; ns/byte: 255,
bandwidth=3.735830 MB/s
2016-12-08 14:23:22,827 - Bytes in read #3: 16347 , block bytes: 33324,
remaining in block: 1015252 duration=339676241 nS; ns/byte: 20779,
bandwidth=0.045896 MB/s
2016-12-08 14:23:22,827 - Bytes in read #4: 1061 , block bytes: 34385,
remaining in block: 1014191 duration=204387 nS; ns/byte: 192,
bandwidth=4.950650 MB/s
2016-12-08 14:23:23,016 - Bytes in read #5: 16347 , block bytes: 50732,
remaining in block: 997844 duration=188918899 nS; ns/byte: 11556,
bandwidth=0.082521 MB/s
2016-12-08 14:23:23,017 - Bytes in read #6: 1061 , block bytes: 51793,
remaining in block: 996783 duration=149986 nS; ns/byte: 141, bandwidth=6.746286
MB/s
2016-12-08 14:23:23,018 - Bytes in read #7: 16347 , block bytes: 68140,
remaining in block: 980436 duration=668380 nS; ns/byte: 40, bandwidth=23.324627
MB/s
2016-12-08 14:23:23,018 - Bytes in read #8: 1061 , block bytes: 69201,
remaining in block: 979375 duration=109412 nS; ns/byte: 103, bandwidth=9.248057
MB/s
2016-12-08 14:23:23,545 - Bytes in read #9: 16347 , block bytes: 85548,
remaining in block: 963028 duration=526539853 nS; ns/byte: 32210,
bandwidth=0.029608 MB/s
2016-12-08 14:23:23,545 - Bytes in read #10: 1061 , block bytes: 86609,
remaining in block: 961967 duration=160982 nS; ns/byte: 151, bandwidth=6.285476
MB/s
2016-12-08 14:23:24,075 - Bytes in read #11: 16347 , block bytes: 102956,
remaining in block: 945620 duration=529957790 nS; ns/byte: 32419,
bandwidth=0.029417 MB/s
2016-12-08 14:23:24,076 - Bytes in read #12: 1061 , block bytes: 104017,
remaining in block: 944559 duration=176802 nS; ns/byte: 166, bandwidth=5.723060
MB/s
2016-12-08 14:23:24,256 - Bytes in read #13: 16347 , block bytes: 120364,
remaining in block: 928212 duration=180087310 nS; ns/byte: 11016,
bandwidth=0.086568 MB/s
2016-12-08 14:23:24,257 - Bytes in read #14: 1061 , block bytes: 121425,
remaining in block: 927151 duration=162863 nS; ns/byte: 153, bandwidth=6.212881
MB/s
2016-12-08 14:23:25,154 - Bytes in read #15: 16347 , block bytes: 137772,
remaining in block: 910804 duration=896281315 nS; ns/byte: 54828,
bandwidth=0.017394 MB/s
2016-12-08 14:23:25,154 - Bytes in read #16: 1061 , block bytes: 138833,
remaining in block: 909743 duration=144944 nS; ns/byte: 136, bandwidth=6.980961
MB/s
2016-12-08 14:23:25,979 - Bytes in read #17: 16347 , block bytes: 155180,
remaining in block: 893396 duration=824595866 nS; ns/byte: 50443,
bandwidth=0.018906 MB/s
2016-12-08 14:23:25,979 - Bytes in read #18: 1061 , block bytes: 156241,
remaining in block: 892335 duration=177202 nS; ns/byte: 167, bandwidth=5.710141
MB/s
2016-12-08 14:23:27,293 - Bytes in read #19: 16347 , block bytes: 172588,
remaining in block: 875988 duration=1313351115 nS; ns/byte: 80342,
bandwidth=0.011870 MB/s
2016-12-08 14:23:27,294 - Bytes in read #20: 1061 , block bytes: 173649,
remaining in block: 874927 duration=171179 nS; ns/byte: 161, bandwidth=5.911055
MB/s
2016-12-08 14:23:28,102 - Bytes in read #21: 16347 , block bytes: 189996,
remaining in block: 858580 duration=808444310 nS; ns/byte: 49455,
bandwidth=0.019284 MB/s
2016-12-08 14:23:28,103 - Bytes in read #22: 1061 , block bytes: 191057,
remaining in block: 857519 duration=94308 nS; ns/byte: 88, bandwidth=10.729190
MB/s
2016-12-08 14:23:28,657 - Bytes in read #23: 16347 , block bytes: 207404,
remaining in block: 841172 duration=554500694 nS; ns/byte: 33920,
bandwidth=0.028115 MB/s
2016-12-08 14:23:28,983 - Bytes in read #24: 1061 , block bytes: 208465,
remaining in block: 840111 duration=325204791 nS; ns/byte: 306507,
bandwidth=0.003111 MB/s
2016-12-08 14:23:31,339 - Bytes in read #25: 16347 , block bytes: 224812,
remaining in block: 823764 duration=2355362418 nS; ns/byte: 144085,
bandwidth=0.006619 MB/s
2016-12-08 14:23:31,340 - Bytes in read #26: 1061 , block bytes: 225873,
remaining in block: 822703 duration=1329505 nS; ns/byte: 1253,
bandwidth=0.761072 MB/s
2016-12-08 14:23:32,054 - Bytes in read #27: 16347 , block bytes: 242220,
remaining in block: 806356 duration=713105706 nS; ns/byte: 43623,
bandwidth=0.021862 MB/s
2016-12-08 14:23:32,054 - Bytes in read #28: 1061 , block bytes: 243281,
remaining in block: 805295 duration=140448 nS; ns/byte: 132, bandwidth=7.204435
MB/s
2016-12-08 14:23:33,300 - Bytes in read #29: 16347 , block bytes: 259628,
remaining in block: 788948 duration=1245922562 nS; ns/byte: 76217,
bandwidth=0.012513 MB/s
2016-12-08 14:23:33,767 - Bytes in read #30: 1061 , block bytes: 260689,
remaining in block: 787887 duration=466030523 nS; ns/byte: 439237,
bandwidth=0.002171 MB/s
2016-12-08 14:23:34,300 - Bytes in read #31: 16347 , block bytes: 277036,
remaining in block: 771540 duration=533252203 nS; ns/byte: 32620,
bandwidth=0.029235 MB/s
2016-12-08 14:23:34,382 - Bytes in read #32: 1061 , block bytes: 278097,
remaining in block: 770479 duration=80960596 nS; ns/byte: 76305,
bandwidth=0.012498 MB/s
2016-12-08 14:23:35,027 - Bytes in read #33: 16347 , block bytes: 294444,
remaining in block: 754132 duration=644705881 nS; ns/byte: 39438,
bandwidth=0.024181 MB/s
2016-12-08 14:23:35,027 - Bytes in read #34: 1061 , block bytes: 295505,
remaining in block: 753071 duration=79536 nS; ns/byte: 74, bandwidth=12.721893
MB/s
2016-12-08 14:23:35,579 - Bytes in read #35: 16347 , block bytes: 311852,
remaining in block: 736724 duration=551360213 nS; ns/byte: 33728,
bandwidth=0.028275 MB/s
2016-12-08 14:23:35,904 - Bytes in read #36: 1061 , block bytes: 312913,
remaining in block: 735663 duration=325436462 nS; ns/byte: 306726,
bandwidth=0.003109 MB/s
2016-12-08 14:23:36,776 - Bytes in read #37: 16347 , block bytes: 329260,
remaining in block: 719316 duration=871155772 nS; ns/byte: 53291,
bandwidth=0.017895 MB/s
2016-12-08 14:23:36,777 - Bytes in read #38: 1061 , block bytes: 330321,
remaining in block: 718255 duration=241257 nS; ns/byte: 227, bandwidth=4.194069
MB/s
2016-12-08 14:23:37,838 - Bytes in read #39: 16347 , block bytes: 346668,
remaining in block: 701908 duration=1061024046 nS; ns/byte: 64906,
bandwidth=0.014693 MB/s
2016-12-08 14:23:38,014 - Bytes in read #40: 1061 , block bytes: 347729,
remaining in block: 700847 duration=175298804 nS; ns/byte: 165220,
bandwidth=0.005772 MB/s
2016-12-08 14:23:38,553 - Bytes in read #41: 16347 , block bytes: 364076,
remaining in block: 684500 duration=538434297 nS; ns/byte: 32937,
bandwidth=0.028954 MB/s
2016-12-08 14:23:38,554 - Bytes in read #42: 1061 , block bytes: 365137,
remaining in block: 683439 duration=1233409 nS; ns/byte: 1162,
bandwidth=0.820367 MB/s
2016-12-08 14:23:40,229 - Bytes in read #43: 16347 , block bytes: 381484,
remaining in block: 667092 duration=1674577082 nS; ns/byte: 102439,
bandwidth=0.009310 MB/s
2016-12-08 14:23:40,586 - Bytes in read #44: 1061 , block bytes: 382545,
remaining in block: 666031 duration=357021347 nS; ns/byte: 336495,
bandwidth=0.002834 MB/s
2016-12-08 14:23:41,275 - Bytes in read #45: 16347 , block bytes: 398892,
remaining in block: 649684 duration=688294002 nS; ns/byte: 42105,
bandwidth=0.022650 MB/s
2016-12-08 14:23:41,276 - Bytes in read #46: 1061 , block bytes: 399953,
remaining in block: 648623 duration=140726 nS; ns/byte: 132, bandwidth=7.190203
MB/s
2016-12-08 14:23:42,389 - Bytes in read #47: 16347 , block bytes: 416300,
remaining in block: 632276 duration=1113488278 nS; ns/byte: 68115,
bandwidth=0.014001 MB/s
2016-12-08 14:23:42,390 - Bytes in read #48: 1061 , block bytes: 417361,
remaining in block: 631215 duration=163118 nS; ns/byte: 153, bandwidth=6.203169
MB/s
2016-12-08 14:23:43,397 - Bytes in read #49: 16347 , block bytes: 433708,
remaining in block: 614868 duration=1006992034 nS; ns/byte: 61601,
bandwidth=0.015481 MB/s
2016-12-08 14:23:43,573 - Bytes in read #50: 1061 , block bytes: 434769,
remaining in block: 613807 duration=175484587 nS; ns/byte: 165395,
bandwidth=0.005766 MB/s
2016-12-08 14:23:43,927 - Bytes in read #51: 16347 , block bytes: 451116,
remaining in block: 597460 duration=353339533 nS; ns/byte: 21614,
bandwidth=0.044121 MB/s
2016-12-08 14:23:44,102 - Bytes in read #52: 1061 , block bytes: 452177,
remaining in block: 596399 duration=174634494 nS; ns/byte: 164594,
bandwidth=0.005794 MB/s
2016-12-08 14:23:44,985 - Bytes in read #53: 16347 , block bytes: 468524,
remaining in block: 580052 duration=882841721 nS; ns/byte: 54006,
bandwidth=0.017659 MB/s
2016-12-08 14:23:44,986 - Bytes in read #54: 1061 , block bytes: 469585,
remaining in block: 578991 duration=168354 nS; ns/byte: 158, bandwidth=6.010243
MB/s
2016-12-08 14:23:46,337 - Bytes in read #55: 16347 , block bytes: 485932,
remaining in block: 562644 duration=1350476638 nS; ns/byte: 82613,
bandwidth=0.011544 MB/s
2016-12-08 14:23:46,337 - Bytes in read #56: 1061 , block bytes: 486993,
remaining in block: 561583 duration=168682 nS; ns/byte: 158, bandwidth=5.998556
MB/s
2016-12-08 14:23:47,058 - Bytes in read #57: 16347 , block bytes: 503340,
remaining in block: 545236 duration=720245455 nS; ns/byte: 44059,
bandwidth=0.021645 MB/s
2016-12-08 14:23:47,058 - Bytes in read #58: 1061 , block bytes: 504401,
remaining in block: 544175 duration=109153 nS; ns/byte: 102, bandwidth=9.270001
MB/s
2016-12-08 14:23:48,051 - Bytes in read #59: 16347 , block bytes: 520748,
remaining in block: 527828 duration=992763828 nS; ns/byte: 60730,
bandwidth=0.015703 MB/s
2016-12-08 14:23:48,517 - Bytes in read #60: 1061 , block bytes: 521809,
remaining in block: 526767 duration=465289883 nS; ns/byte: 438539,
bandwidth=0.002175 MB/s
2016-12-08 14:23:48,851 - Bytes in read #61: 16347 , block bytes: 538156,
remaining in block: 510420 duration=333839573 nS; ns/byte: 20422,
bandwidth=0.046698 MB/s
2016-12-08 14:23:49,211 - Bytes in read #62: 1061 , block bytes: 539217,
remaining in block: 509359 duration=359559220 nS; ns/byte: 338887,
bandwidth=0.002814 MB/s
2016-12-08 14:23:50,006 - Bytes in read #63: 16347 , block bytes: 555564,
remaining in block: 493012 duration=794069765 nS; ns/byte: 48575,
bandwidth=0.019633 MB/s
2016-12-08 14:23:50,006 - Bytes in read #64: 1061 , block bytes: 556625,
remaining in block: 491951 duration=116647 nS; ns/byte: 109, bandwidth=8.674449
MB/s
2016-12-08 14:23:50,896 - Bytes in read #65: 16347 , block bytes: 572972,
remaining in block: 475604 duration=889335208 nS; ns/byte: 54403,
bandwidth=0.017530 MB/s
2016-12-08 14:23:51,280 - Bytes in read #66: 1061 , block bytes: 574033,
remaining in block: 474543 duration=384066718 nS; ns/byte: 361985,
bandwidth=0.002635 MB/s
2016-12-08 14:23:51,791 - Bytes in read #67: 16347 , block bytes: 590380,
remaining in block: 458196 duration=509948788 nS; ns/byte: 31195,
bandwidth=0.030571 MB/s
2016-12-08 14:23:51,791 - Bytes in read #68: 1061 , block bytes: 591441,
remaining in block: 457135 duration=168685 nS; ns/byte: 158, bandwidth=5.998449
MB/s
2016-12-08 14:23:52,326 - Bytes in read #69: 16347 , block bytes: 607788,
remaining in block: 440788 duration=534885343 nS; ns/byte: 32720,
bandwidth=0.029146 MB/s
2016-12-08 14:23:52,327 - Bytes in read #70: 1061 , block bytes: 608849,
remaining in block: 439727 duration=130685 nS; ns/byte: 123, bandwidth=7.742652
MB/s
2016-12-08 14:23:53,890 - Bytes in read #71: 16347 , block bytes: 625196,
remaining in block: 423380 duration=1563070584 nS; ns/byte: 95618,
bandwidth=0.009974 MB/s
{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
> Attachments:
> org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance-output.txt
>
>
> 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
