GET on Feed URLs takes too long

danimo commented 6 years ago

Expected behavior

First (uncached) GET on feed URLs (like /feed/m4a) return almost immediately

Actual behavior

The GET request takes 26 seconds

System information (see `Podlove > Support` menu)

Website                    https://chaosradio.de
PHP Version                7.2.11
WordPress Version          4.9.8
WordPress Theme            Twenty Eleven v2.8
Active Plugins             
           - All-in-One Event Calendar von Time.ly v2.5.32
           - Antispam Bee v2.9.0
           - Check Email v0.5.5
           - Fast Velocity Minify v2.3.5
           - German Slugs v0.2
           - Chaosradio-Links v0.1
           - Insert Headers and Footers v1.4.3
           - Nginx Helper v1.9.12
           - Podlove Podcast Publisher v2.7.16
           - WP DSGVO Tools v2.1.3
           - Twenty Eleven Theme Extensions v1.2
           - UpdraftPlus - Backup/Restore v1.15.3
           - Username Changer v3.1.3
           - WordPress Importer v0.6.4
           - WordPress phpinfo() v16.3
WordPress Database Charset utf8mb4
WordPress Database Collate 
Publisher Version          2.7.16
Web Player Version         player_v4
Twig Version               1.35.3
open_basedir               ok
curl Version               7.62.0
iconv                      available
simplexml                  ok
max_execution_time         30
upload_max_filesize        10M
memory_limit               256M
disable_classes            
disable_functions          
permalinks                 ok (/%postname%)
podlove_permalinks         ok
podcast_settings           ok
web_player                 ok
podlove_cache              on
assets                     
  - mp3    audio/mpeg       https://chaosradio.de/feed/mp3
  - m4a    audio/mp4        https://chaosradio.de/feed/m4a
  - opus   audio/ogg;codecs=opushttps://chaosradio.de/feed/opus
cron                       ok

0 errors
0 notices
Nice, Everything looks fine!

danimo commented 6 years ago

Slow query log analysis (note the insane amount of thousands of request querying for the value 'S' in all possible and impossible fields):

%mysqldumpslow

Reading mysql slow query log from /var/log/mysql/slow-query.log
Count: 1  Time=0.01s (0s)  Lock=0.00s (0s)  Rows_sent=5367.0 (5367), Rows_examined=5367.0 (5367), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_logging_logtable WHERE time > N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3495.0 (3495), Rows_examined=6928.0 (6928), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT post_id, meta_key, meta_value FROM wp_postmeta WHERE post_id IN (N,,{repeated 238 times}N) ORDER BY meta_id ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1833.0 (1833), Rows_examined=6928.0 (6928), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT post_id, meta_key, meta_value FROM wp_postmeta WHERE post_id IN (N,,{repeated 140 times}N) ORDER BY meta_id ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1675.0 (1675), Rows_examined=6928.0 (6928), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT post_id, meta_key, meta_value FROM wp_postmeta WHERE post_id IN (N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N) ORDER BY meta_id ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=240.0 (240), Rows_examined=968.0 (968), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  wp_podlove_episode e
  INNER JOIN wp_posts p ON e.post_id = p.ID
  WHERE
  N = N AND p.post_status = 'S'
  AND p.post_type = "S"
  ORDER BY p.post_date DESC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=240.0 (240), Rows_examined=968.0 (968), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  `wp_podlove_episode` e 
  JOIN `wp_posts` p ON e.post_id = p.ID
  WHERE
  p.post_status IN ("S", "S", "S", "S", "S")
  AND
  p.post_type = "S"
  ORDER BY
  p.post_date DESC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=478.0 (478), Rows_examined=2168.0 (2168), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT  t.*, tt.*, tr.object_id FROM wp_terms AS t  INNER JOIN wp_term_taxonomy AS tt ON t.term_id = tt.term_id INNER JOIN wp_term_relationships AS tr ON tr.term_taxonomy_id = tt.term_taxonomy_id WHERE tt.taxonomy IN ('S', 'S') AND tr.object_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) ORDER BY t.name ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=282.0 (282), Rows_examined=1776.0 (1776), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT  t.*, tt.*, tr.object_id FROM wp_terms AS t  INNER JOIN wp_term_taxonomy AS tt ON t.term_id = tt.term_id INNER JOIN wp_term_relationships AS tr ON tr.term_taxonomy_id = tt.term_taxonomy_id WHERE tt.taxonomy IN ('S', 'S') AND tr.object_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) ORDER BY t.name ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=198.0 (198), Rows_examined=1608.0 (1608), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT  t.*, tt.*, tr.object_id FROM wp_terms AS t  INNER JOIN wp_term_taxonomy AS tt ON t.term_id = tt.term_id INNER JOIN wp_term_relationships AS tr ON tr.term_taxonomy_id = tt.term_taxonomy_id WHERE tt.taxonomy IN ('S', 'S') AND tr.object_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) ORDER BY t.name ASC

