Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Invalidate rather than update cache #34

Merged
merged 4 commits into from
May 3, 2016
Merged

Invalidate rather than update cache #34

merged 4 commits into from
May 3, 2016

Conversation

mrocklin
Copy link
Collaborator

Previously on touch or write events we called _ls to update the local
cache. When we called touch repeatedly this caused a slowdown unless
we used the no_refresh context manager.

Now we just invalidate the cache on write events so that the next read
event will correctly update the cache. This helps with many successive
writes.

cc @martindurant

This still has a couple of failures. I'm probably doing something a bit wacky.

@martindurant
Copy link
Member

Sounds like a more sensible solution for multiple writes than mine. I can look at it later, if you need.

@mrocklin
Copy link
Collaborator Author

Mostly I wanted to make sure that this was a sane approach and to cheaply check if the errors have an obvious cause to you. https://travis-ci.org/dask/s3fs/jobs/126181303

If not then I can continue diving in here unless you're particularly free from other work.

@martindurant
Copy link
Member

I am in a meeting now for at least 90min. I don't think current() can cause any problem, don't mind keeping it here.

@martindurant
Copy link
Member

We should remove the s3.refresh_off() stuff now, the failing test is not even necessary.

@mrocklin
Copy link
Collaborator Author

Under the many-small files case this helps by about a factor of two, but there is still more performance work to do. Here is a profile from a zarr computation:

In [1]: import zarr

In [2]: from s3fs import S3Map, S3FileSystem

In [3]: d = S3Map('zarr-test/test-1')

In [4]: x = zarr.empty(shape=(10000, 10000), chunks=(1000, 1000), dtype='f4', store=d)

In [5]: %time x[:] = 1
CPU times: user 800 ms, sys: 35.5 ms, total: 835 ms
Wall time: 15.6 s

In [6]: %prun x[:] = 2
         620856 function calls (614456 primitive calls) in 15.155 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     3293   11.954    0.004   11.954    0.004 {method 'read' of '_ssl._SSLSocket' objects}
      100    2.103    0.021    2.103    0.021 {built-in method select.select}
      100    0.059    0.001    0.060    0.001 {zarr.blosc.compress}
      100    0.047    0.000    0.047    0.000 {method 'fill' of 'numpy.ndarray' objects}
        3    0.024    0.008    0.024    0.008 {method 'load_verify_locations' of '_ssl._SSLContext' objects}
        3    0.021    0.007    0.021    0.007 {method 'do_handshake' of '_ssl._SSLSocket' objects}
     3300    0.019    0.000    0.038    0.000 parse.py:321(urlsplit)
      600    0.019    0.000    0.019    0.000 {method 'write' of '_ssl._SSLSocket' objects}
    48341    0.015    0.000    0.022    0.000 {built-in method builtins.isinstance}
     6300    0.014    0.000    0.034    0.000 message.py:463(get)
    59899    0.014    0.000    0.014    0.000 {method 'lower' of 'str' objects}
     7200    0.012    0.000    0.015    0.000 parse.py:100(_coerce_args)
2400/1800    0.012    0.000    0.167    0.000 hooks.py:175(_emit)
     2000    0.012    0.000    0.022    0.000 client.py:1038(putheader)
     3003    0.010    0.000   11.973    0.004 {method 'readline' of '_io.BufferedReader' objects}
