Optimizing images on upload is too slow

[miketaylr]

Pillow's optimization is slow. :(

I need to measure more but right now local full-size screenshots are taking forever:

save function took 20237.716 ms
Commenting out the following block in upload.py:

# if self.image_object.format in ['JPEG', 'JPG', 'JPE', 'PNG']:
        #     save_parameters['optimize'] = False
        # # If animated GIF, aka duration > 0, add save_all parameter
        # if (self.image_object.format == 'GIF' and
        #    self.image_object.info['duration'] > 0):
        #         save_parameters['save_all'] = False

save function took 1704.766 ms

cc @karlcow

[miketaylr]

I'll measure what this on staging as well.

[miketaylr]

(maybe bug isn't the right label, it's more a performance regression)

[karlcow]

Ah interesting! Thanks for filling this.
I need to test that in isolation of the Web app.

[karlcow]

@miketaylr Do you remember which format you were trying to upload?

[karlcow]

Also in your comment up there I see

        #     save_parameters['optimize'] = False

When the current code is:

 save_parameters['optimize'] = True

https://github.com/webcompat/webcompat.com/blob/master/webcompat/api/uploads.py#L86

which code are we talking about?

[karlcow]

I wonder if you had issues with PNG images

This discussion is useful.
python-pillow/Pillow#1211

Specifically the compress_level=<value>

[miketaylr]

@miketaylr Do you remember which format you were trying to upload?

PNG.

which code are we talking about?

The code you linked to, I had changed it to False for testing -- and even with False it was 20 seconds. Commenting it out was required to get it back to the old performance.

[miketaylr]

I think we should consider removing optimizations and move towards a solution that happens after upload (using a worker queue or similar). Having to wait 20 seconds is really, really bad UX.

[miketaylr]

(Also, testing the compress_level options would be good)

[karlcow]

In another thread, I think I mentioned that. save is already doing optimizations by default. What I want to understand before we back off is to really identify the source of the issue. If there is no reasonable solution, indeed we should find another way.

Instead of workers, I would recommend a server side optimization of the image using a C lib for compressing images without involving at all the Web Interactions. ^_^

[karlcow]

@miketaylr Do you have a test image when this happened for PNG. I want also to test if the impact is the same for JPEG (my hunch is that it is not happening for JPEG).

[miketaylr]

In another thread, I think I mentioned that. save is already doing optimizations by default.

Yeah, but it wasn't 15x slower. :/

What I want to understand before we back off is to really identify the source of the issue. If there is no reasonable solution, indeed we should find another way.

The current optimizations are taking too long to be beneficial, IMO. Having to wait 20 seconds to file a desktop issue makes me think the app is broken. We can turn it off, find a better solution, and then turn it on.

Instead of workers, I would recommend a server side optimization of the image using a C lib for compressing images without involving at all the Web Interactions. ^_^

I'm not sure what you mean by Web Interactions. I'm talking about using worker queues a la RabbitMQ/ https://www.digitalocean.com/community/tutorials/how-to-use-celery-with-rabbitmq-to-queue-tasks-on-an-ubuntu-vps

[miketaylr]

(OK, let me slow down and stop writing comments that appear so rude. ❤️ )

[miketaylr]

The site I was testing with is: https://www.mozilla.org/en-US/firefox/46.0.1/firstrun/learnmore/ (using the webcompat reporter add-on, which takes a screenshot and submits a base64 string (which is converted to a PNG on the server side).

Here's a PNG that is created from the raw base64 string, without touching Pillow (or our upload code): https://miketaylr.com/misc/original.png
(created like so: copy the base64 string that the add-on creates into a text file called base64.txt: cat base64.txt | base64 -D > original.png)

Here's the PNG that is created with the commented out save_parameters['optimize'] parts of save: https://miketaylr.com/misc/original-save.png
Here's the PNG that is created with save_parameters['optimize'] = True: https://miketaylr.com/misc/opt-true.png
Here's the PNG that is created with save_parameters['optimize'] = False: https://miketaylr.com/misc/opt-false.png (seems like the same file?)

