White Screen of Death on admin/config.

That sounds weird. Because the error message you get only applies to 7.x-2.0-beta5. Versions higher than that does not have a isBehind() call in line 374. Are you using APC or another opcache?

I've heard of strange things like this before (also with other modules using ctools), and often it is due to a broken registry.

I ran into a similar issue. It was when I started using sqlsrv as the database driver (as I had to run the site on a Windows box and client preferred running on there Enterprise SQL Server). Disabling ultimate_cron allowed me to get to the config page. When enabled though I get:

Notice: Undefined index: class in current() (line 292 of C:\inetpub\wwwroot\drupal\includes\database\prefetch.inc). =>

14: DatabaseStatementPrefetch->current() (Array, 2 elements)
  file (String, 34 characters ) includes\database\prefetch.inc:292
  args (Array, 0 elements)
13: DatabaseStatementPrefetch->fetchObject() (Array, 2 elements)
  file (String, 34 characters ) includes\database\prefetch.inc:399
  args (Array, 2 elements)
   0 (String, 28 characters ) UltimateCronDatabaseLogEntry
   1 (Array, 2 elements)
     0 (String, 9 characters ) apps_cron | (Callback) apps_cron();
     1 (Object) UltimateCronDatabaseLogger
     options (Array, 1 element)
     log_entry_class (String, 28 characters ) UltimateCronDatabaseLogEntry
     name (String, 8 characters ) database
     title (String, 8 characters ) Database
     description (String, 28 characters ) Stores logs in the database.
     plugin (Array, 10 elements)
     settings (Array, 0 elements)
     weight (Integer) 0
     type (String, 6 characters ) logger
     key (String, 45 characters ) ultimate_cron_plugin_logger_database_settings

ReflectionException: Class does not exist in ReflectionClass->__construct() (line 295 of C:\inetpub\wwwroot\drupal\includes\database\prefetch.inc).

A follow up for this. I truncated the ultimate_cron_log table. And the error went away. Until I reloaded the page again and there was a new log entry. Then it white screened with same error.

-Jesse

Another follow up. Switching the database logger to cache instead possible bypassed the issue. I am guessing there is some query in the Database logging class that is causing this. I am not going to be able to investigate too much more right now but hopefully this is enough info let me know if I can get you more.

It complains about not being able to find a class (UltimateCronDatabaseLogEntry). A class that's defined in the very same file as the query (plugins/ultimate_cron/logger/database.class.php). Very very odd indeed.

Do you have any code (whatsoever) that defines a namespace? In anycase, I've committed a change to dev that may address this issue. It's a long shot, but you can try it out.

I have found that the status report wsod's on me as ultimate_cron_log table gets too big. When I enable error reporting in settings.php, I get

Additional uncaught exception thrown while handling exception.

Original

PDOException: SQLSTATE[HY000]: General error: 2013 Lost connection to MySQL server during query: SELECT l.* FROM {ultimate_cron_log} l JOIN ( SELECT l3.name, ( SELECT l4.lid FROM {ultimate_cron_log} l4 WHERE l4.name = l3.name AND l4.log_type IN (:log_types_0) ORDER BY l4.name desc, l4.start_time DESC LIMIT 1 ) AS lid FROM {ultimate_cron_log} l3 GROUP BY l3.name ) l2 on l2.lid = l.lid; Array ( [:log_types_0] => 0 ) in UltimateCronJob::loadLatestLogEntries() (line 540 of /home4/resilie4/public_html/sites/all/modules/ultimate_cron/ultimate_cron.job.inc).

If i try to run the query in phpMyAdmin, it never finishes

SELECT l.* FROM ultimate_cron_log l JOIN ( SELECT l3.name, ( SELECT l4.lid FROM ultimate_cron_log l4 WHERE l4.name = l3.name AND l4.log_type='0' ORDER BY l4.name desc, l4.start_time DESC LIMIT 1 ) AS lid FROM ultimate_cron_log l3 GROUP BY l3.name ) l2 on l2.lid = l.lid

Clearing the table allows the status report to run.

Am currently running 7.x-2.0-rc1+6-dev. Will try upgrading to the latest dev.