16915/16615    0.010    0.000    0.012    0.000 {method 'encode' of 'str' objects}
     9509    0.010    0.000    0.020    0.000 _policybase.py:277(_sanitize_header)
      900    0.009    0.000    0.025    0.000 _collections_abc.py:756(update)
    19006    0.009    0.000    0.009    0.000 {method 'get' of 'dict' objects}
     2100    0.009    0.000    0.032    0.000 parse.py:288(urlparse)
    10600    0.008    0.000    0.008    0.000 {built-in method builtins.hasattr}
      600    0.008    0.000    0.047    0.000 feedparser.py:217(_parsegen)
      300    0.007    0.000   12.959    0.043 connectionpool.py:317(_make_request)
      300    0.007    0.000   14.583    0.049 sessions.py:539(send)
      300    0.007    0.000    0.082    0.000 client.py:179(parse_headers)
      300    0.007    0.000    0.039    0.000 auth.py:537(canonical_standard_headers)
     3293    0.007    0.000   11.987    0.004 socket.py:561(readinto)
      300    0.007    0.000    0.007    0.000 {method 'feed' of 'xml.etree.ElementTree.XMLParser' objects}
      300    0.007    0.000    0.017    0.000 feedparser.py:470(_parse_headers)
     5703    0.007    0.000    0.011    0.000 __init__.py:1515(isEnabledFor)
     3293    0.006    0.000   11.971    0.004 ssl.py:913(recv_into)
     9509    0.006    0.000    0.027    0.000 _policybase.py:307(header_fetch_parse)
      400    0.006    0.000    0.007    0.000 socket.py:638(close)
     6000    0.006    0.000    0.008    0.000 structures.py:53(__getitem__)
      300    0.006    0.000    0.012    0.000 parsers.py:639(_parse_non_payload_attrs)
     3500    0.006    0.000    0.011    0.000 _collections_abc.py:599(__contains__)
     6626    0.006    0.000    0.006    0.000 {method 'split' of 'str' objects}
    20324    0.005    0.000    0.005    0.000 {method 'append' of 'list' objects}
      400    0.005    0.000    0.008    0.000 socket.py:208(makefile)
     1300    0.005    0.000    0.005    0.000 {method 'update' of '_hashlib.HASH' objects}
      300    0.005    0.000   15.029    0.050 client.py:514(_make_api_call)
     5700    0.005    0.000    0.016    0.000 __init__.py:1257(debug)
      300    0.005    0.000   13.007    0.043 connectionpool.py:421(urlopen)
     3293    0.005    0.000   11.963    0.004 ssl.py:778(read)
     8409    0.005    0.000    0.009    0.000 utils.py:51(_has_surrogates)
    19955    0.005    0.000    0.005    0.000 {built-in method builtins.len}
     2400    0.005    0.000    0.005    0.000 {method 'format' of 'str' objects}
      300    0.005    0.000    2.219    0.007 client.py:1109(_send_request)
      300    0.005    0.000   13.098    0.044 adapters.py:323(send)
      300    0.005    0.000   10.660    0.036 client.py:275(begin)
     1500    0.005    0.000    0.009    0.000 parse.py:731(quote_from_bytes)
     5703    0.005    0.000    0.005    0.000 __init__.py:1501(getEffectiveLevel)
      200    0.004    0.000    0.010    0.000 parsers.py:376(_parse_xml_string_to_dom)
      300    0.004    0.000   10.564    0.035 client.py:242(_read_status)
     1900    0.004    0.000    0.009    0.000 _collections_abc.py:592(get)
     2200    0.004    0.000    0.006    0.000 message.py:394(__setitem__)
      300    0.004    0.000    0.014    0.000 client.py:915(putrequest)
  500/300    0.004    0.000    0.016    0.000 validate.py:160(_validate_structure)
     1703    0.004    0.000    0.007    0.000 _policybase.py:289(header_source_parse)
     1200    0.004    0.000    0.008    0.000 parse.py:388(urlunsplit)
     1600    0.004    0.000    0.007    0.000 abc.py:178(__instancecheck__)
      200    0.004    0.000    0.028    0.000 {method 'readline' of '_io._IOBase' objects}
      300    0.004    0.000    0.100    0.000 client.py:546(_convert_to_request_dict)
      600    0.004    0.000    0.013    0.000 cookiejar.py:1654(extract_cookies)
      300    0.004    0.000   14.639    0.049 endpoint.py:163(_get_response)
     5615    0.004    0.000    0.004    0.000 {built-in method builtins.getattr}
      200    0.004    0.000    0.007    0.000 ElementTree.py:782(_get_writer)
      300    0.004    0.000    0.047    0.000 serialize.py:374(serialize_to_request)
      300    0.004    0.000    0.015    0.000 models.py:552(__init__)
      300    0.004    0.000    0.028    0.000 response.py:312(from_httplib)
     2303    0.004    0.000    0.005    0.000 _collections.py:154(__getitem__)
      600    0.004    0.000    0.011    0.000 url.py:121(parse_url)
      300    0.004    0.000    0.021    0.000 utils.py:657(switch_to_virtual_host_style)
      300    0.004    0.000    2.175    0.007 awsrequest.py:146(_send_output)
 1800/300    0.004    0.000    0.019    0.000 validate.py:157(_validate)
      300    0.004    0.000    0.006    0.000 feedparser.py:139(__init__)
     4203    0.004    0.000    0.005    0.000 structures.py:48(__setitem__)
      300    0.004    0.000    0.006    0.000 hmac.py:26(__init__)
     3293    0.004    0.000   11.957    0.004 ssl.py:563(read)
      300    0.004    0.000    0.049    0.000 adapters.py:196(build_response)
     3593    0.004    0.000    0.004    0.000 socket.py:600(readable)
     7331    0.004    0.000    0.004    0.000 {method 'find' of 'str' objects}
      300    0.003    0.000    0.030    0.000 models.py:334(prepare_url)
      857    0.003    0.000    0.006    0.000 parse.py:313(_splitnetloc)
      900    0.003    0.000    0.016    0.000 message.py:460(<listcomp>)
     2606    0.003    0.000    0.003    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
     1200    0.003    0.000    0.005    0.000 message.py:498(get_all)
  400/100    0.003    0.000    0.007    0.000 ElementTree.py:895(_serialize_xml)
      300    0.003    0.000    0.006    0.000 response.py:97(__init__)
      300    0.003    0.000    0.122    0.000 signers.py:92(sign)
      300    0.003    0.000    0.095    0.000 awsrequest.py:356(prepare)
     2603    0.003    0.000    0.003    0.000 feedparser.py:75(readline)
      900    0.003    0.000    0.029    0.000 structures.py:42(__init__)
      300    0.003    0.000    0.008    0.000 awsrequest.py:336(__init__)
      600    0.003    0.000    0.027    0.000 cookies.py:115(extract_cookies_to_jar)
        3    0.003    0.001    0.003    0.001 {built-in method _socket.getaddrinfo}
     3293    0.003    0.000    0.003    0.000 {method '_checkClosed' of '_io._IOBase' objects}
      600    0.003    0.000    0.005    0.000 cookiejar.py:1236(__init__)
      500    0.003    0.000    1.438    0.003 response.py:425(read_chunked)
     5003    0.003    0.000    0.003    0.000 {method 'startswith' of 'str' objects}

@martindurant do you see any obvious gains that can be made? Is there a way with boto3 to maintain live connections that might benefit us?

@mrocklin
Copy link
Collaborator Author

This is a profile from master (before this PR) to show the difference.

         4688491 function calls (4566691 primitive calls) in 37.822 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     4177   30.155    0.007   30.155    0.007 {method 'read' of '_ssl._SSLSocket' objects}
      100    2.286    0.023    2.286    0.023 {built-in method select.select}
   133900    0.544    0.000    0.988    0.000 parser.py:64(get_token)
    10300    0.381    0.000    2.095    0.000 parser.py:618(_parse)
20900/400    0.180    0.000    3.748    0.009 parsers.py:312(_handle_structure)
    10300    0.157    0.000    2.709    0.000 parser.py:485(parse)
