Skip to content

Commit

Permalink
perf/diagnostics/onivim#2407/trace logging cpu usage (onivim#2629)
Browse files Browse the repository at this point in the history
More investigation into onivim#2407 - based on the latest logs, like:

```
[TRACE] [ 0.061s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.062s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [ 0.062s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [ 0.067s] Revery.UI.Render : END: Render frame
```

My hypothesis is that there are some animation timers running that are forcing us to re-render - I've added some additional instrumentation in our trace logging here: revery-ui/revery#1011

That change logs out additional information about the timers that are running: 
```
[TRACE] [ 4.921s] Revery.Tick : Tick.pump - starting with 4 active tickers.
[TRACE] [ 4.921s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[DEBUG] [ 4.921s] Oni2.Store.StoreThread : Running effect: Batch:
 vim.input

[INFO]  [ 4.921s] Oni2.Store.dispatch : dispatch: (Vim (Feature_Vim.ModeChanged <opaque>))
[DEBUG] [ 4.922s] Oni2.Store.dispatch : After: (Vim (Feature_Vim.ModeChanged <opaque>))
[INFO]  [ 4.922s] Oni2.Store.dispatch : dispatch: QuickmenuClose
[DEBUG] [ 4.923s] Oni2.Store.dispatch : After: QuickmenuClose
[INFO]  [ 4.923s] Oni2.Store.dispatch : dispatch: (Quit true)
[DEBUG] [ 4.924s] Oni2.Store.dispatch : After: (Quit true)
[INFO]  [ 4.925s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 1);
  msg = ModeChanged {mode = <opaque>; effects = <opaque>}}
[DEBUG] [ 4.926s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 1);
  msg = ModeChanged {mode = <opaque>; effects = <opaque>}}
[DEBUG] [ 4.926s] Oni2.Store.Vim : handled key: <CR>
[DEBUG] [ 4.926s] Oni2.Store.StoreThread : Effect complete: Batch:
 vim.input

[TRACE] [ 4.926s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [ 4.926s] Revery.Tick : Interval - running timer: StatusBar Notification Expirer 31
[TRACE] [ 4.926s] Revery.Tick : Interval - running timer: Notification Animation 32
[TRACE] [ 4.926s] Revery.Tick : Tick.pump - ending with 4 active tickers.
[TRACE] [ 4.926s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 4.930s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 1.000000 zoom: 1.000000 canvasScaling: 1.000000
[TRACE] [ 4.931s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1000
[TRACE] [ 4.939s] Revery.UI.Render : END: Render frame
```

This can help to confirm my hypothesis, and if there is an active timer, we can see if it's a general problem or if there is a specific class of timer that is getting caught in a loop. This will be useful logging to have in any case, but hopefully it can get us to closer to fixing onivim#2407
  • Loading branch information
bryphe authored Oct 28, 2020
1 parent cdd2f46 commit 4616ffb
Show file tree
Hide file tree
Showing 32 changed files with 120 additions and 212 deletions.
14 changes: 7 additions & 7 deletions bench.esy.lock/index.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

14 changes: 7 additions & 7 deletions esy.lock/index.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

1 change: 1 addition & 0 deletions integration_test/lib/Oni_IntegrationTestLib.re
Original file line number Diff line number Diff line change
Expand Up @@ -166,6 +166,7 @@ let runTest =

