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] [Commented] (HADOOP-13871) ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks performance on branch-2.8 awful
Date Thu, 08 Dec 2016 14:27:59 GMT

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


Mime
View raw message