Performance? - Githubissues

NullVoxPopuli commented 8 years ago

I 'think' that vedeu appears to re-render the whole screen whenever refresh or a render is called, it appears that curses can somehow manipulate just a portion of the screen at a time (at the loss of color depth, and less characters (no utf8)

Do you have any metrics / examples of speed of vedeu compared to libraries such as dispel or canis? (or just raw curses)?

NullVoxPopuli commented 8 years ago

It's also possible I'm rendering very inefficiency. lol

gavinlaking commented 8 years ago

Hi,

I don't have any metrics to hand, but I do know that Vedeu is capable of refreshing only parts of the screen at a time, but this is dependent on which refresh event is called and basically how you have it set up.

By using the debug! configuration option (alongside the log option), Vedeu will tell you in some cases how long it took to perform a certain action- Vedeu does this by wrapping the blocks of code with the equivalent of:

Vedeu.timer("some message here") do
   # some code here
end

This results in log entries which will look similar to some message here took x.yyyy ms.

You can try this in your code; with varying degrees of success dependent on which context (binding) you are currently operating under, i.e. if you are using the DSL, it might be a bit problematic, but if you wrap a method or method calling a class then you should get something meaningful back.

If you have a repository with code using Vedeu, (which I think you do- https://github.com/NullVoxPopuli/spiced_rumby) point me to the classes which you think are slow and we can work together to either improve Vedeu or your usage of it.

Would you like me to take a glance at a particular branch of the aforementioned repository and see if I can spot anything/create a pull request for anything that I think could be changed to better suit how Vedeu works?

As an aside, the biggest problem for me with Vedeu is documentation; I intrinsically know how it works, what calls what, and translating this into something for developers such as yourself to use is incredibly (for me) difficult. But! I am willing to keep trying :-)

NullVoxPopuli commented 8 years ago

Thanks for the help! And yeah, that's the project I'm working on :-)

I made some changes as to when I'm rendering last night which seemed to improve performance on my laptop. However, on my VM, things are still slow. It appears as though the input box I'm tying in to is getting entirely redrawn every time I type a letter?

[124.0361] [input]  Waiting for user input...
[126.9436] [event]  Triggering: ':_editor_' for "u"
[126.9474] [update] Vedeu::Cursors::Cursor: 'input'
[126.9513] [event]  Triggering: ':_refresh_cursor_' for :input
[126.9557] [output] Refreshing cursor: 'input'
[126.9646] [update] Vedeu::Editor::Document: 'input'
[126.9698] [event]  Triggering: ':_clear_view_content_' for :input
[126.9744] [timer]  Optimised clearing content: 'input' took 0.465ms.
[126.9798] [timer]  Clearing content: 'input' took 0.475ms.
[126.9859] [output] Rendering via Vedeu::Renderers::Terminal
[126.9909] [event]  Triggering: ':_hide_cursor_'
[126.9960] [update] Vedeu::Cursors::Cursor: 'input'
[127.0000] [output] Refreshing cursor: 'input'
[127.0134] [timer]  Compression for 1696 characters took 9.09ms.
[127.0182] [event]  Triggering: ':_show_cursor_'
[127.0239] [update] Vedeu::Cursors::Cursor: 'input'
[127.0278] [output] Refreshing cursor: 'input'
[127.0372] [update] Vedeu::Cursors::Cursor: 'input'
[127.0435] [event]  Triggering: ':_refresh_cursor_' for :input
[127.0491] [output] Refreshing cursor: 'input'
[127.0542] [input]  Waiting for user input...
[128.1529] [event]  Triggering: ':_editor_' for "a"
[128.1579] [update] Vedeu::Cursors::Cursor: 'input'
[128.1637] [event]  Triggering: ':_refresh_cursor_' for :input
[128.1677] [output] Refreshing cursor: 'input'
[128.1713] [update] Vedeu::Editor::Document: 'input'
[128.1748] [event]  Triggering: ':_clear_view_content_' for :input
[128.1803] [timer]  Optimised clearing content: 'input' took 0.481ms.
[128.1860] [timer]  Clearing content: 'input' took 0.445ms.
[128.1918] [output] Rendering via Vedeu::Renderers::Terminal
[128.1953] [event]  Triggering: ':_hide_cursor_'
[128.1995] [update] Vedeu::Cursors::Cursor: 'input'
[128.2038] [output] Refreshing cursor: 'input'
[128.2136] [timer]  Compression for 1696 characters took 7.901ms.
[128.2187] [event]  Triggering: ':_show_cursor_'
[128.2233] [update] Vedeu::Cursors::Cursor: 'input'
[128.2268] [output] Refreshing cursor: 'input'
[128.2343] [update] Vedeu::Cursors::Cursor: 'input'
[128.2403] [event]  Triggering: ':_refresh_cursor_' for :input
[128.2444] [output] Refreshing cursor: 'input'
[128.2517] [input]  Waiting for user input...

Is there a way to not have it re-render and just append the character?

gavinlaking commented 8 years ago

Removing the cursor related stuff from the log (which is admittedly noisy (will be tamed)), we're left with a log that looks like this:

[124.0361] [input]  Waiting for user input...
[126.9436] [event]  Triggering: ':_editor_' for "u"
[126.9646] [update] Vedeu::Editor::Document: 'input'
[126.9698] [event]  Triggering: ':_clear_view_content_' for :input
[126.9744] [timer]  Optimised clearing content: 'input' took 0.465ms.
[126.9798] [timer]  Clearing content: 'input' took 0.475ms.
[126.9859] [output] Rendering via Vedeu::Renderers::Terminal
[127.0134] [timer]  Compression for 1696 characters took 9.09ms.

[127.0542] [input]  Waiting for user input...
[128.1529] [event]  Triggering: ':_editor_' for "a"
[128.1713] [update] Vedeu::Editor::Document: 'input'
[128.1748] [event]  Triggering: ':_clear_view_content_' for :input
[128.1803] [timer]  Optimised clearing content: 'input' took 0.481ms.
[128.1860] [timer]  Clearing content: 'input' took 0.445ms.
[128.1918] [output] Rendering via Vedeu::Renderers::Terminal
[128.2136] [timer]  Compression for 1696 characters took 7.901ms.

Although the Compression times are still a bit slow, they are still approximately > 100fps. This makes me wonder if there is an issue around the Rendered via Vedeu::Renderers::Terminal lines. The entire :input (Vedeu::Editor::Document) is redrawn each time just because that was the way I first implemented it- this is not necessarily correct but got the feature off the ground. I'll investigate a bit further and see if 'just appending the character' is easy/quick/possible and also check out the speed of the rendering code. I'll use spiced_rumby for my testing, so I'm getting more helpful feedback.

Stay tuned, and thanks :-)

NullVoxPopuli commented 8 years ago

thank you :-)

gavinlaking commented 8 years ago

Running this on my machine reports much slower times than your log suggests. I typed a sentence as fast as I could and noticed missing characters (never good). For a random character pressed, I took the section of the log file and removed the mouse events. I then annotated that log file as below:

[2726.5840] [event]  Triggering: ':_editor_' for "y"
-----.0018
[2726.5858] [update] Vedeu::Editor::Document: 'input'
-----.0001
[2726.5859] [event]  Triggering: ':_clear_view_content_' for :input
-----.0005
[2726.5864] [timer]  Optimised clearing content: 'input' took 0.41ms.
-----.0008
[2726.5872] [timer]  Clearing content: 'input' took 0.678ms.
-----.0129
[2726.6001] [output] Rendering via Vedeu::Renderers::Terminal
-----.0311
[2726.6312] [timer]  Compression for 7280 characters took 28.402ms.
-----.0019
[2726.6331] [input]  Waiting for user input...

