Project

General

Profile

Actions

Bug #14908

closed

Stale object cache on cdev

Added by Raymond Hoh about 3 years ago. Updated over 1 year ago.

Status:
Resolved
Priority name:
Normal
Assignee:
Category name:
Performance
Target version:
Start date:
2021-10-27
Due date:
% Done:

0%

Estimated time:
Deployment actions:

Description

This is a note for Boone that I've experienced some weird instances on cdev with stale object cache.

I noticed this in the admin area yesterday because the BuddyPress update routine kept running on each page load. The value for bp_get_option( '_bp_db_version' ) kept returning the version before BuddyPress v8.0 (12385), whereas the version in the DB was the latest one (12850). As a result, the BP emails kept on installing on each admin page load. See https://commons.gc.cuny.edu/wp-admin/edit.php?post_status=trash&post_type=bp-email where I've cleaned up all instances this has occurred.

Deleting the options object cache fixed this -- wp_cache_delete( 'alloptions', 'options' ).

This also fixed an issue just now where the homepage was throwing a fatal error because the CAC Home Creation plugin was not activated because the object cache was referencing the older 'active_plugins' option.

Has something changed to our memcached set up that might explain the stale object cache?


Related issues

Related to CUNY Academic Commons - Bug #14986: Commons Site Down?ResolvedBoone Gorges2021-11-23

Actions
Related to CUNY Academic Commons - Support #14994: Clear Cache on CDEVResolvedRaymond Hoh2021-11-28

Actions
Actions #1

Updated by Boone Gorges about 3 years ago

Weird. I recall noticing some oddness in the past with cdev's Memcached behavior, but I can't recall if it's something we ever pinned down.

I just looked over the WP cache config for cdev (cac-env-config.php) and it looks like we're set up to use the same Memcached servers as the production site. And the cache is basically working - I can see in Query Monitor that it's hitting the cache. So there must be something more fine-grained happening. But I don't have any guess what it is.

Let's use this ticket to collect more info if and when we see this happen again.

Actions #2

Updated by Raymond Hoh almost 3 years ago

Actions #3

Updated by Raymond Hoh almost 3 years ago

Actions #4

Updated by Raymond Hoh almost 3 years ago

I decided to do some more research about this and came across this documentation link about the size of the alloptions cache while working with memcached: https://docs.wpvip.com/technical-references/code-quality-and-best-practices/working-with-wp_options/#h-identify-and-resolve-problems-with-alloptions

The link outlines that the alloptions cache should be relatively small (around 1MB) to prevent performance issues. On cdev, the wp_1_options table is 13MB (see wp db size --tables --size_format=mb). However on production, the size is 16MB, but we haven't seen many reports of cache problems on production.

Anyway on cdev, I've deleted some older options that were prefixed with 'bbpress_live_cache_' (from an older version of bbPress), 'jpsq_sync' (from Jetpack), and 'bp_system_report' and this dropped the size of the wp_1_options table to 8MB. Still some more work to do.

Actions #5

Updated by Raymond Hoh almost 3 years ago

Update: running OPTIMIZE table wp_1_options; in MySQL after clearing the older options dropped our wp_1_options DB size to 1MB.

I think we should purge the older options on production as well.

Update 2: just did the same thing on production and the wp_1_options DB size is down to 2MB.

Actions #6

Updated by Boone Gorges almost 3 years ago

Thanks for this research, Ray. Seems like a good idea to do the same purges on the production table. Go ahead with it whenever you're ready.

Actions #7

Updated by Raymond Hoh over 2 years ago

From the latest report that the Commons was down, I came back to this ticket.

The wp_1_options DB table was taking up 8MB in size. So I did a search for the largest option_value lengths on the main site:

mysql> select option_name,char_length(option_value) from wp_1_options order by length(option_value) desc limit 50;
+---------------------------------------+---------------------------+
| option_name                           | char_length(option_value) |
+---------------------------------------+---------------------------+
| jpsq_sync-1641321446.847693-544183-7  |                    392482 |
| jpsq_sync-1641396945.759625-80168-7   |                    390932 |
| jpsq_sync-1641416223.677664-161115-7  |                    390835 |
| jpsq_sync-1641668236.448662-364228-7  |                    390004 |
| jpsq_sync-1641581242.880724-566774-7  |                    389977 |
| jpsq_sync-1641314198.418128-619006-30 |                    269035 |
| jpsq_sync-1641340954.696129-271537-9  |                    267970 |
| jpsq_sync-1641487834.788160-586459-6  |                    267956 |
| jpsq_sync-1641405242.348533-493504-6  |                    267874 |
| jpsq_sync-1641565744.413846-152020-7  |                    267414 |
| jpsq_sync-1641662245.755221-637618-6  |                    267397 |
| jpsq_sync-1641668236.418882-364228-4  |                     93898 |
| jpsq_sync-1641415111.027725-803954-5  |                     79445 |
| jpsq_sync-1641405242.323547-493504-3  |                     61236 |
| jpsq_sync-1641340954.676119-271537-5  |                     59742 |
| rewrite_rules                         |                     59595 |
| jpsq_sync-1641416223.662622-161115-3  |                     58203 |
| jpsq_sync-1641581242.847446-566774-3  |                     58203 |
| jpsq_sync-1641321446.823441-544183-3  |                     58202 |
| jpsq_sync-1641407018.601134-323052-5  |                     57656 |
| jpsq_sync-1641668236.406594-364228-3  |                     57083 |
| jpsq_sync-1641662245.730240-637618-3  |                     51819 |
| jpsq_sync-1641487834.768139-586459-3  |                     51819 |
| jpsq_sync-1641314198.331230-619006-24 |                     48102 |
| jpsq_sync-1641342902.730165-259571-3  |                     48101 |
| jpsq_sync-1641396945.715382-80168-3   |                     48096 |
| jpsq_sync-1641565744.385602-152020-3  |                     42274 |
| jpsq_sync-1641415111.018054-803954-4  |                     36952 |
| jpsq_sync-1641340954.669117-271537-4  |                     36431 |
| jpsq_sync-1641405242.312827-493504-2  |                     30217 |
| group-documents-category_children     |                     30177 |
| jpsq_sync-1641416223.657899-161115-2  |                     29539 |
| jpsq_sync-1641581242.836780-566774-2  |                     29539 |
| jpsq_sync-1641321446.814587-544183-2  |                     29538 |
| jpsq_sync-1641396945.705451-80168-2   |                     28069 |
| jpsq_sync-1641662245.722611-637618-2  |                     27404 |
| jpsq_sync-1641487834.759090-586459-2  |                     27403 |
| jpsq_sync-1641407018.594221-323052-4  |                     25310 |
| jpsq_sync-1641342902.722197-259571-2  |                     25276 |
| jpsq_sync-1641314198.325040-619006-23 |                     25276 |
| jpsq_sync-1641565744.379531-152020-2  |                     23040 |
| _bbp_private_forums                   |                     15733 |
| jpsq_sync-1641416222.043645-161115-1  |                     15199 |
| _split_terms                          |                     14251 |
| jpsq_sync-1641343090.666734-169737-1  |                     14062 |
| jpsq_sync-1641342963.836301-593848-1  |                     14035 |
| jpsq_sync-1641343138.835293-326155-1  |                     13917 |
| jpsq_sync-1641342901.283432-259571-1  |                     13906 |
| jpsq_sync-1641341942.409491-520682-1  |                     13541 |
| jpsq_sync-1641315679.261098-170402-1  |                     13526 |
+---------------------------------------+---------------------------+
50 rows in set (0.03 sec)

And noticed a lot of 'jpsq_sync' options, so I did another query to determine how many entries this took up:

mysql> select count(*) from wp_1_options where option_name like 'jpsq_sync%';
+----------+
| count(*) |
+----------+
|      333 |
+----------+
1 row in set (0.00 sec)

Once I purged these 333 options and optimized the wp_1_options DB table, the DB size went down to 0MB.

The interesting thing is we do not have Jetpack activated on the main site. Perhaps another instance of switch_to_blog() is causing this somehow.

Actions #8

Updated by Boone Gorges over 2 years ago

Thanks for this, Ray. Adding Jeremy as a watcher in case he has thoughts about the switch_to_blog() possibility.

Actions #9

Updated by Raymond Hoh over 2 years ago

Actually, looking at the unix timestamps for the jpsq_sync options suggests that this was due to the switch_to_blog() problem in #15170. So we should be in the clear now.

Actions #10

Updated by Boone Gorges over 1 year ago

  • Status changed from New to Resolved
  • Target version set to Not tracked

As the issue hasn't come up again, let's close this ticket.

Actions

Also available in: Atom PDF