Page caching performance has regressed by 30-40%

Docs for date_default_timezone_get() show where the syscalls come from:

http://php.net/manual/en/function.date-default-timezone-get.php

And here's why we're hitting that:

So to fix the E_STRICT warning, we're using @, nice!

subscribe.

Subscribing. Also, that @ is a critical bug in itself. We should never be dealing with errors like that, especially strict errors. That is guaranteed to bite us sooner or later, exactly like this.

Catch, if I understand you correctly (and I may not as I've not studied all of our new date code in detail), the issue is that we're asking for a timezone without setting one, which is forcing PHP to take the longest possible route to derive a timezone to return. So instead we should not do that (duh) and always set a timezone.

That seems like a no-brainer to me, especially since modern PHP versions yell at you if you don't do that. If that's the case, then I'm frankly shocked that we're not already always setting a timezone based on the user-defined site timezone.

@Crell: yes that's right.

@chx: I just checked php.ini on two production servers with different linux distributions and neither had date.timezone set, so I don't think we can add a requirement for it.

Spoke to chx in irc about this. He thinks we should write this into settings.php - which I think is a good idea, but is going to be tricky for head-head updates since we'd have to tell people to make settings.php writable.

However if we go for my plan of setting the variable in the db, we'll still run into issues in the if-modified-since/strtotime() case if that's called without a variable_initialize() first (although that's more of an edge case at this point).

With a PHP.ini set timezone drupal_get_user_timezone only takes about 100 microseconds. The PHP team upgraded the warning from E_STRICT to E_WARNING in PHP 5.3.0.

Why suppress it?

The PHP team definitely considers it is a bug not to have a date.timezone set.

So, in _drupal_bootstrap_page_cache() we are *generally* after DRUPAL_BOOTSTRAP_VARIABLES (as long as page_cache_without_database is off). In that case it is legitimate to load the timezone from the database. So we can simply do something like this:

That said, it strikes me as weird that we are relying on the default timezone here (that should already be set... date_default_timezone_set(date_default_timezone_get()) should be a noop :)). So I would like this to become just 'UTC'.

Subscribe

I added date.timezone = Asia/Tokyo and it didn't make any difference to the strace.

Then in drupal_get_user_timezone() I harded coded return 'Asia/Tokyo'; at the top, and that didn't make any difference either.

Only commenting out the date_default_timezone_set() line altogether stopped them.

That may me wonder if date_default_timezone_set() is the problem instead of date_default_timezone_get().

So I looked at PHP source code.

date_default_timezone_set() calls timelib_timezone_id_is_valid()

This calls seek_to_tz_position(&tzf, timezone, tzdb)) - which looks like it could be responsible.

However even with this commented out, I don't see a massive improvement, although the strace is much nicer.

So...

Profiled again, and there are apparently five calls to cache_get() to serve the page, and cache_get() is using db_select().

I reverted #344088: cache.inc cannot be fully converted to dbtng (although apparently that actual patch never went in) and I can now get between 180-220 requests per second, instead of 120-140. Attached a patch for that alongside webgrind screenshots.

Not sure why this didn't show up earlier, since that's not a new change, but maybe dbtng internals changed (autoloader?) and it's become a problem recently.

Either way that's a big chunk of the regression, patch will need a very long code comment to explain why we're doing it like this, but I don't think it's worth losing 50 requests per second for this.

Also need to identify just why we're doing 5 cache_get() here as well, that could also be the source of the regression.

Opened #1064882: Remove syscalls from calling date_default_timezone_set(), date_default_timezone_get() so we can tackle that separately. It's ugly but it's not actually that big of a performance hit at least compared to the cache_get() stuff.

Ok, trying the patch...

Without patch:

With patch:

Certainly *a lot* faster. I don't quite see the same improvement as catch though.

Here's a re-roll adding that comment.

I also compared Drupal 7 with and without the patch with page caching disabled. The system_list()/module_list() bug doesn't appear to occur when page caching is off, this is because hook_exit() is called as module_invoke_all('exit') which doesn't use the bootstrap list - that might explain why the duplicate queries went un-noticed as well.