I modified the above sql statement (which is defined in ultimate_cron/plugins/ultimate_cron/logger/database.class.php) to this instead, and it now works and the status page loads quickly. Seems to do the same thing, but uses the max() function instead of a subquery to get the most recent log entry for each cron name

    $result = db_query("SELECT l.*
    FROM {ultimate_cron_log} l
    JOIN (
      SELECT l3.name, 
/*
        (
        SELECT l4.lid
        FROM {ultimate_cron_log} l4
        WHERE l4.name = l3.name
        AND l4.log_type IN (:log_types)
        ORDER BY l4.name desc, l4.start_time DESC
        LIMIT 1
        ) 
*/
      max(l3.lid)
      AS lid FROM {ultimate_cron_log} l3
      WHERE l3.log_type IN (:log_types)
      GROUP BY l3.name
    ) l2 on l2.lid = l.lid", array(':log_types' => $log_types));

My fix for the "MySQL has gone away" was to increase the following:

• MySQL settings: I forgot exactly which variables I tweaks but they definitely were related to wait/timeout seconds (default is I think was 30)
• PHP setting: `max_execution_time` (to help debug, and depending on how "expensive" the process is you may need to keep this higher than defaults.

Ran into this error on latest dev: When trying to load the config page.

PHP Fatal error:  Call to a member function loadLatestLogEntries() on a non-object in /path/to/ultimate_cron/ultimate_cron.job.inc on line 540

Everything has been loading fine for a while.... Nothing in ultimate_cron_log table... Maybe that has something to do with it? There is stuff in the lock table.

Here is #14 as a patch against 7.x-2.x

#14 didn't solve my issue to #16 but may solve other ones.

There are many ways to produce a WSOD ;) Perhaps this issue should be split. #17 solves a WSOD that is caused by running into PHP's max execution time due to a slow query.

Well. While that is true, the issue I received was from the same line. So I am guessing there is more issues with this area that would probably get rolled up in one patch. So yes the changes in the patch may have addressed your single issue or maybe it just addressed part of the issue or maybe created new issues. The subquery that is being removed in this patch is doing more than just selecting the "MAX". Its doing ordering on other fields as well. I think we need more investigation around this.

A side note. We are receiving errors on a page that shouldn't even be firing this code/running these queries I would think.

I will mark this as needs review so we may be able to get more feedback. Personally I can't say it is RTBC. Then again its not my call.

The query proposed in #14 and #17 is getting the alphabetically highest lid, while the original query is getting the numerically highest start_time. This means the two queries produce completely different results, so the patch is no good.

The most efficient query I've found that matches the results from the original would be:

SELECT l1.*
FROM {ultimate_cron_log} l1
JOIN (
  SELECT name, MAX(start_time) AS start_time
  FROM {ultimate_cron_log}
  GROUP BY name
) l2
ON l1.name = l2.name AND l1.start_time = l2.start_time
WHERE l1.log_type IN (:log_types)

(adapted from these examples)

This cuts the query time from 27s to 0.073s on my server, with identical results.

Having said that, the reason the slow query is being run at all is that system_admin_config_page() calls system_status() which invokes ultimate_cron_requirements() which calls UltimateCronJob::loadLatestLogEntries() to check if any cron jobs are behind schedule and notifies the user accordingly.

I would question whether this needs to happen anywhere but admin/config/system/cron and admin/reports/status. Is it necessary to check for delayed cron jobs every time admin/config is accessed?

Here are a couple of patches containing the query I described in #23.

One uses db_select() and one uses db_query(), but they both do the same thing and I don't notice any difference in performance, so just use whichever is the more readable I guess.

@morbiD I like this approach. I think we should use the db_query since we can.

I would question whether this needs to happen anywhere but admin/config/system/cron and admin/reports/status. Is it necessary to check for delayed cron jobs every time admin/config is accessed?

I was questioning the exact same thing. I think we should use this issue to solve that problem as well. As the main issue everyone on this queue is talking about is the title "White Screen of Death on admin/config."

So it is nice that we are addressing the query, but I think we need to make the the adjustments so we don't fire this except on the pages:

• admin/config/system/cron
• admin/reports/status

After examining the code of ultimate_cron_requirements() a bit more, I think the maintainers fully intended it to run on admin/config since they set a severity of REQUIREMENT_ERROR if a cron job is behind schedule and the hook_requirements() documentation states:

Any requirement with a severity of REQUIREMENT_ERROR will result in a notice on the administration configuration page.

That particular point probably needs some input from them. However, the patch for the slow query should at least prevent timeouts from occurring when the ultimate_cron_log table is large, which I assume is what was causing people's WSODs.

Is the error in #16 still a problem? I haven't seen it myself.

hello
i had a 502 timeout error when going to /admin/config/system/cron.
one mysql process stayed at 100% of cpu.
my config is set as : "retain only a specific amount of log queries" (1000).
after reading this ticket, i went to see my db and ultimate_cron_log table had 29016 rows.
then i have truncated the table and now the timeout has dissapeared.

maybe this issue has a relation with https://www.drupal.org/node/2721545

using :
ultimate_cron 7.x-2.0-rc2
drupal core 7.44
php 5.6.22
mysql 5.5.49
nginx 1.6.2

@ssm2017 I think you're right about that other issue. I've marked it as a duplicate of this one.

Please test the patches from this issue and give feedback if possible.

The db_query patch in #24 worked for me. Thanks so much for identifying this problem.

(A message for people Googling for "drupal 7 admin pages slow" or "drupal 7 admin page timeout" - if you have ultimate_cron installed and you have thousands of entries in your ultimate_cron_log then this might be your issue)

Regarding slow query performance, how about adding more indexes to the table ultimate_cron_log?
Something along this:

    'indexes' => array(
      'idx_last' => array(
        array('name', 128),
        'start_time',
        'end_time',
        'log_type',
      ),
      'name' => array('name'),
      'log_type' => array('log_type'),
    ),

name and log_type seems to be the core of the query mentioned in #24

+1 to index tweak

I did a little bit of messing around with indexes in phpMyAdmin using a local copy of my live database and it seems that an individual index for log_type makes no difference at all to query time in this case.

An individual index for name makes a fairly significant difference, but nowhere near as much as a combined index for (name, start_time).

See sample query times:

• No additional indexes: 0.4652s
• Individual log_type index: 0.4614s
• Individual name indexes: 0.0580s
• Combined (name, start_time) index: 0.0010s

Seems like the combined one is all we need if we're adding new indexes?

@morbiD Awesome, thanks for the testing!
So I guess we go with:

    'indexes' => array(
      'idx_last' => array(
        array('name', 128),
        'start_time',
        'end_time',
        'log_type',
      ),
      'last_log' => array(
        'name',
        'start_time',
      ),
    ),

Hmm, actually, the existing idx_last index would be usable for this query if it wasn't for the 128-character prefix length on the name column.

That prefix length was added because of #2552573: Unable to install because table ultimate_cron_signal has an index too long, but I don't think it's necessary. The problem there was that a primary key combined two UTF8 VARCHAR(255) columns and went over a 1000B key length limit.

However, calculating for the idx_last index:

name = 255*3 = 765B
start_time = 8B
end_time = 8B
log_type = 4B
total = 785B

Therefore idx_last doesn't need the prefix limit on name to stay within a 1000B key length limit and we can just change it back to:

    'indexes' => array(
      'idx_last' => array(
        'name',
        'start_time',
        'end_time',
        'log_type',
      ),

Does that seem reasonable?

Good checks, thank you for profiling. I knew the current indexes were a little thin for what the log records, glad this is moving.

Patch from #24 solved issue with execution timeout on admin/config/system/cron

Just an update from the 7.x maintainer(s).

I believe this issue to be the only one blocking a 7.x-2.0 release.

@gielfeldt is probably not going to be very active in maintaining the module any more as he is moving on to new job outside the Drupal world. I have told him that is not acceptable :-)

This issue actually covers two very distinct issues (kind of a mess, yes):

1) The original Call to a member function isBehind() on a non-object and the like.

