(11:48:55) photomatt: okay, going to flood to catch ryan up :) (11:49:03) photomatt: did you guys see the mysql guy in #wordpress last night? (11:49:03) photomatt: [11:32AM] photomatt: he suggested some really interesting improvements (11:49:03) photomatt: [11:32AM] photomatt: in my tests it took the main post query from 0.12 to 0.05 (11:49:07) photomatt: [11:32AM] photomatt: on average (11:49:09) photomatt: [11:32AM] photomatt: http://p.defau.lt/?tiJutSuV86iBJfUPGq_h0g (11:49:12) photomatt: [11:33AM] photomatt: http://p.defau.lt/?_hp_YagOMRNnFgeXdhpbpw (11:49:14) photomatt: [11:33AM] photomatt: (the second is 4.1 only though) (11:49:33) photomatt: rboren: if we could eliminate the DISTINCT and GROUP BY from post queries that don't need it (11:49:43) photomatt: and add this suggested index (11:49:53) photomatt: (he also suggested making post_type a shorter varchar, maybe 10-20) (11:50:10) photomatt: well, try out the queries, it helps a lot (11:52:51) domas [n=midom@wikipedia/Midom] entered the room. (11:53:00) domas: hello! can I lurk here? :) (11:53:17) photomatt: totally (11:53:43) photomatt: domas is the fellow who suggested the changes I pasted above (11:53:59) domas: did you collect ones that I pasted afterwards in channel? (11:54:16) photomatt: got two from p.defau.lt (11:54:30) rboren: I'm making the following changes: (11:54:31) rboren: http://p.defau.lt/?tiJutSuV86iBJfUPGq_h0g (11:54:47) rboren: And shortening the varchars for post_type and post_status (11:55:06) domas: category query is important too (11:55:14) photomatt: domas: out of curiosity, why is the index in that order? (11:55:24) photomatt: (post_status,post_type,post_date) (11:55:31) domas: photomatt: it could be type,status,date (11:55:39) domas: status,type - for WHERE, date for ORDER BY (11:56:31) domas: maybe you need to add ID there (11:56:44) domas: at the end (11:56:56) domas: (so you could GROUP BY date DESC, ID DESC (11:57:12) domas: of course, if post_date was unique, you could just GROUP BY date (11:57:21) domas: but you'd have to code according to that (11:57:23) photomatt: mysql can only use one key per query? (11:57:38) photomatt: post_date might not be unique (11:57:48) domas: then append ID at the end. (11:58:12) domas: photomatt: not really. mysql in 5.0 can do index merge for multiple keys, but it won't compile a composite key out of separate indexes (11:58:19) domas: (and that would be painful operation anyway) (11:58:30) photomatt: k (11:58:56) domas: composite keys are used everywhere (12:00:40) domas: these two queries: (12:00:40) domas: 66 Query SELECT * FROM wp_categories WHERE cat_ID > 0 HAVING category_count > 0 ORDER BY cat_name asc (12:00:40) domas: 66 Query SELECT * FROM wp_categories WHERE cat_ID > 0 HAVING link_count > 0 ORDER BY cat_name ASC (12:00:55) domas: could possibly be rewritten into link_count>0 or category_count>0 (12:01:21) domas: this one: (12:01:22) domas: 66 Query SELECT COUNT(DISTINCT ID) FROM wp_posts WHERE 1=1 AND (post_type = 'post' AND (post_status = 'publish')) (12:01:30) domas: can be eliminated too, of course :) (12:02:09) domas: I didn't look yet at the object cache code (12:02:31) photomatt: for post queries we also sometimes have "(post_author = 1 AND post_status = 'private'" (12:02:38) photomatt: to get private posts for the current logged in user (12:03:02) photomatt: but that might be a rare enough case that it doesn't need to be optimized for (12:03:15) domas: *nod* (12:03:18) domas: I'm looking at anon hits (12:04:21) photomatt: but it might be easier just to create a separate section in the admin for private posts and leave them out of public listings all-together (12:04:27) photomatt: it's a weird feature anyway (12:04:57) domas: 'cron' and 'rewrite_rules' should go into autoload options :) (12:05:22) domas: as for categories, this seems fun: (12:05:23) domas: 68 Query SELECT * FROM wp_categories (12:05:23) domas: 68 Query SELECT cat_ID FROM wp_categories (12:06:07) domas: btw, for categories, this query is executed twice too: (12:06:08) domas: 68 Query SELECT COUNT(DISTINCT ID) FROM wp_posts LEFT JOIN wp_post2cat ON (wp_posts.ID = wp_post2cat.post_id) WHERE 1=1 AND (category_id = 4) AND (post_type = 'post' AND (post_status = 'publish')) (12:06:53) domas: it's fast enough and using the (`post_status`,`post_type`,`post_date`,`ID`) index, but still :) (12:08:37) MarkJaquith: photomatt: New wp.org/support/ logins don't seem to be syncing with Trac... you aware? (12:08:47) photomatt: yes (12:09:01) photomatt: haven't been since the server move, I'm going to look at it ina bit (12:09:02) MarkJaquith: Cool. I figured it had something to do with the server move or something (12:09:21) domas: for rss feeds: (12:09:21) domas: 70 Query SELECT post_modified_gmt FROM wp_posts WHERE post_status = 'publish' ORDER BY post_modified_gmt DESC LIMIT 1 (12:09:21) domas: 70 Query SELECT post_date_gmt FROM wp_posts WHERE post_status = 'publish' ORDER BY post_date_gmt DESC LIMIT 1 (12:09:29) domas: both fields have no indexes. (12:10:00) domas: so either these values have to be maintained somewhere else (12:10:23) domas: on the second query you may just use post_date (12:10:31) domas: instead of _gmt, as for ordering value should be the same (12:11:03) MarkJaquith: there is an edge case where they aren't... not sure it matters (12:11:22) domas: well, it's rss feed (12:11:43) domas: on every hit to rss feed you order the column again and again. (12:11:49) domas: it's optimized by mysql though (12:11:57) domas: that is, only one row is used for a sort (12:13:38) domas: woo, article view. (12:14:18) domas: the index I created was used again for several queries (12:15:28) MarkJaquith: what'd you index? (12:15:29) domas: comments: (12:15:51) domas: MarkJaquith: on posts: type,status,date,id (12:16:10) domas: now comments ask for this index: postid,approved,date (12:18:13) mdawaffe is now known as mdawaffe|lunch (12:19:37) domas: with this index comments would not be sorted :) (12:19:46) domas: filesorted, just an index range scan (12:20:17) domas: it picks comments_aproved index (12:20:28) domas: I provided a hint to ignore it (12:21:19) domas: http://p.defau.lt/?DRnl1EN_6SB7UhBfgzLdrw (12:21:56) domas: the /*!4000.. specifies that the ignore index clause should be used on 4.0 or newer (12:22:04) domas: I don't remember if 3.23 actually supported IGNORE INDEX :) (12:22:20) photomatt: wow, you weren't kidding about the mysqlisms ;) (12:22:46) domas: well, /* is official SQL comment (12:22:56) domas: so, on any other platform it would not be executed (12:23:01) domas: oracle uses /*+blahblah (12:23:48) photomatt: got it (12:24:11) domas: anyway, on proper deployments you don't need this hint (12:24:22) domas: it's just my test dataset of single article provides skewed view to optimizer (12:24:37) domas: not much of optimizations can be done with single row, can it? :) (12:25:10) MarkJaquith: heh... at least not any that'll add up to what you can do while optimizing one of the posts/category queries (12:25:41) domas: hehe (12:25:51) rboren: FYI: http://trac.wordpress.org/ticket/2604 (12:26:01) domas: well, I did that analysis post on my real dataset (12:26:08) domas: which at least has >20 posts and >20 comments, ha ha ha (12:27:12) BigJibby [n=matt@mtl58-2-131-132.dialup.sprint-canada.net] entered the room. (12:27:17) MarkJaquith: domas: running 1.5.2, right? (12:27:49) domas: MarkJaquith: yessir (12:28:05) MarkJaquith: (just reading your blog post now) (12:28:39) domas: hehe, sorry for sarcasm, it wasn't directed towards any of you, just for general problem of not dealing with performance (12:29:07) domas: I'm doing performance engineering for opensource project, so every time I have to LART people about various issues (12:29:08) MarkJaquith: DISTINCT needs to go away for single-table post queries for sure (12:29:22) domas: MarkJaquith: for multiple-table you'd be better using proper GROUP BY (12:30:13) domas: http://bugs.mysql.com/bug.php?id=18182 <--- this one if fixed would improve your category query performance even more :) (12:30:37) MarkJaquith: "I’d really like if it just used "publish" status for front page and would not care about anything else. " Good news... that's what's happening for 2.1 (12:31:14) domas: hehe, I just looked at our bugs system (12:31:23) domas: I've opened 6 bugs with words 'index' in description :) (12:31:26) domas: *word (12:31:58) MarkJaquith: The hidden benefit there is that you can now cache the queries, because you don't have that dynamic timestamp variable in each query (12:32:13) ***domas enjoys the fading yellow (12:33:24) domas: caching is nice for small sites enjoying lots of reads and no writes (12:33:37) domas: none of sites I work with or clients of mine have such situations :) (12:33:45) photomatt: that's the bulk of WP installations (12:33:58) photomatt: if you think we have perf problems now, you should have seen 0.72 (12:34:00) photomatt: :) (12:34:31) rboren: Not many people were around to witness 0.72 perf problems. :-) (12:34:43) photomatt: I remember doing a profile and finding 60% of our time being spent on convert_char or something like that (12:34:44) domas: haha, I'm fascinated enough to remember mediawiki 1.3/1.4 ;-) (12:35:03) photomatt: which was individually looping over EVERY SINGLE CHARACTER in every post (12:35:04) domas: photomatt: well, an example of badly optimized situation was (12:35:23) domas: when for interwiki prefixes, for every link there was a hit to our memcached cluster (12:35:31) ***MarkJaquith is so glad he only got involved with WordPress right before 1.2 release (12:35:34) domas: and it takes ~2ms each (12:36:08) domas: so it used to spend 50ms or more on fetching absolutely static data (12:36:27) domas: and the interesting part, why it was not noticed (12:36:40) domas: it always was hidden beneath other tasks that appeared 'long' in profiling trees (12:36:52) domas: only proper kcachegrind analysis allowed to track such issues (12:37:12) domas: moral of the story: do not assume the task is slow until you know what is slow in it. (12:37:50) ***ringmaster re-reads the story of MediaWiki innards and impales himself on a fork. (12:37:50) photomatt: what's kcachegrind? (12:38:17) domas: ringmaster: which story? (12:38:26) ringmaster: The one you just told. :) (12:38:51) domas: photomatt: http://dammit.lt/2006/01/18/mediawiki-graphic-profile/ (12:39:03) domas: photomatt: one (two actually) pictures are better than thousand words. (12:39:05) MarkJaquith: domas: in 2.x, WP now stores comment_count in the posts table, as you suggested (still reading!) (12:39:16) photomatt: that's purty (12:39:36) domas: photomatt: I was working on cpu profiling instead of real time profiling (12:39:42) domas: but ditched that for a while (12:39:45) domas: may resume the effort some day (12:45:49) domas: hehe, wanna see a pic of wordpress kcachegrind graph? :) (12:46:01) photomatt: sounds perfect, I'll definitely try to make it (12:46:40) ***MarkJaquith puts his money down on smiley regexes (12:46:44) MarkJaquith: (kidding) (12:46:55) domas: haha, someone asked for that (12:46:59) domas: in mediawiki (12:47:41) photomatt: sure (12:48:15) domas: I hate such features :) (12:48:18) domas: pain to maintain (12:48:22) domas: breaks other syntax (12:48:25) domas: performance hog (12:49:07) MarkJaquith: 1) wait 2) wait 3) wait 4) wait 5) wait 6) wait 7) almost there 8) SUNGLASSES! (12:50:09) photomatt: ha! (12:50:15) photomatt: LOL (12:51:38) domas: ;-D (12:52:49) MarkJaquith: error_bot: google wordpress smilies (12:52:52) error_bot: MarkJaquith: Search took 0.17 seconds: WordPress Smilies [ Tempus Fugit | TxFx.net ]: ; WordPress Smilies: ; Using Smilies « WordPress Codex: (12:53:16) MarkJaquith: (that first result would be mine, domas) (12:55:49) photomatt: domas: would love to see kcachegrind output for WP (12:56:43) domas: photomatt: hehe (12:56:47) domas: ---> Fetching graphviz (12:56:48) domas: ---> Attempting to fetch graphviz-2.6.tar.gz from http://www.graphviz.org/pub/graphviz/ARCHIVE/ (12:56:52) domas: forgot to install some deps before (12:56:55) domas: on this machine (12:57:18) domas: well, I don't have enough data (12:57:23) domas: so the results would be... skewed again :) (12:57:33) domas: oh, downloaded (12:57:52) domas: this LCD compiles things really fast :) (13:00:11) photomatt: oh that's right you still need the dump file (13:00:23) photomatt: rboren: do you still have that giant MT dump I sent you? I can't find it (13:00:34) rboren: Lemme look... (13:03:54) rboren: Found it. (13:04:02) rboren: I'll upload it somewhere... (13:05:31) BigJibby left the room (quit: Read error: 104 (Connection reset by peer)). (13:05:41) domas: compress it too, thanks! (13:11:30) domas: damn, it got mad with wp profile (13:12:12) domas: there's some code that is executed directly via require_once() instead of calling as functions (13:12:40) photomatt: ? (13:15:09) domas: well, the most expensive functions are require_once (13:15:12) domas: and require (13:15:35) domas: instead of loading file with functions and calling them, you execute it directly (13:15:49) domas: so there's no difference between actually loading file and executing code (13:15:50) domas: in the profile (13:16:02) masquerade [n=masquera@c-68-49-145-242.hsd1.de.comcast.net] entered the room. (13:16:05) photomatt: huh (13:16:25) photomatt: well because of the amount of code, we've always suspected that the biggest overhead was simply parsing it all (13:16:31) domas: not really (13:16:33) photomatt: which is why an opcode cache helps so much (13:16:53) domas: but yeah, opcode helps (13:17:56) domas: it spent 5% of real time on mysql ;-D (13:18:44) domas: eh, I can't provide you with a nice graph, just several small ones probably (13:19:57) photomatt: too much junk? (13:20:36) domas: ah, or doesn't show too much (13:20:40) domas: it's much better if interactive (13:20:49) domas: for analysis of details (13:21:23) domas: and maybe xdebug acting funny on this box :( (13:21:31) domas: ok, I'll do one export (13:23:27) domas: http://dammit.lt/wordpress-kcg.png (13:24:08) domas: most of code is hidden in require or require_once calls (13:24:10) domas: :( (13:24:57) photomatt: weird (13:25:05) photomatt: I'm not sure what we're doing that would make it appear so weird (13:25:32) masquerade: Anyone have Zend Studio's Debug Server setup? Its profiling might help out in this case (13:25:50) photomatt: lots of time in load_template, it looks like (13:26:09) MarkJaquith: lot of file_exists calls eh? (13:26:44) domas: you should really move away execution from script loading (13:27:03) photomatt: I still don't understand exactly what you mean by that (13:27:09) domas: require();require(); dothis(); dothat(); (13:27:21) photomatt: oh I see (13:27:29) photomatt: so the action is happening inside the requires (13:27:34) ringmaster: As opposed to require(