Skip to content

Commit

Permalink
Documenting profiling of engine startup
Browse files Browse the repository at this point in the history
  • Loading branch information
JaroslavTulach committed Feb 4, 2023
1 parent 7b2a422 commit 9a9a7bb
Show file tree
Hide file tree
Showing 3 changed files with 38 additions and 1 deletion.
1 change: 1 addition & 0 deletions distribution/lib/Standard/Base/0.0.0-dev/src/Any.enso
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import project.Data.Ordering.Ordering

import project.Data.Pair.Pair
import project.Data.Range.Extensions
import project.Data.Text.Text
Expand Down
35 changes: 35 additions & 0 deletions docs/profiler/engine-startup.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,35 @@
# Summary

One of the main objectives to deliver satisfactory user experience
when using Enso is to be fast when getting ready to work. This requires the engine
to initialize all services the IDE needs as quickly as possible. In short -
to **start fast**. This document describes how to measure, record and analyze
the startup of the Enso engine.

## Collecting the data

Start `project-manager` with following options to record first 20s of
the Enso engine startup sequence:
```
$ project-manager --profiling-events-log-path=start.log --profiling-path=start.npss --profiling-time=20
```
Let the IDE connect to just launched `project-manager` - e.g. start the IDE with `--no-backed` option.
Once the `start.log` and `start.npss` files are generated (next to each other), open them in GraalVM's VisualVM:
```
$ graalvm/bin/jvisualvm --openfile start.npss
```
Use VisualVM to analyze to recorded data.

### Interactively Analyze

VisualVM offers two timelines. A "stackdepth" one and also _"UI Actions"_ line.
Hovering over boxes in _"UI Actions"_ shows the messages describing what
happens in the engine - what has been logged into `start.log`.
One can then select an interval and get profiling information for that interval:

![VisualVM](https://user-images.githubusercontent.com/26887752/216099011-33866c1d-06ab-48dc-936d-b9190e80b9fb.png)

This picture shows that 2.7s is spend in `EnsoCompiledJob` task. Overall the
goal is to log enough information to help us navigate thru the long startup sequence.
Select appropriate interval based on the displayed _UI Actions_ - e.g. logged
events - and analyze what has happened there based on the sampling of JVM stack traces.
3 changes: 2 additions & 1 deletion docs/profiler/profiling.md
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,8 @@ performing **objective**s.

- **Project startup**
Time from selecting a project from the Hello Screen to a working graph view of
the project. Sub-processes:
the project. See also [engine startup](engine-startup.md) for non-IDE details
on a similar topic. Sub-processes:

- **Graph Editor initialization**
Time needed to display fully-functional graph editor (not colored).
Expand Down

0 comments on commit 9a9a7bb

Please sign in to comment.