From 6a1e3e59cb06b8372be00f9f4277e20d06c9050a Mon Sep 17 00:00:00 2001 From: Aleksey Kladov Date: Wed, 29 May 2019 14:34:21 +0300 Subject: more perf logging --- crates/ra_lsp_server/src/main_loop.rs | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) (limited to 'crates/ra_lsp_server') diff --git a/crates/ra_lsp_server/src/main_loop.rs b/crates/ra_lsp_server/src/main_loop.rs index 87b4e3ac2..16c05e4c3 100644 --- a/crates/ra_lsp_server/src/main_loop.rs +++ b/crates/ra_lsp_server/src/main_loop.rs @@ -170,7 +170,9 @@ fn main_loop_inner( let (libdata_sender, libdata_receiver) = unbounded(); loop { + let _p = profile("loop_turn"); state.maybe_collect_garbage(); + log::trace!("selecting"); let event = select! { recv(msg_receiver) -> msg => match msg { @@ -184,8 +186,11 @@ fn main_loop_inner( }, recv(libdata_receiver) -> data => Event::Lib(data.unwrap()) }; - log::info!("loop_turn = {:?}", event); - let _p = profile("loop_turn"); + log::info!("loop turn = {:?}", event); + let queue_count = pool.queued_count(); + if queue_count > 0 { + log::info!("queued count = {}", queue_count); + } let mut state_changed = false; match event { Event::Task(task) => on_task(task, msg_sender, pending_requests), @@ -468,7 +473,7 @@ impl<'a> PoolDispatcher<'a> { Ok(self) } - fn finish(&mut self) -> ::std::result::Result { + fn finish(&mut self) -> std::result::Result { match (self.res.take(), self.req.take()) { (Some(res), None) => Ok(res), (None, Some(req)) => Err(req), -- cgit v1.2.3 From 118a2113c148ce6806732094c70fb030139b26ac Mon Sep 17 00:00:00 2001 From: Aleksey Kladov Date: Wed, 29 May 2019 14:35:02 +0300 Subject: trigger garbage collection *after* requests, not before --- crates/ra_lsp_server/src/main_loop.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) (limited to 'crates/ra_lsp_server') diff --git a/crates/ra_lsp_server/src/main_loop.rs b/crates/ra_lsp_server/src/main_loop.rs index 16c05e4c3..d406faf6c 100644 --- a/crates/ra_lsp_server/src/main_loop.rs +++ b/crates/ra_lsp_server/src/main_loop.rs @@ -171,7 +171,6 @@ fn main_loop_inner( let (libdata_sender, libdata_receiver) = unbounded(); loop { let _p = profile("loop_turn"); - state.maybe_collect_garbage(); log::trace!("selecting"); let event = select! { @@ -193,13 +192,17 @@ fn main_loop_inner( } let mut state_changed = false; match event { - Event::Task(task) => on_task(task, msg_sender, pending_requests), + Event::Task(task) => { + on_task(task, msg_sender, pending_requests); + state.maybe_collect_garbage(); + } Event::Vfs(task) => { state.vfs.write().handle_task(task); state_changed = true; } Event::Lib(lib) => { state.add_lib(lib); + state.maybe_collect_garbage(); in_flight_libraries -= 1; } Event::Msg(msg) => match msg { -- cgit v1.2.3 From e45c350a3b0ec5b25c23c334e09eba2901adbcd4 Mon Sep 17 00:00:00 2001 From: Aleksey Kladov Date: Wed, 29 May 2019 14:59:01 +0300 Subject: log the actual time of requests --- crates/ra_lsp_server/src/main_loop.rs | 47 +++++++++++++++++++++++------------ 1 file changed, 31 insertions(+), 16 deletions(-) (limited to 'crates/ra_lsp_server') diff --git a/crates/ra_lsp_server/src/main_loop.rs b/crates/ra_lsp_server/src/main_loop.rs index d406faf6c..c3580ab67 100644 --- a/crates/ra_lsp_server/src/main_loop.rs +++ b/crates/ra_lsp_server/src/main_loop.rs @@ -1,7 +1,7 @@ mod handlers; mod subscriptions; -use std::{fmt, path::PathBuf, sync::Arc}; +use std::{fmt, path::PathBuf, sync::Arc, time::Instant}; use crossbeam_channel::{select, unbounded, Receiver, RecvError, Sender}; use failure::{bail, format_err}; @@ -12,7 +12,7 @@ use gen_lsp_server::{ use lsp_types::NumberOrString; use ra_ide_api::{Canceled, FileId, LibraryData}; use ra_vfs::VfsTask; -use rustc_hash::FxHashSet; +use rustc_hash::FxHashMap; use serde::{de::DeserializeOwned, Serialize}; use threadpool::ThreadPool; @@ -82,7 +82,7 @@ pub fn main_loop( log::info!("server initialized, serving requests"); - let mut pending_requests = FxHashSet::default(); + let mut pending_requests = FxHashMap::default(); let mut subs = Subscriptions::new(); let main_res = main_loop_inner( options, @@ -159,7 +159,7 @@ fn main_loop_inner( task_sender: Sender, task_receiver: Receiver, state: &mut ServerWorldState, - pending_requests: &mut FxHashSet, + pending_requests: &mut FxHashMap, subs: &mut Subscriptions, ) -> Result<()> { // We try not to index more than THREADPOOL_SIZE - 3 libraries at the same @@ -170,8 +170,6 @@ fn main_loop_inner( let (libdata_sender, libdata_receiver) = unbounded(); loop { - let _p = profile("loop_turn"); - log::trace!("selecting"); let event = select! { recv(msg_receiver) -> msg => match msg { @@ -185,6 +183,10 @@ fn main_loop_inner( }, recv(libdata_receiver) -> data => Event::Lib(data.unwrap()) }; + // NOTE: don't count blocking select! call as a loop-turn time + let _p = profile("main_loop_inner/loop-turn"); + let loop_start = Instant::now(); + log::info!("loop turn = {:?}", event); let queue_count = pool.queued_count(); if queue_count > 0 { @@ -218,7 +220,14 @@ fn main_loop_inner( msg_sender.send(resp.into()).unwrap() } Err(req) => { - match on_request(state, pending_requests, pool, &task_sender, req)? { + match on_request( + state, + pending_requests, + pool, + &task_sender, + loop_start, + req, + )? { None => (), Some(req) => { log::error!("unknown request: {:?}", req); @@ -280,10 +289,15 @@ fn main_loop_inner( } } -fn on_task(task: Task, msg_sender: &Sender, pending_requests: &mut FxHashSet) { +fn on_task( + task: Task, + msg_sender: &Sender, + pending_requests: &mut FxHashMap, +) { match task { Task::Respond(response) => { - if pending_requests.remove(&response.id) { + if let Some(request_received) = pending_requests.remove(&response.id) { + log::info!("handled req#{} in {:?}", response.id, request_received.elapsed()); msg_sender.send(response.into()).unwrap(); } } @@ -295,9 +309,10 @@ fn on_task(task: Task, msg_sender: &Sender, pending_requests: &mut F fn on_request( world: &mut ServerWorldState, - pending_requests: &mut FxHashSet, + pending_requests: &mut FxHashMap, pool: &ThreadPool, sender: &Sender, + request_received: Instant, req: RawRequest, ) -> Result> { let mut pool_dispatcher = PoolDispatcher { req: Some(req), res: None, pool, world, sender }; @@ -333,8 +348,8 @@ fn on_request( .finish(); match req { Ok(id) => { - let inserted = pending_requests.insert(id); - assert!(inserted, "duplicate request: {}", id); + let prev = pending_requests.insert(id, request_received); + assert!(prev.is_none(), "duplicate request: {}", id); Ok(None) } Err(req) => Ok(Some(req)), @@ -344,7 +359,7 @@ fn on_request( fn on_notification( msg_sender: &Sender, state: &mut ServerWorldState, - pending_requests: &mut FxHashSet, + pending_requests: &mut FxHashMap, subs: &mut Subscriptions, not: RawNotification, ) -> Result<()> { @@ -356,7 +371,7 @@ fn on_notification( panic!("string id's not supported: {:?}", id); } }; - if pending_requests.remove(&id) { + if pending_requests.remove(&id).is_some() { let response = RawResponse::err( id, ErrorCode::RequestCanceled as i32, @@ -434,7 +449,7 @@ impl<'a> PoolDispatcher<'a> { let world = self.world.snapshot(); let sender = self.sender.clone(); self.pool.execute(move || { - let resp = match f(world, params) { + let response = match f(world, params) { Ok(resp) => RawResponse::ok::(id, &resp), Err(e) => match e.downcast::() { Ok(lsp_error) => { @@ -466,7 +481,7 @@ impl<'a> PoolDispatcher<'a> { } }, }; - let task = Task::Respond(resp); + let task = Task::Respond(response); sender.send(task).unwrap(); }); self.res = Some(id); -- cgit v1.2.3