very slow for single-letter completions

[dgutov]

very slow for single-letter completions

[Silex]

Ok, I finally had time to test and yes, the problem is gone.

Thank you!

[dgutov]

Completion after [].p in a non-trivial project takes about 200ms on my system, but it's a fairly fast laptop, so yes, I can imagine it taking more time on older systems. It can also be slower if you're using Rubinius. Completion after []. takes about 4 seconds here, which is a lot anyway.

Apparently, Emacs's JSON parser is pretty slow: if I call elp-instrument-package on robe, company, json, then invoke "slow" completion a few times, json-read comes prominently at the top.

Not sure what can be done about this: currently, for each matching method, we send an array [module_name, is_instance_method, method_name, method.parameters]. Guess we could leave out the last element, and look it up whenever required, but that would only speed up parsing by a factor of 2 or so, and the 5-second delay you're seeing won't become instantaneous.

[dgutov]

I guess this problem cannot be really solved, so my suggestion is to maybe turn the completion into something like "here is the list I have so far", which would be updated whenever new results come in.

That would be pretty hard to implement. Neither Company, nor completion-at-point support this mode of results retrieval.

At least make it asynchronous if you can :)

I can, but the Robe server doesn't handle requests in parallel, so you'd be able to fill its queue with requests, ignore the results of most of them in situations similar to this one (because they take so much time to compute), and then wonder why response times overall have increased considerably.

[Silex]

Completion after [].p in a non-trivial project takes about 200ms on my system, but it's a fairly fast laptop, so yes, I can imagine it taking more time on older systems. It can also be slower if you're using Rubinius. Completion after []. takes about 4 seconds here, which is a lot anyway.

Hum, based on this I think there is a problem with my setup. Basically by me it stops on Connecting to 127.0.0.1:9452 for 10 seconds before displaying the results...

Apparently, Emacs's JSON parser is pretty slow: if I call elp-instrument-package on robe, company, json, then invoke "slow" completion a few times, json-read comes prominently at the top.

I'll try this to see what actually happens by me. Thanks for the suggestion.

[Silex]

Ok I did instrument my completions, I have very different results than you:

robe-request                                     19          26.041458698  1.3706030893
robe-retrieve                                    19          25.890648625  1.3626657171
company-idle-begin                               8           14.043747608  1.755468451
company-begin                                    59          14.015611071  0.2375527300
company-call-backend-raw                         569         14.013845551  0.0246289025
company-auto-begin                               8           14.012657918  1.7515822397
company--begin-new                               8           14.012189961  1.7515237452
company-calculate-candidates                     5           14.010776479  2.8021552959
company-robe                                     577         13.996103252  0.0242566780
company--fetch-candidates                        5           13.989843427  2.7979686854
robe-complete-thing                              5           13.989544593  2.7979089186
robe-eldoc                                       13          12.064940485  0.9280723449
robe-jump-modules                                11          12.034309318  1.0940281198
json-read                                        5445        0.4274381570  7.850...e-05
json-read-array                                  1671        0.3327126769  0.0001991099

Something weird happens in robe-request/robe-retrieve, it's way too slow. Any pointers about how to investiguate these?

[dgutov]

What Ruby version is that?

[dgutov]

Any pointers about how to investiguate these?

You can do some benchmarking on the Ruby side. Robe::Sash is the class that handles all requests, you can instantiate it and pass the same arguments directly.

[Silex]

philippe@philippe-desktop:~/work/ $ rvm list 

rvm rubies

=* ruby-2.1.0 [ x86_64 ]

I found out that all the time is spent in url-retrieve-synchronously inside robe-retrieve, playing with url-debug now.

[Silex]

What... the... HELL? it looks like url-retrieve-synchrously also like to fetch old recentf records?

buffer * URL-DEBUG *:

http -> Activating callback in buffer ( *http 127.0.0.1:24969*)
retrieval -> Synchronous fetching done (#<buffer  *http 127.0.0.1:24969*>)
http -> Spinning waiting for headers...
handlers -> Real file-name-nondirectory("http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1") => "?release=12.04+LTS&page=1"
handlers -> Hooked expand-file-name("http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1" nil) => "http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1"
handlers -> Hooked expand-file-name("http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1" nil) => "http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1"
handlers -> Real get-file-buffer("http://www.ubuntu.com/certification/server/make/Dell/?release=12.04+LTS&page=1") => nil
handlers -> Real file-name-nondirectory("http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c") => "xmas.c"
handlers -> Hooked expand-file-name("http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c" nil) => "http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c"
handlers -> Hooked expand-file-name("http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c" nil) => "http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c"
handlers -> Real get-file-buffer("http://www.cise.ufl.edu/~manuel/obfuscate/xmas.c") => nil

[Silex]

Okay, disabled url-handler-mode which seems to get rid of the "recentf" problem.

Now it's still slow and it looks like it does the request multiple times?

http -> Contacting host: 127.0.0.1:24969
http -> Marking connection as busy: 127.0.0.1:24969 #<process 127.0.0.1>
retrieval -> Spinning in url-retrieve-synchronously: nil (#<buffer  *http 127.0.0.1:24969*>)
http -> Request is: 
GET /method_targets/per/%21/PermissionsController/-/-/yes HTTP/1.1
MIME-Version: 1.0
Connection: keep-alive
Extension: Security/Digest Security/SSL
Host: 127.0.0.1:24969
Accept: */*
User-Agent: URL/Emacs


http -> Calling after change function `url-http-wait-for-headers-change-function' for `#<process 127.0.0.1>'
http -> url-http-wait-for-headers-change-function ( *http 127.0.0.1:24969*)
http -> Saw end of headers... ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Got a content-length, being smart about document end.
http -> Calling initial content-length for extra data at end of headers
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> url-http-parse-headers called in ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Parsed HTTP headers: class=2 status=200
http -> Finished parsing HTTP headers: t
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> Activating callback in buffer ( *http 127.0.0.1:24969*)
retrieval -> Synchronous fetching done (#<buffer  *http 127.0.0.1:24969*>)
http -> Spinning waiting for headers...
http -> Contacting host: 127.0.0.1:24969
http -> Marking connection as busy: 127.0.0.1:24969 #<process 127.0.0.1>
retrieval -> Spinning in url-retrieve-synchronously: nil (#<buffer  *http 127.0.0.1:24969*>)
http -> Request is: 
GET /complete_method/perm/%21/PermissionsController/- HTTP/1.1
MIME-Version: 1.0
Connection: keep-alive
Extension: Security/Digest Security/SSL
Host: 127.0.0.1:24969
Accept: */*
User-Agent: URL/Emacs


http -> Contacting host: 127.0.0.1:24969
http -> Marking connection as busy: 127.0.0.1:24969 #<process 127.0.0.1<1>>
retrieval -> Spinning in url-retrieve-synchronously: nil (#<buffer  *http 127.0.0.1:24969*-858424>)
http -> Request is: 
GET /method_targets/perm/%21/PermissionsController/-/-/yes HTTP/1.1
MIME-Version: 1.0
Connection: keep-alive
Extension: Security/Digest Security/SSL
Host: 127.0.0.1:24969
Accept: */*
User-Agent: URL/Emacs


http -> Calling after change function `url-http-wait-for-headers-change-function' for `#<process 127.0.0.1>'
http -> url-http-wait-for-headers-change-function ( *http 127.0.0.1:24969*)
http -> Saw end of headers... ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Got a content-length, being smart about document end.
http -> Calling initial content-length for extra data at end of headers
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> url-http-parse-headers called in ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Parsed HTTP headers: class=2 status=200
http -> Finished parsing HTTP headers: t
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> Activating callback in buffer ( *http 127.0.0.1:24969*)
retrieval -> Synchronous fetching done (#<buffer  *http 127.0.0.1:24969*>)
http -> Spinning waiting for headers...
http -> Calling after change function `url-http-wait-for-headers-change-function' for `#<process 127.0.0.1<1>>'
http -> url-http-wait-for-headers-change-function ( *http 127.0.0.1:24969*-858424)
http -> Saw end of headers... ( *http 127.0.0.1:24969*-858424)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*-858424)
http -> Got a content-length, being smart about document end.
http -> Calling initial content-length for extra data at end of headers
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1<1>>
http -> url-http-parse-headers called in ( *http 127.0.0.1:24969*-858424)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*-858424)
http -> Parsed HTTP headers: class=2 status=200
http -> Finished parsing HTTP headers: t
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1<1>>
http -> Activating callback in buffer ( *http 127.0.0.1:24969*-858424)
retrieval -> Synchronous fetching done (#<buffer  *http 127.0.0.1:24969*-858424>)
http -> Spinning waiting for headers...
http -> Contacting host: 127.0.0.1:24969
http -> Marking connection as busy: 127.0.0.1:24969 #<process 127.0.0.1>
retrieval -> Spinning in url-retrieve-synchronously: nil (#<buffer  *http 127.0.0.1:24969*>)
http -> Request is: 
GET /method_targets/perm/%21/PermissionsController/-/-/yes HTTP/1.1
MIME-Version: 1.0
Connection: keep-alive
Extension: Security/Digest Security/SSL
Host: 127.0.0.1:24969
Accept: */*
User-Agent: URL/Emacs


http -> Calling after change function `url-http-wait-for-headers-change-function' for `#<process 127.0.0.1>'
http -> url-http-wait-for-headers-change-function ( *http 127.0.0.1:24969*)
http -> Saw end of headers... ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Got a content-length, being smart about document end.
http -> Calling initial content-length for extra data at end of headers
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> url-http-parse-headers called in ( *http 127.0.0.1:24969*)
http -> url-http-parse-response called in ( *http 127.0.0.1:24969*)
http -> Parsed HTTP headers: class=2 status=200
http -> Finished parsing HTTP headers: t
http -> Marking connection as free: 127.0.0.1:24969 #<process 127.0.0.1>
http -> Activating callback in buffer ( *http 127.0.0.1:24969*)
retrieval -> Synchronous fetching done (#<buffer  *http 127.0.0.1:24969*>)
http -> Spinning waiting for headers...```

[dgutov]

What... the... HELL? it looks like url-retrieve-synchrously also like to fetch old recentf records?

This looks bizarre, but maybe there's no fetching going on. If you called recentf during that time (by switching buffers, for example), maybe it was just doing what the text says: converting files to maybe-buffers.

Now:

I don't know what to look at here. :(

[Silex]

I don't know what to look at here. :(

That it seems to do several requests just for one completion.

Anyway, I'll try to play with Robe::Sash as you said... but I suspect the offender is really just local http requests being very slow on this machine for a weird reason.

I'll try to make a testcase like this gist https://gist.github.com/arnested/3006911 does, that way we have something easily reproducible/comparable between our machines (btw -nw changes nothing by me) :)

[dgutov]

That it seems to do several requests just for one completion.

There were two requests, that looks normal:

GET /method_targets/per/%21/PermissionsController/-/-/yes HTTP/1.1
...
GET /method_targets/perm/%21/PermissionsController/-/-/yes HTTP/1.1

that way we have something easily reproducible/comparable between our machines

Have you tried this on a new/sample project? It'll be a necessary part of a reproducible recipe.

[Silex]

that way we have something easily reproducible/comparable between our machines

Have you tried this on a new/sample project? It'll be a necessary part of a reproducible recipe.

Yes, of course the testcase will also create a new rails project, probably a new gemset too.

[dgutov]

Just did some measuring. For an empty prefix, I get about 17K completions, and that takes ~3.6 seconds in total.

Of that, ~800ms is spent collecting completions, ~900 serializing to JSON (as long as we just use the built-in JSON package), and the remaining time (1.9s?) on parsing JSON in Emacs.

For one-letter prefix, everything is an order of magnitude faster, though.

[dgutov]

@Silex You can try it again now. c9de1da has evened out a particular pathological case.

[Silex]

@dgutov: I'll try, but I'm pretty swamped atm