Yoast / wordpress-seo

Yoast SEO for WordPress
https://yoast.com/wordpress/plugins/seo/
Other
1.75k stars 885 forks source link

Performance: SQL queries taking a long time during Save #16386

Open bobbingwide opened 3 years ago

bobbingwide commented 3 years ago

Please give us a description of what happened.

When Saving updates to a post my colleague noticed that Updating was taking a very long time. We traced the SQL execution time during the save. WordPress SEO was using 12 seconds.

I reproduced the problem in my development environment.

The total execution time of SQL queries run by WordPress SEO was 1.20 seconds of total SQL query execution time of 1.30.

This particular post has 120 links to external images.

Everytime the post is saved, the wp_yoast_seo_links are being deleted and re-inserted, even when the only change was to some text.

Example HTML for one of the images.

<!-- wp:image {"linkDestination":"custom"} -->
<figure class="wp-block-image"><a href="https://www.stampsoftheworld.co.uk/w/images/f/fb/Liechtenstein_1992_Ferns_a.jpg"><img src="https://www.stampsoftheworld.co.uk/w/images/f/fb/Liechtenstein_1992_Ferns_a.jpg" alt="" title="title"/></a></figure>
<!-- /wp:image -->

I believe there are significant opportunities to improve the performance by reducing the number of SQL queries being performed.

Please describe what you expected to happen and why.

The time to perform the update should be minimal.

How can we reproduce this behavior?

Using a tool that can log SQL execution for the save request (*)

 wp-admin/post.php?post=959&action=edit&meta-box-loader=1&meta-box-loader-nonce=c47089fee5&_locale=user

where $POST contains action=editpost

  1. Create a post with 241 different links
  2. Save the post
  3. Accumulate the execution time of the SQL

repeat the experiment and summarise the results.

Technical info

In my development environment I was using the block editor in Gutenberg and subsequently just core. In the live site the Classic editor was being used.

Used versions

(*) I used my plugin oik-bwtrace to trace the server activity including saved queries.

bobbingwide commented 3 years ago

Here's a summary of the query elapsed time in my development machine when Saving the post that contains over a hundred image links.

The overall elapsed time for the Save was 2.88 seconds.

Function Count Elapsed
Total 354 1.4749894142151
Yoast\WP\Lib\ORM::execute 259 1.2082939147949
add_option 1 0.11339902877808
wp_insert_post 2 0.030858039855957
wp_update_site 2 0.017335176467896
update_option 2 0.015997886657715
add_metadata 2 0.015048265457153
wp_load_alloptions 1 0.012069940567017
update_metadata 5 0.0091807842254639
delete_metadata 20 0.0089242458343506
WP_Term_Query::get_terms 8 0.0055749416351318
update_meta_cache 8 0.0054419040679932
wp_load_core_site_options 1 0.0039241313934326
get_option 15 0.003838062286377
WP_User::get_data_by 1 0.0037198066711426
WP_Site_Query::get_site_ids 1 0.0036501884460449
WP_Post::get_instance 4 0.002918004989624
_prime_post_caches 1 0.0026938915252686
get_network_option 6 0.0025839805603027
WP_Query::get_posts 3 0.0023701190948486
delete_option 3 0.0017881393432617
_update_post_term_count 2 0.0016560554504395
term_exists 1 0.0011382102966309
get_comment_count 1 0.001129150390625
wp_set_object_terms 1 0.00034308433532715
_prime_site_caches 1 0.00032401084899902
wp_unique_post_slug 1 0.00028514862060547
WP_Site::get_instance 1 0.0002751350402832
clean_term_cache 1 0.0002281665802002

The report is grouped by calling function/method. It's automatically produced as a trace record at shutdown.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-actions.php(350:0) bw_trace_saved_queries_grouped_by_function(1) 
37 0 2020-11-20T15:20:10+00:00 2.875893 0.000800 cf=shutdown 9917 354 964 10485760/12582912 256M
Grouped by function 
bobbingwide commented 3 years ago

These are figures taken from the live site.