94300/500    0.150    0.000    3.751    0.008 parsers.py:254(_parse_shape)
      400    0.134    0.000    0.134    0.000 {method 'feed' of 'xml.etree.ElementTree.XMLParser' objects}
   288400    0.131    0.000    0.190    0.000 parser.py:195(isnum)
    93800    0.125    0.000    0.125    0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
    10300    0.108    0.000    1.232    0.000 parser.py:186(split)
    20900    0.103    0.000    0.301    0.000 parsers.py:353(_build_name_to_xml_node)
   285520    0.101    0.000    0.101    0.000 {built-in method builtins.getattr}
    30900    0.097    0.000    0.097    0.000 {method 'replace' of 'datetime.datetime' objects}
   133900    0.093    0.000    1.081    0.000 parser.py:176(__next__)
    30900    0.081    0.000    0.114    0.000 parser.py:397(append)
    73300    0.078    0.000    2.946    0.000 parsers.py:139(_get_text_content)
   144200    0.070    0.000    0.101    0.000 parser.py:190(isword)
    20600    0.069    0.000    0.069    0.000 {built-in method now}
   319300    0.066    0.000    0.066    0.000 {method 'isdigit' of 'str' objects}
   258300    0.065    0.000    0.065    0.000 {method 'read' of '_io.StringIO' objects}
    10300    0.064    0.000    2.806    0.000 utils.py:308(parse_timestamp)
    83900    0.064    0.000    0.084    0.000 parsers.py:338(_member_key_name)
   123600    0.063    0.000    0.089    0.000 parser.py:221(<genexpr>)
   213508    0.061    0.000    0.061    0.000 {method 'get' of 'dict' objects}
   134553    0.060    0.000    0.118    0.000 {built-in method builtins.isinstance}
    93700    0.059    0.000    0.183    0.000 parsers.py:299(_node_tag)
      100    0.055    0.001    0.057    0.001 {zarr.blosc.compress}
   191540    0.053    0.000    0.199    0.000 {built-in method builtins.len}
   116800    0.050    0.000    0.050    0.000 {built-in method builtins.hasattr}
      100    0.047    0.000    0.047    0.000 {method 'fill' of 'numpy.ndarray' objects}
   161332    0.045    0.000    0.045    0.000 {method 'append' of 'list' objects}
    10300    0.044    0.000    0.044    0.000 tz.py:88(__init__)
    10300    0.042    0.000    0.074    0.000 parser.py:208(__init__)
    10300    0.038    0.000    0.127    0.000 {built-in method builtins.sum}
    12400    0.035    0.000    0.058    0.000 abc.py:178(__instancecheck__)
    10300    0.034    0.000    0.041    0.000 parser.py:52(__init__)
   140244    0.033    0.000    0.033    0.000 {method 'lower' of 'str' objects}
   113300    0.032    0.000    0.032    0.000 {built-in method builtins.setattr}
    20600    0.032    0.000    0.037    0.000 parser.py:323(hms)
    10300    0.031    0.000    0.048    0.000 parser.py:1347(_parsems)
   144200    0.031    0.000    0.031    0.000 {method 'isalpha' of 'str' objects}
        4    0.030    0.008    0.030    0.008 {method 'do_handshake' of '_ssl._SSLSocket' objects}
    72900    0.028    0.000    0.028    0.000 {method 'pop' of 'list' objects}
    10300    0.028    0.000    2.737    0.000 parser.py:1066(parse)
    10300    0.027    0.000    0.027    0.000 parser.py:371(__init__)
        4    0.026    0.006    0.026    0.006 {method 'load_verify_locations' of '_ssl._SSLContext' objects}
    10300    0.025    0.000    0.027    0.000 parser.py:406(resolve_ymd)
     4400    0.025    0.000    0.048    0.000 parse.py:321(urlsplit)
    20600    0.024    0.000    0.029    0.000 parser.py:329(ampm)
    23500    0.023    0.000    0.023    0.000 _weakrefset.py:70(__contains__)
      700    0.022    0.000    0.022    0.000 {method 'write' of '_ssl._SSLSocket' objects}
    41200    0.021    0.000    0.030    0.000 parser.py:200(isspace)
    10300    0.019    0.000    0.146    0.000 parser.py:220(__len__)
     8100    0.018    0.000    0.045    0.000 message.py:463(get)
    20600    0.018    0.000    0.022    0.000 parser.py:304(jump)
    30900    0.017    0.000    0.023    0.000 parser.py:315(month)
3200/2400    0.017    0.000    0.239    0.000 hooks.py:175(_emit)
    10300    0.017    0.000    0.021    0.000 parser.py:357(validate)
    19066    0.016    0.000    0.016    0.000 {method 'split' of 'str' objects}
     4604    0.016    0.000   30.156    0.007 {method 'readline' of '_io.BufferedReader' objects}
     9600    0.016    0.000    0.019    0.000 parse.py:100(_coerce_args)
      100    0.014    0.000   19.493    0.195 core.py:225(_ls)
     2500    0.014    0.000    0.027    0.000 client.py:1038(putheader)
    20600    0.013    0.000    0.017    0.000 parser.py:307(weekday)
    52500    0.013    0.000    0.013    0.000 parsers.py:417(_handle_string)
    12612    0.013    0.000    0.028    0.000 _policybase.py:277(_sanitize_header)
     1200    0.013    0.000    0.035    0.000 _collections_abc.py:756(update)
     2800    0.013    0.000    0.043    0.000 parse.py:288(urlparse)
