Multi-process profiles. (#3395)

See: [#181837344](https://www.pivotaltracker.com/story/show/181837344).

I've separated this PR from some deeper changes I'm making to the profile format, because the changeset was getting too complex. The new APIs and tools in this PR are fully-implemented, except the profile format is too simplistic--it doesn't currently support headers that are needed to determine the relative timings of events from different processes.

- Adds basic support for profile files containing data collected by multiple processes.
- Implements `api_events_to_profile`, a tool for converting backend message logs (#3392) to the `profiler` format so they can be merged with frontend profiles (currently they can be merged with `cat`, but the next PR will introduce a merge tool).
- Introduces `message_beanpoles`, a simple tool that diagrams timing relationships between frontend and backend messages.

### Important Notes
- All TODOs introduced here will be addressed in the next PR that defines the new format.
- Introduced a new crate, `enso_profiler_enso_data`, to be used by profile consumers that need to refer to Enso application datatypes to interpret metadata.
- Introduced a `ProfileBuilder` abstraction for writing the JSON profile format; partially decouples the runtime event log structures from the format definition.
- Introducing the conversion performed for `ProfilerBuilder` uncovered that the `.._with_same_start!` low-level `profiler` APIs don't currently work; they return `Started<_>` profilers, but that is inconsistent with the stricter data model that I introduced when I implemented `profiler_data`; they need to return profilers in a created, unstarted state. Low-level async profilers have not been a priority, but once #3382 merges we'll have a way to render their data, which will be really useful because async profilers capture *why* we're doing things. I'll bring up scheduling this in the next performance meeting.

Cargo.toml

@@ -5,7 +5,7 @@
 # where plausible.
 members = [
     "app/gui",
-    "app/gui/enso-profiler-metadata",
+    "app/gui/enso-profiler-enso-data",
     "build/enso-formatter",
     "build/rust-scripts",
     "lib/rust/*",

app/gui/enso-profiler-enso-data/Cargo.toml

@@ -0,0 +1,13 @@
+[package]
+name = "enso-profiler-enso-data"
+version = "0.1.0"
+edition = "2021"
+authors = ["Enso Team <[email protected]>"]
+
+[dependencies]
+chrono = { version = "0.4.19", features = ["serde"] }
+csv = "1.1"
+serde = { version = "1", features = ["derive"] }
+enso-profiler = { path = "../../../lib/rust/profiler"}
+enso-profiler-data = { path = "../../../lib/rust/profiler/data"}
+ensogl-core = { path = "../../../lib/rust/ensogl/core"}

app/gui/enso-profiler-enso-data/src/backend.rs

@@ -0,0 +1,30 @@
+//! Defines a metadata type for representing backend messages.
+
+
+
+// ===============
+// === Message ===
+// ===============
+
+/// Metadata type for messages between the Language Server and the Compiler.
+#[derive(Clone, Debug, serde::Deserialize, serde::Serialize, PartialEq, Eq)]
+pub struct Message {
+    /// Identifies whether the logging process is the sender or receiver of the message.
+    pub direction:  Direction,
+    /// Used to associate requests and responses.
+    pub request_id: Option<String>,
+    /// Identifies an RPC method.
+    pub endpoint:   String,
+}
+
+
+// === Direction ===
+
+/// Identifies which process is the sender of a message.
+#[derive(Clone, Copy, Debug, serde::Deserialize, serde::Serialize, PartialEq, Eq)]
+pub enum Direction {
+    /// From logging process to other process.
+    Request,
+    /// From other process to logging process.
+    Response,
+}

app/gui/enso-profiler-enso-data/src/beanpole.rs

@@ -0,0 +1,170 @@
+//! A diagram type for illustrating timings of messages between processes.
+//!
+//! Like a UML timing diagram, this illustrates interactions between processes over time. However,
+//! this diagram is simpler (the UML diagram type supports nonspecific times, process state changes,
+//! and many other data complexities); as a result, it is better suited to display of large numbers
+//! of events spread unevenly over a long time range than any UML renderers I[KW] am aware of.
+
+
+
+// ===============
+// === Diagram ===
+// ===============
+
+/// The data necessary to create a diagram of message timings.
+#[derive(Debug, Default)]
+pub struct Diagram<'a> {
+    processes: Vec<&'a str>,
+    messages:  Vec<Message>,
+}
+
+impl<'a> Diagram<'a> {
+    /// Define a new process. Return a handle.
+    pub fn process<'b: 'a>(&mut self, name: &'b str) -> Process {
+        let id = self.processes.len();
+        self.processes.push(name);
+        Process { id }
+    }
+
+    /// Log a message between two processes.
+    pub fn message(&mut self, sender: Process, recipient: Process, time: f64, label: String) {
+        self.messages.push(Message { sender, recipient, time, label });
+    }
+}
+
+
+// === Process ===
+
+/// A process that may send and receive messages.
+#[derive(Clone, Copy, Debug, Eq, PartialEq, Hash)]
+pub struct Process {
+    id: usize,
+}
+
+
+// === Message ===
+
+/// An event of communication between processes.
+#[derive(Clone, Debug)]
+pub struct Message {
+    sender:    Process,
+    recipient: Process,
+    time:      f64,
+    label:     String,
+}
+
+
+
+// ====================
+// === Svg rendering ==
+// ====================
+
+/// Rendering a [`Diagram`] in SVG format.
+pub mod svg {
+    use super::*;
+
+    // How far apart the poles should be.
+    // Unit is the same size as 1 millisecond, but the X-axis is not quantitative.
+    const POLE_SPACING: f64 = 500.0;
+
+    const GRID_INTERVAL_MS: f64 = 100.0;
+
+    // How much space to allow for headers, in millisecond-equivalent units.
+    const HEADER_HEIGHT: f64 = 40.0;
+    // Where to position the header text.
+    const HEADER_BASELINE: f64 = HEADER_HEIGHT - 10.0;
+    const FOOTER_HEIGHT: f64 = 40.0;
+
+    // Y-offset of the point of the arrow from the text field's `y` attribute.
+    // With the current hack of using unicode to get arrows, this must be experimentally
+    // determined. Its exact value isn't important because it only affects placement
+    // of everything relative to the grid, not differences between measurements, and the
+    // grid doesn't need to be lined up to the millisecond.
+    const Y_FUDGE: f64 = 4.0;
+
+    const GRID_COLOR_RGB: &str = "bbbbbb";
+
+    /// Write a SVG representation of the given [`Diagram`].
+    pub fn write_diagram(dia: &Diagram, mut f: impl std::io::Write) -> std::io::Result<()> {
+        writeln!(f, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>")?;
+        let xmlns = "xmlns=\"http://www.w3.org/2000/svg\"";
+        let mut max_time = 0.0;
+        for message in dia.messages.iter() {
+            if message.time > max_time {
+                max_time = message.time;
+            }
+        }
+        let height = max_time;
+        writeln!(f, "<svg height=\"{}\" {}>", height + HEADER_HEIGHT + FOOTER_HEIGHT, xmlns,)?;
+        const LEFT: &str = "end";
+        const MIDDLE: &str = "middle";
+        const RIGHT: &str = "start";
+        for (i, p) in dia.processes.iter().enumerate() {
+            let offset_to_center = POLE_SPACING / 2.0;
+            writeln!(
+                f,
+                "<text y=\"{}\" x=\"{}\" text-anchor=\"{}\">{}</text>",
+                HEADER_BASELINE,
+                POLE_SPACING * i as f64 + offset_to_center,
+                MIDDLE,
+                p,
+            )?;
+        }
+        for i in 0..((height / GRID_INTERVAL_MS) as usize + 1) {
+            writeln!(
+                f,
+                "<text y=\"{}\" x=\"{}\" text-anchor=\"{}\">{}ms</text>",
+                HEADER_HEIGHT + GRID_INTERVAL_MS * i as f64,
+                0,
+                RIGHT,
+                GRID_INTERVAL_MS * i as f64,
+            )?;
+            let y_pos = HEADER_HEIGHT + GRID_INTERVAL_MS * i as f64;
+            let x_len = POLE_SPACING * dia.processes.len() as f64;
+            let path = format!("M0,{} l{},0", y_pos, x_len);
+            writeln!(f, "<path fill=\"none\" stroke=\"#{}\" d=\"{}\"/>", GRID_COLOR_RGB, path)?;
+        }
+        for i in 1..dia.processes.len() {
+            let path = format!("M{},{} l0,{}", POLE_SPACING * i as f64, HEADER_HEIGHT, height);
+            writeln!(f, "<path fill=\"none\" stroke=\"black\" d=\"{}\"/>", path)?;
+        }
+        let simple_only = "Drawing messages between non-adjacent processes is not implemented.";
+        let mut pairs = std::collections::HashMap::new();
+        struct Pair {
+            index:   usize,
+            forward: bool,
+        }
+        for index in 1..dia.processes.len() {
+            let i0 = Process { id: index - 1 };
+            let i1 = Process { id: index };
+            pairs.insert((i0, i1), Pair { index, forward: true });
+            pairs.insert((i1, i0), Pair { index, forward: false });
+        }
+        for m in &dia.messages {
+            let pair = (m.sender, m.recipient);
+            let Pair { index, forward } = *pairs.get(&pair).expect(simple_only);
+            let x = index as f64 * POLE_SPACING;
+            if forward {
+                writeln!(
+                    f,
+                    "<text y=\"{}\" x=\"{}\" text-anchor=\"{}\">{}▶</text>",
+                    HEADER_HEIGHT + m.time + Y_FUDGE,
+                    x,
+                    LEFT,
+                    m.label,
+                )?;
+            } else {
+                writeln!(
+                    f,
+                    "<text y=\"{}\" x=\"{}\" text-anchor=\"{}\">◀{}</text>",
+                    HEADER_HEIGHT + m.time + Y_FUDGE,
+                    x,
+                    RIGHT,
+                    m.label,
+                )?;
+            }
+        }
+        writeln!(f, "</svg>")?;
+        Ok(())
+    }
+}

app/gui/enso-profiler-enso-data/src/bin/api_events_to_profile.rs

@@ -0,0 +1,83 @@
+//! Tool that translates a backend message log into the [`enso_profiler`] JSON format.
+//!
+//! # Usage
+//!
+//! The tool reads a CSV backend message log, and converts it to a
+//! [JSON-formatted event log](https://github.com/enso-org/design/blob/main/epics/profiling/implementation.md#file-format)
+//! for use with [`enso_profiler`] tools.
+//!
+//! For example:
+//!
+//! ```console
+//! ~/git/enso/enso_data $ cargo run --bin api_events_to_profile < messages.csv > messages.json
+//! ```
+
+// === Features ===
+#![feature(test)]
+// === Standard Linter Configuration ===
+#![deny(non_ascii_idents)]
+#![warn(unsafe_code)]
+// === Non-Standard Linter Configuration ===
+#![deny(unconditional_recursion)]
+#![warn(missing_copy_implementations)]
+#![warn(missing_debug_implementations)]
+#![warn(missing_docs)]
+#![warn(trivial_casts)]
+#![warn(trivial_numeric_casts)]
+#![warn(unused_import_braces)]
+
+use enso_profiler::format;
+use enso_profiler_enso_data::backend;
+
+
+
+// ==================================
+// === Backend message log format ===
+// ==================================
+
+mod api_events {
+    use super::*;
+
+    #[derive(Clone, Debug, serde::Deserialize)]
+    pub struct Message {
+        pub timestamp:  chrono::DateTime<chrono::offset::Utc>,
+        pub direction:  backend::Direction,
+        pub request_id: Option<String>,
+        pub endpoint:   String,
+    }
+
+    pub fn parse(r: impl std::io::Read) -> Result<Vec<Message>, Box<dyn std::error::Error>> {
+        let mut log = Vec::new();
+        let mut reader = csv::ReaderBuilder::new().has_headers(false).from_reader(r);
+        for message in reader.deserialize() {
+            let message: Message = message?;
+            log.push(message);
+        }
+        Ok(log)
+    }
+}
+
+
+
+// ============
+// === Main ===
+// ============
+
+fn main() {
+    use std::io::Write;
+
+    let must_be_csv = "Parse error (Is this a CSV logged by the language server?)";
+    let backend_messages = api_events::parse(std::io::stdin()).expect(must_be_csv);
+    let mut backend_profile = format::Builder::new();
+    backend_profile.time_offset_ms(0.0);
+    backend_profile.process("LanguageServer");
+    for message in backend_messages {
+        let api_events::Message { timestamp, direction, request_id, endpoint } = message;
+        let data = backend::Message { direction, request_id, endpoint };
+        let timestamp = timestamp.timestamp_nanos();
+        let timestamp = format::Timestamp::from_ms(timestamp as f64 / 1_000_000.0);
+        backend_profile.metadata(timestamp, "BackendMessage", data);
+    }
+    let backend_profile = backend_profile.build_string();
+    std::io::stdout().write_all(backend_profile.as_bytes()).expect("IO Error writing results");
+}