Possible problem with timers in MUSHclient?

Posted by Nick Gammon on Tue 30 Nov 2010 06:27 AM — 50 posts, 171,593 views.

Nick Gammon Australia Forum Administrator Tue 30 Nov 2010 06:27 AM #0

Fiendish raises an interesting point in this thread:

http://www.gammon.com.au/forum/?id=10792

Basically timers in MUSHclient won't fire at the advertised time if there is a lot of activity. In particular, ones which have a low interval (eg. 0.5 seconds) might be delayed for a second or two while the client processes incoming text.

This includes the OnPluginTick callback, which is supposed to be called 25 times a second.

This is because the timers are implemented by handling a WM_TIMER event from Windows, and this happens to fire only if there is nothing better to do (except redraw windows, heh).

It seems slightly odd to me that no-one has complained before.

It is probably a simple enough change to make, that (say) before processing text from the MUD that the client manually checks if it is time to check timers.

Advantage

Timers would fire closer to the time they should

Disadvantages

Different behaviour to before, may make things work differently to what you are used to.
Checking timers every 1/10 of a second in preference to processing incoming messages may make processing of MUD output (which is input to the client) slower.
Calling OnPluginTick 25 times a second, when there is other stuff to do, like update the output window, process incoming text, handle keystrokes, handle mouse-clicks, might significantly slow down the client (if a plugin is calling that). Conceivably, if the processing in OnPluginTick takes most of the 40 milliseconds that elapse (since there are 40 * 25 milliseconds in a second) the client might become very unresponsive.

I am tempted to leave well-enough alone. No-one has complained before (over about 15 years), even Fiendish said at best he would like the documentation updated. Does anyone have any different ideas?

Worstje Netherlands Tue 30 Nov 2010 07:18 AM #1

There is an obvious difference between timers and the OnPluginTick callback. OnPluginTick is very high maintenance, prone to getting delayed by itself or even a simple repaint.

Timers on the other hand (I believe so anyhow, but too lazy to check) are implemented with a 0.1 being the smallest possible, thus giving them a 40ms to 100ms gap.

So I feel that OnPluginTick might need a different implementation if at all possible since it is designed to be so high-frequency, but Timers seem fine as it usually does not come down to <100ms accuracy with those.

The biggest reason I found for stuff to slow down has indeed become the GUI stuff. I tried a countdown-bar miniwindow once, but it just hogged so much CPU constantly by just having the timer which caused the redraw. It became a really unpleasant playing experience.

So either stuff was not optimized properly in painting back then, or it is just the fact that GDI isn't meant for live graphics.

[offtopic]MUSHclient v5.0: switching to DirectX for rendering the user interface?[/offtopic]

Fiendish USA Global Moderator Tue 30 Nov 2010 04:21 PM #2

Quote:
# Checking timers every 1/10 of a second in preference to processing incoming messages may make processing of MUD output (which is input to the client) slower.

# Calling OnPluginTick 25 times a second, when there is other stuff to do, like update the output window, process incoming text, handle keystrokes, handle mouse-clicks, might significantly slow down the client (if a plugin is calling that). Conceivably, if the processing in OnPluginTick takes most of the 40 milliseconds that elapse (since there are 40 * 25 milliseconds in a second) the client might become very unresponsive.

This I absolutely want to avoid. MUSHclient is already getting extremely slow for me with heavy plugin processing such that I'm having to try to come up with performance hacks to make the experience not terrible. I've resorted to pooling calls to repaint, because if a plugin doesn't call repaint then it doesn't guarantee a paint, so that multiple plugins don't trigger rapid repaints but still don't get starved out because redraw is too low priority, which was the impetus for that particular thread. And now I'm at the point where I have to either go in and try to heavily optimize for performance very complex plugins that I didn't write myself or consider spinning them off into other processes. Or be satisfied with orders of magnitude slowdown, which I'm not, or with not using those plugins at all, whch I'm not. So please, nothing that makes the program slower for no reason. :)

Related to the aforementioned thread, IMO there's a design flaw in how Redraw and Repaint are handled. Since Redraw never gets serviced if a lot of work is going on, the screen does not reliably update from calls to Redraw under load. But if every plugin uses Repaint, as they need to in order to guarantee display, then performance suffers because you only need one actual Repaint per batch of calls.

Nick Gammon Australia Forum Administrator Tue 30 Nov 2010 08:25 PM #3

I would be looking at what you are trying to do to get this "extremely slow" response.

Just as an example, using the client setup I got from you SVN repository, I turned on GMCP debugging, and turned off triggers, and then "runto weather" to see what was being pushed through. For each room, I saw something like this:


East Windy Mountains (272)

<MAPSTART>
East Windy Mountains
 
 
                            
     ^ ~ ^ ~ . , . , ^ ~  
                             
 ^ ~ ^ ~ ^ ~ ^ ~ ^ ~ ^ ~ ^ ~ 
                             
 / \ ^ ~ / \ ^ ~ / \ ^ ~ ^ ~ 
                             
 / \ / \ / \ /#\ / \ / > ^ ~ 
                             
 / \ / \ / \ / \ / \ ^ ~ ^ ~ 
                             
 ^ ~ / \ / \ / \ ^ ~ ^ ~ / \ 
                             
     ~ ~ ^ ~ ^ ~ ~ ~ ~ ~  
                             
 
[ Exits: N E S W ]
<MAPEND>
room.info { "num": 18443, "name": "East Windy Mountains", "zone": "gelidus", 
"terrain": "icemount", "details": "", 
"exits": { "n": 18383, "e": 18444, "s": 18503, "w": 18442 }, 
"coord": { "id": 2, "x": 52, "y": 21, "cont": 1 } }

char.vitals { "hp": 1015, "mana": 1147, "moves": 272 }

Now for a start, you are sending 22 lines of map data (<MAPSTART> through to <MAPEND>) per room. That's 22 lots of:

Processing incoming TCP/IP data
Decoding ANSI colours
Trigger matching
Inserting line into output buffer
Calling a script to save that line in a table
Omitting that line from the output buffer

Done per room.

Then on top of that you get the GMCP data which effectively gives you a lot of the same information again (room number, exits, terrain type, whether there are shops).