22020/21620    0.013    0.000    0.016    0.000 {method 'encode' of 'str' objects}
      400    0.012    0.000    0.128    0.000 client.py:179(parse_headers)
    21404    0.012    0.000    0.012    0.000 {method 'count' of 'str' objects}
      100    0.012    0.000    3.696    0.037 parsers.py:259(_handle_list)
    10300    0.012    0.000    0.015    0.000 parser.py:341(tzoffset)
      400    0.012    0.000   33.180    0.083 sessions.py:539(send)
      800    0.011    0.000    0.070    0.000 feedparser.py:217(_parsegen)
    10400    0.011    0.000    0.011    0.000 parsers.py:413(_handle_integer)
      400    0.011    0.000   31.509    0.079 connectionpool.py:317(_make_request)
      400    0.010    0.000    0.025    0.000 feedparser.py:470(_parse_headers)
    10300    0.010    0.000    0.010    0.000 parser.py:973(<listcomp>)
    10300    0.010    0.000    2.816    0.000 parsers.py:409(_handle_timestamp)
     4177    0.010    0.000   30.199    0.007 socket.py:561(readinto)
      400    0.010    0.000    0.051    0.000 auth.py:537(canonical_standard_headers)
    41200    0.009    0.000    0.009    0.000 {method 'isspace' of 'str' objects}
     7504    0.009    0.000    0.015    0.000 __init__.py:1515(isEnabledFor)
    10400    0.009    0.000    0.015    0.000 parse.py:632(unquote_plus)
     4177    0.008    0.000   30.178    0.007 ssl.py:913(recv_into)
    12612    0.008    0.000    0.036    0.000 _policybase.py:307(header_fetch_parse)
    10300    0.008    0.000    0.008    0.000 {method 'ljust' of 'str' objects}
      400    0.008    0.000   31.577    0.079 connectionpool.py:421(urlopen)
      400    0.008    0.000   28.834    0.072 client.py:242(_read_status)
      400    0.007    0.000   28.981    0.072 client.py:275(begin)
      400    0.007    0.000   37.650    0.094 client.py:514(_make_api_call)
      500    0.007    0.000    0.011    0.000 socket.py:208(makefile)
     7100    0.007    0.000    0.009    0.000 structures.py:53(__getitem__)
      400    0.007    0.000   31.707    0.079 adapters.py:323(send)
      400    0.007    0.000    0.014    0.000 parsers.py:639(_parse_non_payload_attrs)
      500    0.007    0.000    0.009    0.000 socket.py:638(close)
    11212    0.007    0.000    0.012    0.000 utils.py:51(_has_surrogates)
      400    0.007    0.000    2.422    0.006 client.py:1109(_send_request)
     7500    0.007    0.000    0.022    0.000 __init__.py:1257(debug)
      300    0.007    0.000    0.139    0.000 parsers.py:376(_parse_xml_string_to_dom)
     4000    0.007    0.000    0.014    0.000 _collections_abc.py:599(__contains__)
     4177    0.007    0.000   30.168    0.007 ssl.py:778(read)

@mrocklin
Copy link
Collaborator Author

One thing is that we're really doing just 100 puts, but we seem to incur 3000 messages. Are some of these extra messages avoidable?

@mrocklin
Copy link
Collaborator Author

cc @alimanfoo in case he's interested

@alimanfoo
Copy link

Thanks, very interesting.

@martindurant
Copy link
Member

The write interface works assuming big files, and uses multi-part-upload even for small files (so need to create the multi-part, write chunks, and finalize every time). Could give an option for small files/multi-part off.
Better, but more effort, would be to only start the multi-part when the buffer first goes over the block size.

I'll look into the latter, see if it's simpler than I first imagine.

@mrocklin
Copy link
Collaborator Author

Perhaps the put command is more appropriate here because we know at the beginning exactly how large the message will be. Maybe in smallish cases we can opt for a different upload mechanism.

Regardless, uploading many small-to-medium sized files is an application that it would be nice to support efficiently. Creating a benchmark similar to what is above and then optimizing it down might be a satisfying and valuable experience.

@martindurant
Copy link
Member

@mrocklin , please benchmark now; appears to be substantially faster for small files, and I didnd't break anything.

@mrocklin
Copy link
Collaborator Author

Away from an easy testing location at the moment. Will try this out later tonight.

@mrocklin
Copy link
Collaborator Author

In [1]: from s3fs import S3Map, S3FileSystem

In [2]: d = S3Map('zarr-test/test-1')

In [3]: d.clear()

In [4]: import zarr

In [5]: x = zarr.empty(shape=(10000, 10000), chunks=(1000, 1000), dtype='f4', store=d)

In [6]: %prun x[:] = 1

In [7]: %prun -s cumtime x[:] = 2

Sorted by total time

         231165 function calls (230265 primitive calls) in 6.148 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2600    3.796    0.001    3.796    0.001 {method 'read' of '_ssl._SSLSocket' objects}
      100    1.906    0.019    1.906    0.019 {built-in method select.select}
      100    0.052    0.001    0.054    0.001 {zarr.blosc.compress}
      100    0.038    0.000    0.038    0.000 {method 'fill' of 'numpy.ndarray' objects}
      400    0.013    0.000    0.013    0.000 {method 'write' of '_ssl._SSLSocket' objects}
        1    0.006    0.006    0.006    0.006 {method 'load_verify_locations' of '_ssl._SSLContext' objects}
        1    0.006    0.006    0.006    0.006 {method 'do_handshake' of '_ssl._SSLSocket' objects}
     2700    0.006    0.000    0.014    0.000 message.py:463(get)
     1100    0.005    0.000    0.010    0.000 parse.py:321(urlsplit)
    24826    0.005    0.000    0.005    0.000 {method 'lower' of 'str' objects}
    16017    0.005    0.000    0.007    0.000 {built-in method builtins.isinstance}
      500    0.005    0.000    0.005    0.000 {method 'update' of '_hashlib.HASH' objects}
  800/600    0.005    0.000    0.064    0.000 hooks.py:175(_emit)
     2600    0.004    0.000    3.818    0.001 socket.py:561(readinto)
     2600    0.004    0.000    3.808    0.001 ssl.py:913(recv_into)
      800    0.004    0.000    0.008    0.000 client.py:1038(putheader)
      200    0.004    0.000    0.028    0.000 {method 'readline' of '_io._IOBase' objects}
     4003    0.004    0.000    0.008    0.000 _policybase.py:277(_sanitize_header)
     2400    0.004    0.000    0.005    0.000 parse.py:100(_coerce_args)
      300    0.003    0.000    0.009    0.000 _collections_abc.py:756(update)
