[
https://issues.apache.org/jira/browse/HADOOP-13171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15296876#comment-15296876
]
Steve Loughran commented on HADOOP-13171:
-----------------------------------------
For the curious, here's the debug level output of the test of
{{copyFromLocalFile()}}
Everyone of those object_*_requests events is an HTTPS round trip, with all the
overhead of TCP setup and HTTPS auth. Very expensive long haul
Here:
setup: 500ms
upload: 250ms
cleanup: 400ms
That's almost pathological: long-haul connection, small file upload. It just
highlights: don't use small objects. And anything which can be done on
start/stop is worthwhile doing, as here there's about 4x more time spent round
the upload than the upload itself.
{code}
2016-05-23 19:43:20,775 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:initUserAgent(388)) - Using User-Agent: Hadoop
2.9.0-SNAPSHOT
2016-05-23 19:43:22,483 [Thread-0] INFO contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:setup(172)) - Test filesystem =
s3a://stevel-ireland implemented by S3AFileSystem{uri=s3a://stevel-ireland,
workingDir=s3a://stevel-ireland/user/stevel, partSize=104857600,
enableMultiObjectsDelete=true, maxKeys=5000, readAhead=65536,
blockSize=33554432, multiPartThreshold=2147483647, statistics {0 bytes read, 0
bytes written, 0 read ops, 0 large read ops, 0 write ops}, metrics
{{Context=S3AFileSystem}
{FileSystemId=ef20e446-8481-4da5-a406-7ae687fa49de-stevel-ireland}
{fsURI=s3a://stevel-ireland/} {files_created=0} {files_copied=0}
{files_copied_bytes=0} {files_deleted=0} {directories_created=0}
{directories_deleted=0} {ignored_errors=0} {invocations_copyfromlocalfile=0}
{invocations_exists=0} {invocations_getfilestatus=0} {invocations_globstatus=0}
{invocations_is_directory=0} {invocations_is_file=0}
{invocations_listlocatedstatus=0} {invocations_liststatus=0}
{invocations_mdkirs=0} {invocations_rename=0} {object_copy_requests=0}
{object_delete_requests=0} {object_list_requests=0}
{object_metadata_requests=0} {object_multipart_aborted=0} {object_put_bytes=0}
{object_put_requests=0} {streamReadOperations=0}
{streamForwardSeekOperations=0} {streamBytesRead=0} {streamSeekOperations=0}
{streamReadExceptions=0} {streamOpened=0} {streamReadOperationsIncomplete=0}
{streamAborted=0} {streamReadFullyOperations=0} {streamClosed=0}
{streamBytesSkippedOnSeek=0} {streamCloseOperations=0}
{streamBytesBackwardsOnSeek=0} {streamBackwardSeekOperations=0} }}
2016-05-23 19:43:22,485 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerMkdirs(1370)) - Making directory: /test
2016-05-23 19:43:22,485 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_mdkirs += 1 ->
1
2016-05-23 19:43:22,486 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 1
2016-05-23 19:43:22,486 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for /test (test)
2016-05-23 19:43:22,486 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 1
2016-05-23 19:43:22,519 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 2
2016-05-23 19:43:22,549 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 1
2016-05-23 19:43:22,620 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1505)) - Not Found: /test
2016-05-23 19:43:22,620 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 2
2016-05-23 19:43:22,620 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for /test (test)
2016-05-23 19:43:22,620 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 3
2016-05-23 19:43:22,652 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 4
2016-05-23 19:43:22,682 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 2
2016-05-23 19:43:22,720 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1505)) - Not Found: /test
2016-05-23 19:43:22,721 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 3
2016-05-23 19:43:22,721 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for / ()
2016-05-23 19:43:22,721 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 3
2016-05-23 19:43:22,759 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1479)) - Found path as directory (with /): 1/0
2016-05-23 19:43:22,759 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1487)) - Prefix: tests/
2016-05-23 19:43:22,764 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutStartStatistics(1053)) - PUT start 0 bytes
2016-05-23 19:43:22,764 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_put_requests += 1 ->
1
2016-05-23 19:43:22,915 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutProgressStatistics(1069)) - PUT test/: 0 bytes
2016-05-23 19:43:22,945 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) -
invocations_copyfromlocalfile += 1 -> 1
2016-05-23 19:43:22,945 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerCopyFromLocalFile(1563)) - Copying local file from
file:/var/folders/57/xyts0qt105z1f1k0twk6rd8m0000gq/T/tests3acost1305087813317560149.txt
to s3a://stevel-ireland/test/copied
2016-05-23 19:43:22,946 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutStartStatistics(1053)) - PUT start 10240 bytes
2016-05-23 19:43:22,946 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_put_requests += 1 ->
2
2016-05-23 19:43:22,946 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_put_bytes += 10240
-> 10240
2016-05-23 19:43:22,955 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:22,956 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:22,956 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:22,956 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,114 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 8192 bytes
2016-05-23 19:43:23,198 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,198 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,199 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,199 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,199 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 2048 bytes
2016-05-23 19:43:23,199 [java-sdk-progress-listener-callback-thread] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:incrementPutProgressStatistics(1069)) -
PUT test/copied: 0 bytes
2016-05-23 19:43:23,199 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:finishedWrite(1688)) - Finished write to test/copied
2016-05-23 19:43:23,200 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 4
2016-05-23 19:43:23,200 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for /test (test)
2016-05-23 19:43:23,200 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 5
2016-05-23 19:43:23,230 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 6
2016-05-23 19:43:23,283 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1444)) - Found file (with /): fake directory
2016-05-23 19:43:23,283 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:deleteUnnecessaryFakeDirectories(1709)) - Deleting fake
directory test/
2016-05-23 19:43:23,283 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_delete_requests += 1
-> 1
2016-05-23 19:43:23,319 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 5
2016-05-23 19:43:23,320 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for
s3a://stevel-ireland/test/copied (test/copied)
2016-05-23 19:43:23,320 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 7
2016-05-23 19:43:23,352 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1423)) - Found exact file: normal file
2016-05-23 19:43:23,353 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:open(612)) - Opening 's3a://stevel-ireland/test/copied' for
reading.
2016-05-23 19:43:23,353 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 6
2016-05-23 19:43:23,353 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for
s3a://stevel-ireland/test/copied (test/copied)
2016-05-23 19:43:23,353 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 8
2016-05-23 19:43:23,388 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1423)) - Found exact file: normal file
2016-05-23 19:43:23,391 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AInputStream.java:reopen(128)) - reopen(s3a://stevel-ireland/test/copied)
for read from new offset at targetPos=0, length=10240,
requestedStreamLen=10240, streamPosition=0, nextReadPosition=0
2016-05-23 19:43:23,428 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AInputStream.java:closeStream(442)) - Stream
s3a://stevel-ireland/test/copied closed: close() operation; streamPos=10240,
nextReadPos=10240, length=10240
2016-05-23 19:43:23,429 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_exists += 1 ->
1
2016-05-23 19:43:23,429 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 7
2016-05-23 19:43:23,429 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for /test (test)
2016-05-23 19:43:23,429 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 9
2016-05-23 19:43:23,460 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 10
2016-05-23 19:43:23,491 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 4
2016-05-23 19:43:23,625 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1479)) - Found path as directory (with /): 0/1
2016-05-23 19:43:23,625 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1484)) - Summary: test/copied 10240
// this is teardown
2016-05-23 19:43:23,625 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerDelete(1131)) - Delete path /test - recursive true
2016-05-23 19:43:23,625 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - invocations_getfilestatus +=
1 -> 8
2016-05-23 19:43:23,626 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1412)) - Getting path status for /test (test)
2016-05-23 19:43:23,626 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 11
2016-05-23 19:43:23,655 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_metadata_requests +=
1 -> 12
2016-05-23 19:43:23,688 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 5
2016-05-23 19:43:23,727 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1479)) - Found path as directory (with /): 0/1
2016-05-23 19:43:23,727 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1484)) - Summary: test/copied 10240
2016-05-23 19:43:23,727 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerDelete(1144)) - delete: Path is a directory: /test
2016-05-23 19:43:23,727 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerDelete(1165)) - Getting objects for directory prefix
test/ to delete
2016-05-23 19:43:23,728 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_list_requests += 1
-> 6
2016-05-23 19:43:23,765 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerDelete(1180)) - Got object to delete test/copied
2016-05-23 19:43:23,766 [Thread-0] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(59)) - object_delete_requests += 1
-> 2
{code}
> Add StorageStatistics to S3A; instrument some more operations
> -------------------------------------------------------------
>
> Key: HADOOP-13171
> URL: https://issues.apache.org/jira/browse/HADOOP-13171
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Affects Versions: 2.8.0
> Reporter: Steve Loughran
> Assignee: Steve Loughran
> Priority: Minor
> Attachments: HADOOP-13171-branch-2-001.patch,
> HADOOP-13171-branch-2-002.patch, HADOOP-13171-branch-2-003.patch,
> HADOOP-13171-branch-2-004.patch, HADOOP-13171-branch-2-005.patch
>
>
> Add {{StorageStatistics}} support to S3A, collecting the same metrics as the
> instrumentation, but sharing across all instances.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
