Keeps using 100% CPU

[despairblue]

I could figure out which of the two oni process this is and got a callstack for it:

$ sudo gdb -batch -ex bt -p 1120003
[New LWP 1120029]
[New LWP 1120030]
[New LWP 1120031]
[New LWP 1120032]
[New LWP 1120057]
[New LWP 1120069]
[New LWP 1120070]
[New LWP 1120071]
[New LWP 1120072]
[New LWP 1120073]
[New LWP 1120074]
[New LWP 1120075]
[New LWP 1120076]
[New LWP 1120077]
[New LWP 1120078]
[New LWP 1120079]
[New LWP 1120080]
[New LWP 1120081]
[New LWP 1120082]
[New LWP 1120083]
[New LWP 1120085]
[New LWP 1120086]
[New LWP 1120087]
[New LWP 1120088]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
0x0000558de3e08a17 in caml_c_call ()
#0  0x0000558de3e08a17 in caml_c_call ()
#1  0x00007fd117d73c28 in  ()
#2  0x0000558de331a0c3 in camlRevery_UI__ViewNode__renderBorders_1162 ()
#3  0x0000558de42f04a0 in camlSkiaWrapped__Skia_generated_stubs__102 ()
#4  0x00007fd117d73c70 in  ()
#5  0x00007fd117d73c88 in  ()
#6  0x00007fd117d74170 in  ()
#7  0x00007fd117d73c28 in  ()
#8  0x00007fd117d741c8 in  ()
#9  0x0000558de42a1630 in camlRevery_UI__Style__3 ()
#10 0x0000558de42a4cd0 in camlRevery_UI__ViewNode__73 ()
#11 0x00007fd117d73cb8 in  ()
#12 0x00007fd117d74148 in  ()
#13 0x00007fd117d740f0 in  ()
#14 0x00007fd117d73ca0 in  ()
#15 0x00007fd117d74138 in  ()
#16 0x0000558de8012528 in  ()
#17 0x00007fd117d741a0 in  ()
#18 0x0000558de42a4cd0 in camlRevery_UI__ViewNode__73 ()
#19 0x0000558de42a4cd0 in camlRevery_UI__ViewNode__73 ()
#20 0x0000558de663bba8 in  ()
#21 0x3ff0000000000000 in  ()
#22 0x3ff0000000000000 in  ()
#23 0x3ff0000000000000 in  ()
#24 0x0000558de362ec61 in skia_wrapped_stub_57_sk_matrix_concat (x348=<optimized out>, x347=<optimized out>, x346=<optimized out>) at skia_generated_stubs.c:489
#25 0x3ff0000000000000 in  ()
#26 0x000000004019999a in  ()
#27 0x0000558de339d1ac in camlSkiaWrapped__Skia_generated_stubs__fun_3936 ()
#28 0x0000558de8012528 in  ()
#29 0x0000558de331988b in camlRevery_UI__ViewNode__fun_3182 ()
#30 0x00007fd117d74220 in  ()
#31 0x0000558de7fb36a8 in  ()
#32 0x000000004019999a in  ()
#33 0x0000558de8012528 in  ()
#34 0x000000004019999a in  ()
#35 0x0000558de80eef80 in  ()
#36 0x0000558de7e19370 in  ()
#37 0x4049000000000000 in  ()
#38 0x4049000000000000 in  ()
#39 0x3ff0000000000000 in  ()
#40 0x00007fd117d74390 in  ()
#41 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#42 0x0000558de7e19780 in  ()
#43 0x00007fd117d74200 in  ()
#44 0x0000558de7e19760 in  ()
#45 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#46 0x00007fd117d74250 in  ()
#47 0x0000000000000001 in  ()
#48 0x0000558de8012528 in  ()
#49 0x0000558de8012528 in  ()
#50 0x00007fd117d74288 in  ()
#51 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#52 0x0000558de6642648 in  ()
#53 0x00007fd117d74370 in  ()
#54 0x0000558de6642510 in  ()
#55 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#56 0x00007fd117d743c0 in  ()
#57 0x0000000000000001 in  ()
#58 0x0000558de8012528 in  ()
#59 0x0000558de8012528 in  ()
#60 0x00007fd117d743f8 in  ()
#61 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#62 0x0000558de8014b58 in  ()
#63 0x00007fd117d744e0 in  ()
#64 0x0000558de664a130 in  ()
#65 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#66 0x00007fd117d74530 in  ()
#67 0x0000000000000001 in  ()
#68 0x0000558de8012528 in  ()
#69 0x0000558de8012528 in  ()
#70 0x00007fd117d74568 in  ()
#71 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#72 0x0000558de8014940 in  ()
#73 0x00007fd117d74650 in  ()
#74 0x0000558de7e576d0 in  ()
#75 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#76 0x00007fd117d746a0 in  ()
#77 0x0000000000000001 in  ()
#78 0x0000558de8012528 in  ()
#79 0x0000558de8012528 in  ()
#80 0x00007fd117d746d8 in  ()
#81 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#82 0x0000558deaa80be0 in  ()
#83 0x00007fd117d747c0 in  ()
#84 0x0000558de7e57e28 in  ()
#85 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#86 0x00007fd117d74810 in  ()
#87 0x0000000000000001 in  ()
#88 0x0000558de8012528 in  ()
#89 0x0000558de8012528 in  ()
#90 0x00007fd117d74848 in  ()
#91 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#92 0x0000558de8012828 in  ()
#93 0x00007fd117d74930 in  ()
#94 0x0000558de80a8618 in  ()
#95 0x0000558de3307fc6 in camlRevery_UI__Overflow__render_673 ()
#96 0x00007fd117d74980 in  ()
#97 0x0000000000000001 in  ()
#98 0x0000558de8012528 in  ()
#99 0x0000558de8012528 in  ()
#100 0x00007fd117d749b8 in  ()
#101 0x0000558de331e58b in camlRevery_UI__Render__fun_2491 ()
#102 0x00007fd117d74ab8 in  ()
#103 0x00007fd117d74b88 in  ()
#104 0x0000558de8012828 in  ()
#105 0x0000558de8012528 in  ()
#106 0x0000558de80a8658 in  ()
#107 0x0000558de331e37d in camlRevery_UI__Render__render_inner_2405 ()
#108 0x0000000000000001 in  ()
#109 0x0000558de818d2f8 in  ()
#110 0x0000558de818c560 in  ()
#111 0x0000000000000c81 in  ()
#112 0x00000000000007b1 in  ()
#113 0x8000000000000001 in  ()
#114 0x0000000000000001 in  ()
#115 0x8000000000000001 in  ()
#116 0x8000000000000001 in  ()
#117 0x0000000000000001 in  ()
#118 0x0000000000000009 in  ()
#119 0x0000000000000001 in  ()
#120 0x0000000000000001 in  ()
#121 0x0000000000000001 in  ()
#122 0x8000000000000001 in  ()
#123 0x8000000000000001 in  ()
#124 0x8000000000000001 in  ()
#125 0x8000000000000001 in  ()
#126 0x0000558de42a1608 in camlRevery_UI__Style__6 ()
#127 0x0000000000000003 in  ()
#128 0x8000000000000001 in  ()
#129 0x8000000000000001 in  ()
#130 0x8000000000000001 in  ()
#131 0x8000000000000001 in  ()
#132 0x8000000000000001 in  ()
#133 0x8000000000000001 in  ()
#134 0x8000000000000001 in  ()
#135 0x8000000000000001 in  ()
#136 0x8000000000000001 in  ()
#137 0x8000000000000001 in  ()
#138 0x8000000000000001 in  ()
#139 0x8000000000000001 in  ()
#140 0x8000000000000001 in  ()
#141 0x8000000000000001 in  ()
#142 0x8000000000000001 in  ()
#143 0x8000000000000001 in  ()
#144 0x8000000000000001 in  ()
#145 0x8000000000000001 in  ()
#146 0x0000000000000001 in  ()
#147 0x00007fd117dd7100 in  ()
#148 0x00007fd117dd70e8 in  ()
#149 0x00007fd117dd70d0 in  ()
#150 0x00007fd117dd70b8 in  ()
#151 0x00007fd117dd70a0 in  ()
#152 0x00007fd117dd7088 in  ()
#153 0x00007fd117dd7070 in  ()
#154 0x0000558de42a1630 in camlRevery_UI__Style__3 ()
#155 0x0000000000000001 in  ()
#156 0x0000558de42a1620 in camlRevery_UI__Style__4 ()
#157 0x0000000000000001 in  ()
#158 0x0000000000000001 in  ()
#159 0x0000558de80a8658 in  ()
#160 0x0000558de80b5368 in  ()
#161 0x0000000000000c81 in  ()
#162 0x0000558de80a8220 in  ()
#163 0x0000000000000001 in  ()
#164 0x4003333333333333 in  ()
#165 0x0000558de33381f7 in camlRevery_Core__Window__render_1451 ()
#166 0x0000558de80b5368 in  ()
#167 0x0000558de358f0e1 in camlStdlib__list__iter_258 ()
#168 0x0000558ded6f21c8 in  ()
#169 0x0000558de42c66a8 in camlRevery_Core__App__149 ()
#170 0x0000000000000001 in  ()
#171 0x0000558de333c4e1 in camlRevery_Core__App__appLoop_1324 ()
#172 0x0000000000000001 in  ()
#173 0x0000558de7e22230 in  ()
#174 0x00007fd117e1f240 in  ()
#175 0x0000558de33bf866 in camlSdl2___nativeLoop_1314 ()
#176 0x0000558de7e22230 in  ()
#177 0x0000558de3e08a84 in caml_start_program ()
#178 0x00007ffc8f8a60c0 in  ()
#179 0x0000558de3e08ab5 in caml_start_program ()
#180 0x00007ffc8f8a6070 in  ()
#181 0x0000558de33becb9 in camlSdl2__main_792 ()
#182 0x00007ffc8f8a5e00 in  ()
#183 0x000000005f5121a6 in  ()
#184 0x0000000020bd958b in  ()
#185 0x00007fd117e1f248 in  ()
#186 0x0000558de60d97d0 in  ()
#187 0x0000000000000001 in  ()
#188 0x00007fd117e1f598 in  ()
#189 0x00007ffc8f8a6060 in  ()
#190 0x00007fd117e1f2f8 in  ()
#191 0x0000558de3e0024a in caml_callback_exn (arg=<optimized out>, closure=<optimized out>) at callback.c:145
#192 caml_callback (closure=<optimized out>, arg=<optimized out>) at callback.c:199
#193 0x0000558de3ba96d7 in resdl_SDL_main(value, value, value) (ml_argc=94067906712288, ml_argv=94067906712264, closure=94067906712240) at sdl2_wrapper.cpp:1640
[Inferior 1 (process 1120003) detached]