6205/6105    0.003    0.000    0.004    0.000 {method 'encode' of 'str' objects}
     2600    0.003    0.000    3.802    0.001 ssl.py:778(read)
      700    0.003    0.000    0.009    0.000 parse.py:288(urlparse)
      100    0.003    0.000    0.017    0.000 auth.py:537(canonical_standard_headers)
     3800    0.003    0.000    0.003    0.000 {built-in method builtins.hasattr}
      100    0.003    0.000    5.900    0.059 sessions.py:539(send)
     5702    0.003    0.000    0.003    0.000 {method 'get' of 'dict' objects}
      100    0.003    0.000    0.027    0.000 client.py:179(parse_headers)
      200    0.003    0.000    0.015    0.000 feedparser.py:217(_parsegen)
     2301    0.002    0.000    0.004    0.000 __init__.py:1515(isEnabledFor)
     4003    0.002    0.000    0.011    0.000 _policybase.py:307(header_fetch_parse)
      100    0.002    0.000    5.833    0.058 connectionpool.py:317(_make_request)
      100    0.002    0.000    0.006    0.000 feedparser.py:470(_parse_headers)
      200    0.002    0.000    0.003    0.000 socket.py:208(makefile)
     1400    0.002    0.000    0.004    0.000 _collections_abc.py:599(__contains__)
     2700    0.002    0.000    0.002    0.000 socket.py:600(readable)
      200    0.002    0.000    0.003    0.000 socket.py:638(close)
     2400    0.002    0.000    0.003    0.000 structures.py:53(__getitem__)
     2600    0.002    0.000    0.002    0.000 {method '_checkClosed' of '_io._IOBase' objects}
      100    0.002    0.000    0.005    0.000 parsers.py:639(_parse_non_payload_attrs)
      801    0.002    0.000    3.796    0.005 {method 'readline' of '_io.BufferedReader' objects}
     3503    0.002    0.000    0.003    0.000 utils.py:51(_has_surrogates)
      200    0.002    0.000    0.020    0.000 client.py:846(send)
      400    0.002    0.000    0.017    0.000 ssl.py:876(sendall)
     2600    0.002    0.000    3.798    0.001 ssl.py:563(read)
     2300    0.002    0.000    0.006    0.000 __init__.py:1257(debug)
     1000    0.002    0.000    0.003    0.000 message.py:394(__setitem__)
     2600    0.002    0.000    0.004    0.000 {method '_checkReadable' of '_io._IOBase' objects}
        1    0.002    0.002    6.149    6.149 core.py:193(__setitem__)
     7738    0.002    0.000    0.002    0.000 {built-in method builtins.len}
      100    0.002    0.000    5.850    0.058 connectionpool.py:421(urlopen)
     2301    0.002    0.000    0.002    0.000 __init__.py:1501(getEffectiveLevel)
     6908    0.002    0.000    0.002    0.000 {method 'append' of 'list' objects}
      100    0.002    0.000    6.042    0.060 client.py:514(_make_api_call)
      800    0.002    0.000    0.002    0.000 {method 'format' of 'str' objects}
      100    0.002    0.000    3.829    0.038 client.py:275(begin)
      100    0.002    0.000    1.964    0.020 awsrequest.py:146(_send_output)
      100    0.002    0.000    6.146    0.061 core.py:284(_chunk_setitem)
      100    0.002    0.000    5.878    0.059 adapters.py:323(send)
      100    0.002    0.000    1.980    0.020 client.py:1109(_send_request)
      700    0.002    0.000    0.002    0.000 {method 'read' of '_io.BytesIO' objects}
      100    0.002    0.000    0.002    0.000 __init__.py:487(string_at)
     1701    0.001    0.000    0.002    0.000 structures.py:48(__setitem__)
      100    0.001    0.000    3.797    0.038 client.py:242(_read_status)
      601    0.001    0.000    0.003    0.000 _policybase.py:289(header_source_parse)
      100    0.001    0.000    0.022    0.000 client.py:546(_convert_to_request_dict)

Sorted by cumulative time

         231171 function calls (230271 primitive calls) in 5.988 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.989    5.989 {built-in method builtins.exec}
        1    0.000    0.000    5.989    5.989 <string>:1(<module>)
        1    0.002    0.002    5.989    5.989 core.py:193(__setitem__)
      100    0.002    0.000    5.985    0.060 core.py:284(_chunk_setitem)
      100    0.001    0.000    5.879    0.059 mapping.py:64(__setitem__)
      100    0.000    0.000    5.874    0.059 core.py:869(__exit__)
      200    0.001    0.000    5.874    0.029 core.py:818(close)
      100    0.001    0.000    5.872    0.059 client.py:244(_api_call)
      100    0.002    0.000    5.871    0.059 client.py:514(_make_api_call)
      100    0.000    0.000    5.832    0.058 endpoint.py:114(make_request)
      100    0.001    0.000    5.832    0.058 endpoint.py:140(_send_request)
      100    0.002    0.000    5.733    0.057 endpoint.py:163(_get_response)
      100    0.003    0.000    5.718    0.057 sessions.py:539(send)
      100    0.002    0.000    5.694    0.057 adapters.py:323(send)
      100    0.002    0.000    5.662    0.057 connectionpool.py:421(urlopen)
      100    0.003    0.000    5.643    0.056 connectionpool.py:317(_make_request)
      100    0.001    0.000    3.366    0.034 client.py:1130(getresponse)
      100    0.002    0.000    3.363    0.034 client.py:275(begin)
     2600    0.004    0.000    3.349    0.001 socket.py:561(readinto)
     2600    0.004    0.000    3.339    0.001 ssl.py:913(recv_into)
     2600    0.003    0.000    3.333    0.001 ssl.py:778(read)
     2600    0.002    0.000    3.329    0.001 ssl.py:563(read)
      100    0.002    0.000    3.329    0.033 client.py:242(_read_status)
      801    0.002    0.000    3.327    0.004 {method 'readline' of '_io.BufferedReader' objects}
     2600    3.327    0.001    3.327    0.001 {method 'read' of '_ssl._SSLSocket' objects}
      100    0.000    0.000    2.257    0.023 client.py:1081(request)
      100    0.001    0.000    2.257    0.023 awsrequest.py:121(_send_request)
      100    0.002    0.000    2.256    0.023 client.py:1109(_send_request)
      100    0.000    0.000    2.238    0.022 client.py:1066(endheaders)
      100    0.002    0.000    2.237    0.022 awsrequest.py:146(_send_output)
      100    2.176    0.022    2.176    0.022 {built-in method select.select}
      100    0.001    0.000    0.092    0.001 endpoint.py:119(create_request)
  800/600    0.005    0.000    0.068    0.000 hooks.py:175(_emit)
  600/500    0.001    0.000    0.057    0.000 hooks.py:215(emit)
      100    0.000    0.000    0.055    0.001 compression.py:73(compress)
      100    0.053    0.001    0.055    0.001 {zarr.blosc.compress}
      100    0.002    0.000    0.052    0.001 awsrequest.py:195(_handle_expect_response)
      100    0.047    0.000    0.047    0.000 {method 'fill' of 'numpy.ndarray' objects}
      100    0.000    0.000    0.046    0.000 signers.py:85(handler)
      100    0.001    0.000    0.046    0.000 signers.py:92(sign)
      100    0.000    0.000    0.040    0.000 endpoint.py:136(prepare_request)
      100    0.001    0.000    0.035    0.000 awsrequest.py:356(prepare)
      100    0.001    0.000    0.034    0.000 auth.py:624(add_auth)
      100    0.003    0.000    0.029    0.000 client.py:179(parse_headers)
      100    0.001    0.000    0.029    0.000 auth.py:612(get_signature)
      200    0.004    0.000    0.028    0.000 {method 'readline' of '_io._IOBase' objects}
      100    0.001    0.000    0.024    0.000 parser.py:60(parsestr)
      100    0.002    0.000    0.024    0.000 client.py:546(_convert_to_request_dict)
      100    0.001    0.000    0.023    0.000 parser.py:42(parse)
      200    0.001    0.000    0.023    0.000 awsrequest.py:236(send)
      100    0.001    0.000    0.022    0.000 auth.py:602(canonical_string)
      200    0.002    0.000    0.022    0.000 client.py:846(send)
      400    0.002    0.000    0.019    0.000 ssl.py:876(sendall)
      100    0.001    0.000    0.018    0.000 adapters.py:196(build_response)
      100    0.000    0.000    0.018    0.000 awsrequest.py:232(_send_message_body)
      100    0.003    0.000    0.018    0.000 auth.py:537(canonical_standard_headers)
      100    0.000    0.000    0.017    0.000 feedparser.py:175(feed)
      200    0.000    0.000    0.017    0.000 feedparser.py:180(_call_parse)
      200    0.003    0.000    0.016    0.000 feedparser.py:217(_parsegen)
      400    0.001    0.000    0.016    0.000 ssl.py:849(send)
      400    0.001    0.000    0.015    0.000 ssl.py:575(write)
      100    0.000    0.000    0.015    0.000 connectionpool.py:753(_validate_conn)
      400    0.015    0.000    0.015    0.000 {method 'write' of '_ssl._SSLSocket' objects}
        1    0.000    0.000    0.014    0.014 connection.py:202(connect)
     2700    0.006    0.000    0.014    0.000 message.py:463(get)
      100    0.001    0.000    0.014    0.000 validate.py:263(serialize_to_request)