Function | Count | Elapsed
-------- | ----- | -------
Total | 459 | 42.144245624542
Yoast\WP\Lib\ORM::execute | 257 | 41.916359186172
get_option | 109 | 0.097582578659058
delete_metadata | 17 | 0.026755332946777
WP_Query::get_posts | 3 | 0.019870042800903
delete_option | 14 | 0.012069940567017
update_meta_cache | 8 | 0.0089356899261475
wfConfig::loadAllOptions | 1 | 0.0070908069610596
wp_insert_post | 2 | 0.0056920051574707
wfConfig::get | 8 | 0.0056889057159424
WP_User::get_data_by | 1 | 0.0054688453674316
update_metadata | 4 | 0.0048911571502686
WP_Post::get_instance | 4 | 0.0046572685241699
update_metadata_by_mid | 4 | 0.0042548179626465
get_metadata_by_mid | 6 | 0.0040991306304932
wfDB::querySingle | 4 | 0.0032258033752441
wfBlock::lockoutForIP | 2 | 0.0028982162475586
wfBlock::allBlocks | 2 | 0.0025601387023926
_prime_post_caches | 1 | 0.0013430118560791
Smush\Core\Modules\Dir::table_exist | 1 | 0.0013298988342285
wfDB::querySingleRec | 1 | 0.0013120174407959
wfBlock::findIPBlock | 1 | 0.0011677742004395
update_option | 1 | 0.0010190010070801
add_option | 1 | 0.00098299980163574
get_comment_count | 1 | 0.00095605850219727
WordfenceLS\Settings\Model_DB::_cached | 1 | 0.00081896781921387
wp_count_posts | 1 | 0.00072693824768066
wfNotification::notifications | 1 | 0.0006868839263916
wp_unique_post_slug | 1 | 0.00064611434936523
wordfence::veryFirstAction | 1 | 0.00061202049255371
WordfenceLS\Settings\Model_DB::get | 1 | 0.00054407119750977
bobbingwide commented 3 years ago

Here are the slowest queries for that run

<h3>Queries by Time DESC</h3>
#,Time,Accum,Function,SQL
341,5.0649259090424,5.0649259090424,Yoast\WP\Lib\ORM::execute,INSERT INTO `wp_yoast_seo_links` (`url`&comma;  `type`&comma;  `indexable_id`&comma;  `post_id`) VALUES ('https://www.stampsoftheworld.co.uk/w/images/d/d8/Venda_1985_Ferns_25c.jpg\'/'&comma;  'image-ex'&comma;  '4189'&comma;  '29907')
412,4.6171410083771,9.6820669174194,Yoast\WP\Lib\ORM::execute,INSERT INTO `wp_yoast_seo_links` (`url`&comma;  `type`&comma;  `indexable_id`&comma;  `post_id`) VALUES ('https://www.stampsoftheworld.co.uk/w/images/4/49/Norfolk_Island_20040928-_tree_fern_10c.jpg\'/'&comma;  'image-ex'&comma;  '4189'&comma;  '29907')
345,2.1636738777161,11.845740795135,Yoast\WP\Lib\ORM::execute,INSERT INTO `wp_yoast_seo_links` (`url`&comma;  `type`&comma;  `indexable_id`&comma;  `post_id`) VALUES ('https://www.stampsoftheworld.co.uk/w/images/7/7c/Ireland_1986_Ferns_24p.jpg\'/'&comma;  'image-ex'&comma;  '4189'&comma;  '29907')
411,1.9106230735779,13.756363868713,Yoast\WP\Lib\ORM::execute,INSERT INTO `wp_yoast_seo_links` (`url`&comma;  `type`&comma;  `indexable_id`&comma;  `post_id`) VALUES ('https://www.stampsoftheworld.co.uk/w/images/f/f0/British_antarctic_2008_Fern_fossils_d.jpg\'/'&comma;  'image-ex'&comma;  '4189'&comma;  '29907')
bobbingwide commented 3 years ago
When the plugin is deactivated the database performance improves, significantly. Function Count Elapsed
Total 179 0.30243444442749
get_option 101 0.1533522605896
update_metadata_by_mid 4 0.039570093154907
WP_Query::get_posts 3 0.018441200256348
delete_option 13 0.013721942901611
wp_count_posts 1 0.011667966842651
update_metadata 4 0.0098690986633301
wfConfig::get 8 0.0064446926116943
wfConfig::loadAllOptions 1 0.0054471492767334
update_meta_cache 6 0.0050177574157715
get_metadata_by_mid 6 0.0049479007720947
wp_insert_post 2 0.0049393177032471
get_comment_count 1 0.0038449764251709
WP_Post::get_instance 3 0.0029411315917969
wfBlock::lockoutForIP 2 0.0027780532836914
wfDB::querySingle 4 0.0023727416992188
wfBlock::allBlocks 2 0.0020501613616943
ActionScheduler_wpPostStore::find_action 2 0.0015850067138672
ActionScheduler_DBStore::fetch_action 2 0.0013618469238281
wfDB::querySingleRec 1 0.0013251304626465
ActionScheduler_DBStore::find_action 2 0.0012650489807129
_prime_post_caches 1 0.001209020614624
add_option 1 0.0011510848999023
Smush\Core\Modules\Dir::table_exist 1 0.00097012519836426
WordfenceLS\Settings\Model_DB::_cached 1 0.00094079971313477
wfBlock::findIPBlock 1 0.0009009838104248
delete_metadata 1 0.00084304809570312
wfNotification::notifications 1 0.00076389312744141
wordfence::veryFirstAction 1 0.00075602531433105
WordfenceLS\Settings\Model_DB::get 1 0.00074195861816406
WP_User::get_data_by 1 0.00072002410888672
wp_unique_post_slug 1 0.00049400329589844
bobbingwide commented 3 years ago