So that is duplication basically. Duplication that takes time to process. Surely you can amend the GMCP information enough to not need the old <MAPSTART> stuff?

Then there is the room info (room.info). Now every time you visit room 18443 you send the name, zone, terrain, exits, coordinates. More duplication. More processing time.

I argued at some great length on the Mud Standards forum in favour of some sort of caching scheme. Didn't get much support, got a lot of lengthy posts explaining why I was wrong.

The point was, before even making those posts I had noticed this duplication of data, and was trying to alleviate it.

Let's say, instead of:


room.info { "num": 18443, "name": "East Windy Mountains", "zone": "gelidus", 
"terrain": "icemount", "details": "", 
"exits": { "n": 18383, "e": 18444, "s": 18503, "w": 18442 }, 
"coord": { "id": 2, "x": 52, "y": 21, "cont": 1 } }

you just sent:


room.info { "num": 18443 }

And then if you knew all about room 18443, then fine - you can instantly display it. If not you request the details about room 18443. Might be slower the first time. Would be faster every other time.

My other comment is that your idea of "extremely slow" and mine don't necessarily coincide. Last time I showed that I could move about 60 rooms in something like 19 seconds, which I thought was quite fast. You said it was far too slow and your players wouldn't accept it. Well, perhaps some player re-education is called for. You can have fast response time and a text-based interface, or slightly slower response with maps, spellups, status bars, chats windows etc. Or there was even the hybrid we discussed where you turn some features off when running around doing a speedwalk.

Nick Gammon Australia Forum Administrator Tue 30 Nov 2010 08:54 PM #4

Nick Gammon said:

That's 22 lots of ... done per room.

Of course, from the server's point of view too, that's a lot of data it is pumping out if dozens of players are running around.

Fiendish USA Global Moderator Tue 30 Nov 2010 09:29 PM #5

I think you're barking up the wrong tree here. The amount of data streaming through is pretty negligible. You're talking about the order of hundreds of bytes per second, not a whole lot. You can even disable the automap and the speed will still be just as slow, despite now sending less than half the lines.

Compare speedwalks using the version I gave you last time with what is in the repo now:
http://code.google.com/p/aardwolfclientpackage/downloads/list

The data from the mud is the same. The plugins are basically the same. But the new one should be very noticably faster. The difference is mostly the amount of work that gets done inside the GMCP mapper during runs, because I trim down the search space as you suggested. There's also my new repaint buffering which cuts down on the number of repaints.

THESE are the things that make noticeable differences in performance, not lines from the MUD.

Quote:
Of course, from the server's point of view too, that's a lot of data it is pumping out if dozens of players are running around.

Eh, I'll start worrying about that when Lasher does.

Quote:
You said it was far too slow and your players wouldn't accept it. Well, perhaps some player re-education is called for.

I'm not satisfied with being satisfied. :) Not being satisfied with features is what causes me to add new ones. Not being satisfied with performance is what causes me to come up with new ways to make things faster. If something is CPU-limited on a brand new machine like mine, I can only imagine how bad it is on an older slower one.

Larkin Wed 01 Dec 2010 01:02 PM #6

I've noticed some oddities with at least one of my timers lately, but I haven't decided if it's me doing something stupid or my timer being mishandled by MUSHclient. I have a timer that fires ever 2.5 seconds to keep a game clock synchronized on my Info bar. However, sometimes it seems to run ten times slower and the time is very far behind. I double-checked the timer options in the dialog, and it was indeed still set to fire every 2.5 seconds, so I'm confused.

Fiendish USA Global Moderator Wed 01 Dec 2010 04:48 PM #7

Larkin, does Nick's first post in this thread help you at all?

Larkin Wed 01 Dec 2010 05:10 PM #8

I have no idea if the proposed solution would help what I'm seeing (and I'm seeing some of it right now as I play today), but it probably wouldn't hurt.

Fiendish USA Global Moderator Wed 01 Dec 2010 05:33 PM #9

Larkin said:

I have no idea if the proposed solution would help what I'm seeing (and I'm seeing some of it right now as I play today), but it probably wouldn't hurt.

I meant the explanation of the problem, not the proposed solution. Does it only seem to happen when you have a lot of script activity?

Nick Gammon Australia Forum Administrator Wed 01 Dec 2010 10:29 PM #10

Larkin said:

I have a timer that fires ever 2.5 seconds to keep a game clock synchronized on my Info bar. However, sometimes it seems to run ten times slower and the time is very far behind.

Under the circumstances I described (where a lot of incoming text might delay timers firing) I would do a calculation in the timer itself. For example, rather than assuming that 2.5 seconds have elapsed, find out how much actually elapsed and use that in your calculations.

If you use Lua then these days utils.timer () returns the current hi-resolution timer value. So, once initialized at connect time (since it is not a time of day, but just an elapsed time) you could use the new value minus the previous value to find exactly how much time has elapsed. For example, it might be 3 seconds and not 2.5 seconds.

If you assume 2.5 seconds and you often get 3 seconds, then cumulatively you would gradually get further and further out.

Larkin Thu 02 Dec 2010 10:27 AM #11

Yes, the description of the problem may very well apply to me.

And, thanks for the suggestion, Nick! I'll do just that.

David Haley USA Thu 02 Dec 2010 05:55 PM #12

I find it somewhat hard to believe that MUSHclient becomes "extremely slow" if you're doing something reasonable in a plugin. That said, it is easy for GUIs to appear slow if the redrawing thread is blocked during some other processing, but again that strikes me as unlikely unless people are doing something weird.

Typically the solution is to separate heavy processing from the GUI thread, but I think everybody would be inclined to agree that that shouldn't happen unless absolutely necessary due to the complications it involves.

But working through a search space is exactly the kind of activity that shouldn't be done in the main GUI thread. I would not say that "MUSHclient is slow" here, I would say that the stuff you're doing in plugins is slow... and because you're doing it in the thread that should be updating the GUI, the whole application seems to be slow.

Regarding the issue at hand, would it be hard to have an event system? It sounds wasteful to do something 25 times per second if you know you don't have to. If a plugin wants high-frequency logic, would it be unreasonable to force it to go through a special API that registers the intent? You could then not only avoid the cost if you could, but furthermore you could know how much time there is until the next requested tick (or how late you are).