This snippet represents 49.1ms of time, with 44.0ms of unaccounted 'stuff' going on (between 2726.5872 and 2726.6312. The plot thickens.

NullVoxPopuli commented 8 years ago

lol. I believe in you!

gavinlaking commented 8 years ago

Despite spending a couple of hours this evening with this, I'm regretful in only being able to provide the most unhelpful of responses so far.

Logging and debugging has very little impact on actual speed. (So if that was a concern, then it can safely be dismissed.)
Compression does take up a huge (relatively) chunk of time; around 50-70%.
Time spent either updating a buffer or outputting to the screen is marginal; around 2-3% of the time.
Communicating between classes/methods/firing events again is tiny.

Notebook maths not being my strongest subject, I did make an interesting observation:

50 words per minute is about 250 characters a minute.
200 words per minute is about 1000 characters a minute.
1000cpm / 60s = 16.667cps (1000ms / 60fps = 16.667ms).
A keypress in Vedeu takes on average (for my machine (3.4Ghz i5-4670k)) 30ms to run end-to-end.

The conclusion of the above, is that I need (somehow) to make Vedeu twice as quick. Challenge accepted. :-)

Thanks and stay tuned.

gavinlaking commented 8 years ago

A side note; disabling compression yields around twice as much data being sent to the terminal; e.g. 7280 objects becomes 122894 characters. With compression, 7280 objects becomes 72260 characters. The mechanism for compression is rudimentary at best, so this is where I will focus my efforts.

NullVoxPopuli commented 8 years ago

Thanks for the report! I love hearing about all these stats. So, on my native Ubuntu machines, I don't have a speed issue, it's just on my pathetic VM that struggles. haha. But native curses examples seem fine, so that's how I thought there might be some performance investigations in the works :-)

gavinlaking commented 8 years ago

Upon further analysis, I have discovered whilst rendering the 7280 objects, that on average, cumulatively, 7.7ms is spent converting Vedeu::Colours::Colour objects to strings; this is from the way that Vedeu::Presentation::Colour works. If a Vedeu::Views::Char does not have a colour set, then the parent object (a Vedeu::Views::View) is checked for a colour instead- so that we render the underlying interface's/view's colour.

The optimisation of this could reduce the compression time to half of that reported in 39adab0 (~13.2ms -> 5.5ms in the best case scenario).

We're getting somewhere!

NullVoxPopuli commented 8 years ago

woo!

gavinlaking commented 8 years ago

Apart from some other optimisations around the compressor as detailed previously, I've take a small step to refresh only the view which changed when using :fake_mode for a view (i.e. an editor).

Do you want to have a play with the result, and if you're happy with this particular aspect of performance, we can close this issue. If there are other aspects you'd like to address, shall we open a new issue(s) for those?

Hope this helps, and thanks for using Vedeu :-D

NullVoxPopuli commented 8 years ago

thanks for working on this!

I actually re-installed Ubuntu on my VM (now at 15.10), and that alone made things a little faster. Without changing anything on my side of things, here is some gui.log output:

[22.0577] [event]  Triggering: ':_editor_' for "h"
[22.0584] [update] Vedeu::Cursors::Cursor: 'input'
[22.0585] [event]  Triggering: ':_refresh_cursor_' for :input
[22.0587] [output] Refreshing cursor: 'input'
[22.0590] [update] Vedeu::Editor::Document: 'input'
[22.0591] [event]  Triggering: ':_clear_view_content_' for :input
[22.0596] [timer]  Optimised clearing content: 'input' took 0.334ms.
[22.0601] [timer]  Clearing content: 'input' took 0.415ms.
[22.0624] [input]  Waiting for user input...
[22.1190] [event]  Triggering: ':_editor_' for "i"
[22.1197] [update] Vedeu::Cursors::Cursor: 'input'
[22.1198] [event]  Triggering: ':_refresh_cursor_' for :input
[22.1201] [output] Refreshing cursor: 'input'
[22.1205] [update] Vedeu::Editor::Document: 'input'
[22.1206] [event]  Triggering: ':_clear_view_content_' for :input
[22.1212] [timer]  Optimised clearing content: 'input' took 0.522ms.
[22.1220] [timer]  Clearing content: 'input' took 0.711ms.
[22.1247] [input]  Waiting for user input...

it looks like I'm using terminal_mode :fake for the whole app.

so, when typing hi it looks like it took 1.982ms (at least of logged stuff) time difference between h and last waiting: 0.067.. seconds? I'm guessing? so.. that's pretty good?

just a visual thing though, it still looks like the input is re-drawing on every input - not sure if you tried to address that or not -- or even if it is addressable.

gavinlaking / vedeu

Performance? #302