| commit | 585c60e84d56034e5c0f18377269b356427862cb | |
| author | Lucian Wischik <ljw@fb.com> | |
| Tue, 10 Apr 2018 16:45:15 +0000 (10 09:45 -0700) | ||
| committer | Hhvm Bot <hhvm-bot@users.noreply.github.com> | |
| Tue, 10 Apr 2018 16:47:21 +0000 (10 09:47 -0700) | ||
| tree | c5896357b67a15fc3d774f39f737b0deaef58634 | treesnapshot (tar.gz zip) |
| parent | ea06f00924d92670d41ad2296b26a86084210d98 | commitdiff |
LSP has better definition for time_taken logging
Summary:
`queue_time_taken` - this has always measured the time from when the message first arrived from the editor, until when a response was delivered back. This was and remains a good and useful metric.
`time_taken` - prior to this diff, it measured from when we started to wait for an incoming request from the editor, until a response was sent back. This is obviously no use. Who cares how long we were waiting for an incoming request from the editor? And why include a measure that unpredictably includes when hh_server is busy on some work (from a previous request from external clients or watchman) but not on other work (from a previous request from clientLsp)?
I've changed it so that `time_taken` measures how long from when we were "unblocked to handle the request" until when a response was delivered to the editor. What does it mean "unblocked to handle the message" -- it means after an incoming request has arrived from the editor, and after clientLsp's message-loop is in a fit state to handle it after finishing handling all prior rpc calls to hh_server, and after hh_server's message-loop is in a fit state to handle it after all prior rpc calls from other clients and all typechecking work.
Now with this diff, I expect that for LSP methods that are just thin shims around a server RPC call, then the `time_taken` we record here will be just about identical to the `time_taken` that the server already records in its HANDLED_COMMAND event...
So why go to all this work to record the number? (1) I think it's easier to analyze data if a single event CLIENT_LSP_METHOD shows both queue time before the request was handled, and time to handle the request. (2) If clientLsp-side handling is adding lots of overhead, we'll see that here. (3) For editor requests like Formatting and Outline, which bypass the server, we'll still get a meaningful answer.
Reviewed By: arxanas
Differential Revision: D7378532
fbshipit-source-id: c9e6b51308112902b047b13f1a179f1d381ad8cb
Summary:
`queue_time_taken` - this has always measured the time from when the message first arrived from the editor, until when a response was delivered back. This was and remains a good and useful metric.
`time_taken` - prior to this diff, it measured from when we started to wait for an incoming request from the editor, until a response was sent back. This is obviously no use. Who cares how long we were waiting for an incoming request from the editor? And why include a measure that unpredictably includes when hh_server is busy on some work (from a previous request from external clients or watchman) but not on other work (from a previous request from clientLsp)?
I've changed it so that `time_taken` measures how long from when we were "unblocked to handle the request" until when a response was delivered to the editor. What does it mean "unblocked to handle the message" -- it means after an incoming request has arrived from the editor, and after clientLsp's message-loop is in a fit state to handle it after finishing handling all prior rpc calls to hh_server, and after hh_server's message-loop is in a fit state to handle it after all prior rpc calls from other clients and all typechecking work.
Now with this diff, I expect that for LSP methods that are just thin shims around a server RPC call, then the `time_taken` we record here will be just about identical to the `time_taken` that the server already records in its HANDLED_COMMAND event...
So why go to all this work to record the number? (1) I think it's easier to analyze data if a single event CLIENT_LSP_METHOD shows both queue time before the request was handled, and time to handle the request. (2) If clientLsp-side handling is adding lots of overhead, we'll see that here. (3) For editor requests like Formatting and Outline, which bypass the server, we'll still get a meaningful answer.
Reviewed By: arxanas
Differential Revision: D7378532
fbshipit-source-id: c9e6b51308112902b047b13f1a179f1d381ad8cb