I've seen this once before and thought it was just a bad HEAD install, but it just came up again on #597236: Add entity caching to core.

This shows up on every request when loading a node with 50 comments: SELECT table_name FROM information_schema.tables WHERE (table_schema = :db_condition_placeholder_0) AND (table_name = :db_condition_plceholder_1).

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

catch’s picture

Title: field_sql_storaga_schema() not being cached properly » drupal_get_schema() caching is broken
Component: field system » base system
Status: Active » Needs review
FileSize
4.02 KB

OK to reproduce this, truncate {cache} then visit any number of node/n pages but not the front page. This will also be the same for any 'entity' page like user/n, taxonomy/term/n etc.

Here's what happens:

menu_custom_theme() calls menu_get_item(), menu_get_item() loads the objects for that page, this calls node_load(), which calls drupal_schema_fields_sql()

This eventually gets down to drupal_get_schema(). On a cache miss, drupal_get_schema() caches on these conditions:

 if (!empty($schema) && (drupal_get_bootstrap_phase() == DRUPAL_BOOTSTRAP_FULL)) {
        cache_set('schema', $schema);
      }

menu_custom_theme() is called while we're still officially at DRUPAL_BOOTSTRAP_LANGUAGE, because it actually happens inside _drupal_bootstrap_full(), and the phase is set after that's completed.

This means that the schema will never be cached until you hit a page which both requires a schema hit, and calls it after _drupal_bootstrap_full() has completed, which includes the default front page in HEAD, but not many others I can think of.

We probably wouldn't have noticed this unless field_sql_storage_schema() was doing a bad SQL query, but it also means we load all .install files which is a big memory hog.

This patch is a bit ugly but fixes it, along with a bad drupal_function_exists() revert found at the same time - we just set $completed_phase immediately before running the bootstrap phase, instead of afterwards, so that operations which occur during the full bootstrap, know that they're in that rather than the previous one. This is how things happened in D6.

catch’s picture

Note this also means that any function called during hook_init() currently gets DRUPAL_BOOTSTRAP_LANGUAGE if they consult drupal_get_bootstrap_phase(). That's probably a good way to test this thinking about it.

catch’s picture

Tracked down the change to #370454: Simplify page caching - up until then, we set the phase prior to executing it, not afterwards - that looks to be a side-effect of the code there, not its intention.

So while we probably want to do it differently to what's in the current patch, that's the main bug here.

catch’s picture

Title: drupal_get_schema() caching is broken » drupal_get_bootstrap_phase() is broken
FileSize
2.02 KB
3.34 KB

Re-titling, uploading proper patch with a test, and also the test separately - should have one failure.

catch’s picture

chx reviewed in irc, changing the ternary back to an if.

chx’s picture

Status: Needs review » Reviewed & tested by the community

Hm, good catch.

int’s picture

Status: Reviewed & tested by the community » Needs work

All patch's fail the tests

chx’s picture

Status: Needs work » Reviewed & tested by the community

Yes, yes but that does not mean it's wrong.

yched’s picture

looks like the bot should be back now ?

Status: Reviewed & tested by the community » Needs review
Issue tags: -Performance

Re-test of from comment #2405352 was requested by @user.

Status: Needs review » Needs work
Issue tags: +Performance

The last submitted patch, , failed testing.

catch’s picture

It shouldn't be wrong, but I can reproduce the test failures locally with the patch, and not without it.

catch’s picture

Status: Needs work » Needs review
FileSize
3.63 KB

drupal_set_message() suppresses page caching, the page cache tests depend on system_test.module.

Dries’s picture

This seems like the proper fix to me. Although, the test is a bit odd/weird -- it is a bit of a hack really. Do we need a test for this?

catch’s picture

Since it was broken for a good 2-3 months, and caused a serious regression, without anyone noticing apart from via repeated and diverse benchmarking on a completely unrelated patch by more than 2-3 people, I thought it was worth having a test. However I agree the test is a bit weird / hacky and wouldn't be sad if it's removed - the proper test to catch things like this is #638078: Automated performance testing for core.

catch’s picture

chx asked for a change from $completed_phase to $stored_phase - since setting that before we actually execute the phase is a bit strange. internal variable name only. I've also attached a version with and without the test.

chx’s picture

Status: Needs review » Reviewed & tested by the community

Absolutely yes to the test! It helps those who mess with drupal_bootstrap... like Moshe and me :)

Dries’s picture

Status: Reviewed & tested by the community » Needs review

Don't get me wrong; I'm all for testing. It just that this test is really ugly. Can't we write a proper unit test for this?

chx’s picture

Status: Needs review » Reviewed & tested by the community