@mrocklin
Copy link
Collaborator Author

Writing non-trivial data to the array shows how these times relate to other times.

In [10]: %time a = np.random.random(size=x.shape).astype(dtype=x.dtype)
CPU times: user 1.28 s, sys: 231 ms, total: 1.51 s
Wall time: 1.51 s

In [11]: %prun x[:] = a

In [12]: %time a = np.random.random(size=x.shape).astype(dtype=x.dtype)
CPU times: user 1.27 s, sys: 233 ms, total: 1.5 s
Wall time: 1.5 s

In [13]: %prun -s cumtime x[:] = a

Sorted by total time

         621556 function calls (620656 primitive calls) in 34.085 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2600   25.671    0.010   25.671    0.010 {method 'read' of '_ssl._SSLSocket' objects}
      100    4.224    0.042    4.224    0.042 {built-in method select.select}
    49000    1.691    0.000    1.691    0.000 {method 'write' of '_ssl._SSLSocket' objects}
      800    0.736    0.001    0.736    0.001 {method 'update' of '_hashlib.HASH' objects}
      100    0.582    0.006    0.640    0.006 {zarr.blosc.compress}
    49600    0.229    0.000    0.229    0.000 {method 'read' of '_io.BytesIO' objects}
    49000    0.118    0.000    1.941    0.000 ssl.py:876(sendall)
      100    0.105    0.001    0.105    0.001 {method 'write' of '_io.BytesIO' objects}
      100    0.079    0.001    0.079    0.001 {built-in method numpy.core.multiarray.array}
      200    0.077    0.000    2.094    0.010 client.py:846(send)
    49000    0.062    0.000    1.798    0.000 ssl.py:849(send)
      100    0.058    0.001    0.058    0.001 __init__.py:487(string_at)
    49000    0.034    0.000    1.725    0.000 ssl.py:575(write)
   103201    0.024    0.000    0.024    0.000 ssl.py:766(_checkClosed)
    56338    0.015    0.000    0.015    0.000 {built-in method builtins.len}
        1    0.007    0.007    0.007    0.007 {method 'do_handshake' of '_ssl._SSLSocket' objects}
        1    0.007    0.007    0.007    0.007 {method 'load_verify_locations' of '_ssl._SSLContext' objects}
     1100    0.006    0.000    0.012    0.000 parse.py:321(urlsplit)
     2700    0.006    0.000    0.014    0.000 message.py:463(get)
  800/600    0.006    0.000    0.854    0.001 hooks.py:175(_emit)
    16017    0.006    0.000    0.008    0.000 {built-in method builtins.isinstance}
    24826    0.005    0.000    0.005    0.000 {method 'lower' of 'str' objects}
      800    0.005    0.000    0.010    0.000 client.py:1038(putheader)
     2600    0.005    0.000   25.694    0.010 socket.py:561(readinto)
     2600    0.005    0.000   25.683    0.010 ssl.py:913(recv_into)
     4003    0.004    0.000    0.009    0.000 _policybase.py:277(_sanitize_header)
      200    0.004    0.000    0.029    0.000 {method 'readline' of '_io._IOBase' objects}
      300    0.004    0.000    0.010    0.000 _collections_abc.py:756(update)
     2400    0.004    0.000    0.005    0.000 parse.py:100(_coerce_args)