[karlcow]

WONDERFUL! Thanks Mike.
I will do some testing this afternoon.

[miketaylr]

Thanks!

[karlcow]

ok these are your files saved locally.

1707231 opt-false.png
1707158 opt-true.png
1883329 original-save.png
1765239 original.png

ok I created a code to save the file as you did.
https://gist.github.com/karlcow/3541bcfbc87cc8327da8c693a3e7d1cc
I have the same for true and false.

1707158 opt-false.png
1707158 opt-true.png
1883271 original-save.png

I also checked we had the right images.

Now let's go on profiling. I have cut the boring parts aka 0sec and replace it with "…" :)
I put the full trace
https://gist.github.com/karlcow/3541bcfbc87cc8327da8c693a3e7d1cc#gistcomment-1781287

→ time python -m cProfile -s time image-optim.py 
Optim True: 17.3877630234
Optim False: 17.2931690216
Original Save: 1.36256098747
         21377 function calls (21087 primitive calls) in 36.069 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       83   35.819    0.432   35.819    0.432 {method 'encode' of 'ImagingEncoder' objects}
      648    0.132    0.000    0.132    0.000 {method 'decode' of 'ImagingDecoder' objects}
      184    0.015    0.000    0.015    0.000 {PIL._imaging.crc32}
        3    0.009    0.003    0.009    0.003 {method 'close' of 'file' objects}
      270    0.008    0.000    0.008    0.000 {method 'write' of 'file' objects}
        1    0.006    0.006    0.016    0.016 Image.py:27(<module>)
     1959    0.006    0.000    0.006    0.000 {method 'read' of 'file' objects}
        1    0.005    0.005   36.069   36.069 image-optim.py:3(<module>)
        6    0.004    0.001    0.030    0.005 Image.py:342(preinit)
        1    0.004    0.004    0.005    0.005 __init__.py:24(<module>)
        3    0.004    0.001    0.004    0.001 {PIL._imaging.new}
        1    0.004    0.004    0.017    0.017 JpegImagePlugin.py:35(<module>)
        1    0.003    0.003    1.363    1.363 image-optim.py:46(optim_normal)
        1    0.003    0.003   17.293   17.293 image-optim.py:34(optim_false)
        1    0.003    0.003   17.388   17.388 image-optim.py:22(optim_true)
        1    0.003    0.003    0.010    0.010 fractions.py:4(<module>)
        1    0.002    0.002    0.014    0.014 TiffImagePlugin.py:42(<module>)
        1    0.002    0.002    0.005    0.005 BmpImagePlugin.py:27(<module>)
        1    0.002    0.002    0.002    0.002 ImagePalette.py:19(<module>)
        1    0.002    0.002    0.003    0.003 collections.py:1(<module>)
        1    0.002    0.002    0.005    0.005 shutil.py:5(<module>)
      648    0.002    0.000    0.011    0.000 PngImagePlugin.py:557(load_read)
        6    0.002    0.000    0.149    0.025 ImageFile.py:120(load)
        1    0.001    0.001    0.002    0.002 __init__.py:4(<module>)
        1    0.001    0.001    0.001    0.001 GifImagePlugin.py:27(<module>)
        2    0.001    0.001    0.002    0.001 collections.py:293(namedtuple)
      651    0.001    0.000    0.003    0.000 PngImagePlugin.py:107(read)
     1508    0.001    0.000    0.002    0.000 sre_parse.py:193(__next)
    49/10    0.001    0.000    0.004    0.000 sre_parse.py:395(_parse)
        1    0.001    0.001    0.002    0.002 PngImagePlugin.py:34(<module>)
        1    0.001    0.001    0.003    0.003 FixTk.py:1(<module>)
       89    0.001    0.000    0.024    0.000 PngImagePlugin.py:615(putchunk)
      654    0.001    0.000    0.001    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
        3    0.001    0.000   35.844   11.948 ImageFile.py:438(_save)
        1    0.001    0.001    0.001    0.001 heapq.py:31(<module>)
     1386    0.001    0.000    0.002    0.000 sre_parse.py:212(get)
        1    0.001    0.001    0.001    0.001 io.py:34(<module>)
    90/10    0.001    0.000    0.001    0.000 sre_compile.py:64(_compile)
        2    0.001    0.000    0.003    0.002 {__import__}
      657    0.000    0.000    0.001    0.000 _binary.py:56(i32be)
        1    0.000    0.000    0.005    0.005 decimal.py:116(<module>)
