{"id":698,"date":"2011-02-21T10:55:40","date_gmt":"2011-02-21T18:55:40","guid":{"rendered":"http:\/\/www.visophyte.org\/blog\/?p=698"},"modified":"2011-02-22T20:35:49","modified_gmt":"2011-02-23T04:35:49","slug":"why-so-slow-pushlog","status":"publish","type":"post","link":"https:\/\/www.visophyte.org\/blog\/2011\/02\/21\/why-so-slow-pushlog\/","title":{"rendered":"why so slow, pushlog?"},"content":{"rendered":"

I am doing something where I need to talk to the Mozilla hg pushlog. \u00a0I noticed things were running disturbingly slow, so I figured I’d look into it. \u00a0I’m using node.js so htracr<\/a> (a node.js<\/a>, libpcap<\/a>-based via node_pcap<\/a> http transaction visualizer) seemed like the easiest and most fun way to figure out what is going on. \u00a0(In a web browser I would just use the built-in timeline.)<\/p>\n

\"\"<\/a><\/p>\n

\"\"<\/a>

slooooooooooow...<\/p><\/div>\n

The short request is a comm-central pushlog request by date. \u00a0The long request is a mozilla-central pushlog request by date. \u00a0mozilla-central has more pushes, suggesting that the query is either doing something sketchy like a table scan or there is lock contention. \u00a0Quick investigation showed no successful pushes in the given timeframe, eliminating lock contention from the likely list of causes. \u00a0(The implementation uses SQLite, which, when not running with the Write-Ahead-Log enabled, will only experience contention when the reads are occurring from separate connections.)<\/p>\n

This suggests the query is doing a table scan. \u00a0This tends to be a reasonably straightforward problem. \u00a0But since I have a SQLite opcode visualizer in my toolkit (now on github<\/a>!) that needs plugs periodically to keep it on the tip of everyone’s tongue, I used that<\/a>. Plug! Plug! Plug!<\/a><\/p>\n

If you care about these kind of things, click on the small image on the left and look for the red text. \u00a0The giant warning flag is the “Rewind” on the changesets table and the control flow that performs a “Next” \u00a0that appears to be part of a loop case right off the bat. \u00a0(Note that this is using SQLite 3.6.23.1 since I assume that’s what hg.mozilla.org is using.) \u00a0Summary: we perform one table scan of the changesets<\/em> table for every push in the date range.<\/p>\n

The “bad” schema is:<\/p>\n

CREATE TABLE changesets (pushid INTEGER, rev INTEGER, node text);\r\nCREATE TABLE pushlog (id INTEGER PRIMARY KEY AUTOINCREMENT, user TEXT, date INTEGER);\r\nCREATE UNIQUE INDEX changeset_node ON changesets (node);\r\nCREATE UNIQUE INDEX changeset_rev ON changesets (rev);\r\nCREATE INDEX pushlog_date ON pushlog (date);\r\nCREATE INDEX pushlog_user ON pushlog (user)<\/pre>\n
The query is: SELECT id, user, date, node from pushlog LEFT JOIN changesets ON id = pushid WHERE date > 1298306930 AND date < 1298306955 ORDER BY id DESC, rev DESC;<\/p>\n
The query plan via EXPLAIN QUERY PLAN from SQLite 3.6.23.1 on the “bad” schema is:<\/p>\n
0|0|TABLE pushlog WITH INDEX pushlog_date\r\n1|1|TABLE changesets<\/pre>\n
This is obvious if you know what you’re looking for; unfortunately the indication of the problem is the lack of “WITH INDEX” or the like rather than text that calls out the problem.  The much nicer SQLite 3.7.4 EXPLAIN QUERY PLAN (which has great documentation<\/a>!) would make the problem much more obvious by saying “SCAN TABLE” if not for the fact that it ends up creating an automatic index:<\/p>\n
0|0|0|SEARCH TABLE pushlog USING INDEX pushlog_date (date>? AND date<?) (~110000 rows)\r\n0|1|1|SEARCH TABLE changesets USING AUTOMATIC COVERING INDEX (pushid=?) (~7 rows)\r\n0|0|0|USE TEMP B-TREE FOR ORDER BY<\/pre>\n
Although one table scan accompanied by a b-tree building is probably a better idea than N table scans, if you read this and think “SQLite 3.7.x just saved someone’s bacon”, you would be wrong because it still throws away the index at the end. \u00a0The server is still experiencing an initial vicious kick in the pants every time the statement is run; there are just no lighter follow-up kicks (lighter because of the OS disk cache, you see…).<\/p>\n
\"\"<\/a>In any event, the problem is that there is no index on the pushid<\/em> column in the changesets<\/em> table.\u00a0 (And pushid can’t be the primary key because it is not unique.\u00a0 There’s no benefit to using a composite key since SQLite will still create a simple rowid key once we use a composite, so an index is the way to go.)<\/p>\n
Once we fix this, our graph looks like the second one at left (in SQLite 3.6.23.1). \u00a0Again, looking for red text and now also orange text, the key things are that we no longer have a “Rewind” or “Next”, and instead have a SeekGe on the index and a Seek on the table using the row id the index told us about.\u00a0 (We are not using a covering index because we expect extremely high locality in the table based on rowid because the insertions happen consecutively in a single transaction.)<\/p>\n
The 3.6.23.1 query plan now looks like:<\/p>\n
0|0|TABLE pushlog WITH INDEX pushlog_date\r\n1|1|TABLE changesets WITH INDEX changeset_pushid<\/pre>\n
Much nicer!  What does the lovely 3.7.4 say?:<\/p>\n
0|0|0|SEARCH TABLE pushlog USING INDEX pushlog_date (date>? AND date<?) (~110000 rows)\r\n0|1|1|SEARCH TABLE changesets USING INDEX changeset_pushid (pushid=?) (~10 rows)\r\n0|0|0|USE TEMP B-TREE FOR ORDER BY<\/pre>\n
Awww yeah.  Anywho, here’s the schema one wants to use:<\/p>\n
CREATE TABLE changesets (pushid INTEGER, rev INTEGER, node text);\r\nCREATE TABLE pushlog (id INTEGER PRIMARY KEY AUTOINCREMENT, user TEXT, date INTEGER);\r\nCREATE INDEX changeset_pushid ON changesets (pushid);<\/strong>\r\nCREATE UNIQUE INDEX changeset_node ON changesets (node);\r\nCREATE UNIQUE INDEX changeset_rev ON changesets (rev);\r\nCREATE INDEX pushlog_date ON pushlog (date);\r\nCREATE INDEX pushlog_user ON pushlog (user);<\/pre>\n
I am off to file this as a bug… filed as bug 635765<\/a>.<\/p>\n
UPDATE: <\/strong>I initially had a brain glitch where I proposed using a primary key rather than an additional index.\u00a0 Unfortunately, this is what got pushed out to feed readers during the 30 seconds before I realized my massive mistake.\u00a0 If you have come to this page to note the bad-idea-ness of that, please enjoy the corrected blog-post which explains why the primary key is not the best idea before going on to point out any other serious brain glitches \ud83d\ude42<\/p>\n
UPDATE 2<\/strong> (Feb 22, 2011): \u00a0Good news: the change has landed and all the existing databases have been updated. \u00a0Woo! \u00a0Bad news: although things are probably faster now, things are still way too slow. \u00a0(Given that this specific deficiency was determined by inspection and not actual profiling, this is not so surprising.) \u00a0It would appear that the retrieval of the information about the changesets is the cause of the slowdown. \u00a0More inspection on my part suggests that populating the list of tags may be involved, but that’s just a quick guess. \u00a0Please follow the bug or follow-on bugs if you want to witness the entire exciting saga.<\/p>\n","protected":false},"excerpt":{"rendered":"
I am doing something where I need to talk to the Mozilla hg pushlog. \u00a0I noticed things were running disturbingly slow, so I figured I’d look into it. \u00a0I’m using node.js so htracr (a node.js, libpcap-based via node_pcap http transaction … Continue reading →<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"inline_featured_image":false,"footnotes":""},"categories":[7,4],"tags":[24],"class_list":["post-698","post","type-post","status-publish","format-standard","hentry","category-debugging","category-visualizing","tag-sqlite"],"_links":{"self":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/698","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/comments?post=698"}],"version-history":[{"count":17,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/698\/revisions"}],"predecessor-version":[{"id":714,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/698\/revisions\/714"}],"wp:attachment":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/media?parent=698"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/categories?post=698"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/tags?post=698"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}