slow rendering with remote storage on cached thumbnails

[andreav]

Hi.

I'm experimenting slow template rendering due to the fact that easy_thumbnails is touching remote storage although thumbnails are cached.

I'm successfully creating thumbnails in a celery task like this:

thumb = get_thumbnailer(ph.image)[an_alias_str]

My template is using thumbnailer_passive filter and is accessing thumbnails dimensions. I think this is related to this #293 issue, but if i undestand well, it should be fixed by this #298

My template is something like so:

{% for ph in photos %}
    {% with tn=ph.image|thumbnailer_passive %}

 <a href="{{ ph.image.url }}">
  <img class="img-responsive lazyload" 
       data-src="{{ ph.small_square.url }}" alt="{{ ph.image.text }}" 
       data-aspectratio="{{ph.image.width}}/{{ph.image.height}}" 
       data-sizes=auto 
       data-srcset="{% if tn.small_square %}{{tn.small_square.url}} {{tn.small_square.width}}w{% endif %}
                    {% if tn.medium_square %}, {{tn.medium_square.url}} {{tn.medium_square.width}}w{% endif %}
                    {% if tn.large_square %}, {{tn.large_square.url}} {{tn.large_square.width}}w{% endif %}">
 </a>

     {% endwith %}
{% endfor %}

My setup is:

easy-thumbnails==2.2
THUMBNAIL_DEFAULT_STORAGE = 'storages.backends.s3boto.S3BotoStorage'
THUMBNAIL_BASEDIR = 'thumbs'
THUMBNAIL_CACHE_DIMENSIONS = True
THUMBNAIL_CHECK_CACHE_MISS = False

Images and thumbnails are present on Amazon S3.

DbCache seems correctly populated:

id|name|modified|thumbname|widt|height
42|photos-stage-1/A.png|2015-07-08 16:25:01.378407+00:00|thumbs/photos-stage-1/A.png.80x80_q85_crop.jpg|80|80
42|photos-stage-1/A.png|2015-07-08 16:25:01.378407+00:00|thumbs/photos-stage-1/A.png.280x280_q85_crop.jpg|280|280
42|photos-stage-1/A.png|2015-07-08 16:25:01.378407+00:00|thumbs/photos-stage-1/A.png.480x480_q85_crop.jpg|480|480
42|photos-stage-1/A.png|2015-07-08 16:25:01.378407+00:00|thumbs/photos-stage-1/A.png.680x680_q85_crop.jpg|680|680
42|photos-stage-1/A.png|2015-07-08 16:25:01.378407+00:00|thumbs/photos-stage-1/A.png.50x50_q85_crop.jpg|50|50

Some profiling informations: Sorting by tottime you see read spent time

 Ordered by: internal time
 List reduced from 1257 to 251 due to restriction <0.2>

 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    898    1.698    0.002    1.698    0.002 {method 'read' of '_ssl._SSLSocket' objects}
      1    0.373    0.373    0.373    0.373 {method 'do_handshake' of '_ssl._SSLSocket' objects}
      1    0.184    0.184    0.184    0.184 {_socket.getaddrinfo}
      1    0.180    0.180    0.180    0.180 {method 'connect' of '_socket.socket' objects}
  23155    0.050    0.000    0.050    0.000 {posix.lstat}
 ........

Sorting by cumtime: you see open invocation

   Ordered by: cumulative time
   List reduced from 1257 to 251 due to restriction <0.2>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.414    2.414 {my_rootsite}/triptogo/trips/views_stage.py:45(stage_detail)
        1    0.000    0.000    2.388    2.388 {my_rootsite}/local/lib/python2.7/site-packages/django/shortcuts.py:28(render)
        1    0.000    0.000    2.388    2.388 {my_rootsite}/local/lib/python2.7/site-packages/django/template/loader.py:159(render_to_string)
     26/1    0.001    0.000    2.382    2.382 {my_rootsite}/local/lib/python2.7/site-packages/template_timings_panel/panels/TemplateTimings.py:96(timing_hook)
      5/1    0.000    0.000    2.382    2.382 {my_rootsite}/local/lib/python2.7/site-packages/django/template/base.py:144(render)
      7/1    0.000    0.000    2.382    2.382 {my_rootsite}/local/lib/python2.7/site-packages/django/test/utils.py:82(instrumented_test_render)
     35/1    0.001    0.000    2.367    2.367 {my_rootsite}/local/lib/python2.7/site-packages/django/template/base.py:840(render)
    234/1    0.000    0.000    2.367    2.367 {my_rootsite}/local/lib/python2.7/site-packages/django/template/debug.py:78(render_node)
      2/1    0.000    0.000    2.367    2.367 {my_rootsite}/local/lib/python2.7/site-packages/django/template/loader_tags.py:103(render)
    21/11    0.000    0.000    2.357    0.214 {my_rootsite}/local/lib/python2.7/site-packages/django/template/loader_tags.py:51(render)
      105    0.000    0.000    2.311    0.022 {my_rootsite}/local/lib/python2.7/site-packages/django/template/base.py:593(resolve)
      107    0.000    0.000    2.311    0.022 {my_rootsite}/local/lib/python2.7/site-packages/django/template/base.py:730(resolve)
       65    0.000    0.000    2.311    0.036 {my_rootsite}/local/lib/python2.7/site-packages/django/template/base.py:751(_resolve_lookup)
       41    0.000    0.000    2.220    0.054 {my_rootsite}/local/lib/python2.7/site-packages/django/template/debug.py:88(render)
        4    0.000    0.000    2.067    0.517 {my_rootsite}/local/lib/python2.7/site-packages/django/template/loader_tags.py:136(render)
        3    0.000    0.000    2.041    0.680 {my_rootsite}/local/lib/python2.7/site-packages/django/template/defaulttags.py:148(render)
        1    0.000    0.000    2.025    2.025 {my_rootsite}/local/lib/python2.7/site-packages/django/template/defaulttags.py:523(render)