…
        1    0.000    0.000    0.001    0.001 threading.py:1(<module>)
…
       13    0.000    0.000    0.001    0.000 abc.py:86(__new__)
…
       83    0.000    0.000    0.024    0.000 PngImagePlugin.py:633(write)
…
    43/10    0.000    0.000    0.004    0.000 sre_parse.py:317(_parse_sub)
…
       10    0.000    0.000    0.006    0.001 re.py:230(_compile)
        3    0.000    0.000   36.003   12.001 Image.py:1601(save)
…
        1    0.000    0.000    0.001    0.001 TiffTags.py:20(<module>)
…
        3    0.000    0.000   35.844   11.948 PngImagePlugin.py:637(_save)
        1    0.000    0.000    0.001    0.001 PpmImagePlugin.py:18(<module>)
…
       10    0.000    0.000    0.004    0.000 sre_parse.py:706(parse)
…
       10    0.000    0.000    0.006    0.001 sre_compile.py:567(compile)
…
        1    0.000    0.000    0.001    0.001 numbers.py:6(<module>)
…
       10    0.000    0.000    0.006    0.001 re.py:192(compile)
…
        3    0.000    0.000    0.031    0.010 Image.py:2227(open)
…
        3    0.000    0.000    0.004    0.001 ImageFile.py:247(load_prepare)
…
        3    0.000    0.000    0.004    0.001 PngImagePlugin.py:549(load_prepare)
… /* Everything below this is 0 second */


real    0m36.156s
user    0m35.902s
sys 0m0.140s

ok a very quick thing

        1    0.003    0.003    1.363    1.363 image-optim.py:46(optim_normal)
        1    0.003    0.003   17.293   17.293 image-optim.py:34(optim_false)
        1    0.003    0.003   17.388   17.388 image-optim.py:22(optim_true)

save_parameters creates an overhead of ~16s
The overhead is happening in the method encode

       83   35.819    0.432   35.819    0.432 {method 'encode' of 'ImagingEncoder' objects}

It is called 83 times (not sure why)
https://github.com/python-pillow/Pillow/blob/d3727b523ece4f75def72bfc960e1abd104b5dcb/encode.c

The percall column is interesting too.

        3    0.001    0.000   35.844   11.948 ImageFile.py:438(_save)
        3    0.000    0.000   36.003   12.001 Image.py:1601(save)
        3    0.000    0.000   35.844   11.948 PngImagePlugin.py:637(_save)

Trying to run the code with only the method original_save (our base)
And keeping only the interesting information

→ time python -m cProfile -s time image-optim.py 
Original Save: 1.4339568615
         15434 function calls (15144 primitive calls) in 1.464 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       29    1.332    0.046    1.332    0.046 {method 'encode' of 'ImagingEncoder' objects}
      216    0.047    0.000    0.047    0.000 {method 'decode' of 'ImagingDecoder' objects}
        1    0.005    0.005    1.464    1.464 image-optim.py:3(<module>)
        1    0.003    0.003    1.434    1.434 image-optim.py:46(optim_normal)
        1    0.000    0.000    1.341    1.341 ImageFile.py:438(_save)
        1    0.000    0.000    1.393    1.393 Image.py:1601(save)
        1    0.000    0.000    1.341    1.341 PngImagePlugin.py:637(_save)

