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-13171) Add StorageStatistics to S3A; instrument some more operations
Date Mon, 23 May 2016 18:54:13 GMT

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


Mime
View raw message