Support for Drupal 7 is ending on 5 January 2025—it’s time to migrate to Drupal 10! Learn about the many benefits of Drupal 10 and find migration tools in our resource center.See benchmarks from Heine in this forum post http://drupal.org/node/1020494#comment-3947826
Which I reproduced here: http://ca.tchpole.net/node/2
Critical because:
- there's no aggressive caching via the UI in Drupal 7, so no workaround for the majority of sites.
- sites upgraded from Drupal 6 will only be able to serve 2/3 the requests they could to anonymous users before they fall over.
Around a year ago, I did comparison benchmarks between Drupal 6 and 7 page caching, and they were within 5% of each other. So some patch in the past year has caused the regression.
Berdir pointed out:
The by far slowest function for me is date_default_timezone_set() with almost 20% of the total time.
That is from this line:
date_default_timezone_set(drupal_get_user_timezone());
And that line was added in this issue: http://drupal.org/node/348448
That looks pretty likely to me. This is the patch that was committed:
http://drupal.org/node/348448#comment-2830898
| Comment | File | Size | Author |
|---|---|---|---|
| #50 | 1064212-cache-empty.patch | 717 bytes | bfroehle |
| #47 | 1064212-cache-empty.patch | 716 bytes | andypost |
| #41 | fix_page_caching.patch | 1.87 KB | catch |
| #24 | fix_page_caching.patch | 1.85 KB | catch |
| #17 | fix_page_caching.patch | 1.33 KB | catch |
Comments
Comment #1
catchMore issues for background:
#668496: Timezone error on D7 install
Most of the discussion happened in:
#325827: Avoid PHP strict timezone warnings by calling date_default_timezone_set in bootstrap
Benchmarks again (different localhost to yesterday):
The timezone stuff is taking about 5ms on my system. That's definitely accounting for part of this if not all.
Attached screenshot showing that.
Looks like we don't really need to call that so early in bootstrap, and could get away with it only happening in full bootstrap, plus a couple of other places (i.e. it'd need to be called before we call strtotime() when serving cached pages, but we only need to do that for requests sending an if modified since header).
Also, looking in strace I can see both system and overlay modules being loaded - these are both bootstrap modules on my install (which is a clean install from just now), definitely weren't in Drupal 6.
You can see the syscalls for the blocked_ips, cache_page db query, and timezone set here, note:
2694 compared to 2790 for pulling the cached database from the database, so that's definitely a significant regression.
Here's another request, not sure what triggers the full lookup, all I did was refresh the browser a couple of times. I've seen this before on full bootstrap in strace, but didn't have time to look into it yet:
Comment #2
catchDocs 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!
Comment #3
catchSo suggestions to fix this:
1. We should not call date_default_timezone_get() until after variable_init() - so that we can load from the database instead of falling back to syscalls.
2. There is absolutely no need for every single request to Drupal 7 that hasn't hardcoded this variable in settings.php to check the operating system timezone. Did it change yet? Did it change again? What about now? Still UTC is it?
3. We should set that variable on install, and add an update. If you move your site to a different server in a different timezone then you might possible find this doesn't get updated, but people will be less likely to move their sites to different servers if we don't completely hobble performance :( Could look at a nested variable_get() for something we can update automatically in drupal_flush_all_caches() - then we could pick up timezone changes ourselves but still allow sites to set it permanently.
4. We still might not want to do any of this in the default page caching workflow, but it looks like the _get() calls that are killing us more than the _set().
Comment #4
Anonymous (not verified) CreditAttribution: Anonymous commentedsubscribe.
Comment #5
droplet CreditAttribution: droplet commentedsubscribe
Comment #6
Crell CreditAttribution: Crell commentedSubscribing. 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.
Comment #7
chx CreditAttribution: chx commentedMeh. If this is so slow , it's hardly our task to fix this, it should be set in php.ini IMO. Also, I have told numerous times that while I agree with notice free, going strict free is a waste of time and effort.
Comment #8
catch@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).
Comment #9
Heine CreditAttribution: Heine commentedI do have date.timezone set.
For my system (Windows 7, MySQL via 127.0.0.1) the largest discrepancy comes form the time it takes to open a db connection.
In d6 this takes about 10% of the cached page request time (of 19 ms), in d7 it takes a whopping 35% (of 37 ms).
Note, this is seperate from the IPv6 issue many people run it to. I'm specifically using an ipv4-address. Using localhost takes > 1 second to wait on the first timeout.
Comment #10
Heine CreditAttribution: Heine commentedWith 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?
Comment #11
jherencia CreditAttribution: jherencia commentedSub.
Comment #12
Damien Tournoud CreditAttribution: Damien Tournoud commentedThe PHP team definitely considers it is a bug not to have a
date.timezoneset.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'.
Comment #13
ogi CreditAttribution: ogi commentedsubscribe
Comment #14
MustangGB CreditAttribution: MustangGB commentedSubscribe
Comment #15
BerdirI was thinking the same as Damien in #12.
The problem is that we are always calling date_default_timezone_get() for the default value, even if it is hardcoded in settings.php. so that really needs to be improved.
@Heine:
I think the connect is using the socket for me and you are going through the IP. That is probably quite a bit slower. Will try to do a test on a clean install (I have tons of contrib modules enabled on the one I did the test) and using 127.0.0.1 instead of localhost as the database host. Another resource I just found mentiones reverse-lookup on the mysql side: http://allurcode.com/2010/04/07/mysql-very-slow-without-a-reason/
Comment #16
catchI 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.
Comment #17
catchOK here's part two:
We've been fetching cache_get('bootstrap_modules', 'cache_bootstrap'); three times instead of once.
system_list() wasn't checking the static cache for bootstrap modules when called with 'bootstrap' argument, I had a root around in git blame and it's been that way since it went in, which suggests it was relying on module_list() to cache properly.
However module_list() doesn't static cache bootstrap modules either.
So, if we change this as well, we're safely over 200 requests per second (range is around 200-240).
This is still about 10% slower than Drupal 6, but getting closer.
Comment #18
catchOpened #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.
Comment #19
Heine CreditAttribution: Heine commentedWith the patch in #17 and my issue in #1064342: Page caching performance II - PDO connection takes a long time worked around I have D7 serving more pages / s from cache then D6. (480 vs. 460, so in the same league).
Comment #20
BerdirOk, trying the patch...
Without patch:
With patch:
Certainly *a lot* faster. I don't quite see the same improvement as catch though.
Comment #21
sunGarbage collection uses db_delete(), should that also be changed into db_query() then?
Might be worth to add a minimal comment to prevent someone from breaking this again in the future.
Powered by Dreditor.
Comment #22
catchHere'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.
Comment #24
catchThis time with the patch.
Comment #25
catchAnd status change, sorry.
Comment #26
Wim LeersSubscribing.
Comment #27
Jeremy CreditAttribution: Jeremy commentedsubscribing
Comment #28
Dries CreditAttribution: Dries commentedIt sounds like the documentation of db_select() needs to be updated to educate people about when to use db_select() vs db_query(). I expect that most people will naturally use db_select() over db_query() while they should be using db_query(). I think this part of the database API might be a bit 'misleading' for those who don't read the fine-print.
In chat, Crell suggested that it may be useful to benchmark different queries in db_query vs db_select, without other stuff around them, to get a sense for how big a difference it is.
Comment #29
Dries CreditAttribution: Dries commentedThis is an important patch so I'm tracking it.
Comment #30
BerdirThere is an issue for that (TM): #835068: Document usage of static vs dynamic queries. I guess the suggested case there needs to be updated with something like "If the query needs to be very fast (eg cache loading), use db_query() also for dynamic queries".
About general performance with db_select/db_query., there are two things:
- Everything that db_select() does is on top of db_query (DatabaseConnection::query() actually). There are multiple classes involved, a lot of string mangling and many many method calls. So it is obviously a lot slower. Some tests might be interesting, I'll see if I can write someting.
- Additionally in this case, it is about using or not using db_select() at all during the whole request. And this means loading includes/databases/select.inc, including includes/database/driver/select.inc if it exists, checking if there is a SelectQuery_driver class and initiate it.
Comment #31
Dries CreditAttribution: Dries commentedThe second bullet of #30 might be worth including in the code comment? Having the rationale makes it easier to understand.
Comment #32
Eric_A CreditAttribution: Eric_A commentedPart of the performance regression was introduced in #978144: cache_get_multiple() inconsistent with cache_get().
Comment #33
catchI'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.
Comment #34
Dries CreditAttribution: Dries commentedRe @catch in #33: OK, I think that is reasonable. Given #978144: cache_get_multiple() inconsistent with cache_get() this fix seems RTBC.
There is only a tiny difference. Original:
New:
But that looks OK.
Comment #35
catchThat's changed to keep this consistent with cache_get_multiple, which is how this regression got in in the first place.
Comment #36
catchOpened #1066752: Page caching performance has regressed by up to 20% with no opcode cache since we're not quite done yet for opcode cache-less hosts.
Comment #37
Crell CreditAttribution: Crell commentedMy 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.
Comment #38
podaroksubscribe
Comment #39
moshe weitzman CreditAttribution: moshe weitzman commentedThis 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
Comment #40
catch@moshe - do you mean db_escape_table()? If so that sounds like a good idea to me, we should benchmark it but I'll be extremely disappointed if that's at all noticeable. That would save adding the comment Crell suggests in #37. Putting this back to CNR since I agree we need to account for this one way or another.
Also on db_select() and drupal_static(). I think the difference is db_select() is really nice, but drupal_static() is a WTF in itself - we shouldn't have added something just to support the testing framework in the first place, and without a clear idea of how we wanted to use it. #581626: Use a consistent/clean pattern for using $reset or drupal_static() is still open. I opened #1067802: Compare $connection->query() and $connection->select() performance to start work on the db_select() vs. db_query() comparison.
Comment #41
catchAdded db_escape_table(). ab is erroring out on my localhost so hoping someone else can do benchmarks.
Comment #42
Dries CreditAttribution: Dries commentedPatch looks good but could use a final benchmark run.
Comment #43
catchHere 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.
Comment #44
podarokproduction site
ab -c5 -n500
w/o patch
w #41 patch
16.4 % speed-up
NICE!!!
ns2# drush pm-list | grep Enabled
Comment #45
moshe weitzman CreditAttribution: moshe weitzman commentedrtbc based on benchmarks
Comment #46
Dries CreditAttribution: Dries commentedCommitted to CVS HEAD. Thanks.
Comment #47
andypostBy 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.
Comment #48
andypostActually this is Major follow-up because default cache implementation is involved in bootstrap so db_select() should not used at all!
Comment #50
bfroehle CreditAttribution: bfroehle commentedMissed a ! here. The test is "isEmpty()", not "isNotEmpty()".
Powered by Dreditor.
Comment #51
moshe weitzman CreditAttribution: moshe weitzman commentedNow the db_select() witchhunt begins. Sigh.
Comment #52
catchWhen do we actually use isEmpty()? It's definitely not on cached pages or I'd have noticed when working on the original patch.
Comment #53
catchIn 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.