And yes, I agree with Nick that such time-sensitive frame logic handlers should be checking elapsed time and not just assuming that they were invoked at exactly the right time. (This is very standard in many games' main loops, for instance.)

Fiendish USA Global Moderator Thu 02 Dec 2010 06:32 PM #13

David Haley said:

I find it somewhat hard to believe that MUSHclient becomes "extremely slow" if you're doing something reasonable in a plugin.

I disagree with your definition of reasonableness.

Quote:
That said, it is easy for GUIs to appear slow if the redrawing thread is blocked during some other processing, but again that strikes me as unlikely unless people are doing something weird.

I disagree with your definitions of weird and unlikely.

Quote:
But working through a search space is exactly the kind of activity that shouldn't be done in the main GUI thread.

Does spawning new threads inside plugins work?

Quote:
I would not say that "MUSHclient is slow" here, I would say that the stuff you're doing in plugins is slow... and because you're doing it in the thread that should be updating the GUI, the whole application seems to be slow.

I think you're splitting hairs. If a plugin is slow, not only can the entire program become unresponsive for the duration (if you don't force repaints, which are not free, you may not get screen updates at all until many pages of events have gone by, which could be tens of seconds later), but activities like walking around actually take much longer because the user is locked out of both input and output until the program is finished processing. I'm not sure how else to classify "having plugins loaded makes interaction with the game take significantly longer" except for "slow".

Quote:
Regarding the issue at hand, would it be hard to have an event system? It sounds wasteful to do something 25 times per second if you know you don't have to.

I like this idea, but offhand I think the answer is "Yes, it would be hard."

David Haley USA Thu 02 Dec 2010 07:10 PM #14

Fiendish, you may disagree all you like, but running search algorithms is simply not a good idea in the main (or only) GUI thread. Anybody who has written GUI code can tell you this. In fact, GUI frameworks are often designed around this fact of life. It is perhaps not your fault in this instance because you have little choice, but, well, your disagreement doesn't change the fact that it's what you're doing that's messing things up, not some inherent slowness in MUSHclient. I get the impression that you are blaming your problems on MUSHclient, and fretting about having to optimize code. Well, yes -- if the code isn't behaving the way it should according to well-known GUI programming rules, and it is impossible/unacceptable to change its paradigm, then it has to be optimized.

Would it be reasonable for somebody to complain to Nick about MUSHclient being slow because they're doing a full mini-max search routine to optimize some AI agent's playing strength in a plugin? No, that would be silly.

As a framework developer, Nick can provide two things here:
- a way for plugins to (temporarily) relinquish control to the GUI thread to restore responsiveness
- multi-threaded plugins to avoid computation in the GUI thread in the first place

This is all a separate issue from the timer issue, of course. It's related in the sense that plugins can consume time and that can mess with the main loop.

I don't believe that the scripting languages currently allow preemptive multi-threading.

You could perhaps restore the impression of responsiveness by using coroutines or something instead of whatever main loop you're doing now.

Fiendish USA Global Moderator Thu 02 Dec 2010 07:35 PM #15

David Haley said:
It is perhaps not your fault in this instance because you have little choice, but, well, your disagreement doesn't change the fact that it's what you're doing that's messing things up, not some inherent slowness in MUSHclient.

As far as I know, the inability to do work outside of the GUI thread is inherent to the design of the program. So forgive me for thinking that the buck stops there. I'd love to see counterexamples.

Quote:
Would it be reasonable for somebody to complain to Nick about MUSHclient being slow because they're doing a full mini-max search routine to optimize some AI agent's playing strength in a plugin?

If this search routine is so popular that it spawns dozens of threads from people saying "Hey, that's a neat idea. I'd like to adapt it for my MUD too!" like the graphical bigmap and the gmcp mapper, and if hundreds of people want to use it but find that it's too slow as it is, then absolutely 100%. That's how the program advances. I'm concerned that you think otherwise.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 07:39 PM #16

One of the problems I have with this talk of MUSHclient being "extremely slow" and then, after certain changes are made "much faster" is that it is so vague as to be almost meaningless.

Before you can improve a metric you need to measure it. In my case in an earlier thread about the mapper speed I actually timed running from A to B (which turned out to take around 18 seconds to run 60 rooms, which I would not personally call "extremely slow"). Then I made changes to the search depth and got the speed down to 9 seconds for the same run.

I really think to get anywhere you need to post figures and give environments. For example:

On my 2.5 GHz Pentium with 2 Gb RAM
I have MUSHclient's window set to 2500 x 1500 pixels
I have 32-bit colour depth on my monitor
My search depth in the mapper is set to 10 rooms
I have these plugins installed: A, B, C, D
I have these options enabled which might cause a lot of comms output (eg. the ASCII room map)
My map window is sized to 200 x 300 pixels
I started at "recall"
I ran to "weather station" which is 60 rooms away.
It took 14 seconds on my stopwatch
Then, adding the following optimizations (listed) to my plugin the travel time reduced to 8 seconds.

This is stuff you can measure. Words are vague. You can say 9 seconds is too slow, others might say it is amazingly fast.

I already pointed out that if your goal is to move 60 rooms in 5 seconds, then drawing a large search depth is ridiculous - how can you possibly absorb thousands of rooms appearing on the screen in 5 seconds?

Also you need to take into account absolute and relative values. For example, you might say reducing the speed from 2 seconds to 1 second "cut the time in half". I might say "well, you only saved a second".

Another thing you can look at, if you want to keep the mapper going while you move rapidly, is to simply rewrite the mapper module in C++. By removing the interpreted language doing the CPU-intensive search-and-draw, you might actually reduce the time taken by the mapper by quite a lot.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 07:51 PM #17

Fiendish said:

As far as I know, the inability to do work outside of the GUI thread is inherent to the design of the program. So forgive me for thinking that the buck stops there. I'd love to see counterexamples.

What could work quite well in your case, and adapt itself to drawing lots of rooms if you are standing still, and not as many if you are moving, is coroutines.

