[
https://issues.apache.org/jira/browse/HADOOP-13047?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15252518#comment-15252518
]
Steve Loughran commented on HADOOP-13047:
-----------------------------------------
Output of a test run from my laptop (E over Power to base station, BT FTTC
80Mbit down/15 up), connected to amazon US.
This is with lazy seek; the log is showing initial getPos() value, then final
getPos(); actual will
Looks like 1s is time to open a connection
{code}
2016-04-21 20:26:32,979 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of stat = 187,328,000 ns
2016-04-21 20:26:33,149 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of open = 169,326,000 ns
2016-04-21 20:26:33,149 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:33,496 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of read() [pos = 0] = 345,822,000 ns
2016-04-21 20:26:33,496 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1 nextReadPos=1
contentLength=20299927}
2016-04-21 20:26:33,496 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:33,497 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of seek(256) [pos = 1] = 17,000 ns
2016-04-21 20:26:33,497 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1 nextReadPos=256
contentLength=20299927}
2016-04-21 20:26:33,497 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:33,497 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of seek(256) [pos = 256] = 17,000 ns
2016-04-21 20:26:33,498 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1 nextReadPos=256
contentLength=20299927}
2016-04-21 20:26:33,499 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:33,499 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of seek(EOF-2) [pos = 256] = 12,000 ns
2016-04-21 20:26:33,499 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1 nextReadPos=20299925
contentLength=20299927}
2016-04-21 20:26:33,499 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:34,423 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of read() [pos = 20299925] = 922,650,000 ns
2016-04-21 20:26:34,423 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=20299926
nextReadPos=20299926 contentLength=20299927}
2016-04-21 20:26:34,423 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:34,758 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(1, byte[1]) [pos = 20299926] = 333,713,000 ns
2016-04-21 20:26:34,758 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=2 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:34,758 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
// series of forward looking reads
2016-04-21 20:26:35,767 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(1, byte[256]) [pos = 20299926] = 1,008,214,000 ns
2016-04-21 20:26:35,767 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=257 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:35,767 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
next read is in available(), so cost is 61 microseconds
2016-04-21 20:26:35,768 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(260, byte[256]) [pos = 20299926] = 61,000 ns
2016-04-21 20:26:35,768 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=516 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:35,768 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
As is this one, just under 512 bytes ahead
2016-04-21 20:26:35,768 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(1024, byte[256]) [pos = 20299926] = 23,000 ns
2016-04-21 20:26:35,769 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1280 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:35,769 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:35,769 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(1536, byte[256]) [pos = 20299926] = 28,000 ns
2016-04-21 20:26:35,769 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=1792 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:35,769 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
// going forward to 8192 bytes triggers a full close and read
2016-04-21 20:26:38,634 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(8192, byte[1024]) [pos = 20299926] = 2,863,740,000 ns
2016-04-21 20:26:38,634 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=9216 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:38,634 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
// as now does a read ony 512 bytes ahead
2016-04-21 20:26:39,777 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of readFully(9728, byte[1024]) [pos = 20299926] = 1,142,347,000 ns
2016-04-21 20:26:39,778 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=10752 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:39,778 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:39,778 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of seek(getPos) [pos = 20299926] = 44,000 ns
2016-04-21 20:26:39,779 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=10752 nextReadPos=20299926
contentLength=20299927}
2016-04-21 20:26:39,779 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
2016-04-21 20:26:40,660 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of read() [pos = 20299926] = 880,644,000 ns
2016-04-21 20:26:40,660 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
S3AInputStream{s3a://landsat-pds/scene_list.gz pos=20299927
nextReadPos=20299927 contentLength=20299927}
2016-04-21 20:26:40,661 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
Duration of close() = 66,000 ns
2016-04-21 20:26:40,662 INFO s3.S3aIOSuite (Logging.scala:logInfo(54)) -
{code}
The notable ones are the {{readFully(8192, byte[1024])}} followed by the next
read only 512 bytes ahead of the pointer. That was further ahead than had
collected locally, which triggered a full reconnect and a delay of over a
second as a result.
> S3a Forward seek in stream length to be configurable
> ----------------------------------------------------
>
> Key: HADOOP-13047
> URL: https://issues.apache.org/jira/browse/HADOOP-13047
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Affects Versions: 2.8.0
> Reporter: Steve Loughran
>
> Even with lazy seek, tests can show that sometimes a short-distance forward
> seek is triggering a close + reopen, because the threshold for the seek is
> simply available bytes in the inner stream.
> A configurable threshold would allow data to be read and discarded before
> that seek. This should be beneficial over long-haul networks as the time to
> set up the TCP channel is high, and TCP-slow-start means that the ramp up of
> bandwidth is slow. In such deployments, it will better to read forward than
> re-open, though the exact "best" number will vary with client and endpoint.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
