Site slow because of img_assist module and how to solve it

A client with a Drupal web site that is growing too fast asked us to assist with performance problems they were experiencing. Pages would take too long to load.

Upon closer examination, we saw that certain pages were taking up to 6 seconds to load. Using the devel module we found the following picture:

Executed 314 queries in 3198.5 milliseconds. Page execution time was 6280.94 ms.

This means that the database was bogged down, and there is some overhead in PHP as well.

Using the query log in devel, we found the following queries taking a lot of time:

210.80 1 _img_assist_remove	SELECT * FROM files WHERE nid=5906 AND filename='img_assist_custom'
200.60 1 _img_assist_remove	SELECT * FROM files WHERE nid=5903 AND filename='img_assist_custom'
197.65 1 image_load	SELECT filename, filepath FROM files WHERE nid=5903
196.81 1 _img_assist_remove	SELECT * FROM files WHERE nid=5904 AND filename='img_assist_custom'
192.52 1 _img_assist_remove	SELECT * FROM files WHERE nid=5905 AND filename='img_assist_custom'
190.13 1 _img_assist_remove	SELECT * FROM files WHERE nid=5902 AND filename='img_assist_custom'
186.66 1 _img_assist_remove	SELECT * FROM files WHERE nid=5901 AND filename='img_assist_custom'
174.63 1 _img_assist_remove	DELETE FROM files WHERE nid=5904 AND filename='img_assist_custom'
174.44 1 image_load	SELECT filename, filepath FROM files WHERE nid=5906
172.25 1 image_load	SELECT filename, filepath FROM files WHERE nid=5904
171.87 1 image_load	SELECT filename, filepath FROM files WHERE nid=5905
171.29 1 _img_assist_remove	DELETE FROM files WHERE nid=5903 AND filename='img_assist_custom'
170.77 1 _img_assist_remove	DELETE FROM files WHERE nid=5906 AND filename='img_assist_custom'
170.49 1 _img_assist_remove	DELETE FROM files WHERE nid=5905 AND filename='img_assist_custom'
169.81 1 _img_assist_remove	DELETE FROM files WHERE nid=5902 AND filename='img_assist_custom'
169.51 1 image_load	SELECT filename, filepath FROM files WHERE nid=5901
166.21 1 _img_assist_remove	DELETE FROM files WHERE nid=5901 AND filename='img_assist_custom' 

160 to 210 ms per query is way too much, but now we know that img_assist is the module to blame.

Next, we found a lot of locks when we used SHOW PROCESSLIST in mysql, mainly on the files table because of the above DELETEs.

We traced this to the function img_assist_display() which called the build derivatives function, which in turn called the remove function which did the DELETE from the database, when a node is viewed.

As a temporary measure, we commented the following lines to stop the resource bleed.

  /*
if ($regen) {
_img_assist_build_derivatives($node, false, $size);
}
*/ 

Things are better now, with devel showing:

Executed 284 queries in 1063.12 milliseconds. Page execution time was 1329.95 ms.

Not ideal, but 1.3 seconds is better than 6.2 seconds.

And the slow queries are now:

163.87	1	image_load	SELECT filename, filepath FROM files WHERE nid=5902
163.63	1	image_load	SELECT filename, filepath FROM files WHERE nid=5905
162.25	1	image_load	SELECT filename, filepath FROM files WHERE nid=5901
161.87	1	image_load	SELECT filename, filepath FROM files WHERE nid=5903
161.62	1	image_load	SELECT filename, filepath FROM files WHERE nid=5906
161.33	1	image_load	SELECT filename, filepath FROM files WHERE nid=5904 

As you can see, no more DELETEs.

However, this is not a proper solution, since nodes that have [img_assist] tags would not show the images, which is unacceptable.

We kept digging in the code and saw that img_assist_custom label, which does not exist in the files table. Finally, we found that the following settings are the culprit:

• Yes, create 200x200 temporary images for the image properties window (useful if the thumbnail size is small)
• Yes, allow all img_assist users to create custom size inline images
• Yes, allow priviledged users to create custom size inline images

These cause the derivative to be generated for every page view, and hence cause the DELETE for every embedded image in the node!

After turning the above settings off, we get the following:

Executed 288 queries in 61.16 milliseconds. Page execution time was 281.85 ms.

from 6.2 seconds down to 0.281 seconds. Not bad!

Mission accomplished!