Count: 240  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (240), Rows_examined=729.0 (174960), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  `wp_podlove_episode` e
  JOIN `wp_posts` p ON e.post_id = p.ID
  WHERE
  p.post_type = 'S' AND
  p.post_status = 'S' 
  ORDER BY
  p.post_date ASC
  LIMIT N,N

Count: 240  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (240), Rows_examined=729.0 (174960), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  `wp_podlove_episode` e
  JOIN `wp_posts` p ON e.post_id = p.ID
  WHERE
  p.post_type = 'S' AND
  p.post_status = 'S' 
  ORDER BY
  p.post_date DESC
  LIMIT N,N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=720.0 (720), Rows_examined=1208.0 (1208), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  p.post_status,
  mf.episode_id,
  mf.episode_asset_id,
  mf.size,
  mf.id media_file_id
  FROM
  `wp_podlove_mediafile` mf
  JOIN `wp_podlove_episode` e ON e.id = mf.`episode_id`
  JOIN `wp_posts` p ON e.`post_id` = p.`ID`
  WHERE
  p.`post_type` = 'S'
  AND p.post_status in ('S', 'S', 'S', 'S', 'S')

Count: 7  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=2.0 (14), Rows_examined=3190.0 (22330), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT comment_approved, COUNT( * ) AS total
  FROM wp_comments
  GROUP BY comment_approved

Count: 5760  Time=0.00s (6s)  Lock=0.00s (0s)  Rows_sent=1.0 (5520), Rows_examined=614.1 (3537120), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  `wp_podlove_episode` e
  JOIN `wp_posts` p ON e.post_id = p.ID
  WHERE
  p.post_type = 'S' AND
  p.post_status = 'S' 
  AND DATE(p.post_date) > 'S'
  ORDER BY
  p.post_date ASC
  LIMIT N,N

Count: 11520  Time=0.00s (12s)  Lock=0.00s (0s)  Rows_sent=1.0 (11040), Rows_examined=603.8 (6956160), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  e.*
  FROM
  `wp_podlove_episode` e
  JOIN `wp_posts` p ON e.post_id = p.ID
  WHERE
  p.post_type = 'S' AND
  p.post_status = 'S' 
  AND DATE(p.post_date) < 'S'
  ORDER BY
  p.post_date DESC
  LIMIT N,N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=2.0 (2), Rows_examined=8.0 (8), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT DISTINCT p.*, e.post_id, i.id AS instance_id, i.start AS start, i.end AS end, e.allday AS event_allday, e.recurrence_rules, e.exception_rules, e.ticket_url, e.instant_event, e.recurrence_dates, e.exception_dates, e.venue, e.country, e.address, e.city, e.province, e.postal_code, e.show_map, e.contact_name, e.contact_phone, e.contact_email, e.cost, e.ical_feed_url, e.ical_source_url, e.ical_organizer, e.ical_contact, e.ical_uid, e.timezone_name, e.longitude, e.latitude FROM wp_ai1ec_events e INNER JOIN wp_posts p ON e.post_id = p.ID  INNER JOIN wp_ai1ec_event_instances i ON e.post_id = i.post_id  WHERE post_type = 'S'  AND i.end >= N AND post_status = 'S'  ORDER BY i.start ASC, post_title ASC LIMIT N, N

Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=606.0 (1818), Rows_examined=606.0 (1818), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_job

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=2.0 (2), Rows_examined=8.0 (8), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT DISTINCT p.*, e.post_id, i.id AS instance_id, i.start AS start, i.end AS end, e.allday AS event_allday, e.recurrence_rules, e.exception_rules, e.ticket_url, e.instant_event, e.recurrence_dates, e.exception_dates, e.venue, e.country, e.address, e.city, e.province, e.postal_code, e.show_map, e.contact_name, e.contact_phone, e.contact_email, e.cost, e.ical_feed_url, e.ical_source_url, e.ical_organizer, e.ical_contact, e.ical_uid, e.timezone_name, e.longitude, e.latitude FROM wp_ai1ec_events e INNER JOIN wp_posts p ON e.post_id = p.ID  INNER JOIN wp_ai1ec_event_instances i ON e.post_id = i.post_id  WHERE post_type = 'S'  AND i.end >= N AND post_status IN ( 'S', 'S' )  ORDER BY i.start ASC, post_title ASC LIMIT N, N