6205/6105    0.004    0.000    0.004    0.000 {method 'encode' of 'str' objects}
     2600    0.003    0.000   25.677    0.010 ssl.py:778(read)
      700    0.003    0.000    0.010    0.000 parse.py:288(urlparse)
      200    0.003    0.000    0.005    0.000 socket.py:208(makefile)
      100    0.003    0.000   32.115    0.321 connectionpool.py:317(_make_request)
      100    0.003    0.000   32.192    0.322 sessions.py:539(send)
      100    0.003    0.000    0.019    0.000 auth.py:537(canonical_standard_headers)
     3800    0.003    0.000    0.003    0.000 {built-in method builtins.hasattr}
      100    0.003    0.000    0.030    0.000 client.py:179(parse_headers)
     5702    0.003    0.000    0.003    0.000 {method 'get' of 'dict' objects}
      200    0.003    0.000    0.016    0.000 feedparser.py:217(_parsegen)
     2301    0.003    0.000    0.005    0.000 __init__.py:1515(isEnabledFor)
      801    0.003    0.000   25.672    0.032 {method 'readline' of '_io.BufferedReader' objects}
      200    0.003    0.000    0.003    0.000 socket.py:638(close)
        1    0.003    0.003   34.086   34.086 core.py:193(__setitem__)
      100    0.003    0.000   34.081    0.341 core.py:284(_chunk_setitem)
      100    0.003    0.000    0.006    0.000 feedparser.py:470(_parse_headers)
     4003    0.002    0.000    0.011    0.000 _policybase.py:307(header_fetch_parse)
      100    0.002    0.000   33.138    0.331 client.py:514(_make_api_call)
      100    0.002    0.000    0.006    0.000 parsers.py:639(_parse_non_payload_attrs)
      800    0.002    0.000    0.002    0.000 {method 'format' of 'str' objects}
      100    0.002    0.000   32.134    0.321 connectionpool.py:421(urlopen)
     2300    0.002    0.000    0.007    0.000 __init__.py:1257(debug)
     2700    0.002    0.000    0.002    0.000 socket.py:600(readable)
      100    0.002    0.000   25.709    0.257 client.py:275(begin)
     2400    0.002    0.000    0.003    0.000 structures.py:53(__getitem__)
      100    0.002    0.000   25.673    0.257 client.py:242(_read_status)
     1400    0.002    0.000    0.005    0.000 _collections_abc.py:599(__contains__)
     3503    0.002    0.000    0.004    0.000 utils.py:51(_has_surrogates)
     2600    0.002    0.000   25.673    0.010 ssl.py:563(read)
      100    0.002    0.000   32.167    0.322 adapters.py:323(send)
     2600    0.002    0.000    0.002    0.000 {method '_checkClosed' of '_io._IOBase' objects}
      100    0.002    0.000    0.028    0.000 client.py:546(_convert_to_request_dict)
     2301    0.002    0.000    0.002    0.000 __init__.py:1501(getEffectiveLevel)
     2600    0.002    0.000    0.004    0.000 {method '_checkReadable' of '_io._IOBase' objects}
     1000    0.002    0.000    0.003    0.000 message.py:394(__setitem__)
     6908    0.002    0.000    0.002    0.000 {method 'append' of 'list' objects}

Sorted by cumulative time

         621571 function calls (620671 primitive calls) in 29.433 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   29.434   29.434 {built-in method builtins.exec}
        1    0.000    0.000   29.434   29.434 <string>:1(<module>)
        1    0.003    0.003   29.434   29.434 core.py:193(__setitem__)
      100    0.003    0.000   29.429    0.294 core.py:284(_chunk_setitem)
      100    0.002    0.000   28.703    0.287 mapping.py:64(__setitem__)
      100    0.000    0.000   28.598    0.286 core.py:869(__exit__)
      200    0.002    0.000   28.598    0.143 core.py:818(close)
      100    0.001    0.000   28.496    0.285 client.py:244(_api_call)
      100    0.003    0.000   28.495    0.285 client.py:514(_make_api_call)
      100    0.000    0.000   27.670    0.277 endpoint.py:114(make_request)
      100    0.001    0.000   27.670    0.277 endpoint.py:140(_send_request)
      100    0.002    0.000   27.562    0.276 endpoint.py:163(_get_response)
      100    0.003    0.000   27.547    0.275 sessions.py:539(send)
      100    0.002    0.000   27.522    0.275 adapters.py:323(send)
      100    0.002    0.000   27.490    0.275 connectionpool.py:421(urlopen)
      100    0.003    0.000   27.471    0.275 connectionpool.py:317(_make_request)
      100    0.001    0.000   21.255    0.213 client.py:1130(getresponse)
      100    0.002    0.000   21.250    0.213 client.py:275(begin)
     2600    0.005    0.000   21.234    0.008 socket.py:561(readinto)
     2600    0.005    0.000   21.223    0.008 ssl.py:913(recv_into)
     2600    0.003    0.000   21.217    0.008 ssl.py:778(read)
      100    0.002    0.000   21.214    0.212 client.py:242(_read_status)
     2600    0.002    0.000   21.213    0.008 ssl.py:563(read)
      801    0.003    0.000   21.212    0.026 {method 'readline' of '_io.BufferedReader' objects}
     2600   21.211    0.008   21.211    0.008 {method 'read' of '_ssl._SSLSocket' objects}
      100    0.000    0.000    6.195    0.062 client.py:1081(request)
      100    0.001    0.000    6.195    0.062 awsrequest.py:121(_send_request)
      100    0.002    0.000    6.194    0.062 client.py:1109(_send_request)
      100    0.000    0.000    6.176    0.062 client.py:1066(endheaders)
      100    0.002    0.000    6.176    0.062 awsrequest.py:146(_send_output)
      100    3.918    0.039    3.918    0.039 {built-in method select.select}
      100    0.002    0.000    2.247    0.022 awsrequest.py:195(_handle_expect_response)
      200    0.001    0.000    2.218    0.011 awsrequest.py:236(send)
      200    0.083    0.000    2.218    0.011 client.py:846(send)
      100    0.000    0.000    2.212    0.022 awsrequest.py:232(_send_message_body)
    49000    0.123    0.000    2.055    0.000 ssl.py:876(sendall)
    49000    0.064    0.000    1.906    0.000 ssl.py:849(send)
    49000    0.035    0.000    1.832    0.000 ssl.py:575(write)
    49000    1.796    0.000    1.796    0.000 {method 'write' of '_ssl._SSLSocket' objects}
  800/600    0.006    0.000    0.854    0.001 hooks.py:175(_emit)
      200    0.000    0.000    0.792    0.004 hooks.py:228(emit_until_response)
      100    0.001    0.000    0.788    0.008 handlers.py:151(conditionally_calculate_md5)
      100    0.001    0.000    0.788    0.008 handlers.py:125(calculate_md5)
      100    0.002    0.000    0.786    0.008 handlers.py:142(_calculate_md5_from_file)
      800    0.735    0.001    0.735    0.001 {method 'update' of '_hashlib.HASH' objects}
      100    0.000    0.000    0.642    0.006 compression.py:73(compress)
      100    0.585    0.006    0.642    0.006 {zarr.blosc.compress}
    49600    0.228    0.000    0.228    0.000 {method 'read' of '_io.BytesIO' objects}
      100    0.001    0.000    0.100    0.001 endpoint.py:119(create_request)
      100    0.001    0.000    0.100    0.001 core.py:739(write)
      100    0.100    0.001    0.100    0.001 {method 'write' of '_io.BytesIO' objects}
      100    0.000    0.000    0.079    0.001 numeric.py:535(ascontiguousarray)
      100    0.078    0.001    0.078    0.001 {built-in method numpy.core.multiarray.array}
  600/500    0.001    0.000    0.063    0.000 hooks.py:215(emit)
      100    0.057    0.001    0.057    0.001 __init__.py:487(string_at)
      100    0.000    0.000    0.050    0.000 signers.py:85(handler)
      100    0.001    0.000    0.050    0.000 signers.py:92(sign)
      500    0.001    0.000    0.048    0.000 handlers.py:145(<lambda>)
      100    0.000    0.000    0.044    0.000 endpoint.py:136(prepare_request)
      100    0.001    0.000    0.039    0.000 awsrequest.py:356(prepare)
      100    0.001    0.000    0.036    0.000 auth.py:624(add_auth)
      100    0.003    0.000    0.031    0.000 client.py:179(parse_headers)
      100    0.001    0.000    0.031    0.000 auth.py:612(get_signature)
      200    0.004    0.000    0.029    0.000 {method 'readline' of '_io._IOBase' objects}
      100    0.002    0.000    0.028    0.000 client.py:546(_convert_to_request_dict)

