Add Language Server benchmarking tool (#3578)

This commit is contained in:
Dmitry Bushev 2022-07-22 17:12:52 +03:00 committed by GitHub
parent be311457bd
commit 0701e762ea
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
28 changed files with 1158 additions and 11 deletions

1
.gitignore vendored
View File

@ -147,3 +147,4 @@ test-results
*.ir
*.meta
.enso/

View File

@ -295,6 +295,7 @@
- [Replace `this` with `self`][3524]
- [Introduce a smaller version of the standard library, just for testing][3531]
- [Remove `here` and make method name resolution case-sensitive][3531]
- [Added benchmarking tool for the language server][3578]
[3227]: https://github.com/enso-org/enso/pull/3227
[3248]: https://github.com/enso-org/enso/pull/3248
@ -328,6 +329,7 @@
[3531]: https://github.com/enso-org/enso/pull/3531
[3562]: https://github.com/enso-org/enso/pull/3562
[3538]: https://github.com/enso-org/enso/pull/3538
[3578]: https://github.com/enso-org/enso/pull/3578
# Enso 2.0.0-alpha.18 (2021-10-12)

91
Cargo.lock generated
View File

@ -1666,9 +1666,9 @@ checksum = "4bb454f0228b18c7f4c3b0ebbee346ed9c52e7443b0999cd543ff3571205701d"
[[package]]
name = "either"
version = "1.6.1"
version = "1.7.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e78d4f1cc4ae33bbfc157ed5d5a5ef3bc29227303d595861deb238fcec4e9457"
checksum = "3f107b87b6afc2a64fd13cac55fe06d6c8859f12d4b14cbcdd2c67d0976781be"
[[package]]
name = "enclose"
@ -3693,7 +3693,7 @@ version = "1.4.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "5617e92fc2f2501c3e2bc6ce547cad841adba2bae5b921c7e52510beca6d084c"
dependencies = [
"base64 0.11.0",
"base64 0.13.0",
"bytes 1.1.0",
"http",
"httpdate 1.0.2",
@ -4232,6 +4232,19 @@ dependencies = [
"value-bag",
]
[[package]]
name = "logstat"
version = "0.1.0"
dependencies = [
"clap 3.1.18",
"enso-prelude",
"lazy_static",
"regex",
"time 0.3.9",
"tokio 1.19.2",
"tokio-stream",
]
[[package]]
name = "matchers"
version = "0.1.0"
@ -5561,9 +5574,9 @@ dependencies = [
[[package]]
name = "regex"
version = "1.5.6"
version = "1.6.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d83f127d94bdbcda4c8cc2e50f6f84f4b611f69c902699ca385a39c3a75f9ff1"
checksum = "4c4eb3267174b8c6c2f654116623910a0fef09c4753f8dd83db29c48a0df988b"
dependencies = [
"aho-corasick",
"memchr",
@ -5581,9 +5594,9 @@ dependencies = [
[[package]]
name = "regex-syntax"
version = "0.6.26"
version = "0.6.27"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "49b3de9ec5dc0a3417da371aab17d729997c15010e7fd24ff707773a33bddb64"
checksum = "a3f87b73ce11b1619a3c6332f45341e0047173771e8b8b73f87bfeefb7b56244"
[[package]]
name = "remove_dir_all"
@ -6572,6 +6585,16 @@ dependencies = [
"syn",
]
[[package]]
name = "tokio-native-tls"
version = "0.3.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f7d995660bd2b7f8c1568414c1126076c13fbb725c40112dc0120b78eb9b717b"
dependencies = [
"native-tls",
"tokio 1.19.2",
]
[[package]]
name = "tokio-reactor"
version = "0.1.12"
@ -6615,9 +6638,9 @@ dependencies = [
[[package]]
name = "tokio-stream"
version = "0.1.8"
version = "0.1.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "50145484efff8818b5ccd256697f36863f587da82cf8b409c53adf1e840798e3"
checksum = "df54d54117d6fdc4e4fea40fe1e4e566b3505700e148a6827e59b34b0d2600d9"
dependencies = [
"futures-core",
"pin-project-lite 0.2.9",
@ -7289,6 +7312,39 @@ dependencies = [
"url 1.7.2",
]
[[package]]
name = "websocket-codec"
version = "0.5.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "72154d7f42457a99b2832ff093a22a6b303d88c6fe87ca975515cc6c7bc8d21d"
dependencies = [
"base64 0.13.0",
"byteorder",
"bytes 1.1.0",
"httparse",
"rand 0.8.5",
"sha1 0.6.1",
"tokio-util 0.7.2",
]
[[package]]
name = "websocket-lite"
version = "0.5.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "44a2fea74fd5c7e2720dfd619bf029b46acef012cc619793d6d76d29c0ba8c14"
dependencies = [
"base64 0.13.0",
"bytes 1.1.0",
"futures 0.3.21",
"native-tls",
"rand 0.8.5",
"tokio 1.19.2",
"tokio-native-tls",
"tokio-util 0.7.2",
"url 2.2.2",
"websocket-codec",
]
[[package]]
name = "welcome-screen"
version = "0.1.0"
@ -7464,6 +7520,23 @@ dependencies = [
"winapi-build",
]
[[package]]
name = "wstest"
version = "0.1.0"
dependencies = [
"base64 0.13.0",
"clap 3.1.18",
"either",
"enso-prelude",
"futures 0.3.21",
"regex",
"time 0.3.9",
"tokio 1.19.2",
"tokio-stream",
"url 2.2.2",
"websocket-lite",
]
[[package]]
name = "xattr"
version = "0.2.3"

View File

@ -12,7 +12,9 @@ members = [
"lib/rust/parser/src/syntax/tree/visitor",
"lib/rust/parser/generate-java",
"lib/rust/profiler/data",
"integration-test"
"integration-test",
"tools/language-server/logstat",
"tools/language-server/wstest"
]
# The default memebers are those we want to check and test by default.
default-members = ["app/gui", "lib/rust/*"]

View File

@ -1,6 +1,6 @@
# Options intended to be common for all developers.
wasm-size-limit: 5.16 MiB
wasm-size-limit: 5.17 MiB
required-versions:
cargo-watch: ^8.1.1

View File

@ -0,0 +1,14 @@
[package]
name = "logstat"
version = "0.1.0"
authors = ["Enso Team <contact@enso.org>"]
edition = "2021"
[dependencies]
clap = { version = "3", features = ["derive"] }
lazy_static = "1.4.0"
enso-prelude = { path = "../../../lib/rust/prelude" }
regex = "1.6.0"
time = { version = "0.3", features = ["formatting", "parsing"] }
tokio = { version = "1", features = ["full"] }
tokio-stream = { version = "0.1.9", features = ["io-util"] }

View File

@ -0,0 +1,9 @@
# logstat
The tool for analyzing performance from the logs output. It takes the log file
and the specification file containing the log entries to look for. Then it can
extract the operations from logs and calculate the durations and averages of
each operation.
Logstat is supposed to be used together with `wstest` tool. Take a look at
`wstest/benchmarks` directory of example usages.

View File

@ -0,0 +1,7 @@
[org.enso.jsonrpc.JsonRpcServer] Received text message: { "jsonrpc": "2.0", "method": "text/applyEdit"
[org.enso.languageserver.protocol.json.JsonConnectionController] received handled Request(ApplyEdit
[org.enso.languageserver.runtime.RuntimeConnector] received handled Request(None,EditFileNotification
[enso] Executing command: EditFileCmd...
[enso] Job EnsureCompiledJob finished
[enso] Visualisation computed
[org.enso.languageserver.runtime.ContextRegistry] received handled VisualisationUpdate

View File

@ -0,0 +1,7 @@
[org.enso.jsonrpc.JsonRpcServer] Received text message: { "jsonrpc": "2.0", "method": "text/applyExpressionValue"
[org.enso.languageserver.protocol.json.JsonConnectionController] received handled Request(ApplyExpressionValue
[org.enso.languageserver.runtime.RuntimeConnector] received handled Request(None,SetExpressionValueNotification
[enso] Executing command: SetExpressionValueCmd
[enso] Job EnsureCompiledJob finished
[enso] Visualisation computed
[org.enso.languageserver.runtime.ContextRegistry] received handled VisualisationUpdate

View File

@ -0,0 +1,373 @@
//! The crate provides an executable for collecting the performance statistics by analyzing the
//! log files.
// === Standard Linter Configuration ===
#![deny(non_ascii_idents)]
#![warn(unsafe_code)]
// === Non-Standard Linter Configuration ===
#![warn(missing_docs)]
#![warn(trivial_casts)]
#![warn(trivial_numeric_casts)]
#![warn(unused_import_braces)]
#![warn(unused_qualifications)]
#![warn(missing_copy_implementations)]
#![warn(missing_debug_implementations)]
use enso_prelude::*;
use clap::Parser;
use clap::ValueHint;
use lazy_static::lazy_static;
use regex::Regex;
use std::fmt;
use std::io::Result;
use std::path::PathBuf;
use std::process;
use time::format_description::well_known::Rfc3339;
use time::Duration;
use time::OffsetDateTime;
use tokio::fs::File;
use tokio::io::AsyncBufReadExt;
use tokio::io::BufReader;
use tokio_stream::wrappers::LinesStream;
use tokio_stream::StreamExt;
// =====================
// === CLI Arguments ===
// =====================
#[derive(Parser, Debug)]
#[clap(version, about)]
struct Args {
/// Logfile to analyze.
#[clap(value_name = "FILE", value_hint = ValueHint::FilePath)]
log: PathBuf,
/// Specification file.
#[clap(long, value_name = "FILE", value_hint = ValueHint::FilePath)]
spec: PathBuf,
/// Wstest log file.
#[clap(long, value_name = "FILE", value_hint = ValueHint::FilePath)]
wstest_log: Option<PathBuf>,
/// Number of iterations to skip.
#[clap(long, default_value = "0")]
skip_iterations: usize,
/// Calculate median instead of mean.
#[clap(long)]
median: bool,
}
// =========================
// === Log Specification ===
// =========================
/// A specification containing lines to lookup in the log file.
#[derive(Debug)]
struct Spec {
matches: Vec<String>,
}
// =================
// === Operation ===
// =================
/// Timed operation.
#[derive(Debug)]
struct Operation {
duration: Duration,
timestamp: OffsetDateTime,
line: String,
}
impl Display for Operation {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
let duration_millis = self.duration.whole_milliseconds();
let timestamp = self.timestamp.format(&Rfc3339).unwrap();
let truncated_line = self.line.chars().take(80).collect::<String>();
write!(f, "{}ms [{}] {}...", duration_millis, timestamp, truncated_line)
}
}
// =================
// === Iteration ===
// =================
/// Single iteration containing multiple sub-operations.
#[derive(Debug)]
struct Iteration {
pub operations: Vec<Operation>,
}
impl Iteration {
pub fn total_time(&self) -> Duration {
let mut total: Duration = Duration::ZERO;
for operation in &self.operations {
total += operation.duration
}
total
}
}
// ==================
// === Statistics ===
// ==================
/// Final statistics about benchmarked operation.
#[derive(Debug)]
struct Stats {
min: Duration,
max: Duration,
avg: Duration,
line: String,
}
impl Display for Stats {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
let avg_millis = self.avg.whole_milliseconds();
let min_millis = self.min.whole_milliseconds();
let max_millis = self.max.whole_milliseconds();
let truncated_line = self.line.chars().take(80).collect::<String>();
write!(f, "{avg_millis}ms [{min_millis}..{max_millis}] {truncated_line}")
}
}
// =================
// === Constants ===
// =================
/// First operation of Wstest sequence of operations.
static WSTEST_FIRST_OPERATION: usize = 1;
/// Capture group containing the timestamp part of the log line.
static RE_LOGLINE_TIMESTAMP_CAPTURE_GROUP: usize = 2;
/// Capture group containing the message part of the log line
static RE_LOGLINE_MESSAGE_CAPTURE_GROUP: usize = 3;
lazy_static! {
/// Regex for parsing the log line.
static ref RE_LOGLINE: Regex = Regex::new(r"\[([\w]+)\] \[([\w\d:.-]+)\] (.*)").unwrap();
/// Specification for the log file produced by the wstest tool.
static ref WSTEST_SPEC: Spec = Spec {
matches: vec![
"wstest sent bench request".to_string(),
"wstest handled response".to_string(),
],
};
}
// =================
// === Utilities ===
// =================
/// Read the file with specification.
async fn read_specs(path: &PathBuf) -> Result<Spec> {
let file = File::open(path).await?;
let lines_reader = BufReader::new(file).lines();
let matches = LinesStream::new(lines_reader).collect::<Result<Vec<_>>>().await?;
Ok(Spec { matches })
}
/// Extract the iterations information from logfile according to the provided spec.
async fn read_logfile(path: &PathBuf, spec: &Spec) -> Result<Vec<Iteration>> {
let file = File::open(path).await?;
let mut lines = BufReader::new(file).lines();
let mut iterations = vec![];
let mut current_operations = vec![];
let mut matches = spec.matches.iter();
let mut current_match = matches.next().expect("Empty spec!");
while let Some(line) = lines.next_line().await? {
if let Some(cap) = RE_LOGLINE.captures(line.as_str()) {
let groups = (
cap.get(RE_LOGLINE_TIMESTAMP_CAPTURE_GROUP),
cap.get(RE_LOGLINE_MESSAGE_CAPTURE_GROUP),
);
match groups {
(Some(timestamp), Some(message)) =>
if message.as_str().contains(current_match) {
let duration = Duration::ZERO;
let timestamp =
OffsetDateTime::parse(timestamp.as_str(), &Rfc3339).unwrap();
let line = message.as_str().to_string();
current_operations.push(Operation { duration, timestamp, line });
if let Some(m) = matches.next() {
current_match = m
} else {
matches = spec.matches.iter();
current_match = matches.next().expect("Empty spec!");
iterations.push(Iteration { operations: current_operations });
current_operations = vec![];
}
},
_ => {
eprintln!("[ERR] Invalid log line [{}]", line);
}
}
}
}
Ok(iterations)
}
/// Calcualte median of values.
fn median<I>(durations_iter: I) -> Duration
where I: Iterator<Item = Duration> {
let mut durations = durations_iter.collect::<Vec<_>>();
durations.sort();
let mid = durations.len() / 2;
if durations.len() % 2 == 0 {
(durations[mid - 1] + durations[mid]) / 2
} else {
durations[mid]
}
}
/// Merge iterations from two log files.
///
/// Function insert operations from logfile after the first operation of wstest tool.
fn merge_iterations(ws_iterations: &mut [Iteration], log_iterations: Vec<Iteration>) {
log_iterations.into_iter().zip(ws_iterations.iter_mut()).for_each(|(log_iter, ws_iter)| {
ws_iter
.operations
.splice(WSTEST_FIRST_OPERATION..WSTEST_FIRST_OPERATION, log_iter.operations);
});
}
/// Calculate operation durations for each benchmark iteration.
fn calculate_durations(iterations: &mut Vec<Iteration>) {
for iteration in iterations {
let mut timestamp = OffsetDateTime::UNIX_EPOCH;
for mut op in iteration.operations.iter_mut() {
if timestamp == OffsetDateTime::UNIX_EPOCH {
timestamp = op.timestamp
}
op.duration = op.timestamp - timestamp;
timestamp = op.timestamp;
}
}
}
/// Analyze benchmark results.
fn analyze_iterations(iterations: &[Iteration], use_median: bool) -> Vec<Stats> {
let iterations_len = iterations.len();
let operations_len = iterations.first().unwrap().operations.len();
let mut stats = (0..operations_len)
.map(|operation_index| {
let current_line = &iterations[0].operations[operation_index].line;
let durations = iterations.iter().map(|it| it.operations[operation_index].duration);
let min = durations.clone().min().unwrap_or(Duration::ZERO);
let max = durations.clone().max().unwrap_or(Duration::ZERO);
let avg = if use_median {
median(durations)
} else {
durations.sum::<Duration>() / iterations_len as u32
};
let line = current_line.to_string();
Stats { min, max, avg, line }
})
.collect_vec();
let overall_stats = iterations_average(iterations, &stats);
stats.push(overall_stats);
stats
}
/// Calculate the average of all iterations.
fn iterations_average(ops: &[Iteration], stats: &[Stats]) -> Stats {
let min_opt = ops.iter().map(|o| o.total_time()).min();
let max_opt = ops.iter().map(|o| o.total_time()).max();
let min = min_opt.unwrap_or(Duration::ZERO);
let max = max_opt.unwrap_or(Duration::ZERO);
let avg = stats.iter().map(|s| s.avg).sum();
let line = String::from("Total");
Stats { min, max, avg, line }
}
// ============
// === Main ===
// ============
#[tokio::main]
async fn main() -> Result<()> {
let args = Args::parse();
let spec = read_specs(&args.spec).await?;
let log_iterations = read_logfile(&args.log, &spec).await?;
let mut iterations = if let Some(path_buf) = args.wstest_log {
let mut ws_iterations = read_logfile(&path_buf, &WSTEST_SPEC).await?;
// skip warmup iterations
let start_time = &ws_iterations[0].operations[0].timestamp;
let log_iterations_without_warmup = log_iterations
.into_iter()
.skip_while(|iteration| {
let first_operation = &iteration.operations[0];
&first_operation.timestamp < start_time
})
.collect_vec();
if ws_iterations.len() != log_iterations_without_warmup.len() {
eprintln!(
"[ERR] Unequal number of benchmark iterations in log files! [{}] vs. [{}]",
ws_iterations.len(),
log_iterations_without_warmup.len()
);
process::exit(1);
}
merge_iterations(&mut ws_iterations, log_iterations_without_warmup);
ws_iterations
} else {
log_iterations
};
// cleanup iterations info before analyzing
iterations.drain(..args.skip_iterations);
calculate_durations(&mut iterations);
let stats = analyze_iterations(&iterations, args.median);
println!("avg [min..max] (of {} records)", iterations.len());
for s in &stats {
println!("{}", s);
}
Ok(())
}

View File

@ -0,0 +1,18 @@
[package]
name = "wstest"
version = "0.1.0"
authors = ["Enso Team <contact@enso.org>"]
edition = "2021"
[dependencies]
base64 = "0.13.0"
clap = { version = "3", features = ["derive"] }
either = "1.7.0"
futures = "0.3"
enso-prelude = { path = "../../../lib/rust/prelude" }
regex = "1.6.0"
time = { version = "0.3", features = ["formatting"] }
tokio = { version = "1.19.2", features = ["full"] }
tokio-stream = { version = "0.1.9", features = ["io-util"] }
url = "2.2"
websocket-lite = "0.5"

View File

@ -0,0 +1,7 @@
# wstest
A tool for benchmarking the language server by sending a specified sequence of
requests and waiting for expected responses. The results then can be analyzed
with the `logstat` tool.
See `benchmarks` directory for examples.

View File

@ -0,0 +1,69 @@
# set-expression-value
Benchmark for command that applies text edit. It sends the `text/applyEdit`
message and waits for the visualization message on binary WebSocket.
## Run
Build Enso distribution.
```bash
sbt buildEngineDistribution
```
Start the Language Server and redirect ouput to `language-server.log`
```bash
built-distribution/enso-engine-0.0.0-dev-linux-amd64/enso-0.0.0-dev/bin/enso \
--log-level trace \
--server \
--root-id 6f7d58dd-8ee8-44cf-9ab7-9f0454033641 \
--path $(pwd)/tools/language-server/wstest/benchmarks/apply-edit/Unnamed/ \
--rpc-port 30616 \
--data-port 30717 \
2>&1| tee language-server.log
```
Run the test and redirect output to `wstest.log`
```bash
cargo run -p wstest -- \
--binary-socket ws://127.0.0.1:30717 \
--init-binary-socket tools/language-server/wstest/benchmarks/apply-edit/init.bin \
--init-text-socket tools/language-server/wstest/benchmarks/apply-edit/init.txt \
--wait-after-init 10000 \
--ignore-text-socket-responses tools/language-server/wstest/benchmarks/apply-edit/ignore_responses.txt \
--input tools/language-server/wstest/benchmarks/apply-edit/input.txt \
--input-expects-binary-responses \
--warmup-iterations 100 \
--wait-after-warmup 3000 \
--benchmark-iterations 100 \
ws://127.0.0.1:30616 \
2>&1| tee wstest.log
```
Analyze logs
```bash
cargo run -p logstat -- \
--median \
--spec tools/language-server/logstat/apply-edit-spec.txt \
--wstest-log wstest.log
language-server.log
```
Example output
```text
avg [min..max] (of 100 records)
0ms [0..0] [main] wstest sent bench request [{ "jsonrpc": "2.0", "method": "text/applyEdit"
0ms [0..3] [org.enso.jsonrpc.JsonRpcServer] Received text message: { "jsonrpc": "2.0", "met
0ms [0..1] [org.enso.languageserver.protocol.json.JsonConnectionController] received handle
1ms [0..2] [org.enso.languageserver.runtime.RuntimeConnector] received handled Request(None
0ms [0..1] [enso] Executing command: EditFileCmd...
14ms [11..24] [enso] Job EnsureCompiledJob finished in 23 ms.
1ms [1..9] [enso] Visualisation computed 524dd815-b652-4bbe-b9f2-26b35d17993a.
0ms [0..1] [org.enso.languageserver.runtime.ContextRegistry] received handled Visualisation
0ms [0..1] [main] wstest handled response [<binary>]
17ms [15..33] Total
```

View File

@ -0,0 +1,7 @@
name: Unnamed
namespace: local
version: 0.0.1
license: ""
authors: []
maintainers: []
prefer-local-libraries: true

View File

@ -0,0 +1,13 @@
from Standard.Base import all
import Standard.Visualization
main =
variable = 8
IO.println variable
#### METADATA ####
[[{"index":{"value":5},"size":{"value":8}},"30e01fad-128e-4b5a-a22c-bd3b21252fd9"],[{"index":{"value":13},"size":{"value":1}},"f868fa0b-1802-450e-85d5-f1577643a1f4"],[{"index":{"value":14},"size":{"value":4}},"18565040-ef59-4267-ace8-048560f4086e"],[{"index":{"value":26},"size":{"value":3}},"4ecc4b5b-d5d2-446f-bcd5-fada2e48a042"],[{"index":{"value":0},"size":{"value":29}},"31fe4373-eee6-450d-a0ea-2bfff9d0d7b5"],[{"index":{"value":37},"size":{"value":8}},"718ff7cf-19c4-4f41-91a9-d2ff4221d5c2"],[{"index":{"value":45},"size":{"value":1}},"b794d41d-4007-44a7-8427-15fff08df9dd"],[{"index":{"value":46},"size":{"value":13}},"564816d2-b2cd-4504-a9e6-1062351887a0"],[{"index":{"value":30},"size":{"value":29}},"47952db2-9f21-4ee3-9ac6-53606eab1e03"],[{"index":{"value":61},"size":{"value":4}},"236aa79f-56e1-42f9-8bcb-99b1c2576719"],[{"index":{"value":66},"size":{"value":1}},"14539f71-fe59-41cc-9424-e18d5beb45d2"],[{"index":{"value":72},"size":{"value":8}},"cbe6ef7b-564e-44f4-87bc-51f277d48387"],[{"index":{"value":81},"size":{"value":1}},"2e69d11c-c79b-449a-ab7c-f08b698ad605"],[{"index":{"value":83},"size":{"value":1}},"524dd815-b652-4bbe-b9f2-26b35d17993a"],[{"index":{"value":72},"size":{"value":12}},"8740a5e4-cfb3-449b-958f-d2dd967642a5"],[{"index":{"value":89},"size":{"value":2}},"05a391e1-465a-4518-9f4f-3bde0cfd619e"],[{"index":{"value":91},"size":{"value":1}},"f61cf1f6-d89a-46da-85e3-74991abe9b82"],[{"index":{"value":92},"size":{"value":7}},"34887a2b-d4f9-413d-b11d-b339cf6c79f0"],[{"index":{"value":89},"size":{"value":10}},"734641cf-d983-4609-80aa-897ce2641ba4"],[{"index":{"value":100},"size":{"value":8}},"446d7d7d-599d-4207-878a-749862460884"],[{"index":{"value":89},"size":{"value":19}},"74ce36e2-e27c-44c1-90f1-faee61a1def2"],[{"index":{"value":67},"size":{"value":43}},"f6c651d5-bb31-48fb-9bc6-2eb373b00e43"],[{"index":{"value":61},"size":{"value":49}},"3b84a460-cddd-47ce-97d9-c94ccda80343"]]
{"ide":{"node":{"524dd815-b652-4bbe-b9f2-26b35d17993a":{"position":{"vector":[-100.0,140.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":{"name":{"content":{"content":"JSON"}},"project":"Builtin"}},"74ce36e2-e27c-44c1-90f1-faee61a1def2":{"position":{"vector":[-100.0,80.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":null}},"project":null}}

View File

@ -0,0 +1,4 @@
"jsonrpc":"2.0","id":5,"result":null
"method":"file/rootAdded"
"method":"executionContext/expressionUpdates"
"jsonrpc":"2.0","id":7,"result":null

View File

@ -0,0 +1 @@
EAAAAAwAHgAIAAAABwAYAAwAAAAAAAABnt62wJU/S4ceSD2b5jWEaAwAAAAAAAYAFAAEAAYAAAD/PR80J3cGoXxKagLysxqu

View File

@ -0,0 +1,5 @@
t|{ "jsonrpc": "2.0", "method": "session/initProtocolConnection", "id": 0, "params": { "clientId": "ae1ab3f2-026a-4a7c-a106-7727341f3dff" } }
t|{"jsonrpc":"2.0","id":1,"method":"text/openFile","params":{"path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}}}
t|{"jsonrpc":"2.0","id":3,"method":"executionContext/create","params":{"contextId":"1949b079-81e2-46b7-91be-5c5072aaba12"}}
t|{"jsonrpc":"2.0","id":5,"method":"executionContext/push","params":{"contextId":"1949b079-81e2-46b7-91be-5c5072aaba12","stackItem":{"methodPointer":{"definedOnType":"local.Unnamed.Main","module":"local.Unnamed.Main","name":"main"},"positionalArgumentsExpressions":[],"thisArgumentExpression":null,"type":"ExplicitCall"}}}
b|{"jsonrpc": "2.0", "id": 7, "method": "executionContext/attachVisualisation", "params": { "expressionId": "524dd815-b652-4bbe-b9f2-26b35d17993a", "visualisationConfig": { "executionContextId": "1949b079-81e2-46b7-91be-5c5072aaba12", "expression": "x -> x.to_text", "visualisationModule": "local.Unnamed.Main" }, "visualisationId": "a1cced79-1e4b-47f6-a85d-73f766325372" } }

View File

@ -0,0 +1,2 @@
{ "jsonrpc": "2.0", "method": "text/applyEdit", "id": 0, "params": { "edit": { "path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}, "edits":[{"range":{"start":{"line":4,"character":4},"end":{"line":4,"character":16}}, "text":"variable = 9"}], "oldVersion":"e980e79db6f43cfb85f74b642a5df42b46ff6827ae191e2551d82456", "newVersion":"6dea845964972ebdceccc36e3d4605324fc54bde40709e5d35c1a93e" } } }
{ "jsonrpc": "2.0", "method": "text/applyEdit", "id": 0, "params": { "edit": { "path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}, "edits":[{"range":{"start":{"line":4,"character":4},"end":{"line":4,"character":16}}, "text":"variable = 8"}], "oldVersion":"6dea845964972ebdceccc36e3d4605324fc54bde40709e5d35c1a93e", "newVersion":"e980e79db6f43cfb85f74b642a5df42b46ff6827ae191e2551d82456" } } }

View File

@ -0,0 +1,70 @@
# set-expression-value
Benchmark for command that sets the expression value. It sends the
`text/applyExpressionValue` command and waits for the visualization message on
binary WebSocket.
## Run
Build Enso distribution.
```bash
sbt buildEngineDistribution
```
Start the Language Server and redirect ouput to `language-server.log`
```bash
built-distribution/enso-engine-0.0.0-dev-linux-amd64/enso-0.0.0-dev/bin/enso \
--log-level trace \
--server \
--root-id 6f7d58dd-8ee8-44cf-9ab7-9f0454033641 \
--path $(pwd)/tools/language-server/wstest/benchmarks/set-expression-value/Unnamed/ \
--rpc-port 30616 \
--data-port 30717 \
2>&1| tee language-server.log
```
Run the test and redirect output to `wstest.log`
```bash
cargo run -p wstest -- \
--binary-socket ws://127.0.0.1:30717 \
--init-binary-socket tools/language-server/wstest/benchmarks/set-expression-value/init.bin \
--init-text-socket tools/language-server/wstest/benchmarks/set-expression-value/init.txt \
--wait-after-init 10000 \
--ignore-text-socket-responses tools/language-server/wstest/benchmarks/set-expression-value/ignore_responses.txt \
--input tools/language-server/wstest/benchmarks/set-expression-value/input.txt \
--input-expects-binary-responses \
--warmup-iterations 100 \
--wait-after-warmup 3000 \
--benchmark-iterations 100 \
ws://127.0.0.1:30616 \
2>&1| tee wstest.log
```
Analyze logs
```bash
cargo run -p logstat -- \
--median \
--spec tools/language-server/logstat/apply-expression-value-spec.txt \
--wstest-log wstest.log
language-server.log
```
Example output
```text
avg [min..max] (of 150 records)
0ms [0..0] [main] wstest sent bench request [{ "jsonrpc": "2.0", "method": "text/applyExpre
0ms [0..2] [org.enso.jsonrpc.JsonRpcServer] Received text message: { "jsonrpc": "2.0", "met
0ms [0..1] [org.enso.languageserver.protocol.json.JsonConnectionController] received handle
1ms [0..2] [org.enso.languageserver.runtime.RuntimeConnector] received handled Request(None
0ms [0..2] [enso] Executing command: SetExpressionValueCmd...
5ms [3..16] [enso] Job EnsureCompiledJob finished in 5 ms.
1ms [0..9] [enso] Visualisation computed 524dd815-b652-4bbe-b9f2-26b35d17993a.
0ms [0..1] [org.enso.languageserver.runtime.ContextRegistry] received handled Visualisation
1ms [0..1] [main] wstest handled response [<binary>]
8ms [7..22] Total
```

View File

@ -0,0 +1,7 @@
name: Unnamed
namespace: local
version: 0.0.1
license: ""
authors: []
maintainers: []
prefer-local-libraries: true

View File

@ -0,0 +1,13 @@
from Standard.Base import all
import Standard.Visualization
main =
variable = 8
IO.println variable
#### METADATA ####
[[{"index":{"value":5},"size":{"value":8}},"30e01fad-128e-4b5a-a22c-bd3b21252fd9"],[{"index":{"value":13},"size":{"value":1}},"f868fa0b-1802-450e-85d5-f1577643a1f4"],[{"index":{"value":14},"size":{"value":4}},"18565040-ef59-4267-ace8-048560f4086e"],[{"index":{"value":26},"size":{"value":3}},"4ecc4b5b-d5d2-446f-bcd5-fada2e48a042"],[{"index":{"value":0},"size":{"value":29}},"31fe4373-eee6-450d-a0ea-2bfff9d0d7b5"],[{"index":{"value":37},"size":{"value":8}},"718ff7cf-19c4-4f41-91a9-d2ff4221d5c2"],[{"index":{"value":45},"size":{"value":1}},"b794d41d-4007-44a7-8427-15fff08df9dd"],[{"index":{"value":46},"size":{"value":13}},"564816d2-b2cd-4504-a9e6-1062351887a0"],[{"index":{"value":30},"size":{"value":29}},"47952db2-9f21-4ee3-9ac6-53606eab1e03"],[{"index":{"value":61},"size":{"value":4}},"236aa79f-56e1-42f9-8bcb-99b1c2576719"],[{"index":{"value":66},"size":{"value":1}},"14539f71-fe59-41cc-9424-e18d5beb45d2"],[{"index":{"value":72},"size":{"value":8}},"cbe6ef7b-564e-44f4-87bc-51f277d48387"],[{"index":{"value":81},"size":{"value":1}},"2e69d11c-c79b-449a-ab7c-f08b698ad605"],[{"index":{"value":83},"size":{"value":1}},"524dd815-b652-4bbe-b9f2-26b35d17993a"],[{"index":{"value":72},"size":{"value":12}},"8740a5e4-cfb3-449b-958f-d2dd967642a5"],[{"index":{"value":89},"size":{"value":2}},"05a391e1-465a-4518-9f4f-3bde0cfd619e"],[{"index":{"value":91},"size":{"value":1}},"f61cf1f6-d89a-46da-85e3-74991abe9b82"],[{"index":{"value":92},"size":{"value":7}},"34887a2b-d4f9-413d-b11d-b339cf6c79f0"],[{"index":{"value":89},"size":{"value":10}},"734641cf-d983-4609-80aa-897ce2641ba4"],[{"index":{"value":100},"size":{"value":8}},"446d7d7d-599d-4207-878a-749862460884"],[{"index":{"value":89},"size":{"value":19}},"74ce36e2-e27c-44c1-90f1-faee61a1def2"],[{"index":{"value":67},"size":{"value":43}},"f6c651d5-bb31-48fb-9bc6-2eb373b00e43"],[{"index":{"value":61},"size":{"value":49}},"3b84a460-cddd-47ce-97d9-c94ccda80343"]]
{"ide":{"node":{"524dd815-b652-4bbe-b9f2-26b35d17993a":{"position":{"vector":[-100.0,140.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":{"name":{"content":{"content":"JSON"}},"project":"Builtin"}},"74ce36e2-e27c-44c1-90f1-faee61a1def2":{"position":{"vector":[-100.0,80.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":null}},"project":null}}

View File

@ -0,0 +1,4 @@
"jsonrpc":"2.0","id":5,"result":null
"method":"file/rootAdded"
"method":"executionContext/expressionUpdates"
"jsonrpc":"2.0","id":7,"result":null

View File

@ -0,0 +1 @@
EAAAAAwAHgAIAAAABwAYAAwAAAAAAAABnt62wJU/S4ceSD2b5jWEaAwAAAAAAAYAFAAEAAYAAAD/PR80J3cGoXxKagLysxqu

View File

@ -0,0 +1,5 @@
t|{ "jsonrpc": "2.0", "method": "session/initProtocolConnection", "id": 0, "params": { "clientId": "ae1ab3f2-026a-4a7c-a106-7727341f3dff" } }
t|{"jsonrpc":"2.0","id":1,"method":"text/openFile","params":{"path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}}}
t|{"jsonrpc":"2.0","id":3,"method":"executionContext/create","params":{"contextId":"1949b079-81e2-46b7-91be-5c5072aaba12"}}
t|{"jsonrpc":"2.0","id":5,"method":"executionContext/push","params":{"contextId":"1949b079-81e2-46b7-91be-5c5072aaba12","stackItem":{"methodPointer":{"definedOnType":"local.Unnamed.Main","module":"local.Unnamed.Main","name":"main"},"positionalArgumentsExpressions":[],"thisArgumentExpression":null,"type":"ExplicitCall"}}}
b|{"jsonrpc": "2.0", "id": 7, "method": "executionContext/attachVisualisation", "params": { "expressionId": "524dd815-b652-4bbe-b9f2-26b35d17993a", "visualisationConfig": { "executionContextId": "1949b079-81e2-46b7-91be-5c5072aaba12", "expression": "x -> x.to_text", "visualisationModule": "local.Unnamed.Main" }, "visualisationId": "a1cced79-1e4b-47f6-a85d-73f766325372" } }

View File

@ -0,0 +1,2 @@
{ "jsonrpc": "2.0", "method": "text/applyExpressionValue", "id": 0, "params": { "expressionId": "524dd815-b652-4bbe-b9f2-26b35d17993a", "path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}, "edit":{"range":{"start":{"line":4,"character":15},"end":{"line":4,"character":16}}, "text":"9"}, "oldVersion":"e980e79db6f43cfb85f74b642a5df42b46ff6827ae191e2551d82456", "newVersion":"6dea845964972ebdceccc36e3d4605324fc54bde40709e5d35c1a93e" } }
{ "jsonrpc": "2.0", "method": "text/applyExpressionValue", "id": 0, "params": { "expressionId": "524dd815-b652-4bbe-b9f2-26b35d17993a", "path":{"rootId":"6f7d58dd-8ee8-44cf-9ab7-9f0454033641","segments":["src","Main.enso"]}, "edit":{"range":{"start":{"line":4,"character":15},"end":{"line":4,"character":16}}, "text":"8"}, "oldVersion":"6dea845964972ebdceccc36e3d4605324fc54bde40709e5d35c1a93e", "newVersion":"e980e79db6f43cfb85f74b642a5df42b46ff6827ae191e2551d82456" } }

View File

@ -0,0 +1,66 @@
use time::format_description::well_known::Rfc3339;
use time::OffsetDateTime;
// =================
// === Constants ===
// =================
pub static MESSAGE_BINARY: &str = "<binary>";
static INIT_REQUEST_SENT: &str = "wstest sent init request";
static BENCH_REQUEST_SENT: &str = "wstest sent bench request";
static WARMUP_REQUEST_SENT: &str = "wstest sent warmup request";
static RESPONSE_HANDLED: &str = "wstest handled response";
static RESPONSE_IGNORED: &str = "wstest ignored response";
static FMT_LEVEL: &str = "info";
static FMT_MODULE: &str = "main";
// ==========================
// === Message Formatting ===
// ==========================
/// Message for logging the initialization request
pub fn init_request(message: &str) -> String {
fmt(format!("{} [{}]", INIT_REQUEST_SENT, message).as_str())
}
/// Message for logging the warmup request
pub fn warmup_request(message: &str) -> String {
fmt(format!("{} [{}]", WARMUP_REQUEST_SENT, message).as_str())
}
/// Message for logging the benchmarking request
pub fn bench_request(message: &str) -> String {
fmt(format!("{} [{}]", BENCH_REQUEST_SENT, message).as_str())
}
/// Message for logging the text response
pub fn response_text(message: &str) -> String {
fmt(format!("{} [{}]", RESPONSE_HANDLED, message).as_str())
}
/// Message for logging the binary response
pub fn response_binary() -> String {
fmt(format!("{} [{}]", RESPONSE_HANDLED, MESSAGE_BINARY).as_str())
}
/// Message for logging the ignored response
pub fn response_ignored(message: &str) -> String {
fmt(format!("{} [{}]", RESPONSE_IGNORED, message).as_str())
}
fn fmt(message: &str) -> String {
let time_now = OffsetDateTime::now_utc();
format!(
"[{level}] [{timestamp}] [{module}] {message}",
level = FMT_LEVEL,
timestamp = time_now.format(&Rfc3339).unwrap(),
module = FMT_MODULE,
message = message,
)
}

View File

@ -0,0 +1,365 @@
//! The crate provides an executable for benchmarking the language server.
// === Standard Linter Configuration ===
#![deny(non_ascii_idents)]
#![warn(unsafe_code)]
// === Non-Standard Linter Configuration ===
#![warn(missing_docs)]
#![warn(trivial_casts)]
#![warn(trivial_numeric_casts)]
#![warn(unused_import_braces)]
#![warn(unused_qualifications)]
#![warn(missing_copy_implementations)]
#![warn(missing_debug_implementations)]
mod format;
use enso_prelude::*;
use std::path::PathBuf;
use std::time::Duration;
use clap::Parser;
use clap::ValueHint;
use futures::SinkExt;
use futures::StreamExt;
use tokio::io::AsyncBufReadExt;
use tokio::io::BufReader;
use tokio::sync::mpsc;
use tokio_stream::wrappers::LinesStream;
use url::Url;
use websocket_lite::ClientBuilder;
use websocket_lite::Message;
use websocket_lite::Opcode;
use websocket_lite::Result;
// =================
// === Constants ===
// =================
static EXPECT_TEXT_RESPONSE: &str = "t|";
static EXPECT_BINARY_RESPONSE: &str = "b|";
// =====================
// === CLI Arguments ===
// =====================
#[derive(Parser, Debug)]
#[clap(version, about)]
struct Args {
/// Text websocket to connect to.
#[clap(value_name = "URL", value_hint = ValueHint::Url)]
text_socket: Url,
/// File containing messages to initialize the main socket.
#[clap(long, value_hint = ValueHint::FilePath)]
init_text_socket: Option<PathBuf>,
/// File containing responses to ignore.
#[clap(long, value_hint = ValueHint::FilePath)]
ignore_text_socket_responses: Option<PathBuf>,
/// Binary socket to connect to.
#[clap(long, value_name = "URL", value_hint = ValueHint::Url)]
binary_socket: Option<Url>,
/// File containing messages to initialize the binary socket.
#[clap(long, value_hint = ValueHint::FilePath)]
init_binary_socket: Option<PathBuf>,
/// Path to a file with commands to send.
#[clap(long, value_name = "FILE", value_hint = ValueHint::FilePath)]
input: Option<PathBuf>,
/// Input commands expect responses from a binary socket.
#[clap(long)]
input_expects_binary_responses: bool,
/// Number of warmup requests to send.
#[clap(long, default_value = "5")]
warmup_iterations: usize,
/// Number of benchmarked requests to send.
#[clap(long, default_value = "5")]
benchmark_iterations: usize,
/// Time in milliseconds to wait before sending input messages (after the init sequence is
/// complete).
#[clap(long, value_name = "MILLISECONDS", default_value = "0")]
wait_after_init: u64,
/// Time in milliseconds to wait before starting benchmark (after the warmup is complete).
#[clap(long, value_name = "MILLISECONDS", default_value = "0")]
wait_after_warmup: u64,
/// Time in milliseconds to wait before sending the next request from the `input` file.
#[clap(long, value_name = "MILLISECONDS", default_value = "0")]
wait_after_response: u64,
}
// =====================
// === Sync Messages ===
// =====================
/// Synchronization messages used for establishing order between requests and responses.
#[derive(Debug)]
enum SyncMessage {
ResponseReceived,
}
// =============
// === Utils ===
// ==============
/// Read file line by line.
async fn read_lines(path_buf: PathBuf) -> std::io::Result<Vec<String>> {
let file = tokio::fs::File::open(path_buf.as_path()).await?;
let lines_reader = BufReader::new(file).lines();
let lines_stream = LinesStream::new(lines_reader);
tokio_stream::StreamExt::collect(lines_stream).await
}
// ============
// === Main ===
// ============
#[tokio::main]
async fn main() -> Result<()> {
let args = Args::parse();
// text socket connection
let text_socket_client = ClientBuilder::from_url(args.text_socket).async_connect().await?;
let (text_sink, text_stream) = text_socket_client.split();
// binary socket connection
let (binary_sink, binary_stream) = if let Some(binary_socket) = args.binary_socket {
let binary_client = ClientBuilder::from_url(binary_socket).async_connect().await?;
let (sink, stream) = binary_client.split::<Message>();
(Some(sink), Some(stream))
} else {
(None, None)
};
// ignored responses
let mut ignored_text_responses = regex::RegexSet::empty();
if let Some(path_buf) = args.ignore_text_socket_responses {
let ignored_lines = read_lines(path_buf).await?;
ignored_text_responses = regex::RegexSet::new(ignored_lines)?;
}
// synchronization channels between requests and responses
let (text_tx, mut text_rx) = mpsc::channel::<SyncMessage>(1);
let (binary_tx, mut binary_rx) = mpsc::channel::<SyncMessage>(1);
let send_loop = async {
let mut sink_mut = text_sink;
// initialize binary socket
if let Some(mut sink_mut) = binary_sink {
if let Some(path_buf) = args.init_binary_socket {
let file = tokio::fs::File::open(path_buf.as_path()).await?;
let mut lines = BufReader::new(file).lines();
while let Some(line) = lines.next_line().await? {
let bytes = base64::decode(line)?;
let message = Message::binary(bytes);
sink_mut.send(message).await?;
println!("{}", format::init_request(format::MESSAGE_BINARY));
// wait for response
let binary_response = binary_rx.recv().await;
if binary_response.is_none() {
break;
}
}
}
}
// initialize text socket
if let Some(path_buf) = args.init_text_socket {
let file = tokio::fs::File::open(path_buf.as_path()).await?;
let mut lines = BufReader::new(file).lines();
while let Some(line) = lines.next_line().await? {
let (prefix, message_text) = line.split_at(2);
let message = Message::text(message_text);
sink_mut.send(message).await?;
println!("{}", format::init_request(message_text));
// wait for response
if prefix == EXPECT_TEXT_RESPONSE {
let text_response = text_rx.recv().await;
if text_response.is_none() {
break;
}
} else if prefix == EXPECT_BINARY_RESPONSE {
let binary_response = binary_rx.recv().await;
if binary_response.is_none() {
break;
}
}
}
}
// wait after init
tokio::time::sleep(Duration::from_millis(args.wait_after_init)).await;
// send input messages
match args.input {
Some(path_buf) => {
let lines = read_lines(path_buf).await?;
// send warmup messages
let warmup_input = lines.iter().cycle().take(args.warmup_iterations);
for line in warmup_input {
let message = Message::text(line.as_str());
sink_mut.send(message).await?;
println!("{}", format::warmup_request(line.as_str()));
// wait for response
if args.input_expects_binary_responses {
let binary_response = binary_rx.recv().await;
if binary_response.is_none() {
break;
}
} else {
let text_response = text_rx.recv().await;
if text_response.is_none() {
break;
}
}
tokio::time::sleep(Duration::from_millis(args.wait_after_response)).await;
}
// wait after warmup
tokio::time::sleep(Duration::from_millis(args.wait_after_warmup)).await;
// send benchmark messages
let bench_input = lines
.iter()
.cycle()
.take(args.warmup_iterations + args.benchmark_iterations)
.skip(args.warmup_iterations);
for line in bench_input {
let message = Message::text(line.as_str());
sink_mut.send(message).await?;
println!("{}", format::bench_request(line.as_str()));
// wait for response
if args.input_expects_binary_responses {
let binary_response = binary_rx.recv().await;
if binary_response.is_none() {
break;
}
} else {
let text_response = text_rx.recv().await;
if text_response.is_none() {
break;
}
}
tokio::time::sleep(Duration::from_millis(args.wait_after_response)).await;
}
}
None => {
let mut lines = BufReader::new(tokio::io::stdin()).lines();
while let Some(data) = lines.next_line().await? {
let message = Message::text(data);
sink_mut.send(message).await?;
}
}
}
Ok::<_, websocket_lite::Error>(())
};
// receive text messages
let text_recv_loop = async {
let mut stream_mut = text_stream;
loop {
let (message, stream) = stream_mut.into_future().await;
let message = if let Some(message) = message {
message?
} else {
break;
};
if let Opcode::Text = message.opcode() {
if let Some(text_message) = message.as_text() {
// send acknowledgement
if ignored_text_responses.is_match(text_message) {
println!("{}", format::response_ignored(text_message));
} else {
println!("{}", format::response_text(text_message));
text_tx.send(SyncMessage::ResponseReceived).await?;
}
}
}
stream_mut = stream;
}
Ok::<_, websocket_lite::Error>(())
};
// receive binary messages
let mut binary_recv = either::Left(futures::future::pending::<()>());
if let Some(mut stream_mut) = binary_stream {
let binary_recv_loop = async {
loop {
let (message, stream) = stream_mut.into_future().await;
let message = if let Some(message) = message {
message?
} else {
break;
};
if let Opcode::Binary = message.opcode() {
println!("{}", format::response_binary());
binary_tx.send(SyncMessage::ResponseReceived).await?;
}
stream_mut = stream;
}
Ok::<_, websocket_lite::Error>(())
};
binary_recv = either::Right(binary_recv_loop);
}
let binary_recv_loop = async {
match binary_recv {
either::Left(l) => {
l.await;
Ok(())
}
either::Right(r) => r.await,
}
};
tokio::select! {
_ = send_loop => {}
_ = text_recv_loop => {}
_ = binary_recv_loop => {}
}
Ok(())
}