Not sure if this helps.

[bryphe]

Thanks @despairblue , that does help!

There's a few cases we run into where we continue to 'dirty' the UI in the background - a few cases I've seen:

• QuickOpen / fuzzy finder
• Search pane
• File Explorer

I need to narrow down add some test cases to help ensure we don't get into this constant-re-render state

[lucis]

+1 here!

I couldn't quite track or metrify the usage, but from hearing the vents on my MPB it's clear that the editor is using a lot of power. I believe it wasn't related to specific usage, just plain file editing.

[jamesgecko]

I haven't figured out a reliable reproduction, but I've managed to hit 100% CPU with only two or three onivim config files open in the editor.

[tristil]

With OniVim open in a large repository I get this (Macos):

[enisdenjo]

In my case, this happens only in TypeScript projects. For example in Go projects (with the VSCode Go extension installed), I haven't had any resource consumption problems whatsoever.

[despairblue]

For me it happens regularly with reason projects.

[jsiebern]

It happens to me almost always (no matter which language) after a certain time. The activity manager in OSX shows an insane number of reactivations (sometimes 10k +), that's when it shoots up in CPU usage and powers up the macbook jet engines...

[bryphe]

Ouch, interesting - one thing that might be helpful is a log file. But it's a bit of pain since it seems, in some of those repros, it's only happening after a while. What I'm curious is if there are some events being logged out periodically that are causing us to wake-up / re-render - that might help narrow the issue down.

I'll look into adding a way to get the logs / events at runtime so we can narrow it down. With that switch, once this high CPU usage is observed, we could flip the logging on (ie, via an option in the command palette) and figure out if there is an obvious culprit.

[jsiebern]

I have just worked a few hours with the editor and I can say this for sure now: It's fine if I never cmd+tab away. But I literally had it happening just now opening a browser window and writing this message. That switch would be much appreciated, I'd be happy to provide you with anything else you'd need for debugging as well.