Count: 41  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=224.2 (9192), Rows_examined=1238.2 (50766), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT option_name, option_value FROM wp_options WHERE autoload = 'S'

Count: 36  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=606.0 (21816), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT 
  *
  FROM
  wp_podlove_job j
  WHERE `class` LIKE "S" AND steps_total > steps_progress
  ORDER BY `updated_at` DESC
  LIMIT N,N

Count: 18  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=606.0 (10908), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT 
  *
  FROM
  wp_podlove_job j
  WHERE `class` LIKE "S" AND steps_total <= steps_progress
  ORDER BY `updated_at` DESC
  LIMIT N,N

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (6), Rows_examined=607.0 (3642), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT 
  *
  FROM
  wp_podlove_job j
  WHERE `class` LIKE "S"
  ORDER BY `updated_at` DESC
  LIMIT N,N

Count: 5  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=606.0 (3030), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  *
  FROM
  wp_podlove_job
  WHERE
  steps_total > steps_progress
  ORDER BY created_at ASC
  LIMIT N, N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=45.0 (45), Rows_examined=180.0 (180), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  ec.id, ec.role_id, ec.group_id, 
  (case when c.gender = 'S' then N else N end)                  AS male,
  (case when c.gender = 'S' then N else N end)                AS female,
  (case when c.gender NOT IN ('S', 'S') then N else N end) AS notattributed
  FROM
  `wp_podlove_modules_contributors_episodecontribution` ec
  JOIN `wp_podlove_episode` e     ON e.id = ec.episode_id
  JOIN `wp_posts` p              ON p.ID = e.`post_id` AND p.post_status IN ('S', 'S')
  JOIN `wp_podlove_modules_contributors_contributor` c ON ec.`contributor_id` = c.id

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (1), Rows_examined=1.0 (1), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM `TABLES` WHERE `TABLE_SCHEMA` = 'S' AND `TABLE_NAME` = 'S'

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (6), Rows_examined=12.0 (24), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT
  f.*
  FROM
  wp_podlove_feed f
  JOIN wp_podlove_episodeasset a ON a.id = f.episode_asset_id
  JOIN wp_podlove_filetype ft ON ft.id = a.file_type_id
  WHERE
  f.slug IS NOT NULL  AND f.discoverable
  ORDER BY 
  position ASC

Count: 240  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (720), Rows_examined=9.0 (2160), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT M.*
  FROM wp_podlove_mediafile M
  JOIN wp_podlove_episodeasset A ON A.id = M.episode_asset_id
  WHERE M.episode_id = 'S' 
  ORDER BY A.position ASC

Count: 240  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=25.0 (6000), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_seasons_season WHERE start_date < 'S' OR start_date IS NULL AND id != N

Count: 6000  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (5760), Rows_examined=26.0 (155760), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_seasons_season WHERE 
  start_date < 'S' 
  OR start_date IS NULL 
  ORDER BY
  start_date DESC LIMIT N,N

Count: 42  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (126), Rows_examined=3.0 (126), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_feed

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (3), Rows_examined=3.0 (3), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_feed WHERE discoverable = 'S'

Count: 20283  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (20043), Rows_examined=26.0 (527118), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_seasons_season WHERE start_date > 'S' ORDER BY start_date ASC LIMIT N,N

Count: 240  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=25.0 (6000), Rows_examined=25.0 (6000), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_seasons_season

