[ https://issues.apache.org/jira/browse/HADOOP-13871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15733129#comment-15733129 ]
Steve Loughran edited comment on HADOOP-13871 at 12/9/16 11:51 AM: ------------------------------------------------------------------- Also now seen on trunk. netstat shows the link is up, {code} tcp4 0 0 192.168.1.12.55256 s3-us-west-2-r-w.https ESTABLISHED {code} and nettop shows inaction, though the rx_ooo counter seemed be incrementing at2 2KB/s for a bit, before hanging completely {code} state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W java.16828 24502 13 MiB 8 3507 B 37 KiB 4654 KiB 0 B tcp4 192.168.1.12:55256<->s3-us-west-2-r-w.amazonaws.com:443 Established 24502 13 MiB 8 3507 B 37 KiB 4654 KiB 0 B 185.31 ms 15.03 ms 256 KiB 21 KiB - - - - {code} That's 4MB of OOO packets for 13 MB read, symptomatic of routing fun. Then, suddenly, that TCP connection got closed (socket timeout) and a new one opened that went through the full dataset in a second or two {code} state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W java.16828 41636 37 MiB 25 9210 B 37 KiB 4654 KiB 0 B tcp4 192.168.1.12:55256<->s3-us-west-2-r-w.amazonaws.com:443 FinWait2 24502 13 MiB 9 3560 B 37 KiB 4654 KiB 0 B 184.16 ms 12.44 ms 256 KiB 21 KiB - - - - {code} The really good news: curl is now suffering too. Which means its not a Java problem. Either the latop (which has been rebooted with SMC reset), or the rest of the network. {code} $ curl -O https://landsat-pds.s3.amazonaws.com/scene_list.gz % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 5 37.4M 5 2090k 0 0 11824 0 0:55:21 0:03:01 0:52:20 7039 $ nettop -p 17105 state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W curl.17105 3178 2323 KiB 4 482 B 10232 B 918 KiB 0 B tcp4 192.168.1.12:55731<->s3-us-west-2-w.amazonaws.com:443 Established 3178 2323 KiB 4 482 B 10232 B 918 KiB 0 B 173.56 ms 20.41 ms 256 KiB 16 KiB - - - - {code} And on another attempt {code} curl -O https://landsat-pds.s3.amazonaws.com/scene_list.gz % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 37.4M 100 37.4M 0 0 4410k 0 0:00:08 0:00:08 --:--:-- 6382k {code} Conclusions # sometimes over a network, we can get awful S3 read performance # which goes away on a reconnect, including those detected by socket timeouts # and which can be seen on other processes, so it's not a JVM/SDK problem # which means that curl can be used as a probe independent of everything else; nettop giving more details I'm going to try to set some more aggressive socket timeouts than 200 seconds. If it does address this, maybe we should consider having a smaller default. Also: time for that advanced troubleshooting document was (Author: ste...@apache.org): Also now seen on trunk. netstat shows the link is up, {code} tcp4 0 0 192.168.1.12.55256 s3-us-west-2-r-w.https ESTABLISHED {code} and nettop shows inaction, though the rx_ooo counter seemed be incrementing at2 2KB/s for a bit, before hanging completely {code} state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W java.16828 24502 13 MiB 8 3507 B 37 KiB 4654 KiB 0 B tcp4 192.168.1.12:55256<->s3-us-west-2-r-w.amazonaws.com:443 Established 24502 13 MiB 8 3507 B 37 KiB 4654 KiB 0 B 185.31 ms 15.03 ms 256 KiB 21 KiB - - - - {code} That's 4MB of OOO packets for 13 MB read, symptomatic of routing fun. Then, suddenly, that TCP connection got closed (socket timeout) and a new one opened that went through the full dataset in a second or two {code} state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W java.16828 41636 37 MiB 25 9210 B 37 KiB 4654 KiB 0 B tcp4 192.168.1.12:55256<->s3-us-west-2-r-w.amazonaws.com:443 FinWait2 24502 13 MiB 9 3560 B 37 KiB 4654 KiB 0 B 184.16 ms 12.44 ms 256 KiB 21 KiB - - - - {code} The really good news: curl is now suffering too. Which means its not a Java problem. Either the latop (which has been rebooted with SMC reset), or the rest of the network. {code} $ curl -O https://landsat-pds.s3.amazonaws.com/scene_list.gz % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 5 37.4M 5 2090k 0 0 11824 0 0:55:21 0:03:01 0:52:20 7039 $ nettop -p 17105 state packets_in bytes_in packets_out bytes_out rx_dupe rx_ooo re-tx rtt_avg rtt_var rcvsize tx_win P C R W curl.17105 3178 2323 KiB 4 482 B 10232 B 918 KiB 0 B tcp4 192.168.1.12:55731<->s3-us-west-2-w.amazonaws.com:443 Established 3178 2323 KiB 4 482 B 10232 B 918 KiB 0 B 173.56 ms 20.41 ms 256 KiB 16 KiB - - - - {code} And on another attempt {code} curl -O https://landsat-pds.s3.amazonaws.com/scene_list.gz % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 37.4M 100 37.4M 0 0 4410k 0 0:00:08 0:00:08 --:--:-- 6382k {code} Conclusions # sometimes over a network, we can get awful S3 read performance # which goes away on a reconnect, including those detected by socket timeouts # and which can be seen on other processes, so it's not a JVM/SDK problem # which means that curl can be used as a probe independent of everything else; nettop giving more details I'm going to try to set some more aggressive socket timeouts than 200 seconds. If it does address this, maybe we should consider having a smaller default. Also: time for that advanced troubleshooting document > 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, 2.9.0, 3.0.0-alpha2 > Environment: landsat bucket from the UK > Reporter: Steve Loughran > Assignee: Steve Loughran > Attachments: HADOOP-13871-001.patch, HADOOP-13871-002.patch, > org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance-output.txt > > > The ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks takes > 15s on branch-2, but is now taking minutes. > 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