The most recent report is from @dobe 4 months ago. I haven't experienced it myself recently - but that's probably just because I no longer maintain the site where it frequently happened.

This is most likely a problem in ctools_get_plugins() and/or ctools_plugin_get_class(). The root cause could be #2598166: Plugin information cache can become inconsistent.

or something similar.

I just added a patch hardening our usage of ctools plugins. This won't avoid the problem but hopefully we'll be able to gather more information about it.

2) Timeout during database lookup.

There is a patch from @morbid and @torotil (thank you for working on that).

I spoke to @gielfeldt about the patch and he wasn't convinced it would be a good idea to apply it.

When he wrote the current query he tested it thoroughly on very large amount of data (20-30 million log entries) and found that using MAX and GROUP BY had bad performance characteristics.

Of course there is no help in having a query that performs good at very large amounts of data but timeouts with lower values.

Could we try to do some benchmarking of the current code and the patch with different amounts of log entries?

Finally there is the stuff about indexes. Let's revisit when we have settled on the query.

I can confirm this issue with todays dev:
WSOD on admin/config/system/cron & admin/reports/status

The problem stopped after a
drush sqlq "delete from ultimate_cron_log;"

Thanks everyone for working on this and count me in for some help. I'm using this extensively.

> @gielfeldt is probably not going to be very active in maintaining the module any more as he is moving on to new job outside the Drupal world. I have told him that is not acceptable :-)