_save method in PngImagePlugin.py
https://github.com/python-pillow/Pillow/blob/d3727b523ece4f75def72bfc960e1abd104b5dcb/PIL/PngImagePlugin.py#L637

to compare with

→ time python -m cProfile -s time image-optim.py 
Optim True: 17.3722939491
         15388 function calls (15098 primitive calls) in 17.390 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       27   17.290    0.640   17.290    0.640 {method 'encode' of 'ImagingEncoder' objects}
      216    0.047    0.000    0.047    0.000 {method 'decode' of 'ImagingDecoder' objects}
        1    0.004    0.004   17.390   17.390 image-optim.py:3(<module>)
        1    0.004    0.004   17.372   17.372 image-optim.py:22(optim_true)
        1    0.000    0.000   17.298   17.298 ImageFile.py:438(_save)
        1    0.000    0.000   17.349   17.349 Image.py:1601(save)
        1    0.000    0.000   17.298   17.298 PngImagePlugin.py:637(_save)

The number of calls to the encoder is the same but the percall is skyrocketing.

The encoder options are given in https://github.com/python-pillow/Pillow/blob/d3727b523ece4f75def72bfc960e1abd104b5dcb/PIL/PngImagePlugin.py#L667

    # encoder options
    if "dictionary" in im.encoderinfo:
        dictionary = im.encoderinfo["dictionary"]
    else:
        dictionary = b""

    im.encoderconfig = ("optimize" in im.encoderinfo,
                        im.encoderinfo.get("compress_level", -1),
                        im.encoderinfo.get("compress_type", -1),
dictionary)

I slightly modified the code to just see what is the object before erasing it.

    print image_object.encoderconfig
    print image_object.encoderinfo
    del image_object

OOOOOooooooh…

(True, -1, -1, '')
{'optimize': True}
Optim True: 17.2523300648
========================
(True, -1, -1, '')
{'optimize': False}
Optim False: 17.1993100643
========================
(False, -1, -1, '')
{}
Original Save: 1.35688710213

You see what I see… the parameter for optimize False is ignored. This explains that we get the same results in between False and True. The original_save has a False for optimizations. As we have seen above the

• Optimizing True/False: (1765239-1707231)/1765239 = -3.29%
• Save_Normal: (1765239-1707231)/1765239 = +6.69%

So the save_normal is increasing the size BUT the time spent on it… is a lot better.

On the other we could not expect a lot better for optimization, because screenshots are most of the time, not simple logo, graphs. PNG is good at big uniform area of colors, not that much at complicated patterns.

I want to test a couple more things

• JPEG
• compress_level

Stay tuned.

[karlcow]

Compression levels and PNG

I modified the code a bit again:

def optim_compress(IMAGE_PATH, IMAGE_DEST, level):
    time_beg = time.time()
    image_file = '%s/original-compress-l%s.png' % (IMAGE_DEST, str(level))
    image_object = Image.open(IMAGE_PATH)
    image_object.save(image_file, compress_level=level)
    print image_object.encoderconfig
    print image_object.encoderinfo
    del image_object
    time_end = time.time()
    print 'Compress Level %s: %s' % (str(level), time_end - time_beg)

and

    for level in xrange(1, 10):
        optim_compress(IMAGE_PATH, IMAGE_DEST, level)

These are the results with the first one being the normal save.

First the files

2809608 original-compress-l1.png
2614006 original-compress-l2.png
2390662 original-compress-l3.png
2150987 original-compress-l4.png
2020509 original-compress-l5.png
1883271 original-compress-l6.png
1830500 original-compress-l7.png
1738089 original-compress-l8.png
1703913 original-compress-l9.png
1883271 original-save.png

Then the execution time.