Count: 5  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (5), Rows_examined=2.0 (10), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_feed WHERE slug = 'S' LIMIT N,N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (6), Rows_examined=3.0 (6), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_episodeasset

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (1), Rows_examined=45.0 (45), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT COUNT(*) FROM wp_podlove_modules_contributors_episodecontribution

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=2.0 (2), Rows_examined=2.0 (2), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_template

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=5.0 (5), Rows_examined=5.0 (5), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_modules_contributors_showcontribution

Count: 965  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=1.0 (965), Rows_examined=1.0 (965), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT * FROM wp_podlove_template WHERE title = 'S' LIMIT N,N

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT `feed_id` FROM `wp_ai1ec_event_feeds`

Count: 274  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=3.0 (822), Rows_examined=3.0 (822), Rows_affected=0.0 (0), wordpress[wordpress]@localhost
  SELECT slug FROM wp_podlove_feed

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), 0users@0hosts
  # Time: N N:N:N
  # User@Host: wordpress[wordpress] @ localhost []
  # Thread_id: N  Schema: chaosradio  QC_hit: No
  # Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N
  # Rows_affected: N  Bytes_sent: N
  SET timestamp=N;
  SELECT option_name, option_value FROM wp_options WHERE autoload = 'S'

eteubert commented 6 years ago

It seems the seasons module produces excessive/expensive queries on feed generation. In my quick tests it increased feed generation time dramatically.

In general the feed generation could use a rewrite. Data can and should be queried much more efficiently.

That being said, 26 seconds seems excessive, even for a feed with hundreds of episodes. In my tests just now I used a podcast with 220 episodes and it renders in about 5 seconds.

danimo commented 6 years ago

And I cannot make heads or tails about the queries for S. Or is that just the way of the query logger to mark common queries with different values?

danimo commented 6 years ago

Is there a way to more console/log file debugging somewhere for the RSS generator?

eteubert commented 6 years ago

The N/S variables are a substitution of mysqldumpslow I think.

I like to use https://wordpress.org/plugins/query-monitor/ for basic performance stuff but unfortunately that relies on a web UI and is not usable for RSS as far as I know. So I do it manually.

# wp-config.php
define('WP_DEBUG', true);
define('WP_DEBUG_LOG', true);
define('SAVEQUERIES', true);

At the end of <publisher-plugin>/templates/feed-rss2.php:

</rss>

<?php
global $wpdb;

$sum = 0;

foreach ($wpdb->queries as $query) {
    $sum += $query[1];
    error_log(print_r($query[0] . " in " . $query[1] . "\n\n", true));
}

error_log(print_r(count($wpdb->queries) . " queries in " . $sum, true));

Then all queries and their times are logged in wp-content/debug.log. Requires a bunch of PHP memory though as SAVEQUERIES keeps a lot of metadata.

danimo commented 6 years ago

Do you want me to run this? alternative, I can grant you temporary access or offer a backup for offline debugging purposes.

eteubert commented 6 years ago

You don't need to, I am pretty sure I know where I need to optimize. It also serves as a note to myself ;)

This https://github.com/podlove/podlove-publisher/blob/master/lib/modules/seasons/model/season.php#L16 is really expensive and run for every episode in the feed. Shouldn't be too hard to optimize at least that section.

danimo commented 6 years ago

Hey Eric, do you have an ETA for a patch? Not trying to be pushy, just checking if I need to deploy a special caching strategy for the feeds before the relaunch. Let me know if I can help.

eteubert commented 6 years ago

I have a patch ready that should help a lot. Just needs some more testing that I didn't break anything. Should be released within the next few days.

I also have some plans of rewriting the whole feed generation for another big performance gain but that will take more time.

Since the feed is one of the notable podcast hosting bottlenecks, caching is still not a bad idea. Only with some manual effort you can prevent feed requests to go through PHP/WordPress.

An idea:

run a cron every minute that curls the feed URL and writes it to a static file
serve that static file directly via Apache/nginx

danimo commented 6 years ago

I am currently using the fastcgi_cache mechanism to cache all assets, but only for a limited time (it gets purged by a WP plugin once related things in WP change). I would probably need to remove time timeout in this case. Cronjob sounds like a good idea as well.

eteubert commented 6 years ago

Forgot to reference the issue in the commit message: https://github.com/podlove/podlove-publisher/commit/ad5f9138a5bb0bdb3de3a0eefc74721865750d17

danimo commented 6 years ago

Wow, this brought down rendering time to ~1sec.

podlove / podlove-publisher