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

    [ 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/8/16 7:09 PM:
------------------------------------------------------------------

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: stevel@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 a2 2KB/s for a
bit, before handing 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, 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-unsubscribe@hadoop.apache.org
For additional commands, e-mail: common-issues-help@hadoop.apache.org


Mime
View raw message