(False, -1, -1, '')
{}
Original Save: 1.47113919258
(False, 1, -1, '')
{'compress_level': 1}
Compress Level 1: 0.514011144638
(False, 2, -1, '')
{'compress_level': 2}
Compress Level 2: 0.554822206497
(False, 3, -1, '')
{'compress_level': 3}
Compress Level 3: 0.736438989639
(False, 4, -1, '')
{'compress_level': 4}
Compress Level 4: 0.762644052505
(False, 5, -1, '')
{'compress_level': 5}
Compress Level 5: 0.944289922714
(False, 6, -1, '')
{'compress_level': 6}
Compress Level 6: 1.50567102432
(False, 7, -1, '')
{'compress_level': 7}
Compress Level 7: 2.2676320076
(False, 8, -1, '')
{'compress_level': 8}
Compress Level 8: 8.7926030159
(False, 9, -1, '')
{'compress_level': 9}
Compress Level 9: 18.2454030514

[karlcow]

The original file size is 1765239 original.png

• compress_level = 8 gives 1738089 for 9s
• compress_level = 7 gives 1830500 for 2.3s

If we do not compress at all, we are very fast, but the file is huge. 0.51s for 2809608 (almost double the size)

❗️For PNG files, I guess we should completely avoid any kind of optimization and we should even avoid the Pillow library altogether.

[karlcow]

JPEG test

For the JPEG test, I will use
https://upload.wikimedia.org/wikipedia/commons/8/8f/NYC-Diner-Bacon-Cheeseburger.jpg
which is ~5.0 Mo

The objective is to understand if optimize has any effect on time and/or size.

Size results

5219298 burger.jpg
 900592 burger-original.jpg
 869905 burger-true.jpg

Good Stuff already, we gain weight.
Let's see about time.

================================
(0, False, 0, False, 0, 0, 0, -1, None, '', '')
{}
Original Save: 0.526042938232
================================
(0, False, 0, True, 0, 0, 0, -1, None, '', '')
{'optimize': True}
Burger Optim True: 0.550024986267

Yeah! Clap clap! The time overhead is insignificant.

I checked the quality difference. Nothing visibly damaging.

So let's keep the code for JPEG files at least.

[karlcow]

PNG to JPEG

My last test or trick ;) as you prefer. Let's take @miketaylr's image and convert it to JPEG.

1765239 original.png
 218156 pngjpg-original.jpg
 166887 pngjpg-true.jpg

Wooot! ;) Very good for size.

What about time?

================================
(0, False, 0, False, 0, 0, 0, -1, None, '', '')
{}
JPGPNG Save: 0.202679872513
================================
(0, False, 0, True, 0, 0, 0, -1, None, '', '')
{'optimize': True}
JPGPNG Optim True: 0.184612989426

Very Nice. ok! ok! But quality must be crappy. Let's see.

Original. Just save.

Optimize true

[karlcow]

I don't know for you… but apart of Animated GIF which needs to be directly saved without Pillow.
I would encourage we convert things to JPEG, for the benefits of the server AND the user's bandwidth.

I put the full code of my test there. Not compact on purpose.
https://gist.github.com/karlcow/3541bcfbc87cc8327da8c693a3e7d1cc

[karlcow]

>>> file_dest = 'blahblah/foobar.png'
>>> 'jpg'.join(file_dest.rsplit('png',1))
'blahblah/foobar.jpg'
>>> file_dest = 'blahblah/foobar.jpg'
>>> 'jpg'.join(file_dest.rsplit('png',1))
'blahblah/foobar.jpg'

[miketaylr]

I don't know for you… but apart of Animated GIF which needs to be directly saved without Pillow.
I would encourage we convert things to JPEG, for the benefits of the server AND the user's bandwidth.

Yep, I agree. I'll file a bug to save animated GIF in a non-Pillow path. Thanks so much @karlcow!

[miketaylr]

😍 These findings are so awesome @karlcow. The difference in size and speed for JPEG is sort of mind-boggling.

[karlcow]

@miketaylr Thanks. My naive interpretation is that PNG decoder needs to read the full picture pixel by pixel (easy), but the PNG encoder needs to rearrange all these pixels by linear family (aka sorting before, reordering) before rewriting. And this can take a long time. PNG is a losless format.