3003/2756    0.002    0.000    1.808    0.001 {getattr}
        4    0.000    0.000    1.801    0.450 {my_rootsite}/local/lib/python2.7/site-packages/django/core/files/images.py:16(_get_width)
        2    0.000    0.000    1.801    0.901 {my_rootsite}/local/lib/python2.7/site-packages/django/core/files/images.py:24(_get_image_dimensions)
        1    0.000    0.000    1.801    1.801 {my_rootsite}/local/lib/python2.7/site-packages/django/db/models/fields/files.py:77(open)
        2    0.000    0.000    1.109    0.555 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/connection.py:643(make_request)
        2    0.000    0.000    1.109    0.554 {my_rootsite}/local/lib/python2.7/site-packages/boto/connection.py:1062(make_request)
        2    0.000    0.000    1.108    0.554 {my_rootsite}/local/lib/python2.7/site-packages/boto/connection.py:886(_mexe)
      898    0.001    0.000    1.083    0.001 /usr/lib/python2.7/ssl.py:702(recv)
      898    0.001    0.000    1.081    0.001 /usr/lib/python2.7/ssl.py:592(read)
      898    1.081    0.001    1.081    0.001 {method 'read' of '_ssl._SSLSocket' objects}
        2    0.000    0.000    0.902    0.451 {my_rootsite}/local/lib/python2.7/site-packages/django/core/files/storage.py:31(open)
        5    0.000    0.000    0.902    0.180 {my_rootsite}/local/lib/python2.7/site-packages/django/db/models/fields/files.py:46(_get_file)
        1    0.000    0.000    0.902    0.902 {my_rootsite}/local/lib/python2.7/site-packages/storages/backends/s3boto.py:362(_open)
        1    0.000    0.000    0.902    0.902 {my_rootsite}/local/lib/python2.7/site-packages/storages/backends/s3boto.py:101(__init__)
        1    0.000    0.000    0.902    0.902 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/bucket.py:144(get_key)
        1    0.000    0.000    0.902    0.902 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/bucket.py:195(_get_key_internal)
        1    0.000    0.000    0.899    0.899 {my_rootsite}/local/lib/python2.7/site-packages/django/core/files/base.py:122(open)
        1    0.000    0.000    0.899    0.899 {my_rootsite}/local/lib/python2.7/site-packages/django/core/files/base.py:60(_get_closed)
        6    0.000    0.000    0.899    0.150 {my_rootsite}/local/lib/python2.7/site-packages/storages/backends/s3boto.py:123(_get_file)
        1    0.000    0.000    0.899    0.899 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/key.py:1588(get_contents_to_file)
        1    0.000    0.000    0.899    0.899 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/key.py:1430(get_file)
        1    0.000    0.000    0.899    0.899 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/key.py:1484(_get_file_internal)
        2    0.000    0.000    0.710    0.355 /usr/lib/python2.7/httplib.py:999(request)
        2    0.000    0.000    0.710    0.355 /usr/lib/python2.7/httplib.py:1020(_send_request)
        2    0.000    0.000    0.710    0.355 /usr/lib/python2.7/httplib.py:984(endheaders)
        2    0.000    0.000    0.710    0.355 /usr/lib/python2.7/httplib.py:835(_send_output)
        2    0.000    0.000    0.710    0.355 /usr/lib/python2.7/httplib.py:808(send)
        1    0.000    0.000    0.709    0.709 /usr/lib/python2.7/httplib.py:1196(connect)
       20    0.000    0.000    0.691    0.035 {my_rootsite}/local/lib/python2.7/site-packages/boto/s3/key.py:375(next)
       22    0.000    0.000    0.690    0.031 {my_rootsite}/local/lib/python2.7/site-packages/boto/connection.py:393(read)
       22    0.000    0.000    0.690    0.031 /usr/lib/python2.7/httplib.py:540(read)
       19    0.000    0.000    0.690    0.036 /usr/lib/python2.7/socket.py:336(read)
    34/32    0.000    0.000    0.532    0.017 {my_rootsite}/local/lib/python2.7/site-packages/django/db/models/query.py:964(_fetch_all)

[mekanics]

@andreav did manage to solve your slow rendering problem? it's a long time ago, I know, but I'm having the same issue.