not without mocking the actual bootstrap functions. my mock function based unit testing idea was voted down for Drupal 7 early. See you in Drupal 8 :)

Dries’s picture

Priority: Critical » Normal
Status: Reviewed & tested by the community » Needs review

I committed the patch without the test to move things forward. However, I'll look into the test within 48 hours (tests can go in after code freeze). I want to ponder about the tests a bit more. I'm setting this back to 'needs review' for the time being.

David_Rothstein’s picture

Status: Needs review » Needs work

Hm...

The API docs for drupal_bootstrap() say this:

 * @return
 *   The most recently completed phase.

And for drupal_get_bootstrap_phase() say this:

 * Returns the current bootstrap phase for this Drupal process.
 *
 * The current phase is the one most recently completed by drupal_bootstrap().

Which means the API docs were correct before this patch, but now are completely wrong, right?

Also, even if the API docs are changed... what I don't understand is this seems to mean there is now no way to use this function to actually detect when the bootstrap is fully complete??? Since it will return DRUPAL_BOOTSTRAP_FULL when in the middle of running that phase, but also will return it at the end. It almost seems like we need a second function here, i.e. drupal_get_last_completed_bootstrap_phase() or something like that.

Fabianx’s picture

Priority: Normal » Critical
Issue summary: View changes
Status: Needs work » Needs review
Issue tags: +needs patch

Indeed it is still totally broken, calling drupal_get_bootstrap_phase from any phase below FULL will cause the bootstrap to _abort_ leading to a WSOD without any information at all.

The patch is very simple: Don't set new phase when retrieving the state.

 function drupal_get_bootstrap_phase() {
-  return drupal_bootstrap();
+  return drupal_bootstrap(NULL, FALSE);
 }

Before what was happening was:

drupal_bootstrap($phase = NULL, $new_phase = TRUE) // called with default values.

if ($new_phase) {
$final_phase = $phase;
}

$final_phase gets set to NULL.

and then obviously $final_phase > $stored_phase is no longer TRUE, so the loop gets aborted ...

plach’s picture

Here's a patch implementing #23.

chx’s picture

Issue tags: -needs patch
FileSize
1.9 KB

Note this is identical (aside from a comment) to the patch in #1806992: drupal_get_bootstrap_phase / drupal_bootstrap is broken and honestly this issue should be closed in favor of that but w/e.

Fabianx’s picture

Status: Needs review » Reviewed & tested by the community

This looks great to me!

**RTBC**

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

plach queued 26: 667098_26.patch for re-testing.

plach’s picture

Back to RTBC

plach’s picture

Status: Needs review » Reviewed & tested by the community

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

plach queued 26: 667098_26.patch for re-testing.

plach’s picture

Status: Needs review » Reviewed & tested by the community

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

chx queued 26: 667098_26.patch for re-testing.

chx’s picture

Status: Needs review » Reviewed & tested by the community

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

joelpittet queued 26: 667098_26.patch for re-testing.

chx’s picture

Status: Needs review » Reviewed & tested by the community

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

chx queued 26: 667098_26.patch for re-testing.

dcam’s picture

Status: Needs review » Reviewed & tested by the community

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: 667098_26.patch, failed testing.

Status: Needs work » Needs review

chx queued 26: 667098_26.patch for re-testing.

chx’s picture

Status: Needs review » Reviewed & tested by the community

  • David_Rothstein committed 4a93ebd on 7.x
    Issue #667098 by catch, chx, plach, Fabianx: Fixed a bug which caused...
David_Rothstein’s picture

Priority: Critical » Normal
Status: Reviewed & tested by the community » Active
Issue tags: +7.33 release notes

Committed to 7.x - thanks!

But I would say this is still a bit broken even afterwards (or at least incorrectly documented) - see #22. And the history of this issue plus the fact that there are some uncommitted tests in the patches above suggest that it would be great to have some kind of test for this function...

Maybe those can be split off to new issues, but leaving this one open for now.

  • Dries committed 239cec2 on 8.3.x
    - Patch #667098 by catch: drupal_get_bootstrap_phase() was broken.
    
    

  • Dries committed 239cec2 on 8.3.x
    - Patch #667098 by catch: drupal_get_bootstrap_phase() was broken.
    
    

  • Dries committed 239cec2 on 8.4.x
    - Patch #667098 by catch: drupal_get_bootstrap_phase() was broken.
    
    

  • Dries committed 239cec2 on 8.4.x
    - Patch #667098 by catch: drupal_get_bootstrap_phase() was broken.
    
    

  • Dries committed 239cec2 on 9.1.x
    - Patch #667098 by catch: drupal_get_bootstrap_phase() was broken.