+1 from me!

After some thorough reading of the issue it looks to me like:
* #24 is RTBC as of #29, #36,#37
** i'd suggest committing that fix and leaving the index optimization from #33/#34 to a followup commit in this issue
** i'd prefer the cleaner db_select over db_query but that's up to the maintainer

as i understand it, the summary from #33/#34 would be:

'indexes' => array(
      'idx_last' => array(
        'name',
        'start_time',
        'end_time',
        'log_type',
      ),
      'last_log' => array(
        'name',
        'start_time',
      ),
    ),

Here's the index optimizations patch. To test it
* apply one of the patches from #24
* apply this patch

I can confirm that #24-select + this patch fixes the issue for me.
I can confirm that this patch 's upgrade function seemed to do the right thing to the indexes here.

I can also confirm that #24 + #43 seems to improves the query a lot for loadLatestLogEntries. However loading of a single log entry is still a problem. Back in the day, I had a lot of issues with MySQL using the correct indexes and using them properly (innodb random cardinality calculation, etc), which was one of the reasons I avoided using MAX. Perhaps this has changed. Let's hope so.

To take advantage of the same index, this one seems to do it. Putting the where name = :name inside the subselect seems to make mysql choose a poorer execution plan.

SELECT l1.*
FROM ultimate_cron_log l1
JOIN (
    SELECT name, MAX(start_time) AS start_time
    FROM ultimate_cron_log 
    GROUP BY name
) l2
ON l1.name = l2.name AND l1.start_time = l2.start_time
WHERE l1.log_type IN (:log_types)
AND l1.name = :name

I've test with 400+ jobs and 2M log entries. I've also tested with only a couple of hundred log entries. Both cases seem to perform fine with #24 + #43.

Thanks to everybody for pitching in!

Btw, I was too lazy to provide a patch for the above query. Also, I wouldn't want to deprive @arnested of all the fun :-)

> Back in the day, I had a lot of issues with MySQL using the correct indexes and using them properly (innodb random cardinality calculation, etc), which was one of the reasons I avoided using MAX. Perhaps this has changed. Let's hope so.

Yesterday i played a bit and succeeded with a single join without max, but no better timing.
If that dragons pop out again, we can go that way.

I just realized that the query

SELECT l1.*
FROM ultimate_cron_log l1
JOIN (
    SELECT name, MAX(start_time) AS start_time
    FROM ultimate_cron_log 
    GROUP BY name
) l2
ON l1.name = l2.name AND l1.start_time = l2.start_time
WHERE l1.log_type IN (:log_types)

... is broken. The where clause on log_type needs to be in the subselect in order to work as expected. The index is not tuned for this however.

I've included it all in one patch. I had to add log_type to the index as well. Somebody wanna test it?

Yo i had a broken site in spare and tested it there: Patch applied well and fixed the problem.
RTBC so.

(Note: Commit #48 has been something different.)

Wrt #2552573: Unable to install because table ultimate_cron_signal has an index too long, I think it could be an idea to reduce the actual column size of the job_name, signal_name and lock_name in order for mysql to accept the compound primary key (job_name, signal_name) in the signals table.

Reducing the size of the index has 2 problems:
- performance-hit as seen in this ticket
- doesn't work on postgres (and possibly others)

I'm thinking a size of 128 each for all three. Any thoughts?

I believe this to be fixed in 7.x-2.0-rc4 now.

@gielfeldt committed a fix for the timeout issue, index been fixed as part of #2552573 and we should now fail more gracefull on the ctools plugins issue.

I'm going to mark the issue as Fixed now. Feel free to reopen and comment if you still experience problems with rc4.

A big thank you to everyone involved!

Strange. Everything running fine for me on v2.3 - and out of nowhere, yesterday and today the RuntimeException is thrown but I also get a WSOD. I'm investigating and will share. Assume this is just my site until I update this post.