To view the page in question see https://ebps.org.uk/fern-stamps-of-the-world/ For access to the site contact @AndrewMLeonard

Djennez commented 3 years ago

Is this only the case for images with links, or are large amounts of links without images also problematic?

bobbingwide commented 3 years ago

I'll do a test.

bobbingwide commented 3 years ago

Here are the results for 100 links to the external images in my local development.

Initial save:

Function Count Elapsed
Total 218 0.53643202781677
Yoast\WP\Lib\ORM::execute 120 0.41069531440735
add_metadata 5 0.031879425048828
add_option 1 0.022969961166382
update_option 2 0.015158891677856
wp_insert_post 2 0.0087070465087891
wp_update_site 2 0.008303165435791
WP_Term_Query::get_terms 8 0.005885124206543
delete_metadata 20 0.0057210922241211
update_meta_cache 9 0.0045614242553711
update_metadata 4 0.0035731792449951
get_option 15 0.003432035446167
get_network_option 6 0.0023961067199707
WP_Post::get_instance 4 0.0018181800842285
get_comment_count 1 0.0014970302581787
wp_load_alloptions 1 0.0014500617980957
_prime_post_caches 1 0.0011448860168457
WP_Query::get_posts 3 0.0011413097381592
WP_Site_Query::get_site_ids 1 0.0011270046234131
_update_post_term_count 2 0.001107931137085
wp_load_core_site_options 1 0.00080394744873047
term_exists 1 0.00078606605529785
delete_option 3 0.00056982040405273
WP_User::get_data_by 1 0.0004420280456543
WP_Site::get_instance 1 0.00033402442932129
wp_unique_post_slug 1 0.00026392936706543
wp_set_object_terms 1 0.0002439022064209
_prime_site_caches 1 0.00023102760314941
clean_term_cache 1 0.00018811225891113
Subsequent update: Function Count Elapsed
Total 77 0.054238319396973
wp_delete_post 7 0.012842178344727
Yoast\WP\Lib\ORM::execute 11 0.005739688873291
get_network_option 13 0.0055019855499268
get_option 16 0.0040726661682129
get_comment_count 1 0.0039801597595215
wp_unique_post_slug 2 0.0037820339202881
count_user_posts 1 0.0030510425567627
WP_Query::get_posts 4 0.002763032913208
WP_Post::get_instance 2 0.002532958984375
WP_Term_Query::get_terms 4 0.0020380020141602
update_meta_cache 5 0.0017192363739014
delete_metadata 3 0.001474142074585
wp_enqueue_media 1 0.0012340545654297
wp_get_post_autosave 1 0.0010781288146973
wp_load_alloptions 1 0.00091695785522461
WP_Site_Query::get_site_ids 1 0.00042295455932617
WP_User::get_data_by 1 0.00039911270141602
wp_load_core_site_options 1 0.00033283233642578
delete_option 1 0.00020909309387207
_prime_site_caches 1 0.00014805793762207
bobbingwide commented 3 years ago

Here are the results for creating the same content as the previous test on the live site. We're just using external links; all <img> tags removed.

<!-- wp:paragraph -->
<p>100 links to photos of Fern stamps. </p>
<!-- /wp:paragraph -->