It's odd how much time we spend reading

@mrocklin
Copy link
Collaborator Author

So all in all this is a huge improvement. I'm still generally curious what is taking up time here. Any ideas?

@martindurant
Copy link
Member

I'll look into it, but at a first guess, would this include time waiting for the server to supply a response? Every call on S3 must be a HTTP PUT/POST, but the response is always checked to see if the operation was successful.

@mrocklin
Copy link
Collaborator Author

mrocklin commented May 1, 2016

There appear to be precisely 2600 calls to method 'read' of '_ssl._SSLSocket' objects for 100 connection calls in all occurrences above. This appears to be independent of the size of the data. To me this feels like a surprising number of reads, signalling that there might be some complex handshaking going back and forth. Is there a way to set up a long running HTTP connection with S3 to reduce the back and forth?

@martindurant
Copy link
Member

I looked into S3 connections, and I can’t find any way to keep them open.
There is in theory the option to turn off SSL (which doesn’t seem like a good idea), but I tried the relevant option and it didn’t seem to make any difference (maybe some servers allow it, or only for anonymous use?).

(Ideally we would not be writing tiny chunks, would this be used in a real scenario?)

@mrocklin
Copy link
Collaborator Author

mrocklin commented May 2, 2016

In this comment we dump 400MB of 1000x1000 chunks into S3 over 30s from a box on EC2. This is roughly 10MB/s which is quite a bit slower than what I would expect.

Most of the time comes from {method 'read' of '_ssl._SSLSocket' objects}, not from actually writing to a socket which takes only 1.6s (much more like what I would expect).

I consider 4MB chunks to be a perhaps a bit small, but not that small. Assuming we have 100MB/s write bandwidth and this read overhead is around 300ms this means that we need to be writing chunks in the hundreds of megabytes before we stop noticing the overhead. This seems too large to me.

@martindurant
Copy link
Member

We were not the first to think about this http://stackoverflow.com/questions/8650625/efficiently-move-many-small-files-to-amazon-s3 (refers to a previous python-fuse s3fs I didn't know about)
General suggestion seems to be many threads; I have found no way yet to accelerate a single transfer.

@mrocklin
Copy link
Collaborator Author

mrocklin commented May 2, 2016

It's odd that the overhead for a single put is 300ms. I wonder if there is hidden API somewhere in boto3 that does this faster. My suggestion would be to write a stackoverflow post asking about how to write to S3 with low overhead. I suspect that with the proper tags (something like s3 and boto) we'd get an expert opinion within a day or two.

@martindurant
Copy link
Member

@martindurant
Copy link
Member

Experiment with threads:
7cc4d6a
yes, you can ignore responses in threads left to die by themselves.

@martindurant
Copy link
Member

Any reason not to merge the work here so far (minus the experimental commit with threads)? Anything fancy to deal with latency can come separately.

@mrocklin
Copy link
Collaborator Author

mrocklin commented May 3, 2016

Sure. Should I take care of the rebase or would you like to?

If you do it note that I have a commit in there titled squash that I intended to squash into the commit above.

@martindurant
Copy link
Member

If you want to restructure the commits at all, then please go ahead.

mrocklin and others added 2 commits May 3, 2016 07:56
Previously on touch or write events we called `_ls` to update the local
cache.  When we called touch repeatedly this caused a slowdown unless
we used the `no_refresh` context manager.

Now we just invalidate the cache on write events so that the next read
event will correctly update the cache.  This helps with many successive
writes.
a better way to solve the many-writes problem; no need to check the
filelist until the next time we need the listing/detail.
@mrocklin mrocklin merged commit e75362e into master May 3, 2016
@mrocklin mrocklin deleted the invalidate-cache branch May 3, 2016 15:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants