{"action":"created","issue":{"url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/4271","labels_url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/4271/labels{/name}","comments_url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/4271/comments","events_url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/4271/events","html_url":"https://github.com/rethinkdb/rethinkdb/issues/4271","id":79702687,"number":4271,"title":"datum_t::get_field() exhibits pathological performance on missing attributes","user":{"login":"bcantrill","id":328614,"avatar_url":"https://avatars.githubusercontent.com/u/328614?v=3","gravatar_id":"","url":"https://api.github.com/users/bcantrill","html_url":"https://github.com/bcantrill","followers_url":"https://api.github.com/users/bcantrill/followers","following_url":"https://api.github.com/users/bcantrill/following{/other_user}","gists_url":"https://api.github.com/users/bcantrill/gists{/gist_id}","starred_url":"https://api.github.com/users/bcantrill/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bcantrill/subscriptions","organizations_url":"https://api.github.com/users/bcantrill/orgs","repos_url":"https://api.github.com/users/bcantrill/repos","events_url":"https://api.github.com/users/bcantrill/events{/privacy}","received_events_url":"https://api.github.com/users/bcantrill/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-05-23T02:54:46Z","updated_at":"2015-05-23T03:11:56Z","closed_at":null,"body":"\r\nI have a database that consists of ~200,000 JSON documents.  I have noticed vast differences on query time depending on the presence of a property.  For example, here is a query that looks for a match on a property named \"node\".  This property is present in all documents, and the filter returns a selection of 116 of them: \r\n\r\n```\r\n$ time rql 'r.table(\"dumps\").filter({\"node\": \"486Y9R1\"}).pluck(\"dump\")'\r\n\r\nreal    0m0.710s\r\nuser    0m0.121s\r\nsys     0m0.051s\r\n```\r\n\r\nConsidering that this property is unindexed, this performance is great.  If, however, the query is on a property that is present in many fewer of the documents, the query time is increased by an order of magnitude.  This is a query of a property that is only present in ~12,000 of the documents: \r\n\r\n```\r\n$ time rql 'r.table(\"dumps\").filter({\"ticket\": \"OS-1028\"}).pluck(\"dump\")'\r\n\r\nreal    0m15.891s\r\nuser    0m0.125s\r\nsys     0m0.054s\r\n```\r\n\r\nAnd if the filter is phrased as a function, the performance degrades by another order of magnitude:\r\n\r\n```\r\n$ time rql 'r.table(\"dumps\").filter(lambda dump: dump[\"ticket\"] == \"OS-1028\").pluck(\"dump\")'\r\n\r\nreal    3m8.122s\r\nuser    0m0.090s\r\nsys     0m0.038s\r\n```\r\n\r\nNote that this cannot simply be explained by the additional overhead of executing an arbitrary function; returning to the first query but rephrasing it in terms of a function results in a much more modest hit: \r\n\r\n```\r\n$ time rql 'r.table(\"dumps\").filter(lambda dump: dump[\"node\"] == \"486Y9R1\").pluck(\"dump\")'\r\n\r\nreal    0m1.314s\r\nuser    0m0.120s\r\nsys     0m0.050s\r\n```\r\n\r\nI am running this on a DTrace-capable Linux platform (namely, a Linux container on [the Triton stack](http://dtrace.org/blogs/bmc/2015/03/24/triton-docker-and-the-best-of-all-worlds/)); looking into this with DTrace reveals that in the most pathological case, we're spending a significant amount of time in vfprintf(): \r\n\r\n```\r\n# dtrace -n profile-1234hz'/arg1 != NULL && execname == \"rethinkdb\"/{@[usym(arg1)] = count()}' -n tick-1sec'/++i == 10/{trunc(@, 30); printa(\"%10@d %A\\n\", @); exit(0)}' -q\r\n       195 libc.so.6`0x7ffffbc86e5f\r\n       210 rethinkdb`0x972d10\r\n       210 rethinkdb`_Z10force_readP13read_stream_tPvl\r\n       220 rethinkdb`_ZN2ql7datum_t14data_wrapper_t11assign_copyERKS1_\r\n       233 rethinkdb`cJSON_CreateStringN\r\n       289 libc.so.6`0x7ffffbc86ea6\r\n       299 rethinkdb`_ZN2ql20datum_get_array_sizeERK16shared_buf_ref_tIcE\r\n       322 libpthread.so.0`__lll_unlock_wake\r\n       325 rethinkdb`_ZN2ql31datum_deserialize_pair_from_bufERK16shared_buf_ref_tIcEm\r\n       328 rethinkdb`_ZNK2ql7datum_t11as_json_rawEv\r\n       369 libc.so.6`__printf_fp\r\n       382 libpthread.so.0`pthread_mutex_unlock\r\n       417 libc.so.6`0x7ffffbc724a8\r\n       436 libc.so.6`0x7ffffbc724f8\r\n       438 libc.so.6`0x7ffffbc724b7\r\n       449 libc.so.6`0x7ffffbc724f0\r\n       466 rethinkdb`_ZN2ql26datum_deserialize_from_bufERK16shared_buf_ref_tIcEm\r\n       480 libstdc++.so.6`__gxx_personality_v0\r\n       487 libpthread.so.0`__lll_lock_wait\r\n       559 rethinkdb`_ZN2ql24datum_get_element_offsetERK16shared_buf_ref_tIcEm\r\n       583 rethinkdb`_ZN2ql7datum_t14data_wrapper_t8destructEv\r\n       637 libc.so.6`0x7ffffbc86ea2\r\n       642 libpthread.so.0`pthread_mutex_lock\r\n       841 rethinkdb`_ZNK14datum_string_t4sizeEv\r\n       861 libc.so.6`strlen\r\n      1068 libc.so.6`0x7ffffbc724a0\r\n      1443 libc.so.6`_IO_default_xsputn\r\n      1652 rethinkdb`malloc\r\n      1666 rethinkdb`free\r\n      2408 libc.so.6`vfprintf\r\n```\r\n\r\nHere's where those calls are coming from:\r\n\r\n```\r\n# dtrace -n pid14912::vfprintf:entry'{@[usym(ucaller)] = count()}'\r\ndtrace: description 'pid14912::vfprintf:entry' matched 2 probes\r\n^C\r\n\r\n  libc.so.6`__vsnprintf_chk                                    142145\r\n  libc.so.6`__vasprintf_chk                                    370300\r\n```\r\n\r\nDigging into where these are coming from:\r\n\r\n```\r\n#pragma D option strsize=128\r\n\r\npid$target::__vsnprintf_chk:entry\r\n{\r\n\tself->buf = arg0;\r\n}\r\n\r\npid$target::__vsnprintf_chk:return\r\n/self->buf/\r\n{\r\n\t@[copyinstr(self->buf)] = count();\r\n\tself->buf = NULL;\r\n}\r\n\r\nEND\r\n{\r\n\ttrunc(@, 10);\r\n}\r\n```\r\n\r\nHere's the output running for a few seconds on the pathological query:\r\n\r\n```\r\n$ dtrace -s ./re-snprintf.d -p 14912\r\ndtrace: script './re.d' matched 3 probes\r\n^C\r\nCPU     ID                    FUNCTION:NAME\r\n  2      2                             :END \r\n\r\n  No attribute `ticket` in object:\r\n{\r\n\t\"cmd\":\t\"zabbix_sender\",\r\n\t\"dump\":\t\"/thoth/stor/thoth/b811bc0736b2cf885d700ec47d33821f/core.z               28\r\n  No attribute `ticket` in object:\r\n{\r\n\t\"cmd\":\t\"zabbix_sender\",\r\n\t\"dump\":\t\"/thoth/stor/thoth/b86a105f641545827b96ade8977c8753/core.z               28\r\n  No attribute `ticket` in object:\r\n{\r\n\t\"cmd\":\t\"zdb\",\r\n\t\"dump\":\t\"/thoth/stor/thoth/b795da70280bccb539826e4555ce1354/core.zdb.87172\",               28\r\n  No attribute `ticket` in object:\r\n{\r\n\t\"cmd\":\t\"zdb\",\r\n\t\"dump\":\t\"/thoth/stor/thoth/b890ccbbd943a35c76753f3f5c4c049c/core.zdb.54093\",               28\r\n  No attribute `ticket` in object:\r\n{\r\n\t\"dump\":\t\"/thoth/stor/thoth/b80c1a837b2faf8ae44b5e77dda9831e/vmcore.0\",\r\n\t\"id\":\t\"b80c1a837b2f               28\r\n  Evaluating pluck.                                                40\r\n  Evaluating bracket.                                          175367\r\n  Evaluating EQ.                                               175368\r\n  Evaluating var.                                              175407\r\n  Evaluating datum.                                            185719\r\n```\r\n\r\nIf it isn't clear, the objects themselves that lack the specified property are clearly be snprintf()'d in a human-readable way!  Looking for the \"No attribute\" string in the source reveals the source: \r\n\r\n```\r\ndatum_t datum_t::get_field(const datum_string_t &key, throw_bool_t throw_bool) const {\r\n    // Use binary search on top of unchecked_get_pair()\r\n    size_t range_beg = 0;\r\n    // The obj_size() also makes sure that this has the right type (R_OBJECT)\r\n    size_t range_end = obj_size();\r\n    while (range_beg < range_end) {\r\n        const size_t center = range_beg + ((range_end - range_beg) / 2);\r\n        auto center_pair = unchecked_get_pair(center);\r\n        const int cmp = key.compare(center_pair.first);\r\n        if (cmp == 0) {\r\n            // Found it\r\n            return center_pair.second;\r\n        } else if (cmp < 0) {\r\n            range_end = center;\r\n        } else {\r\n            range_beg = center + 1;\r\n        }\r\n        rassert(range_beg <= range_end);\r\n    }\r\n\r\n    // Didn't find it\r\n    if (throw_bool == THROW) {\r\n        rfail(base_exc_t::NON_EXISTENCE,\r\n              \"No attribute `%s` in object:\\n%s\", key.to_std().c_str(), print().c_str());\r\n    }\r\n    return datum_t();\r\n}\r\n```\r\n\r\nHere's a script which explores the amount of time we're actually spending in datum_t::get_field() for missing properties:\r\n\r\n```\r\n#pragma D option quiet\r\n\r\nBEGIN\r\n{\r\n\tstart = timestamp;\r\n}\r\n\r\npid$target::_ZNK2ql7datum_t9get_fieldERK14datum_string_tNS_12throw_bool_tE:entry\r\n{\r\n\tself->ts = vtimestamp;\r\n\t@ttl = count();\r\n}\r\n\r\npid$target::__cxa_throw:entry\r\n/self->ts/\r\n{\r\n\t@missing = sum(vtimestamp - self->ts);\r\n\t@ttlmissing = count();\r\n\tself->ts = 0;\r\n}\r\n\r\npid$target::_ZNK2ql7datum_t9get_fieldERK14datum_string_tNS_12throw_bool_tE:return\r\n/self->ts/\r\n{\r\n\t@found = sum(vtimestamp - self->ts);\r\n\t@ttlfound = count();\r\n\tself->ts = 0;\r\n}\r\n\r\nsched:::on-cpu\r\n/pid == $target/\r\n{\r\n\tself->on = vtimestamp;\r\n}\r\n\r\nsched:::off-cpu\r\n/pid == $target && self->on/\r\n{\r\n\t@alltime = sum(vtimestamp - self->on);\r\n}\r\n\r\ntick-100ms\r\n/timestamp - start > 60 * 1000000000/\r\n{\r\n\tnormalize(@found, 1000000);\r\n\tnormalize(@missing, 1000000);\r\n\tnormalize(@alltime, 1000000);\r\n\r\n\tprintf(\"%10d => wall clock ms\\n\", (timestamp - start) / 1000000);\r\n\tprinta(\"%10@d => total CPU ms\\n\\n\", @alltime);\r\n\tprinta(\"%10@d => total calls to datum_t::get_field()\\n\", @ttl);\r\n\tprinta(\"%10@d => calls on found attributes\\n\", @ttlfound);\r\n\tprinta(\"%10@d => calls on missing attributes\\n\\n\", @ttlmissing);\r\n\tprinta(\"%10@d => total CPU ms on found attributes\\n\", @found);\r\n\tprinta(\"%10@d => total CPU ms on missing attributes\\n\", @missing);\r\n\texit(0);\r\n}\r\n```\r\n\r\nRunning this for one of the (several) minutes that the pathological query is running yields:\r\n\r\n```\r\n     60081 => wall clock ms\r\n    239799 => total CPU ms\r\n\r\n    316125 => total calls to datum_t::get_field()\r\n     19194 => calls on found attributes\r\n    296931 => calls on missing attributes\r\n\r\n       103 => total CPU ms on found attributes\r\n    112481 => total CPU ms on missing attributes\r\n```\r\n\r\nThis is telling us that at least half of our CPU time is being spent in datum_t::get_field() on missing attributes -- with a whopping ~380 usecs per call.  Further, it seems quite possible (if not likely) that the other half of our CPU time is being spent on the mechanics of throwing and then (presumably) discarding the exception.  It seems at the very, very least datum_t::get_field() should not be printing an entire verbatim, human-readable copy of the object before it throws that an attribute is missing.  Beyond that, it seems likely that performance could be substantially improved by using (or introducing, as necessary) a method that would get a property without throwing an exception on its absence (that is, returning failure instead of throwing an exception).  \r\n"},"comment":{"url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/comments/104823654","html_url":"https://github.com/rethinkdb/rethinkdb/issues/4271#issuecomment-104823654","issue_url":"https://api.github.com/repos/rethinkdb/rethinkdb/issues/4271","id":104823654,"user":{"login":"timmaxw","id":316661,"avatar_url":"https://avatars.githubusercontent.com/u/316661?v=3","gravatar_id":"","url":"https://api.github.com/users/timmaxw","html_url":"https://github.com/timmaxw","followers_url":"https://api.github.com/users/timmaxw/followers","following_url":"https://api.github.com/users/timmaxw/following{/other_user}","gists_url":"https://api.github.com/users/timmaxw/gists{/gist_id}","starred_url":"https://api.github.com/users/timmaxw/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/timmaxw/subscriptions","organizations_url":"https://api.github.com/users/timmaxw/orgs","repos_url":"https://api.github.com/users/timmaxw/repos","events_url":"https://api.github.com/users/timmaxw/events{/privacy}","received_events_url":"https://api.github.com/users/timmaxw/received_events","type":"User","site_admin":false},"created_at":"2015-05-23T03:11:56Z","updated_at":"2015-05-23T03:11:56Z","body":"Hi @bcantrill. Sorry you ran into this issue, and thanks for the detailed analysis. It looks like there are two separate issues here: the fact that we're formatting the document for every failed lookup, and the fact that we're using C++ exceptions to represent ReQL exceptions. The former issue is relatively easy to fix, but the latter would require more work. @mlucy @danielmewes, any thoughts?"}}