let _: unit => unit =
Revery.Tick.interval(
~name="Integration Test Ticker",
_ => {
let state = currentState^;
Revery.Utility.HeadlessWindow.render(
Expand Down
14 changes: 7 additions & 7 deletions integrationtest.esy.lock/index.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -256,7 +256,7 @@
"revery-terminal": "*"
},
"resolutions": {
"revery": "revery-ui/revery#b43852b",
"revery": "revery-ui/revery#4d2dae6",
"esy-skia": "revery-ui/esy-skia#60e0260",
"rench": "bryphe/rench#a976fe5",
"reasonFuzz": "CrossR/reasonFuzz#1ad6f5d",
Expand Down
14 changes: 7 additions & 7 deletions release.esy.lock/index.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

9 changes: 7 additions & 2 deletions src/Components/BusyBar.re
Original file line number Diff line number Diff line change
Expand Up @@ -27,9 +27,14 @@ module Animations = {
};

let%component make = (~visible: bool, ~theme, ()) => {
let%hook opacity = Hooks.transition(visible ? 1.0 : 0.0);
let%hook opacity =
Hooks.transition(~name="BusyBar Opacity Transition", visible ? 1.0 : 0.0);
let%hook (time, _, _) =
Hooks.animation(~active=opacity >= 0.2, Animations.motion);
Hooks.animation(
~name="BusyBar Animation",
~active=opacity >= 0.2,
Animations.motion,
);

let%hook (width, setWidth) = Hooks.state(0);

Expand Down
2 changes: 2 additions & 0 deletions src/Components/Button.re
Original file line number Diff line number Diff line change
Expand Up @@ -57,12 +57,14 @@ let%component make =

let%hook background =
CustomHooks.colorTransition(
~name="Button Color Transition",
~duration=Animations.backgroundTransitionDuration,
background,
);

let%hook yOffset =
Hooks.transition(
~name="Button Lift Transition",
~duration=Animations.liftTransitionDuration,
isHovered ? (-2.0) : 0.0,
);
Expand Down
8 changes: 5 additions & 3 deletions src/Components/CustomHooks.re
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ let colorTransition =
~duration=Time.seconds(1),
~delay as delayDuration=Time.zero,
~easing=Easing.linear,
~name,
target,
) => {
let%hook ((start, stop), setTarget) = Hooks.state((target, target));
Expand All @@ -21,7 +22,8 @@ let colorTransition =
|> map(gradient)
);

let%hook (current, _animationState, resetTimer) = Hooks.animation(anim);
let%hook (current, _animationState, resetTimer) =
Hooks.animation(~name, anim);

let%hook () =
Hooks.effect(
Expand All @@ -36,10 +38,10 @@ let colorTransition =
current;
};

let useExpiration = (~equals=(==), ~expireAfter, items) => {
let useExpiration = (~name, ~equals=(==), ~expireAfter, items) => {
let%hook (active, setActive) = Hooks.state([]);
let%hook expired = Hooks.ref([]);
let%hook (time, _reset) = Hooks.timer(~active=active != [], ());
let%hook (time, _reset) = Hooks.timer(~name, ~active=active != [], ());

let (stillActive, freshlyExpired) =
List.partition(
Expand Down
6 changes: 5 additions & 1 deletion src/Components/InputText/View.re
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,11 @@ module Cursor = {
Hooks.effect(OnMountAndIf((!=), isFocused), () =>
if (isFocused) {
let clear =
Tick.interval(time => dispatch(Tick(time)), Time.ms(16));
Tick.interval(
~name="Input Text Cursor Interval",
time => dispatch(Tick(time)),
Time.ms(16),
);
Some(() => {clear()});
} else {
None;
Expand Down
1 change: 1 addition & 0 deletions src/Components/KeyDisplayer.re
Original file line number Diff line number Diff line change
Expand Up @@ -162,6 +162,7 @@ let%component make =
(~model, ~uiFont, ~top=?, ~left=?, ~right=?, ~bottom=?, ()) => {
let%hook activeGroups =
CustomHooks.useExpiration(
~name="KeyDisplayer Expirer",
~equals=(a, b) => a.id == b.id,
~expireAfter=Time.ms(int_of_float(Constants.duration *. 1000.)),
model.groups,
Expand Down
1 change: 1 addition & 0 deletions src/Components/Tooltip.re
Original file line number Diff line number Diff line change
Expand Up @@ -84,6 +84,7 @@ module Overlay: {
| Some(tooltip) =>
clearTimeout :=
Tick.timeout(
~name="Tooltip Timeout",
() => internalSetTooltip^(_ => Some(tooltip)),
Constants.delay,
)
Expand Down
1 change: 1 addition & 0 deletions src/Components/VimList/Component_VimList.re
Original file line number Diff line number Diff line change
Expand Up @@ -834,6 +834,7 @@ module View = {

let ((scrollY, _setScrollYImmediately), hooks) =
Hooks.spring(
~name="VimList Scroll Spring",
~target=model.scrollY,
~restThreshold=10.,
~enabled=isScrollAnimated,
Expand Down
6 changes: 5 additions & 1 deletion src/Core/Codicon.re
Original file line number Diff line number Diff line change
Expand Up @@ -847,7 +847,11 @@ module Animation = {

let%component make = (~spin=false, ~icon, ~fontSize=15., ~color, ()) => {
let%hook (rotation, _animationState, _reset) =
Hooks.animation(Animation.rotation, ~active=spin);
Hooks.animation(
~name="Codicon Spinner",
Animation.rotation,
~active=spin,
);
<View
style=Style.[
transform([
Expand Down
1 change: 1 addition & 0 deletions src/Core/Ripgrep.re
Original file line number Diff line number Diff line change
Expand Up @@ -210,6 +210,7 @@ let process = (rgPath, args, onUpdate, onComplete, onError) => {
disposeTick :=
Some(
Revery.Tick.interval(
~name="Ripgrep - Processing Ticker",
_ =>
if (!Job.isComplete(job^)) {
job := Job.tick(job^);
Expand Down
37 changes: 0 additions & 37 deletions src/Core/Utility/FunEx.re
Original file line number Diff line number Diff line change
Expand Up @@ -2,40 +2,3 @@ let tap = (f, x) => {
f(x);
x;
};

type throttleState('a) =
| NothingWaiting
| Collecting
| Throttling({latest: 'a});

let throttle =
(~leading=true, ~trailing=true, ~timeout=Revery.Tick.timeout, ~time, f) => {
let throttleState = ref(NothingWaiting);

let finish = () => {
switch (throttleState^) {
| NothingWaiting => () // This shouldn't really happen..
| Collecting => () // We queued up, but there weren't any further calls - nothing to do
| Throttling({latest}) =>
if (trailing) {
f(latest);
}
};

throttleState := NothingWaiting;
};

v => {
switch (throttleState^) {
// Nothing is waiting... execute immediately, start timer, collect
| NothingWaiting =>
if (leading) {
f(v);
};
let _: unit => unit = timeout(finish, time);
throttleState := Collecting;
| Collecting
| Throttling(_) => throttleState := Throttling({latest: v})
};
};
};
2 changes: 2 additions & 0 deletions src/Feature/Editor/CursorView.re
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,7 @@ let%component make =

let%hook y =
Hooks.transitionf(
~name="Cursor Y Transition",
~active=animatedCursor,
~duration=durationFunc,
~delay,
Expand All @@ -57,6 +58,7 @@ let%component make =
);
let%hook x =
Hooks.transitionf(
~name="Cursor X Transition",
~active=animatedCursor,
~delay,
~duration=durationFunc,
Expand Down
2 changes: 2 additions & 0 deletions src/Feature/Editor/EditorSurface.re
Original file line number Diff line number Diff line change
Expand Up @@ -254,13 +254,15 @@ let%component make =

let%hook (scrollY, _setScrollYImmediately) =
Hooks.spring(
~name="Editor ScrollY Spring",
~target=Editor.scrollY(editor),
~restThreshold=10.,
~enabled=smoothScroll && isScrollAnimated,
scrollSpringOptions,
);
let%hook (scrollX, _setScrollXImmediately) =
Hooks.spring(
~name="Editor ScrollX Spring",
~target=Editor.scrollX(editor),
~restThreshold=10.,
~enabled=smoothScroll && isScrollAnimated,
Expand Down
2 changes: 1 addition & 1 deletion src/Feature/Editor/SurfaceView.re
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ let%component make =
let%hook hoverTimerActive = React.Hooks.ref(false);
let%hook lastMousePosition = React.Hooks.ref(None);
let%hook (hoverTimer, resetHoverTimer) =
Hooks.timer(~active=hoverTimerActive^, ());
Hooks.timer(~name="Mouse Hover Timer", ~active=hoverTimerActive^, ());

let lineCount = editor |> Editor.totalViewLines;
let indentation = Buffer.getIndentation(buffer);
Expand Down
Loading

0 comments on commit 4616ffb

Please sign in to comment.