<!-- wp:list {"ordered":true} -->
<ol><li><a href="https://www.stampsoftheworld.co.uk/w/images/0/02/Venda_1985_Ferns_FDC.jpg">/0/02/Venda_1985_Ferns_FDC</a></li><li><a href="https://www.stampsoftheworld.co.uk/w/images/0/04/Christmas_Island_2012_Ferns_fdc.jpg">/0/04/Christmas_Island_2012_Ferns_fdc</a></li><li><a href="https://www.stampsoftheworld.co.uk/w/images/0/04/United_States_of_America_2014_Ferns_a.jpg">/0/04/United_States_of_America_2014_Ferns_a</a></li>
...

Yoast queries are taking a long time for both Initial creation and subsequent update, where I only removed the space at the end of the sentence in the first paragraph.

Initial creation

Function Count Elapsed
Total 338 13.680368423462
Yoast\WP\Lib\ORM::execute 122 13.430119991302
get_option 106 0.091906070709229
delete_metadata 32 0.036865234375
wp_insert_post 4 0.032763719558716
wfConfig::loadAllOptions 1 0.015074014663696
delete_option 16 0.014199018478394
update_metadata 6 0.0080218315124512
WP_Post::get_instance 7 0.007673978805542
update_meta_cache 6 0.0067276954650879
WP_Query::get_posts 4 0.0062003135681152
wfConfig::get 8 0.0059926509857178
wfBlock::lockoutForIP 2 0.002640962600708
update_metadata_by_mid 2 0.0026299953460693
wfDB::querySingle 4 0.0024890899658203
add_metadata 2 0.0023760795593262
wfBlock::allBlocks 2 0.0017988681793213
get_metadata_by_mid 2 0.0017666816711426
wfDB::querySingleRec 1 0.0013260841369629
update_option 1 0.001194953918457
WP_User::get_data_by 1 0.0010108947753906
wordfence::veryFirstAction 1 0.00098204612731934
Smush\Core\Modules\Dir::table_exist 1 0.00096487998962402
wp_unique_post_slug 1 0.00095009803771973
wfBlock::findIPBlock 1 0.00089001655578613
WordfenceLS\Settings\Model_DB::get 1 0.00086498260498047
wp_count_posts 1 0.00083804130554199
WordfenceLS\Settings\Model_DB::_cached 1 0.00083208084106445
wfNotification::notifications 1 0.00063896179199219
get_comment_count 1 0.00062918663024902

Subsequent update

And here are the results for a subsequent update to the page. Function Count Elapsed
Total 332 3.8934552669525
Yoast\WP\Lib\ORM::execute 118 3.6929154396057
get_option 108 0.085776805877686
delete_metadata 32 0.03379225730896
delete_option 14 0.011565923690796
WP_Post::get_instance 7 0.0070834159851074
WP_Query::get_posts 4 0.0069770812988281
update_meta_cache 7 0.0069053173065186
wp_insert_post 4 0.0067989826202393
wfConfig::get 8 0.0063514709472656
wfConfig::loadAllOptions 1 0.0062301158905029
update_metadata 4 0.0051357746124268
wfDB::querySingle 4 0.00341796875
wfBlock::lockoutForIP 2 0.002885103225708
update_metadata_by_mid 2 0.0024409294128418
wfBlock::allBlocks 2 0.0019128322601318
wfDB::querySingleRec 1 0.0015289783477783
get_metadata_by_mid 2 0.0013349056243896
update_option 1 0.0013060569763184
Smush\Core\Modules\Dir::table_exist 1 0.0010509490966797
_prime_post_caches 1 0.0010430812835693
wfBlock::findIPBlock 1 0.00091409683227539
wp_count_posts 1 0.00090694427490234
wordfence::veryFirstAction 1 0.00088000297546387
WordfenceLS\Settings\Model_DB::_cached 1 0.00087618827819824
WP_User::get_data_by 1 0.0008399486541748
WordfenceLS\Settings\Model_DB::get 1 0.00072383880615234
wp_unique_post_slug 1 0.0006568431854248
wfNotification::notifications 1 0.00064420700073242
get_comment_count 1 0.00055980682373047
bobbingwide commented 3 years ago

For an additional test we copied the table from the XML sitemap for pages https://ebps.org.uk/page-sitemap.xml 424 links to the pages. The new page is https://ebps.org.uk/sitemap-xml-links/

Initial creation

Function Count Elapsed
Total 1506 35.527378797531
Yoast\WP\Lib\ORM::execute 1294 35.298835754395
get_option 105 0.09008002281189

...

Subsequent update

Function Count Elapsed
Total 1477 8.4251437187195
Yoast\WP\Lib\ORM::execute 1290 8.2497501373291
get_option 105 0.077110528945923

...