Excessive cache_get time

We encourage users to post events happening in the community to the community events group on https://www.drupal.org.
ajayg's picture

I have noticed (I think) a strange thing. My cache_get times are excessive compared to rest of queries consistently. E.g on front page for logged in user I am seeing these numbers through devl module


203.92 1 cache_get SELECT data, created, headers, expire FROM main_cache WHERE cid = 'locale:mr'
172.59 1 cache_get SELECT data, created, headers, expire FROM main_cache_menu WHERE cid = '1:mr'
41.89 1 eval SELECT COUNT(uid) AS number FROM main_users WHERE status=1
25.56 1 drupal_lookup_path SELECT dst FROM main_url_alias WHERE src = 'front_page1'
.....

Consistently all queries below drupal_lookup_path are in single digit milliseconds. SO Why would cache_get took this long? The configuration is two dedicated server one running drupal and other running mysql.

I already confirmed there is index on cid for mainc_cache and main_cache_menu table and it is being utilized.

I am suspicious of the mysql limitation when a blob field is involved in query, the temp tables will be always disk based and not memory based. Is that happening here (a disk based table for the query)?because I have noticed only all sorts of cache table queries taking significantly longer.

Anybody has seen this before? Or may be http://2bits.com/articles/slow-mysql-queries-multi-server-setup-use-comp... is at play here?

Comments

Network bottleneck?

kbahey's picture

Is MySQL on another box? If so, is the connection 10MBps, 100MBps, or 1000MBps?

You can find out by doing:

ethtool eth1

And it will show you the port speed.

Try the patch that I posted (linked in the URL you provided).

Also, you can run the following MySQL and see if the queries return a large data set:

SELECT LENGTH(data) FROM main_cache WHERE cid = 'locale:mr';

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

turned out to be compression solution

ajayg's picture

This turned out to be compression solution as pointed on 2bits.com article by khalid. After turning on the compression flag
ie using

$connection = @mysql_connect($url['host'], $url['user'], $url['pass'], TRUE, MYSQL_CLIENT_FOUND_ROWS|MYSQL_CLIENT_COMPRESS);

it significantly reduced (by ab almost 1/3) the time spent in cache_get
Before
203.92 1 cache_get SELECT data, created, headers, expire FROM main_cache WHERE cid = 'locale:mr'
172.59 1 cache_get SELECT data, created, headers, expire FROM main_cache_menu WHERE cid = '1:mr'

61.96 1 cache_get SELECT data, created, headers, expire FROM main_cache_menu WHERE cid = '1:mr'
59.71 1 cache_get SELECT data, created, headers, expire FROM main_cache WHERE cid = 'locale:mr'

On other pages where there are views, the performance improvements was more dramatic . almost 1/10 reduction in cache_get. For a known(but unresolved) issue cache for views_tables can get big and this really helps.

I also tried using mysql_pconnect for persistent connection with no significant difference.

Now a natural question would be what happens to overall page times and not just the cache_get times. I found that there is a slight increase in other query times. But since the cache_get time was order of magnitude higher than other queries, the overall page query times and execution time reduced as well (but slightly reduced rate than improvement in cache_get)

So here is tracker times.
Before compression

Executed 227 queries in 2102.74 milliseconds. Page execution time was 2458.11 ms.
407.6 1 pager_query
372.93 1 cache_get SELECT data, created, headers, expire FROM main_cache_views WHERE cid = 'views_tables:mr'
215.65 1 cache_get SELECT data, created, headers, expire FROM main_cache_menu WHERE cid = '1:mr'
163.27 1 cache_get SELECT data, created, headers, expire FROM main_cache WHERE cid = 'locale:mr'

After Compression
Executed 227 queries in 1006.24 milliseconds  Page execution time was 1334.13 ms.
391.81 1 pager_query
88.66 1 cache_get  SELECT data, created, headers, expire FROM main_cache_views WHERE cid = 'views_tables:mr'
54.75 1 cache_get SELECT data, created, headers, expire FROM main_cache WHERE cid = 'locale:mr'
43.52 1 cache_get SELECT data, created, headers, expire FROM main_cache_menu WHERE cid = '1:mr'

A better solution?

ajayg's picture

IS there a proven way to store the cache in a compressed way? That way we can get best of both the worlds. The larger dataset will be passed compressed through network and existing smaller dataset queries need not be cached?

what engine is your cache

entendu's picture

what engine is your cache table using?

I am using MyISAM

ajayg's picture

I am using MyISAM

I don't have any lock

entendu's picture

I don't have any lock contention stats to go off of, but try switching that table to innodb and running the same test. Post the results!

I doubt this is lock

ajayg's picture

I doubt this is lock related. All the above stats are for a single user.

Ah, got it. Still possible

entendu's picture

Ah, got it. Still possible considering you'll be writing to the table, but way less likely with a single user, I suppose.

Have you tried running the query directly on the box (ssh'ing into the mysql box and running it locally, not using -h from somewhere else)? Any significant difference?

What kind of compression are

scotthoff's picture

What kind of compression are you talking about? the compression modules?