However there are 16 calls to cache_get() with the minimal profile, and we swap those db_select() for db_query() with the patch applied. Here's the numbers to compare - note that wall time is very variable between requests so don't get too excited, although I think I can see a small measurable improvement when benchmarking too.

HEAD:
Total Incl. Wall Time (microsec): 46,068 microsecs
Total Incl. CPU (microsecs): 40,000 microsecs
Total Incl. MemUse (bytes): 4,869,176 bytes
Total Incl. PeakMemUse (bytes): 5,060,552 bytes
Number of Function Calls: 5,636

Patch:
Total Incl. Wall Time (microsec): 40,380 microsecs
Total Incl. CPU (microsecs): 40,000 microsecs
Total Incl. MemUse (bytes): 4,999,928 bytes
Total Incl. PeakMemUse (bytes): 5,187,336 bytes
Number of Function Calls: 4,439

I don't know why the memory usage goes up with the patch, maybe there's a memory leak in db_query() compared to SelectQuery->execute()? Even xhprof didn't have many clues - inclusive memory usage for cache_get() went down from 1,144,152 to 756,976 but other functions were higher.

Out of interest, here's benchmarks with APC disabled on the 7-minimal install with and without the patch. This should benefit from not loading select.inc and query.inc (although it'd be good to benchmark only with and without the db autoloader to see what difference it makes only including those files - that was something Rasmus didn't like last Drupalcon, different issue though).

HEAD:

That only closes the 30 request/second gap compared to Drupal 6 by 10 requests/second, so some things still going on here.

And status change, sorry.

subscribing

This is an important patch so I'm tracking it.

The second bullet of #30 might be worth including in the code comment? Having the rationale makes it easier to understand.

I'd prefer it if we open a new issue to discuss the db autoload stuff and benchmark whether the autoload itself is adding overhead compared to just including the files. I took lock.inc out during benchmarks and only saw about 0.5% improvement even without APC, so would rather not write any assumptions into a code comment except for the general one that db_select() is a lot slower.

Eric_A, thanks for finding the commit. This is why we desperately need automated performance testing of core - any potential performance implication of that patch was dismissed in one comment and never looked at again. At least it's only been in for three months though, I'd been thinking I'd missed this last time I checked page caching about 14 months ago.

That's changed to keep this consistent with cache_get_multiple, which is how this regression got in in the first place.

My only note is that table names in static queries are not escaped, so I'm not sure if that's a possible SQL injection vector. Presumably you'd never use user-supplied variables for the cache bin name, but if you did and didn't sanitize it first then that would be a possible attack vector. We may want to document that in the docblock.

Other than that, I support this patch.

This is a good patch. IMO we should db_quote($table_name) just in case.

Still, we have a problem when we are afraid to use our own APIs. We added a nice db_select() but we can only use it for performance insensitive pages/queries. Thats a drupal WTF, IMO. Reminds me of drupal_static() and drupal_static_fast

Added db_escape_table(). ab is erroring out on my localhost so hoping someone else can do benchmarks.

Here we go - different system to most of the benchmarks above:

HEAD: 108.56 #/sec
Patch from #24: 135.53 [#/sec]
Patch from #41: Requests per second: 138.67 [#/sec] (mean)

#41 should not be any faster, so that means there's no obvious regression at least.

And all escapeTable() does is this, in a class that's already been instantiated, so I think we're fine.

rtbc based on benchmarks

By the same way we need to change isEmpty() - this query is not alterable.

db_select() should be used only for places where query could be altered. db_query() has docs about it.

The last submitted patch, 1064212-cache-empty.patch, failed testing.

Now the db_select() witchhunt begins. Sigh.

In fact no I'm doing this. Please open a new issue if you think this is important, explaining where isEmpty() is being used that the extra millisecond or so from db_select() is a problem. The fact we have to do db_escape_table() (afaik the only call to that in core now) for cache_get() means there is a perfectly valid reason to use db_select() - because the query is dynamic by virtue of having a variable table name.