This issue is literally the only thing that is a show stopper for starting to advocate the editor to my boss (I can't defend frequent restarts). It's like torture because I learned to love this editor so damn much 😍 (VSCode feels so dang janky now)

/ Edit: Just looked into the docs for creating that log file, I'll try to get a snapshot of it happening if possible

[bryphe]

I can't defend frequent restarts

Totally understandable @jsiebern ! Want to get to the bottom of it. Hope you can recommend it to your boss after we get this fixed 😄

Just looked into the docs for creating that log file, I'll try to get a snapshot of it happening if possible

Sounds good! It might not be the most useful at the moment, since it seems like it happens when you Cmd+Tab - but I'll work on adding this switch on Monday. That way, once we see this happen - we can collect the data and get to the bottom of it.

Hopefully we can get some more info once that's in place - thanks for all the help / information so far

[jsiebern]

Bad news I think. I'm not able to reproduce it now, the "workaround" to the problem seems to be the performance hit for -f -debug. At least for me. That'll make it real hard to track down then 😣

The Idle Wake Ups value that can easily jump to 10k+ (which is usually the point of no return with 25% GPU & 80%+ CPU) without these flags will never go much higher than 4k now.

Sorry for the spam, just trying to add some data points.

[jsiebern]

Okay, so I think I might have a way to reproduce it sort of reliably. I worked in a lot of open files (approx 15 I think). I needed to do some work in all of them, just opening them without doing anything didn't work. Then I closed all of them quickly by hitting CMD+W which resulted in the described behavior. I could repeat this twice now.

I have attached a log file of that session, but as you said, it's doubtful if it's any good. The last parts might be of value though, as I have just closed all files and then watched the activity monitor. I then let the CPU and GPU stuff run for a few seconds and terminated the process. So hopefully it caught something at the end.

oni.log.zip

[bryphe]

Thanks for the log, @jsiebern !

It seems like, towards the end of the log, when the windows are closing - there's some activity with SCM:

[DEBUG]    +9ms Oni2.Store.StoreThread : Running effect: Batch:
 scm.getOriginalSourceLines

[DEBUG]    +0ms Oni2.Store.StoreThread : Effect complete: Batch:
 scm.getOriginalSourceLines

[INFO]    +18ms Oni2.Store.dispatch : dispatch: (SCM
   GotOriginalContent {bufferId = 17;
     lines =

This is where we ask the SCM provider for the 'original' content, so that we can show diff markers in the editor.

I'm wondering, for your repro case - what is the working directory? Is it a monorepo with some nested git repos inside? Or a single git repository?

I also saw some syntax highlighting activity:

[INFO]     +0ms Oni2.Store.dispatch : dispatch: (Syntax TokensHighlighted {bufferId = 17; tokens = <opaque>})
[DEBUG]    +0ms Oni2.Store.dispatch : After: (Syntax TokensHighlighted {bufferId = 17; tokens = <opaque>})

which is a bit curious, as we shouldn't need to do any extra syntax highlighting work for buffers that are unmodified and already open.

Working on a change here to be able to turn on logging at runtime: https://github.com/onivim/oni2/pull/2598

[jsiebern]

@bryphe Thanks for looking into it. It's a subdirectory of a single git repo, no nested git repos inside. But it happened in basically every directory I have worked in so far - I just found a way to make it fail here with closing the files.

I'll try to catch it with runtime logging as soon as that's available in nightly. Let me know if I can do anything else to provide you with better data.

[despairblue]

Ran into this yesterday a lot too (not using oni for daily work yet). For me it mostly happens when I have a couple of files open, then closing some of them and then using ctrl-tab to switch between open files and by this accidentally reopening closed files (as ctrl tab retains a list of every file ever opened). So ctrl-tab seems to be one of the cases triggering it for me.

I can also see that this may be related to the git markers or at least breaking them as they don't update anymore for me, e.g. if I add a line above a change marker then the added line shows up as changed and the changed line below has no marker anymore.

[bryphe]

Thanks @jsiebern and @despairblue for the extra details. Still working on getting https://github.com/onivim/oni2/pull/2598 through (CI issues).

One extra data point would be to track down exactly process has the high-CPU usage.

@jsiebern - On OSX - in activity monitor - setting View -> All Process, Hierarchically can help:

In particular, this could tell us whether the high CPU usage is in node (vscode extension host, or the git extension), if it is in the syntax highlight service, or the core editor.

@despairblue - I think we can get similar info with htop when pressing F5. It looks like from your original screenshot it's likely the core editor process - but this can help us confirm.

It sounds like in both cases, it's occurring when files are closed (and re-opened). In the meantime, there's a couple of items I'm going to look at to start as I continue working on reproducing:

• The way we sync back SCM markers in the file explorer is expensive. I don't think this is the culprit, but something to streamline.
• The way we ask for the 'original content' with multiple SCM providers is potentially problematic - I also don't think it's the culprit, but it could be related to the quirkiness observed with the change markers.
• I'll update the extension host + SCM / git extension, to pick up any fixes coming

[jsiebern]

@bryphe Sorry, no dice with more details (or rather confirmation then I suppose):

But @despairblue is absolutely right, I just had one file open now and did a CTRL+TAB several times: Spun right out of control.

I'm gonna test this some more by only CMD+P opening files for a while (and won't close any).

[bryphe]

Thanks @jsiebern - it's actually really helpful! Confirms that the CPU usage is in the main editor process (the one that does the rendering), and not the syntax highlight or vscode extension host.

If we can get a debug trace via #2598 :

...should be able to get some details. The PR is merged in master, but not yet on the portal - should make it in tonight's nightly.

[jsiebern]

Closing tabs with :q doesn't seem to trigger it btw. I also noticed the following behaviour that could be related:

• Open a folder
• Open & Edit a file (make a change)
• CMD+W close the file
• Try to exit the editor

It seems that buffers of tabs closed by CMD+W are kept around in the background when they shouldn't. (Just tested :q! with the same setup, same behaviour actually)

Waiting on the nightly now to provide you with a trace log 😊

[despairblue]

I updated today and used the trace command. When I tail the trace file the only thing it prints out is Oni2.Syntax.Server : Parent still active.

Details

-- Log started at 2020-10-23T10:42:37Z -- [INFO] [ 0.000s] Oni2.Store.dispatch : dispatch: (Logging (Feature_Logging.LogFileStarted "onivim2-trace.log")) [DEBUG] [ 0.004s] Oni2.Store.dispatch : After: (Logging (Feature_Logging.LogFileStarted "onivim2-trace.log")) [DEBUG] [ 0.004s] Oni2.Store.StoreThread : Effect complete: Batch: Feature.Logging.traceToFile [DEBUG] [ 0.016s] Oni2.Store.StoreThread : Running effect: Batch: notification.create [INFO] [ 0.016s] Oni2.Store.dispatch : dispatch: (Notification (Created { id = 8; kind = Info; message = "Logging to: onivim2-trace.log"; source = None })) [DEBUG] [ 0.016s] Oni2.Store.dispatch : After: (Notification (Created { id = 8; kind = Info; message = "Logging to: onivim2-trace.log"; source = None })) [DEBUG] [ 0.016s] Oni2.Store.StoreThread : Effect complete: Batch: notification.create [INFO] [ 0.066s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [ 0.067s] Oni2.Store.dispatch : After: (KeyUp (, )) [DEBUG] [ 0.067s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [ 0.067s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [TRACE] [ 3.197s] Oni2.Syntax.Server : Parent still active. [INFO] [ 4.005s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [ 4.006s] Oni2.Input.Handler : keyPressToString - key name: Left GUI [TRACE] [ 4.006s] Oni2.Input.Handler : Processing keycode: 1073742051|Left GUI [TRACE] [ 4.006s] Oni2.Input.Handler : Key blocked: Left GUI [DEBUG] [ 4.007s] Oni2.Store.dispatch : After: (KeyDown (, )) [DEBUG] [ 4.008s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [ 4.008s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [INFO] [ 4.187s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [ 4.187s] Oni2.Store.dispatch : After: (KeyUp (, )) [INFO] [ 4.188s] Oni2.Store.dispatch : dispatch: WindowFocusLost [DEBUG] [ 4.188s] Oni2.Store.dispatch : After: WindowFocusLost [DEBUG] [ 4.189s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [ 4.189s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [TRACE] [ 8.198s] Oni2.Syntax.Server : Parent still active. [TRACE] [13.206s] Oni2.Syntax.Server : Parent still active. [INFO] [17.389s] Oni2.Store.dispatch : dispatch: WindowFocusGained [DEBUG] [17.390s] Oni2.Store.dispatch : After: WindowFocusGained [INFO] [17.390s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [17.390s] Oni2.Input.Handler : keyPressToString - key name: 2 [TRACE] [17.390s] Oni2.Input.Handler : Processing keycode: 50|2 [TRACE] [17.390s] Oni2.Input.Handler : Key blocked: 2 [DEBUG] [17.391s] Oni2.Store.dispatch : After: (KeyDown (, )) [INFO] [17.391s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [17.391s] Oni2.Input.Handler : keyPressToString - key name: Left GUI [TRACE] [17.391s] Oni2.Input.Handler : Processing keycode: 1073742051|Left GUI [TRACE] [17.391s] Oni2.Input.Handler : Key blocked: Left GUI [DEBUG] [17.392s] Oni2.Store.dispatch : After: (KeyDown (, )) [DEBUG] [17.392s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [17.392s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [DEBUG] [17.392s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [17.392s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [INFO] [17.527s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [17.527s] Oni2.Store.dispatch : After: (KeyUp (, )) [INFO] [17.527s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [17.528s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [17.528s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [17.528s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [DEBUG] [17.528s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [17.528s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [17.528s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [17.528s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [17.825s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [17.825s] Oni2.Store.dispatch : After: (KeyUp (, )) [DEBUG] [17.826s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [17.826s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [TRACE] [18.205s] Oni2.Syntax.Server : Parent still active. [INFO] [18.528s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [18.528s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [18.529s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.529s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [18.529s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [18.529s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [18.541s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 31; byte = 24 }}} [DEBUG] [18.543s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 31; byte = 24 }}} [INFO] [18.543s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 33; byte = 62 }}} [DEBUG] [18.544s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 33; byte = 62 }}} [DEBUG] [18.544s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.544s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 31; character = 24 }))) [DEBUG] [18.544s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 31; character = 24 }))) [DEBUG] [18.544s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [18.544s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.544s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 33; character = 62 }))) [DEBUG] [18.544s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 33; character = 62 }))) [DEBUG] [18.544s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [18.561s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 36; byte = 63 }}} [DEBUG] [18.562s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 36; byte = 63 }}} [INFO] [18.562s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 38; byte = 62 }}} [DEBUG] [18.562s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 38; byte = 62 }}} [INFO] [18.562s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 40; byte = 55 }}} [DEBUG] [18.562s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 40; byte = 55 }}} [DEBUG] [18.563s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.563s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 36; character = 63 }))) [DEBUG] [18.563s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 36; character = 63 }))) [DEBUG] [18.563s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [18.563s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.563s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 38; character = 62 }))) [DEBUG] [18.563s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 38; character = 62 }))) [DEBUG] [18.563s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [18.563s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.563s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 40; character = 55 }))) [DEBUG] [18.563s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 40; character = 55 }))) [DEBUG] [18.563s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [18.575s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 42; byte = 14 }}} [DEBUG] [18.576s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 42; byte = 14 }}} [INFO] [18.576s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 17 }}} [DEBUG] [18.576s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 17 }}} [DEBUG] [18.576s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.576s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 42; character = 14 }))) [DEBUG] [18.576s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 42; character = 14 }))) [DEBUG] [18.576s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [18.576s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.576s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 17 }))) [DEBUG] [18.577s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 17 }))) [DEBUG] [18.577s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [18.591s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [DEBUG] [18.591s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [INFO] [18.591s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 47; byte = 19 }}} [DEBUG] [18.592s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 47; byte = 19 }}} [DEBUG] [18.592s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.592s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [18.592s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [18.592s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [18.592s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.592s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 47; character = 19 }))) [DEBUG] [18.593s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 47; character = 19 }))) [DEBUG] [18.593s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [18.603s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 48; byte = 9 }}} [DEBUG] [18.604s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 48; byte = 9 }}} [DEBUG] [18.604s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [18.604s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 48; character = 9 }))) [DEBUG] [18.604s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 48; character = 9 }))) [DEBUG] [18.604s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [19.566s] Oni2.Store.dispatch : dispatch: (StatusBar Feature_StatusBar.NotificationCountClicked) [DEBUG] [19.567s] Oni2.Store.dispatch : After: (StatusBar Feature_StatusBar.NotificationCountClicked) [INFO] [19.595s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 979; widthInPixels = 223}))) [DEBUG] [19.595s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 979; widthInPixels = 223}))) [INFO] [19.605s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 953; widthInPixels = 223}))) [DEBUG] [19.606s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 953; widthInPixels = 223}))) [INFO] [19.606s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1085} [TRACE] [19.606s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.606s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1085} [TRACE] [19.612s] Oni2.Syntax.Server : Visibility changed [INFO] [19.617s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 927; widthInPixels = 223}))) [DEBUG] [19.617s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 927; widthInPixels = 223}))) [INFO] [19.617s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1059} [TRACE] [19.618s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.618s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1059} [TRACE] [19.624s] Oni2.Syntax.Server : Visibility changed [INFO] [19.628s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 900; widthInPixels = 223}))) [DEBUG] [19.628s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 900; widthInPixels = 223}))) [INFO] [19.628s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1033} [TRACE] [19.628s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.628s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1033} [TRACE] [19.634s] Oni2.Syntax.Server : Visibility changed [INFO] [19.638s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 879; widthInPixels = 223}))) [DEBUG] [19.638s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 879; widthInPixels = 223}))) [INFO] [19.638s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1006} [TRACE] [19.638s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.638s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 1006} [TRACE] [19.644s] Oni2.Syntax.Server : Visibility changed [INFO] [19.648s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 860; widthInPixels = 223}))) [DEBUG] [19.649s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 860; widthInPixels = 223}))) [INFO] [19.649s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 985} [TRACE] [19.649s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.649s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 985} [TRACE] [19.655s] Oni2.Syntax.Server : Visibility changed [INFO] [19.659s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 844; widthInPixels = 223}))) [DEBUG] [19.660s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 844; widthInPixels = 223}))) [INFO] [19.660s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 966} [TRACE] [19.660s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.660s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 966} [TRACE] [19.666s] Oni2.Syntax.Server : Visibility changed [INFO] [19.669s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 832; widthInPixels = 223}))) [DEBUG] [19.669s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 832; widthInPixels = 223}))) [INFO] [19.669s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 950} [DEBUG] [19.670s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 950} [INFO] [19.681s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 822; widthInPixels = 223}))) [DEBUG] [19.682s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 822; widthInPixels = 223}))) [INFO] [19.682s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 938} [TRACE] [19.682s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.682s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 938} [TRACE] [19.691s] Oni2.Syntax.Server : Visibility changed [INFO] [19.696s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 813; widthInPixels = 223}))) [DEBUG] [19.697s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 813; widthInPixels = 223}))) [INFO] [19.697s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 928} [TRACE] [19.697s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.697s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 928} [TRACE] [19.703s] Oni2.Syntax.Server : Visibility changed [INFO] [19.707s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 808; widthInPixels = 223}))) [DEBUG] [19.709s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 808; widthInPixels = 223}))) [INFO] [19.709s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 919} [DEBUG] [19.710s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 919} [INFO] [19.719s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 805; widthInPixels = 223}))) [DEBUG] [19.719s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 805; widthInPixels = 223}))) [INFO] [19.719s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 914} [DEBUG] [19.719s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 914} [INFO] [19.729s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 803; widthInPixels = 223}))) [DEBUG] [19.730s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 803; widthInPixels = 223}))) [INFO] [19.730s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 911} [DEBUG] [19.730s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 911} [INFO] [19.739s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 909} [DEBUG] [19.740s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 909} [INFO] [19.749s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 802; widthInPixels = 223}))) [DEBUG] [19.749s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 802; widthInPixels = 223}))) [INFO] [19.760s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 803; widthInPixels = 223}))) [DEBUG] [19.761s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 803; widthInPixels = 223}))) [INFO] [19.761s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 908} [TRACE] [19.761s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.761s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 908} [TRACE] [19.767s] Oni2.Syntax.Server : Visibility changed [INFO] [19.771s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 909} [TRACE] [19.771s] Oni2.Syntax.Client : Sending visibleRangesChanged notification... [DEBUG] [19.771s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 909} [TRACE] [19.777s] Oni2.Syntax.Server : Visibility changed [INFO] [19.780s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 804; widthInPixels = 223}))) [DEBUG] [19.781s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 804; widthInPixels = 223}))) [INFO] [19.790s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 805; widthInPixels = 223}))) [DEBUG] [19.791s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 805; widthInPixels = 223}))) [INFO] [19.791s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 910} [DEBUG] [19.791s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 910} [INFO] [19.802s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 806; widthInPixels = 223}))) [DEBUG] [19.802s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 806; widthInPixels = 223}))) [INFO] [19.802s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 911} [DEBUG] [19.803s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 911} [INFO] [19.813s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 912} [DEBUG] [19.814s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 912} [INFO] [19.827s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 807; widthInPixels = 223}))) [DEBUG] [19.827s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 807; widthInPixels = 223}))) [INFO] [19.844s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 808; widthInPixels = 223}))) [DEBUG] [19.844s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 808; widthInPixels = 223}))) [INFO] [19.844s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 913} [DEBUG] [19.845s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 913} [INFO] [19.856s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 809; widthInPixels = 223}))) [DEBUG] [19.858s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 809; widthInPixels = 223}))) [INFO] [19.858s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 914} [DEBUG] [19.858s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 914} [INFO] [19.870s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 915} [DEBUG] [19.871s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 915} [INFO] [19.897s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 810; widthInPixels = 223}))) [DEBUG] [19.897s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 810; widthInPixels = 223}))) [INFO] [19.911s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 916} [DEBUG] [19.912s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 916} [INFO] [19.998s] Oni2.Store.dispatch : dispatch: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 809; widthInPixels = 223}))) [DEBUG] [19.998s] Oni2.Store.dispatch : After: (Search (ResultsList (Component_VimTree.List Component_VimList.ViewDimensionsChanged {heightInPixels = 809; widthInPixels = 223}))) [INFO] [20.008s] Oni2.Store.dispatch : dispatch: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 915} [DEBUG] [20.008s] Oni2.Store.dispatch : After: EditorSizeChanged {id = 2; pixelWidth = 1637; pixelHeight = 915} [INFO] [21.275s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [DEBUG] [21.276s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [DEBUG] [21.277s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.277s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [21.277s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [21.277s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.290s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [DEBUG] [21.291s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 46; byte = -1 }}} [INFO] [21.291s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 45; byte = 3 }}} [DEBUG] [21.291s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 45; byte = 3 }}} [DEBUG] [21.291s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.291s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [21.291s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 46; character = 0 }))) [DEBUG] [21.291s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [21.291s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.291s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 45; character = 3 }))) [DEBUG] [21.291s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 45; character = 3 }))) [DEBUG] [21.291s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.304s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 45; byte = 5 }}} [DEBUG] [21.305s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 45; byte = 5 }}} [INFO] [21.305s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 6 }}} [DEBUG] [21.305s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 6 }}} [DEBUG] [21.306s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.306s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 45; character = 5 }))) [DEBUG] [21.306s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 45; character = 5 }))) [DEBUG] [21.306s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [21.306s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.306s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 6 }))) [DEBUG] [21.307s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 6 }))) [DEBUG] [21.307s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.310s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 44; byte = 6 }}} [DEBUG] [21.311s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 44; byte = 6 }}} [INFO] [21.319s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 7 }}} [DEBUG] [21.319s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 7 }}} [INFO] [21.320s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 9 }}} [DEBUG] [21.320s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 44; byte = 9 }}} [DEBUG] [21.320s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousehovered [INFO] [21.320s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 44; character = 6 }))) [DEBUG] [21.320s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 44; character = 6 }))) [DEBUG] [21.320s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousehovered [DEBUG] [21.320s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.320s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 7 }))) [DEBUG] [21.321s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 7 }))) [DEBUG] [21.321s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [21.321s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.321s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 9 }))) [DEBUG] [21.321s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 44; character = 9 }))) [DEBUG] [21.321s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.330s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 9 }}} [DEBUG] [21.330s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 9 }}} [INFO] [21.330s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 10 }}} [DEBUG] [21.331s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 10 }}} [DEBUG] [21.331s] Oni2.Store.StoreThread : Running effect: Batch: Batch: language.provideHover [DEBUG] [21.331s] Oni2.Store.StoreThread : Effect complete: Batch: Batch: language.provideHover [DEBUG] [21.331s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.331s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 9 }))) [DEBUG] [21.331s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 9 }))) [DEBUG] [21.331s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [21.331s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.331s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 10 }))) [DEBUG] [21.332s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 10 }))) [DEBUG] [21.332s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.340s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [21.341s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [21.341s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.341s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.341s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.341s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.350s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [21.350s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [INFO] [21.350s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [21.351s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [21.351s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.351s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.351s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.351s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [DEBUG] [21.351s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [21.351s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.351s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 43; character = 11 }))) [DEBUG] [21.351s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [21.643s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [21.643s] Oni2.Input.Handler : keyPressToString - key name: Left GUI [TRACE] [21.644s] Oni2.Input.Handler : Processing keycode: 1073742051|Left GUI [TRACE] [21.644s] Oni2.Input.Handler : Key blocked: Left GUI [DEBUG] [21.644s] Oni2.Store.dispatch : After: (KeyDown (, )) [DEBUG] [21.644s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [21.644s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [INFO] [21.827s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [21.828s] Oni2.Store.dispatch : After: (KeyUp (, )) [INFO] [21.829s] Oni2.Store.dispatch : dispatch: WindowFocusLost [DEBUG] [21.829s] Oni2.Store.dispatch : After: WindowFocusLost [DEBUG] [21.829s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [21.829s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [INFO] [22.349s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [22.349s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [22.355s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousehovered [INFO] [22.355s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 43; character = 11 }))) [DEBUG] [22.355s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 43; character = 11 }))) [DEBUG] [22.355s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousehovered [INFO] [22.357s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [22.358s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseHovered {bytePosition = { line = 43; byte = 11 }}} [DEBUG] [22.364s] Oni2.Store.StoreThread : Running effect: Batch: Batch: language.provideHover [DEBUG] [22.364s] Oni2.Store.StoreThread : Effect complete: Batch: Batch: language.provideHover [DEBUG] [22.364s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousehovered [INFO] [22.365s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 43; character = 11 }))) [DEBUG] [22.365s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseHovered { line = 43; character = 11 }))) [DEBUG] [22.365s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousehovered [DEBUG] [22.372s] Oni2.Store.StoreThread : Running effect: Batch: Batch: language.provideHover [DEBUG] [22.372s] Oni2.Store.StoreThread : Effect complete: Batch: Batch: language.provideHover [TRACE] [23.209s] Oni2.Syntax.Server : Parent still active. [TRACE] [28.213s] Oni2.Syntax.Server : Parent still active. [TRACE] [33.214s] Oni2.Syntax.Server : Parent still active. [TRACE] [38.221s] Oni2.Syntax.Server : Parent still active. [TRACE] [43.223s] Oni2.Syntax.Server : Parent still active. [TRACE] [48.222s] Oni2.Syntax.Server : Parent still active. [TRACE] [53.235s] Oni2.Syntax.Server : Parent still active. [INFO] [53.372s] Oni2.Store.dispatch : dispatch: WindowFocusGained [DEBUG] [53.372s] Oni2.Store.dispatch : After: WindowFocusGained [INFO] [53.372s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [53.373s] Oni2.Input.Handler : keyPressToString - key name: 2 [TRACE] [53.373s] Oni2.Input.Handler : Processing keycode: 50|2 [TRACE] [53.373s] Oni2.Input.Handler : Key blocked: 2 [DEBUG] [53.373s] Oni2.Store.dispatch : After: (KeyDown (, )) [INFO] [53.373s] Oni2.Store.dispatch : dispatch: (KeyDown (, )) [TRACE] [53.373s] Oni2.Input.Handler : keyPressToString - key name: Left GUI [TRACE] [53.373s] Oni2.Input.Handler : Processing keycode: 1073742051|Left GUI [TRACE] [53.373s] Oni2.Input.Handler : Key blocked: Left GUI [DEBUG] [53.373s] Oni2.Store.dispatch : After: (KeyDown (, )) [DEBUG] [53.374s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [53.374s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [DEBUG] [53.374s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [53.374s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [INFO] [53.487s] Oni2.Store.dispatch : dispatch: (KeyUp (, )) [DEBUG] [53.488s] Oni2.Store.dispatch : After: (KeyUp (, )) [INFO] [53.488s] Oni2.Store.dispatch : dispatch: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [53.489s] Oni2.Store.dispatch : After: Editor {scope = (EditorScope.Editor 2); msg = MouseMoved {bytePosition = { line = 29; byte = 30 }}} [DEBUG] [53.490s] Oni2.Store.StoreThread : Running effect: Batch: input.immediateDispatch [DEBUG] [53.490s] Oni2.Store.StoreThread : Effect complete: Batch: input.immediateDispatch [DEBUG] [53.490s] Oni2.Store.StoreThread : Running effect: Batch: editor.mousemoved [INFO] [53.490s] Oni2.Store.dispatch : dispatch: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [53.491s] Oni2.Store.dispatch : After: (LanguageSupport (Feature_LanguageSupport.Hover (MouseMoved { line = 29; character = 30 }))) [DEBUG] [53.491s] Oni2.Store.StoreThread : Effect complete: Batch: editor.mousemoved [INFO] [53.839s] Oni2.Store.dispatch : dispatch: (Quit true) [DEBUG] [53.840s] Oni2.Store.dispatch : After: (Quit true)

[jsiebern]

Here's a trace from one of my setups where it goes nuts: onivim2-trace.log.zip

(The beginning will probably be the most interesting as I started the log after being in that high CPU state for a while already as I didn't realize it until the system slowed down significantly)

[despairblue]

This may be interesting:

logs.zip

After a while I noticed the CPU going crazy again and started the trace, I tailed the file and it spammed my terminal with this:

[TRACE] [ 0.018s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.020s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [ 0.020s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [ 0.025s] Revery.UI.Render : END: Render frame
[TRACE] [ 0.026s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.035s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [ 0.035s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [ 0.046s] Revery.UI.Render : END: Render frame
[TRACE] [ 0.046s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.048s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [ 0.048s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [ 0.054s] Revery.UI.Render : END: Render frame
[TRACE] [ 0.055s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.055s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [ 0.055s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [ 0.061s] Revery.UI.Render : END: Render frame
[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

Most of the file is just this. I close oni after 25 seconds and 1.5 mb of logs.

[bryphe]

Thanks @despairblue and @jsiebern for the logs! Very helpful.

Indeed, seems like both cases got stuck in this loop:

[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

It looks like we're getting stuck in a case where Revery ends up animating non-stop - continually asking for a re-render because it's animating something. Trying to dive in and see why this could be occurring-

[jsiebern]

Trace log with #2629 in case that helps: onivim2-trace.log.zip

[despairblue]

Also did a new one:

logs.zip

Mostly

[TRACE] [14.430s] Revery.Tick : Tick.pump - starting with 3 active tickers.
[TRACE] [14.430s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[TRACE] [14.430s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [14.431s] Revery.Tick : Interval - running timer: Mouse Hover Timer 75
[TRACE] [14.431s] Revery.Tick : Tick.pump - ending with 3 active tickers.
[TRACE] [14.431s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [14.431s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [14.431s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [14.443s] Revery.UI.Render : END: Render frame

[bryphe]

Thanks @despairblue and @jsiebern ! You're a step ahead of me, I just was thinking I should let you know that #2629 is in :smile: Really appreciate the logs.

The logs are very helpful - it seems the commonality in both your logs is that there is this a runaway mouse hover timer:

[TRACE] [14.431s] Revery.Tick : Interval - running timer: Mouse Hover Timer 75

I'll dive into this further and see why it's being stuck open. The timer will cause a re-render while active, but it shouldn't be active for long - must be a bug there. Will investigate further and keep you posted

[jsiebern]

@bryphe Thank you so much - after a first few test runs with the current nightly it seems fixed! I'll keep an eye out for it happening again, but so far no issues where I could reproduce it easily before.

Update: I got a light version of it this time. It did not go as crazy and only after doing some editing / closing & opening a lot of files, hopefully this trace will help: onivim2-trace.log.zip

[despairblue]

Had it again:

logs.zip

[TRACE] [20.038s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [20.042s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [20.042s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1181
[TRACE] [20.062s] Revery.UI.Render : END: Render frame
[TRACE] [20.062s] Revery.Tick : Tick.pump - starting with 3 active tickers.
[TRACE] [20.062s] Revery.Tick : Interval - running timer: Editor ScrollY Spring 338
[TRACE] [20.062s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[TRACE] [20.062s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [20.062s] Revery.Tick : Tick.pump - ending with 3 active tickers.

The mouse ticker is gone though, so one of them was fixed with the PR done :+1:

[jsiebern]

Just had another one as well going crazy (90+% CPU): onivim2-trace.log.zip

[TRACE] [ 5.070s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 5.070s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 1.000000 zoom: 1.000000 canvasScaling: 1.000000
[TRACE] [ 5.070s] Revery.UI.Render : -- RENDER: adjustedWidth: 2560 adjustedHeight: 1338
[TRACE] [ 5.092s] Revery.UI.Render : END: Render frame
[TRACE] [ 5.092s] Revery.Tick : Tick.pump - starting with 3 active tickers.
[TRACE] [ 5.092s] Revery.Tick : Interval - running timer: Editor ScrollY Spring 257
[TRACE] [ 5.092s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[TRACE] [ 5.092s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [ 5.094s] Revery.Tick : Tick.pump - ending with 3 active tickers.

[glennsl]

My bet is that it's the "Editor ScrollY Spring" timer. Might be an idea to try setting editor.smoothScoll to false.

[despairblue]

Huh, there is editor.smoothScoll and also experimental.editor.smoothScroll according to the docs: https://onivim.github.io/docs/configuration/settings

I set both to false, but scrolling is still smooth. :thinking:

[glennsl]

@despairblue The experimental setting no longer exists, it just hasn't been removed from the docs. I submitted #2665 earlier today to fix it.

Setting editor.smoothScroll to false works for me. You should see it if you jump between the top and bottom of a long file, for example. When enabled the viewport will scroll gradually, and when disabled it will jump instantly.

[despairblue]

I'll make a video tomorrow. For me everything still scrolls in an animated way. 🤷

[despairblue]

Video: https://youtu.be/vkSn082cpyw

It's still processing the HD version.

[despairblue]

Nevermind me. smoothScoll can't work. It needs an r :facepalm:

Works now, I'll use that and see if it changes the CPU consumption, thanks @glennsl

[despairblue]

I think @glennsl is right, haven't had the issue for 2 days now while using oni for my day job. :clap:

[jsiebern]

Same here. I'm also not getting a bug where the buffer is shifted by a line or so once in a while.

[bryphe]

Thanks for the updates @despairblue and @jsiebern ! Sounds like we're getting closer. Good call @glennsl on the workaround / troubleshooting!

I'm investigating - trying to figure if it's a general error with the spring or timer hooks - or if it's specific to the spring hook.

Same here. I'm also not getting a bug where the buffer is shifted by a line or so once in a while.

@jsiebern - hmm, like the buffer is rendered incorrectly?

[jsiebern]

@bryphe I just had another one unfortunately. Between your recent fix and disabling editor.smoothScroll it has gotten a lot better though (this was the first one today in many hours of work).

onivim2-trace.log.zip

[TRACE] [ 0.189s] Revery.Tick : Tick.pump - starting with 8 active tickers.
[TRACE] [ 0.189s] Revery.Tick : Interval - running timer: Notification Animation 323
[TRACE] [ 0.189s] Revery.Tick : Interval - running timer: StatusBar Notification Expirer 322
[TRACE] [ 0.189s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [ 0.191s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[TRACE] [ 0.191s] Revery.Tick : Interval - running timer: Yank Highlights Animation 108
[TRACE] [ 0.191s] Revery.Tick : Interval - running timer: Yank Highlights Animation 109
[TRACE] [ 0.191s] Revery.Tick : Interval - running timer: StatusBar Background Color Transition 324
[TRACE] [ 0.191s] Revery.Tick : Interval - running timer: StatusBar Foreground Color Transition 325
[TRACE] [ 0.191s] Revery.Tick : Tick.pump - ending with 8 active tickers.
[TRACE] [ 0.191s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.192s] Revery.UI.Render : -- RENDER: pixelRatio: 2.000000 scaleAndZoom: 1.000000 zoom: 1.000000 canvasScaling: 2.000000
[TRACE] [ 0.192s] Revery.UI.Render : -- RENDER: adjustedWidth: 1792 adjustedHeight: 1017
[TRACE] [ 0.205s] Revery.UI.Render : END: Render frame

The trace file is a little bigger as I was unable to end the editor when trying to hit "Save All" (had to go discard all for it to end).

hmm, like the buffer is rendered incorrectly?

Yeah, this might warrant an issue itself. It did not happen without smoothScroll so far though. Also I have to investigate, if it only happens when editing PHP using the "PHP Intelephense" Plugin. If I can reproduce it I'll record a video and open a separate issue (I only get back to PHP next week at work).

---

By the way: Thank you for all your effort and your great communication ❤️

[jsiebern]

It still happens kind of reliably when I CMD+W close a bunch of tabs very fast unfortunately.

Not sure why these Yank Highlights Animation 1763 timers are still around. As it only happens after working a bit inside the files being closed, this might be related?

[TRACE] [ 0.030s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [ 0.032s] Revery.UI.Render : -- RENDER: pixelRatio: 2.000000 scaleAndZoom: 1.000000 zoom: 1.000000 canvasScaling: 2.000000
[TRACE] [ 0.032s] Revery.UI.Render : -- RENDER: adjustedWidth: 1680 adjustedHeight: 949
[TRACE] [ 0.041s] Revery.UI.Render : END: Render frame
[TRACE] [ 0.041s] Revery.Tick : Tick.pump - starting with 8 active tickers.
[TRACE] [ 0.041s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1763
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1762
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1761
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1760
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1758
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Yank Highlights Animation 1757
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Store: Run Effects 1
[TRACE] [ 0.042s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [ 0.045s] Revery.Tick : Tick.pump - ending with 8 active tickers.

onivim2-trace.log.zip

[bryphe]

  Yeah, this might warrant an issue itself. It did not happen without smoothScroll so far though. Also I have to investigate, if it only happens when editing PHP using the "PHP Intelephense" Plugin. If I can reproduce it I'll record a video and open a separate issue (I only get back to PHP next week at work).

An issue would be great for it (and the video) :+1: Thanks for all the help! I wonder if the PHP Intelephense plugin is modifying the file externally, or something. It's interesting that it only reproduces with smooth scroll on.

Not sure why these Yank Highlights Animation 1763 timers are still around. As it only happens after working a bit inside the files being closed, this might be related?

Ya, this is helpful for sure, and does seem related - it confirms my suspicion that the problem is more general.

There's actually a descriptive comment here: https://github.com/revery-ui/revery/blob/833d86dfc8b718441702b23e9d73a4a84c7154cf/src/UI_Hooks/Timer.re#L16 - but it's essentially the same issue. Seems like anything using a timer-hook is susceptible to this (including the scroll spring, color transition, yank highlights).

I'm evaluating some options still - I think the hook logic is tricky to get right, so for these animations, I may experiment with moving to an elm-subscription-model, like: https://package.elm-lang.org/packages/mdgriffith/elm-style-animation/latest/ - this would be more robust, since it wouldn't depend on tricky timing dependencies in the view or mount/unmount of components.

Bottom line though is I'm working on a holistic fix to address this class of issue - whether it's through the timer hook, or switching to a different, more robust animation model.

By the way: Thank you for all your effort and your great communication heart

Thank you for all the help troubleshooting and grabbing logs, really appreciate it! Been incredibly helpful

[bryphe]

Chipping away at these:

• [x] Fix hanging hover timer (https://github.com/onivim/oni2/pull/2654)
• [x] Fix hanging smooth scroll timer (https://github.com/onivim/oni2/pull/2710)
• [x] Fix hanging yank highlight timer (https://github.com/onivim/oni2/pull/2717)
• [x] Migrate expirer timer to model-based approach (https://github.com/onivim/oni2/pull/2718)
• [x] Migrate color transition timer to model-based approach (#2740)
• [x] Migrate notification animation to model-based approach (#2736)
• [ ] Migrate remaining timers to model-based approach

I think once we get through these - should fix the cases seen in the logs so far. And then, beyond that, migrating the remainder of the hook-based timers to model-based subscriptions. Hopefully getting closer!

[despairblue]

I'm running latest nightly from today, which includes the fix for the smooth scroll. So I enabled it again, but I'm seeing this issue happening a lot again now:

[TRACE] [17.151s] Revery.UI.Render : BEGIN: Render frame
[TRACE] [17.153s] Revery.UI.Render : -- RENDER: pixelRatio: 1.000000 scaleAndZoom: 2.000000 zoom: 2.000000 canvasScaling: 2.000000
[TRACE] [17.153s] Revery.UI.Render : -- RENDER: adjustedWidth: 1920 adjustedHeight: 1061
[TRACE] [17.164s] Revery.UI.Render : END: Render frame
[TRACE] [17.164s] Revery.Tick : Tick.pump - starting with 4 active tickers.
[TRACE] [17.164s] Revery.Tick : Interval - running timer: Oni2_Editor Apploop 0
[TRACE] [17.164s] Revery.Tick : Interval - running timer: Store: Run Effects 3
[TRACE] [17.164s] Revery.Tick : Interval - running timer: Notification Animation 470
[TRACE] [17.164s] Revery.Tick : Interval - running timer: Notification Animation 471
[TRACE] [17.164s] Revery.Tick : Tick.pump - ending with 4 active tickers.

Hope that helps. Let me know if you need the full log.

I try disabling the smooth scroll again for now.

[jsiebern]

@bryphe It has gotten so much better, thank you. It just happened again, so I wanted to provide a trace in case there is something we missed.

onivim2-trace.log.zip

Unrelated maybe: It looks like there is something funky going on at the end from line 5126 onward. This is directly after saving. It seems that every single char of that buffer has been processed in some way, just want to confirm that this is normal or maybe just for debugging when tracing is active?

[bryphe]

Fixed a few more places with potentially hanging timers in #3603

These are the remaining areas I need to fix as next step:

• [ ] src/Components/BusyBar.re: Hooks.animation(
• [ ] src/Components/BusyBar.re: Hooks.transition(~name="BusyBar Opacity Transition", visible ? 1.0 : 0.0);
• [ ] src/Feature/Quickmenu/View.re: |> Hooks.animation(~name="QuickMenu busyBar")
• [ ] src/Feature/Registration/Feature_Registration.re: Hooks.animation(
• [ ] src/UI/QuickmenuView.re: |> Hooks.animation(~name="QuickMenu busyBar"
• [ ] src/Feature/Editor/CursorView.re: Hooks.transitionf(
• [ ] src/Feature/Editor/CursorView.re: Hooks.transitionf(