{"action":"created","issue":{"url":"https://api.github.com/repos/ocaml/merlin/issues/779","repository_url":"https://api.github.com/repos/ocaml/merlin","labels_url":"https://api.github.com/repos/ocaml/merlin/issues/779/labels{/name}","comments_url":"https://api.github.com/repos/ocaml/merlin/issues/779/comments","events_url":"https://api.github.com/repos/ocaml/merlin/issues/779/events","html_url":"https://github.com/ocaml/merlin/issues/779","id":293980170,"number":779,"title":"Large v3 performance regression (and proposed solutions)","user":{"login":"arxanas","id":454057,"avatar_url":"https://avatars3.githubusercontent.com/u/454057?v=4","gravatar_id":"","url":"https://api.github.com/users/arxanas","html_url":"https://github.com/arxanas","followers_url":"https://api.github.com/users/arxanas/followers","following_url":"https://api.github.com/users/arxanas/following{/other_user}","gists_url":"https://api.github.com/users/arxanas/gists{/gist_id}","starred_url":"https://api.github.com/users/arxanas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/arxanas/subscriptions","organizations_url":"https://api.github.com/users/arxanas/orgs","repos_url":"https://api.github.com/users/arxanas/repos","events_url":"https://api.github.com/users/arxanas/events{/privacy}","received_events_url":"https://api.github.com/users/arxanas/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-02-02T18:25:21Z","updated_at":"2018-02-09T07:51:10Z","closed_at":null,"author_association":"NONE","body":"At Facebook, we upgraded to Merlin 3, but encountered a huge performance regression in doing so. To typecheck https://github.com/facebook/hhvm/blob/master/hphp/hack/src/typing/typing.ml went from ~2s to ~6s. I timed how long it took to typecheck this file for each previous version of Merlin and tracked down two commits, each of which increase the typechecking time by about 2s each.\r\n\r\nThe commits are b4ce455 (~2s -> ~4s) and 68a0095 (~4s -> ~6s).\r\n\r\n[You can see the raw timing data here](https://gist.github.com/arxanas/17eb45513f66ad10afbf609864a0b2f9). Each line is the commit hash followed by the benchmarked total elapsed time, generated with `/usr/bin/time ./ocamlmerlin single errors -filename /path/to/typing.ml </path/to/typing.ml`. I double-checked around the problematic commits in question, and ran the timing several times, but there's no question that these two commits are the causes. It is possible that my use of `ocamlmerlin single` is not representative of typical IDE use, though.\r\n\r\nWhy do these commits cause performance regressions? Here's my analysis of the first problematic commit. I didn't look into the second commit very much.\r\n\r\nHere's a profile from `perf` before b4ce455:\r\n\r\n```\r\n24.09%  ocamlmerlin-ser  [kernel.vmlinux]    [k] __d_lookup_rcu\r\n 6.65%  ocamlmerlin-ser  [kernel.vmlinux]    [k] avc_has_perm_noaudit\r\n 6.50%  ocamlmerlin-ser  [kernel.vmlinux]    [k] selinux_inode_permission\r\n 5.94%  ocamlmerlin-ser  [kernel.vmlinux]    [k] link_path_walk\r\n 3.90%  ocamlmerlin-ser  [kernel.vmlinux]    [k] lookup_fast\r\n 3.39%  ocamlmerlin-ser  [kernel.vmlinux]    [k] walk_component\r\n 2.31%  ocamlmerlin-ser  [kernel.vmlinux]    [k] generic_permission\r\n 2.02%  ocamlmerlin-ser  [kernel.vmlinux]    [k] security_inode_permission\r\n 1.97%  ocamlmerlin-ser  [kernel.vmlinux]    [k] inode_permission\r\n 1.95%  ocamlmerlin-ser  [kernel.vmlinux]    [k] __inode_permission\r\n 1.95%  ocamlmerlin-ser  [kernel.vmlinux]    [k] strncpy_from_user\r\n 1.81%  ocamlmerlin-ser  libc-2.17.so        [.] _int_malloc\r\n 1.64%  ocamlmerlin-ser  [kernel.vmlinux]    [k] creds_are_invalid\r\n 1.64%  ocamlmerlin-ser  [kernel.vmlinux]    [k] in_group_p\r\n 1.49%  ocamlmerlin-ser  libc-2.17.so        [.] __memmove_ssse3_back\r\n 1.43%  ocamlmerlin-ser  [kernel.vmlinux]    [k] do_syscall_64\r\n 1.30%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlFilename__concat_1330\r\n 1.11%  ocamlmerlin-ser  libc-2.17.so        [.] __xstat64\r\n 1.06%  ocamlmerlin-ser  ocamlmerlin-server  [.] mark_slice\r\n 1.05%  ocamlmerlin-ser  libc-2.17.so        [.] __memcpy_ssse3_back\r\n 0.99%  ocamlmerlin-ser  libc-2.17.so        [.] __strlen_sse2_pminub\r\n 0.96%  ocamlmerlin-ser  [kernel.vmlinux]    [k] avc_has_perm_flags\r\n 0.90%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_alloc_string\r\n 0.82%  ocamlmerlin-ser  libc-2.17.so        [.] _int_free\r\n 0.82%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlPervasives__$5e_1117\r\n 0.78%  ocamlmerlin-ser  ocamlmerlin-server  [.] sweep_slice\r\n 0.72%  ocamlmerlin-ser  [kernel.vmlinux]    [k] security_inode_getattr\r\n 0.59%  ocamlmerlin-ser  [kernel.vmlinux]    [k] selinux_is_enabled\r\n 0.50%  ocamlmerlin-ser  [kernel.vmlinux]    [k] kmem_cache_alloc\r\n```\r\n\r\nAs you can see, much of the time is spent on the filesystem. Commit b4ce455 intends to add a layer of caching for the filesystem. But does it improve performance? Here's the output from `time` for the first bad commit:\r\n\r\n```\r\n2.46user 1.41system 0:03.91elapsed 99%CPU (0avgtext+0avgdata 149596maxresident)k\r\n1608inputs+0outputs (0major+36902minor)pagefaults 0swaps\r\n```\r\n\r\nAnd here's the output from `time` for the last good commit:\r\n\r\n```\r\n0.42user 1.70system 0:02.13elapsed 99%CPU (0avgtext+0avgdata 51024maxresident)k\r\n0inputs+0outputs (0major+12068minor)pagefaults 0swaps\r\n```\r\n\r\nSo we did reduce system time by a little bit (-0.3s), but dramatically increased CPU time (+2s). Presumably your results will vary depending on what type of system you have; in our case, we use SSDs for our development work, so filesystem access may be faster than whatever this commit was tested on.\r\n\r\nWhy did this happen? Let's look at the `perf` profile:\r\n\r\nHere's the `perf` profile:\r\n\r\n```\r\n10.97%  ocamlmerlin-ser  [kernel.vmlinux]    [k] __d_lookup_rcu\r\n 7.45%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlString__needs_escape_1313\r\n 7.15%  ocamlmerlin-ser  ocamlmerlin-server  [.] mark_slice\r\n 5.61%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlHashtbl__find_1406\r\n 4.05%  ocamlmerlin-ser  ocamlmerlin-server  [.] compare_val\r\n 3.89%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_hash_mix_string\r\n 3.26%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_page_table_lookup\r\n 3.22%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_string_length\r\n 2.89%  ocamlmerlin-ser  [kernel.vmlinux]    [k] selinux_inode_permission\r\n 2.84%  ocamlmerlin-ser  libc-2.17.so        [.] __memmove_ssse3_back\r\n 2.81%  ocamlmerlin-ser  ocamlmerlin-server  [.] sweep_slice\r\n 2.36%  ocamlmerlin-ser  [kernel.vmlinux]    [k] avc_has_perm_noaudit\r\n 2.09%  ocamlmerlin-ser  [kernel.vmlinux]    [k] link_path_walk\r\n 1.83%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_hash\r\n 1.80%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlFilename__concat_1330\r\n 1.74%  ocamlmerlin-ser  libc-2.17.so        [.] __memcmp_sse4_1\r\n 1.48%  ocamlmerlin-ser  [kernel.vmlinux]    [k] lookup_fast\r\n 1.21%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_fl_allocate\r\n 1.19%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlHashtbl__insert_bucket_1368\r\n 1.11%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_oldify_one\r\n 1.01%  ocamlmerlin-ser  [kernel.vmlinux]    [k] walk_component\r\n 0.98%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_alloc_string\r\n 0.97%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlFilename__is_dir_sep_1247\r\n 0.93%  ocamlmerlin-ser  [kernel.vmlinux]    [k] inode_permission\r\n 0.70%  ocamlmerlin-ser  [kernel.vmlinux]    [k] __inode_permission\r\n 0.69%  ocamlmerlin-ser  [kernel.vmlinux]    [k] generic_permission\r\n 0.63%  ocamlmerlin-ser  [kernel.vmlinux]    [k] strncpy_from_user\r\n 0.59%  ocamlmerlin-ser  [kernel.vmlinux]    [k] do_syscall_64\r\n 0.58%  ocamlmerlin-ser  [kernel.vmlinux]    [k] clear_page_c_e\r\n 0.58%  ocamlmerlin-ser  libc-2.17.so        [.] _int_malloc\r\n 0.57%  ocamlmerlin-ser  [kernel.vmlinux]    [k] security_inode_permission\r\n 0.56%  ocamlmerlin-ser  [kernel.vmlinux]    [k] in_group_p\r\n 0.54%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlCamlinternalFormat__strput_acc_64848\r\n 0.54%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_modify\r\n 0.52%  ocamlmerlin-ser  ocamlmerlin-server  [.] caml_apply2\r\n 0.50%  ocamlmerlin-ser  ocamlmerlin-server  [.] camlFilename__base_1238\r\n```\r\n\r\nWe're spending a tad less time on filesystem-related functions, but a lot more time in the garbage collector, hashing strings, and manipulating strings (such as with `Filename.concat`). After looking at this for a while, my conclusion is that these strings are the filenames that we're using as cache keys, and operations like `Filename.basename`, `Filename.dirname`, and `Filename.concat` are being called too often and causing serious memory pressure and using a lot of CPU time. This may not manifest in a smaller codebase, but we do have a few hundred or thousand OCaml files in the repo, and their paths are on the order of 100 characters long.\r\n\r\nI'm not exactly sure what the second commit does, but it looks like it's related to filesystem operations as well.\r\n\r\nWhat can we do about it? Some solutions:\r\n\r\n* **Revert the two commits**. This works in my testing and drops the benchmark time back down to 2s.\r\n* **Opt out of these behaviors using per-project configuration**. I couldn't figure out how to implement this. In particular, simply changing the file caching strategy from `Stat_dir_cache` to `Stat_fs` everywhere did not seem to affect the performance, and I didn't understand why.\r\n* **Switch to using a faster filename manipulation implementation**, to reduce memory pressure and speed up common operations like basename, dirname, and concat, as well as hashing. One can envision a structure where each component of the path is stored in a (persistent) linked list, and to manipulate these we need only push/pop things onto the linked list or append two linked lists. Since we can reuse most of the linked list nodes, and don't have to allocate more strings for these operations, it should reduce CPU time and memory pressure significantly. We can also store the hash alongside this structure to make hashing operations fast."},"comment":{"url":"https://api.github.com/repos/ocaml/merlin/issues/comments/364360593","html_url":"https://github.com/ocaml/merlin/issues/779#issuecomment-364360593","issue_url":"https://api.github.com/repos/ocaml/merlin/issues/779","id":364360593,"user":{"login":"let-def","id":1048096,"avatar_url":"https://avatars2.githubusercontent.com/u/1048096?v=4","gravatar_id":"","url":"https://api.github.com/users/let-def","html_url":"https://github.com/let-def","followers_url":"https://api.github.com/users/let-def/followers","following_url":"https://api.github.com/users/let-def/following{/other_user}","gists_url":"https://api.github.com/users/let-def/gists{/gist_id}","starred_url":"https://api.github.com/users/let-def/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/let-def/subscriptions","organizations_url":"https://api.github.com/users/let-def/orgs","repos_url":"https://api.github.com/users/let-def/repos","events_url":"https://api.github.com/users/let-def/events{/privacy}","received_events_url":"https://api.github.com/users/let-def/received_events","type":"User","site_admin":false},"created_at":"2018-02-09T07:51:10Z","updated_at":"2018-02-09T07:51:10Z","author_association":"CONTRIBUTOR","body":"I encountered this issue. I should be able to fix it (btw the stat cache was added for people running large repository over nfs, where stat was significantly more expensive), however I don't have much time these days.\r\n\r\nSorry for that, and I am very grateful you took time to make a detailed bug report."}}
{"actor":{"display_login":"let-def"}}