The inner thread of the mapper (which does the search) could be a coroutine, yielding at each change of search depth. So it draws 1 room out (eg. 4 rooms) and yields. Then 2 rooms out, and yields again, etc. I think that is a natural part of the mapper loop anyway.

Then you need to resume of course, and this is where the OnPluginTick could be used. If nothing much is happening, it fires frequently, and you can keep drawing the map (by resuming the coroutine).

If you have moved rooms, then the mapper basically stops drawing this room and starts again. I'm not sure how responsive this would be, you may need to make it yield every 3 search depths for example. Or maybe a single yield after drawing two rooms out would work well for fast moving, and then if it gets control back (for that room) you draw the rest. Or some combination.

Fiendish said:

I think you're barking up the wrong tree here. The amount of data streaming through is pretty negligible. You're talking about the order of hundreds of bytes per second, not a whole lot. You can even disable the automap and the speed will still be just as slow, despite now sending less than half the lines.

Did you actually measure this? My point was that hundreds of bytes or not, this is causing Windows events that delay the timer. Each line, for example, might (or might not be) a new event.

The other thing to take into account here is future maintainability. To shave off maybe a couple of seconds, you might have made the code so convoluted that no-one else can ever maintain it. Maybe.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 08:42 PM #18

I enabled timing and tried the test again (on the earlier version of the mapper, without your Redraw improvements). On one room for example:


Time to draw 1114 rooms = 0.486 seconds, search depth = 30

OK, over 1,000 rooms drawn in half a second. Not too bad, ramping back the depth would have helped.

Total for the runto weather station (search depth 30):


Cumulative: 71342 rooms in 32.823 seconds

That's drawing 2,173 rooms a second. Sure, 4,000 rooms a second would be faster. But hardly "extremely slow". And yes, this is slower than my earlier test. I think something is wrong with my Mac. Maybe the new RAM is behaving strangely.

But again I think you need to measure things. Rather than saying "slow" or "extremely slow" or "too slow" we could say something like: "I measured a draw rate of 2,000 rooms per second in the mapper. I would like a rate of 3,000 rooms per second". Now we have a goal we can aim for and measure.

So in this example, I dropped the search depth down to 8 and tried again:


Cumulative: 7159 rooms in 2.480 seconds

This time, 2,887 rooms per second.

Interestingly, dropping down further to a search depth of 5:


Cumulative: 2650 rooms in 1.129 seconds

That is 2,347 rooms per second. So actually worse than a search depth of 8.

So this shows that blindly following one path may not necessarily give the best results. But I do think that trying one thing, and carefully measuring, and finding the "sweet spot" is a helpful way of improving performance.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 08:52 PM #19

Another test. Search depth of 10, and resized the mapper window down to about 500 x 500 pixels.

This time:


Cumulative: 11292 rooms in 3.669 seconds

That's 3,075 rooms per second, above my hypothetical required barrier of 3,000 rooms per second.

All my tests were done on a large screen (2560 x 1440 pixels) which requires quite a lot of bit blitting.

Sizing the client window down to 1363 x 1232 reduces that time by lowering the raw number of pixels to be copied. In this case then:


Cumulative: 9776 rooms in 2.593 seconds

That's 3,770 rooms per second.

David Haley USA Thu 02 Dec 2010 09:18 PM #20

Fiendish, I'm not sure what you're trying to say. My point is straightforward: doing computationally intensive tasks in the GUI thread is a bad idea, plain and simple. This is a well-known issue with GUI programming. I already said that in this instance, you have little choice in the matter given how the framework is set up. I also gave some options that Nick could implement to work around this. I also gave an option that you could try: coroutines. What is it that you want, exactly? It seems that you expect there to be some solution that will fix things without creating work. You've been using somewhat vague metrics when discussing slowness which leads me to believe that you haven't actually measured this and do not know if the slowness is your fault, Nick's fault, or due to doing computationally intensive work in the GUI thread.

Even if Nick does adopt one of the solutions I mentioned, your code will have to be changed, perhaps quite a lot, to be made multithreading-aware.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 09:21 PM #21

Just to clarify the posts above, the rooms counts are "room boxes" drawn on the screen. The actual "MUD rooms" travelled was 73 rooms (from recall to Weather Station). My latest test which counted those showed:


Cumulative: 9776 rooms in 2.579 seconds (3790 per second)
We have traversed 73 rooms (28 per second)

So in this case the mapper actually drew 28 different rooms per second. So in effect this is 28 FPS in movie terminology (where modern movies are 24 FPS, although NTSC video screens at 30 FPS and PAL at 25 FPS).

David Haley USA Thu 02 Dec 2010 09:24 PM #22

I think it's pretty clear that MUSHclient's rendering etc. are not responsible for the slowness. It doesn't take a lot of processing in plugins that interrupt the GUI drawing for a program to appear very slow and unresponsive.

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 09:58 PM #23

I tried out the coroutine idea. Basically the "draw" function was renamed "draw_thread" and then these lines added:


function draw (uid)

  thread = coroutine.create (draw_thread) 
  assert (coroutine.resume (thread, uid))

end -- draw

function resume_drawing ()

  if thread then
    assert (coroutine.resume (thread))
    Redraw ()
  end -- if
  
end -- resume_drawing

Inside draw_thread I yielded for each search loop:


 while #rooms_to_be_drawn > 0 and depth < config.SCAN.depth do
    local old_generation = rooms_to_be_drawn
    rooms_to_be_drawn = {}  -- new generation
    for i, part in ipairs (old_generation) do 
      draw_room (part.uid, part.path, part.x, part.y)
    end -- for each existing room
    depth = depth + 1
    coroutine.yield ()
  end -- while all rooms_to_be_drawn

At the end of draw_thread I did this:


  thread = nil  -- indicate finished

That is so you don't resume a dead coroutine.

Finally inside the mapper plugin (not the mapper.lua) I added this to push the drawing along:


function OnPluginTick ()
  mapper.resume_drawing ()
end -- OnPluginTick

I also moved around the drawing loop (above, with the yield in it) to lower down, otherwise you don't see the map, border etc. at all until it is finished.

The end result? Well I laughed when I saw it. The rooms now draw in a sort of "starburst" way, starting at the middle and gracefully filling outwards in all directions (which is what I expected).

It's a bit slow to draw, given that it waits 40 milliseconds (the OnPluginTick inverval) for each extra layer. That could probably be fixed by making it draw four layers or so rather than one, at a time.

However what does happen is that when running around, it only draws the current room, thus significantly speeding up the time taken when on the move.

In fact, this seems to compromise quite well:


 if depth % 4 == 0 then
    coroutine.yield ()
 end -- if

So it draws 4 levels out, then yields. This makes drawing pretty fast if you are just looking around, and only draws 4 levels if you are speedwalking.

David Haley USA Thu 02 Dec 2010 10:05 PM #24

Out of curiosity, is Fiendish's slowness report regarding rendering, or regarding the search routine that his plugins are running? Or just in general?

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 10:41 PM #25

Below is 90 second podcast that shows the effect of yielding inside the drawing routine:

Nick Gammon Australia Forum Administrator Thu 02 Dec 2010 10:45 PM #26

David Haley said:

Out of curiosity, is Fiendish's slowness report regarding rendering, or regarding the search routine that his plugins are running? Or just in general?

My impression is he is talking about the overall experience. It is a combination of CPU being used by drawing the map, which then delays the time it can process incoming text from the MUD, which then means screen updates are deferred (being lower priority) and timers are deferred (being lower priority) so it has a knock-on effect.

From the video posted above I personally wouldn't say it is "extremely slow".

Twisol USA Thu 02 Dec 2010 11:59 PM #27

That's a really cool optimization. I actually very much like how it looks when you're walking around quickly. My only qualm is that the golden rings (which I assume are "special points" of some kind) only appear when everything is drawn, even though the layer they're on may have been drawn for some time.

[EDIT]: I understand that the rings overlap nearby rooms, so if you did do it as the layer is drawn, the rings might be drawn underneath the neighboring rooms. However, if you used a separate transparent layer for those points and simply merged the layers together right before updating the map, that might work better.

Nick Gammon Australia Forum Administrator Fri 03 Dec 2010 01:07 AM #28

The rings are area transitions (area A to area B). Until you draw area B you don't know the ring will be needed. I suppose the rings could be cumulatively drawn, but really the time when you are running around and the map is half-drawn you probably don't care, until you stop and evaluate where you are.

Nick Gammon Australia Forum Administrator Fri 03 Dec 2010 01:39 AM #29

In any case, the thing is a proof of concept, not a finished product. For another thing, the rooms down the bottom overwrite the area name. Some minor tweaking would be needed before this amended version went live.

It does however show the possibility of doing a map that gobbles up CPU selectively - if it is available you see lots of rooms, if things are pretty busy, it does less.

Twisol USA Fri 03 Dec 2010 04:23 AM #30

Nick Gammon said:
For another thing, the rooms down the bottom overwrite the area name. Some minor tweaking would be needed before this amended version went live.

Which is another excellent reason to use layers to separate the content. Draw the room graph to one image, and the overlays (room name, options button, golden circles, etc.) to another. When you update the visible window, merge the layers together.

Fiendish USA Global Moderator Fri 03 Dec 2010 04:48 PM #31

Thanks for the update, Nick. :)

David Haley said:
I think it's pretty clear that MUSHclient's rendering etc. are not responsible for the slowness. It doesn't take a lot of processing in plugins that interrupt the GUI drawing for a program to appear very slow and unresponsive.

What's the difference between being slow and unresponsive and appearing to be slow and unresponsive?

David Haley USA Fri 03 Dec 2010 08:48 PM #32

It's the difference between actually running inefficient code, perhaps in GUI rendering, versus the bad practice of running code in the GUI thread thereby preventing the GUI from updating frequently enough. If you render the GUI 5 times per second it will feel less responsive than if you render it 30 times per second. This is different from rendering the GUI 5 times per second because the rendering operation is actually expensive. This is why it is important to understand if perceived slowness is due to actual rendering cost, due to the bad practice of running unrelated code in the GUI thread, or due to something else.

In other words, the appearance of slowness can be due to actual slowness (slow code) or simply not rendering the graphics often enough (bad practice). These are very different things.

Nick Gammon Australia Forum Administrator Sat 04 Dec 2010 01:55 AM #33

Potential problems with mapping during speedwalking are that:

You compute a large map (hundreds of rooms in the case of outside areas) that are not even shown, because the window is not redrawn. Hence that is wasted CPU power.
You compute a large map which the player can barely see (eg. for 25 frames per second you would be hard pressed to register each map redrawing in any meaningful way)
The player isn't interested anyway - they only want to know when they have arrived
Blitting the map to the output window takes extra CPU time, on top of the time taken to calculate it in the first place
All this CPU time takes available power away from processing keystrokes, MUD output, triggers etc.
The processing causes timers to fire more slowly then they otherwise might

My suggested amendment (based on David's idea of coroutines) alleviates that somewhat by breaking the computation up into smaller pieces, which are then abandoned if no longer required.

Another approach would be to simply give a different user experience. For example, knowing they are speedwalking, draw the "big map" instead, with a big yellow line showing the progress from the start to the end point.

When I first did the map in Lua, I was pleasantly surprised that the map seemed very fast and responsive - however that was for "manually walking" around, where you might tap "north", and then review where you were. Or even walking reasonably quickly by using the keyboard. Some MUDs impose a limit (IRE ones do I think) of around 0.5 seconds per room, and if you attempt to walk faster than that the MUD declines to act.

Fiendish USA Global Moderator Sat 04 Dec 2010 04:15 PM #34

Nick, I like the amendment. I'll try it out. In the meantime, though, I did already put in to practice your suggestion of cutting down the search space during speedwalks to 4 rooms. It works pretty well, but the coroutine stuff will give me more free overhead to add in other plugins.

David Haley said:
...If you render the GUI 5 times per second it will feel less responsive than if you render it 30 times per second...

No, it will BE less responsive. In terms of responsiveness, there is no metric OTHER than how it appears. So a program cannot "be fast and responsive" but "appear unresponsive". If it appears unresponsive, it is unresponsive.

David Haley USA Sat 04 Dec 2010 06:53 PM #35

Fiendish, you are taking my posts in a rather disingenuous way and it's becoming somewhat unpleasant. :( I think I made some serious points to address the difference between appearance of slowness and actual slowness, and all I get back is a sound-bite argument that ignores the point. I'm not sure what your goal is. You talk to me of metrics and measurements yet you provide none. Well, I'm glad Nick is doing the right thing.

Nick Gammon Australia Forum Administrator Sat 04 Dec 2010 08:53 PM #36

Fiendish said:

No, it will BE less responsive. In terms of responsiveness, there is no metric OTHER than how it appears. So a program cannot "be fast and responsive" but "appear unresponsive".

I think you are confused here. From my understanding of English, "responsive" refers to how well the program responds. However "fast" (although not really defined by you here) would indicate to me how quickly it does something.

So for example, by keeping Redraw rather than Repaint the program may update the screen slowly (since that is a low priority event). You might say the screen updating is "not fast" (again I would prefer a measurement, eg. "it only updates ever 2 seconds").

However to be responsive it might quickly respond to keystrokes, menu items, triggers etc. even though you might not see that response.

Now if you throw in a lot of Repaints then after a particular event (such as moving rooms) it may immediately draw the new room. However during the time it does so it may respond less quickly to other events.

In the olden days, when PCs were a lot slower, I did a lot of work in programming things like Macs where you paid a lot of attention to this sort of thing. In fact, you normally would not invalidate a whole screen.

Even today you see web browser designers compromising responsiveness and speed. For example, rather than waiting for everything (eg. every graphic) on a page to arrive from the web server, they start drawing what they can. And then, if you decide to change pages, they may abandon that page entirely and start drawing a new one (effectively similar to the coroutine idea with the mapper).

So what probably happens is that the page starts drawing sooner (thus feeling responsive) but finishes drawing later (due to redrawing parts as image sizes cause things to be relocated), which means the overall time to draw the page is slower. So, more responsive, but slower.

In an earlier thread you wanted me to speed up the drawing of gradients because they were slow. Well, gradients will tend to be slow, because they involve a lot of calculations. You could simply not use them. But you didn't want to do that.

Your design decisions about how the end-product looks are going to impact its speed.

Personally I would be designing so you had speed to spare - not everyone will have a PC as fast as yours.

Fiendish USA Global Moderator Sat 04 Dec 2010 11:36 PM #37

First of all, this has all gotten very academic. None of this is likely going to get us very far. But I do find it interesting so perhaps let's press on. :)

David Haley said:

Fiendish, you are taking my posts in a rather disingenuous way and it's becoming somewhat unpleasant. :(

I don't know. Maybe both of us should start over. I felt you were being hostile. I apologize.

Nick Gammon said:
I think you are confused here. From my understanding of English, "responsive" refers to how well the program responds. However "fast" (although not really defined by you here) would indicate to me how quickly it does something.

No, I think we're just not talking about the same thing. Let's back up a bit and try to get on the same page. "Responsive" as I'm using it is short for "apparently responsive", as in if something happens outside of the window where I care then I can't call it responsive, because to me it's as if it didn't respond. It's not good enough to handle input at some point in the future. If I say "Hi Grandma" to my grandmother and she does nothing, and maybe I say "Hi Grandma" again, and she does nothing again, it doesn't do me any good if after I leave she perks up and says "Hi Grandson. Hi Grandson." That wouldn't really be responsive, because the response doesn't come inside of the window of immediacy (the point by which the user expects to see a response). I'm already out the door. To me it's as if she never responded. So if you want to say that that's just "slow", fine. I'll change my words around. Whatever word you want to use for that phenomenon is fine. :)

Quote:
However to be responsive it might quickly respond to keystrokes, menu items, triggers etc. even though you might not see that response.

That's a matter of perspective. From my grandmother's perspective, there was a response. From my perspective, there wasn't. I'm not ok with measuring from a perspective other than the user's window of immediacy.

Quote:
Now if you throw in a lot of Repaints then after a particular event (such as moving rooms) it may immediately draw the new room. However during the time it does so it may respond less quickly to other events.

Which is why I now buffer repaints.

Quote:
In fact, you normally would not invalidate a whole screen.

Actually, I've been wondering about this. Is there a way in MFC to only repaint part of the screen?

Quote:
In an earlier thread you wanted me to speed up the drawing of gradients because they were slow. Well, gradients will tend to be slow, because they involve a lot of calculations. You could simply not use them. But you didn't want to do that.

And then you made them faster. So, what can we learn from that exercise? My desire for increased performance ended up with getting increased performance. And you figure that's going to get me to realize the error of my ways and stop? ;)

Quote:
Personally I would be designing so you had speed to spare - not everyone will have a PC as fast as yours

I try to. That's why I'm never satisfied when you say something is fast enough. Hence the exercise with the gradients. :) But I'm also not willing to sacrifice aesthetics. Figuring out how to have both is the way to move forward.

David Haley USA Sun 05 Dec 2010 12:35 AM #38

Sorry if you felt I was being hostile. My main goal is just to identify where the problems are coming from because I've been seeing a trend on the forums where people point the finger at Nick for "slowness" where it's not really his fault. Hopefully starting over will work. :-)

Let's start from basic principles. Firstly, I think we all agree that what the user sees matters for the user's experience.
What Nick and I are saying though is that why the user might see a delay can happen for several reasons. Perhaps the CPU is overloaded and can't draw fast enough. Perhaps the CPU is overloaded and is doing some necessary and uninterruptible task before it gets the chance to draw. Perhaps some task is taking a long time and isn't giving the GUI routine a chance to run, but could. Basically, there are many reasons why a program could appear slow.

You want to measure the user's window of immediacy. That's fine, as an end goal. But when trying to fix the problem, you need to get to the underlying cause of the slowness.

I'm not trying to be coy when I talk about the difference between the appearance of unresponsiveness and actual unresponsiveness. I realize that the statement might sound odd or even foolish at a quick glance. But this is an important distinction, because once you know which situation you're in, you know where you need to fix things. If something merely appears unresponsive but in fact is working under the hood on user input and so forth, you know that you need to give your GUI routines more chances to draw. But if something is actually slow under the hood, then you shouldn't be looking to the GUI but instead at the code that is slow. Sometimes these problems can be combined, which is why I suggested the coroutine idea, an approach that seems to be giving Nick good improvements based on his empirical measurements.

I think that it's unlikely that MUSHclient's rendering speed needs improvement here, because based on Nick's measurements, it can render an awful lot of things awfully quickly. You said early on that you're running a lot of search routines. Those are a great place to start looking, because while they are running you aren't updating the GUI.

Regardless, until we identify the culprit(s) through empirical measurement, any optimization is premature, and we know what they say about premature optimization. :-)

Twisol USA Sun 05 Dec 2010 12:46 AM #39

In other words, it's the difference between slowness due to task backup and slowness due to inefficiency.

Nick Gammon Australia Forum Administrator Sun 05 Dec 2010 03:20 AM #40

Fiendish said:

Actually, I've been wondering about this. Is there a way in MFC to only repaint part of the screen?

Absolutely. I used to do that before miniwindows came along. But it can be tricky to get right. And in any case, since the end result is one big bitmap, and the text scrolls, there isn't a huge amount of point.

Let's assume that the map window overlaps the text output, at least by a bit. As the text scrolls up you at least have to invalidate the text part, and then redraw it, and then blit the miniwindow back on top of the text. Which is what happens now, without all the complex calculations about which part should be redrawn.

If you have a pure text window (which we don't) then there is an API call (ScrollWindow I think) that internally shifts the bitmap vertically (or whichever way) so it doesn't need to be redrawn, and then you invalidate the last few lines, and redraw those. But you can't shift the bitmap vertically if it is even slightly overlapped by a miniwindow, because that would jump up as well, looking really really bad.

So basically to implement miniwindows I decided to get rid of selective invalidating, and just redraw the whole thing. The miniwindow are reasonably efficient themselves, because they aren't recreated, just blitted back on top of the text.

Fiendish said:

If I say "Hi Grandma" to my grandmother and she does nothing, and maybe I say "Hi Grandma" again, and she does nothing again, it doesn't do me any good if after I leave she perks up and says "Hi Grandson. Hi Grandson."

Scenario.

Your grandmother is driving you in her car down a slippery mountain road (ice, sleet that sort of thing). She is concentrating hard on the road, and responding quickly and efficiently to the curves in the road, and keeping you both alive.

So it actually does do you good that she doesn't immediately respond to your saying "Hi Grandma", it is keeping you alive. She is processing a higher priority task. When the higher priority task allows it, she responds.

I understand what you are saying about it being important for the player to feel things are responded to. In fact one of the things I like about WoW is the way that things feel very responsive. And the way they do that is, for one thing, to let you move your toon around at the client end, instantly. And then it transmits your updated position to the server. So if you happen to play alongside another player, the images on the two screens can be out of sync. On one screen you might be ahead of your friend, on another, behind him.

Ditto for inventory. If you look at your inventory it immediately appears, because it is cached locally. And the map. And quests. And I'm pretty sure even mobs have a "initial reaction" coded into them, which makes them respond and run towards you, even before the server has told them to. Eventually the server kicks in and has the final say, and sometimes you then see mobs jump around to different places.

I'm all in favour of fast-appearing responses. But I think that to a certain extent they need to be designed in. As in my suggestion of a different way of displaying speedwalks, one that is less processor-intensive.

Similarly for the spellups. I think a while back Lasher and I agreed on a protocol where you found what spellups (buffs) you had on you, and then the server just advises of changes (gain, lose one or more). That way the client always had a local picture of the spellups, and could display them promptly.

Fiendish USA Global Moderator Thu 09 Dec 2010 09:16 AM #41

Nick,
I finally tried out your suggested coroutine changes, and I'm not seeing what you show in your video. Maybe it's a consequence of my setup, but for every room I walk through the mapper window disappears and then reappears when the drawing is done. I don't see a starburst. I see the mapper window flickering. Are we using the same mapper code? I think I'll just stick with setting the search depth to 4 during speedwalks for now, since that seems to work well.

Nick Gammon Australia Forum Administrator Thu 09 Dec 2010 11:41 AM #42

As I said on the earlier page:

Nick Gammon said:

I also moved around the drawing loop (above, with the yield in it) to lower down, otherwise you don't see the map, border etc. at all until it is finished.

If you don't do that, yes you will get that effect. The relevant part was moved down here:


 -- 3D box around whole thing
  
  --draw_3d_box (win, 0, 0, config.WINDOW.width, config.WINDOW.height)
  draw_edge()

  add_resize_tag()
     

  -- make sure window visible
  WindowShow (win, not hidden)

  rooms_traversed = (rooms_traversed or 0) + 1

  while #rooms_to_be_drawn > 0 and depth < config.SCAN.depth do
    local old_generation = rooms_to_be_drawn
    rooms_to_be_drawn = {}  -- new generation
    for i, part in ipairs (old_generation) do 
      draw_room (part.uid, part.path, part.x, part.y)
    end -- for each existing room
    depth = depth + 1
    if depth % 3 == 0 then
      coroutine.yield ()
    end -- if
  end -- while all rooms_to_be_drawn
  
  for area, zone_exit in pairs (area_exits) do
    draw_zone_exit (zone_exit)
  end -- for
  
  last_drawn = uid  -- last room number we drew (for zooming)

For one thing, you need to at least do a WindowShow before yielding in the coroutine, and by moving the room drawing part down, you get the borders, room title etc. first.

Only problem is the lower rooms might overlap the title or area, but I thought I would leave that as an exercise. Maybe make drawing the area and title in a separate function, and do it once at the start (so you see it during the updating) and then again at the end to plonk on top of any rooms that went near the edge.

Fiendish USA Global Moderator Thu 09 Dec 2010 05:52 PM #43

Ah, I missed that part. Thanks.

Twisol USA Thu 09 Dec 2010 08:30 PM #44

Nick Gammon said:
Only problem is the lower rooms might overlap the title or area, but I thought I would leave that as an exercise. Maybe make drawing the area and title in a separate function, and do it once at the start (so you see it during the updating) and then again at the end to plonk on top of any rooms that went near the edge.

Is there something about layering that you really want to avoid?

Nick Gammon Australia Forum Administrator Thu 09 Dec 2010 11:34 PM #45

Twisol said:

Is there something about layering that you really want to avoid?

It's not in the official release. I did it as a proof of concept. As an exercise, you can improve it. Layer it, change the drawing order, whatever.

Twisol said:

When you update the visible window, merge the layers together.

Well, how exactly? Blending layers using blending modes means choosing a good mode, most of them interact in some way. You probably want an alpha mask. This all adds somewhat to the complexity. The upper layer would need to have a mask created at the same time you draw the content (which is basically twice the work). Then you need to merge with the mask. The extra complexity hardly warrants, for me, the change from a simpler solution of making the few things that are drawn on top (like the room name and area name) into a separate function. Call it once at the start so they appear while the rooms are being drawn, and then again at the end in case the rooms overwrote them.

Larkin Wed 15 Dec 2010 06:41 PM #46

Where do we stand on improving the performance of the timers? I'm noticing more and more problems with things that I do that rely on timers, and I'm wondering if it will be improved in the next release of MUSHclient or if I should be looking for alternative solutions to my problems, like manually checking my own expirations on each prompt.

I made changes to my calendar timing, and it ticks along nicely for a while before it becomes pretty much unresponsive and needs to be kickstarted again. It could well be a bug with my own logic, I admit, but the behavior is just odd.

Nick Gammon Australia Forum Administrator Thu 16 Dec 2010 08:51 PM #47

Well it's a design decision. I can make timers higher priority than processing incoming text. At present they are lower, so if you get a lot of text it will tend to push timers out quite a bit.

What would probably work is to check every time data arrives from the MUD, if it is time for the timer to fire (eg. if 1/10 of a second has elapsed since last time) and if so, process timers anyway.

That could slow down processing the text slightly but the timers should fire much closer to their designed times.

Larkin Thu 16 Dec 2010 08:57 PM #48

With what I'm seeing lately, I'd gladly take a small hit to processing incoming text to help these poor timers out a bit.

I assume the timers would continue to be processed in the background, too, for when text isn't coming in, and this is just an extra check.

I've always left my temporary timers hanging around and just disabled them, but now I'm thinking it'll be better to create and destroy them, even if I do so frequently. Not sure which is more expensive overall...

Nick Gammon Australia Forum Administrator Thu 16 Dec 2010 10:49 PM #49

It skips disabled timers quickly enough.

My testing so far shows this. First, I put in a "tick" timer (an ordinary timer that fires as fast as possible, namely after 0.1 seconds).


<timers>
  <timer enabled="y" 
   second="0.10" 
   send_to="12"
>
  <send>
local time = utils.timer ()

if last_tick_time then
  print (string.format ("Tick after %0.6f", time - last_tick_time))
end -- if

last_tick_time = time

</send>

  </timer>
</timers>

Old version


Sitting around doing nothing

Tick after 0.100140
Tick after 0.100146
Tick after 0.100151
Tick after 0.100255
Tick after 0.100022
Tick after 0.100142
Tick after 0.100162
Tick after 0.100159
Tick after 0.100101
Tick after 0.100168

Running to weather station

...

East Windy Mountains (386)
East Windy Mountains (385)
East Windy Mountains (384)
East Windy Mountains (383)
East Windy Mountains (382)
Entrance to the Weather Observatory
  You stand in the entrance of the Weather Observatory building. Many pictures 
of weather events line the entrance. Nothing fancy about the entry room. To 
the south there appear to be offices. You can leave the area by heading down 
from here.
[Exits: south down]
Tick after 10.466981

In other words, a lengthy delay for the timer (10.5 seconds).

New version


Sitting around doing nothing


Tick after 0.100138
Tick after 0.100158
Tick after 0.100142
Tick after 0.100134
Tick after 0.100150
Tick after 0.100136
Tick after 0.100140
Tick after 0.100158


Running to weather station

...

Tick after 1.071707
Koloma Forest (604)
Koloma Forest (603)
Dread Fields (602)
Dread Fields (601)
A Grassy Spot (600)
Dread Fields (599)
Danameq Kujalleq (598)
Danameq Kujalleq (597)
Diamond Gorge (596)
Tick after 1.360532
Glaciers of Hypergelidus (595)
Glaciers of Hypergelidus (594)
West Windy Mountains (593)
West Windy Mountains (592)
West Windy Mountains (591)
West Windy Mountains (590)
Rashara Bheigh (589)
West Windy Mountains (588)
The Windy Mountains (587)
The Windy Mountains (586)
Tick after 1.522459
The Windy Mountains (585)
The Windy Mountains (584)
The Windy Mountains (583)
The Windy Mountains (582)
The Windy Mountains (581)
A Shrine to an Unnamed God (580)
East Windy Mountains (579)
East Windy Mountains (578)
Sarakhalah (577)
East Windy Mountains (576)
East Windy Mountains (575)
East Windy Mountains (574)
East Windy Mountains (573)
Tick after 1.869307
East Windy Mountains (572)
East Windy Mountains (571)
Entrance to the Weather Observatory
  You stand in the entrance of the Weather Observatory building. Many pictures 
of weather events line the entrance. Nothing fancy about the entry room. To 
the south there appear to be offices. You can leave the area by heading down 
from here.
[Exits: south down]
An administrator is here shuffling papers.
Tick after 0.764838

The ticks above are at a much better interval than after 10 seconds, but still more than 0.1 second. However a bit more research shows that there were 15 "tick" lines during the run, and there were in fact 15 packets received from the MUD in that time. Now I added an extra test for the timers when a packet was received, so that accounts for why we got 15 ticks (one per packet).

I think the Aardwolf "run to" is a bit of an extreme case. The MUD bangs out large amounts of data in large packets, so you traverse about 60 rooms in only 15 packets.

Under more normal situations (like a battle) the MUD would be processing fight rounds for each player and packaging things up into smaller packets.

It would be possible to test for timers more frequently but then you get the possible case of the client spending more time checking timers than doing anything else.

At least in the example above, since the timers are now processed (potentially) per packet received, then you get a chance for some timer-based event to fire as soon as anything happens on the MUD. And if nothing happens, you still get the normal timeout that you used to get.