Zugg Software :: View topic

SubAdmin Joined: 18 Nov 2001 Posts: 5182

I started noticing this when trying to test the locking issue with 2.09. Let me start by saying that the test method here shows 1 bug and another optimization issue, but I am really only concerned by the bug displayed in these 2 timed tests. I know this is another of my 'extreme' tests. Once triggers change in this fashion they tend to stay slower.

Posted: Sat Nov 03, 2007 7:28 pm

You were a bit vague about the issues you were reporting here, so I could've misunderstood, but I saw no bug with the #waitsignal. I also saw no slowdown as the script continued. Four of them were delayed - one create was about 5s, two creates were about 15s, and one compile was 20s - but my test wasn't exactly stringent. The rest were very much at the median, 1300/700/1100.

If "the numbers get bigger" wasn't the issue you were reporting, please be a bit more specific. And I have no idea what your bug with #waitsignal was.

Posted: Sat Nov 03, 2007 7:38 pm

I reread your post and get the feeling that my report does back up your slowdown claims. I went back to check this when I went to close CMUD and my god, it took an age to close. I was trying to see if it was cache thrashing or using 100% cpu, but by the time I thought to check, it had closed. Definintely something here.

About the #waitsignal thing, though, I'm clueless.

Enchanter Joined: 09 Sep 2007 Posts: 605

Vijilante, I ran your script with #LOOP 100 {time}. After 8th iteration CMUD crashed with "insufficient quota to execute a command" message or like. Create time raises steady by 400 with each iteration, compile time at 6/7/8th steps was 912/998/2479

SubAdmin Joined: 18 Nov 2001 Posts: 5182

Using the #WAITSIGNAL and #SIGNAL is just a method to put the entire #LOOP 100 {time} into a background thread cleaner than hitting SHIFT-ESC. Those work perfectly.

If you examine the output snippet I included you will see that the time for the testing of the triggers increased evenly by about 900ms. That is the portion that looks to be a bug. Also from that ouput snippet you will see that I had to run the loop up over 110 times, as I say I have seen that particular time increase much sooner.

Any of the huge time jumps, and the massive delay when closing are caused by the background package updates. The only possible way I can see them becoming a problem in normal usage is if a script creates and fires at #TEMP triggers. It appears from the testing that I have done that it leaves something behind in the package file each time. This would mean that over the course of hours of play the background update could conceivably become a serious problem.

So there are 2 different tests presented, one glaringly highlights the background updates by having the #LOOP 100 {time} run in the main user thread. The other puts that loop into a background thread which lets things flow along better until the but with trigger execution time can be observed. Both tests have the same first 3 steps, then step 4 and step 5 determine which test you are doing. Sorry I didn't make it clearer, I was in a little bit of a rush.

Arde That is interesting, I can run that foreground loop test quite a bit further. I never ran it out enough to get a crash and the times involved are quite a bit different. Again something that appears a matter of system specs. Mine are floating all over the board in numerous crash dumps I have posted. Having yours might be interesting if no one else finds anything. Also I will take some time to run the foreground loop test out to a crash, although I shudder at the thought of how long it might take.

Posted: Sat Nov 03, 2007 9:28 pm

@Arde: 8 is rather low, but consider that during the course of that, CMUD has created and deleted 8000 triggers. That's quite a lot - if you've not got much RAM, I can see that many triggers being a problem.

@Viji: You only posted two loop iterations, and two got slower and one got faster. It was hard to tell just from that what you were highlighting as the problem. Regardless, I didn't see any slowdown over the iterations - they were all the same. The only slowdowns I saw were the background updates.

On that topic, I'm really not surprised that the background thread takes so long. When you consider that the test creates at least one hundred thousand triggers, it's hardly surprising that the background thread takes a while. I'd assume that it only saves things that're flagged as changed, and that's a lot of items that're marked as changed and need to be written to disk. I had the thread update about once every 30k triggers, which is still rather a lot :|

Enchanter Joined: 09 Sep 2007 Posts: 605

Ran 1st script (foreground loop) again, now it lasted for 9 loops. Here is the timings

Enchanter Joined: 09 Sep 2007 Posts: 605

I modified Vijilante' step 3 script and add #THREAD command to its tail. I can see increasing number of stopped threads with each loop, up to 12-15 of them. If choose to continue application after the crash, it may reduce number of stopped threads or may not to do so... Heh, loop 30, I have 38 threads...

SubAdmin Joined: 18 Nov 2001 Posts: 5182

I am not that concerned about the background updating. It takes about 2k triggers created and destroyed to add 1 second to that on my system, and my final test of reloading the package into a fresh launch shows that delay caused there is reset with each launch. The only way it could be an issue is if someone leaves CMud open continuously and uses a fairly large number of #TEMP triggers or #UNVAR. I guess knowing about it and the way in which it causes a periodic 100% CPU pause only is the only use of having found it. It lets us give better support and advice.

Obviously the crash isn't good, but it is caused by having the test in the foreground main thread. This is the same crash that the test done with 2.09 would cause. Look at Zugg's notes there.

In terms of the part I consider a bug I may have to just forget about it because it is very hard to replicate, and virtually impossible to cause in any normal usage. I will however post the full procedure and some final stats for consideration.

1. Launch CMud
2. Close Sessions window (ESC)
3. Enter at the command line

Wizard Joined: 14 Aug 2004 Posts: 1269

If you want to make sure that using other programs doesn't affect CMUD, one thing that will help is to open Task Manager and in the Processes list, locate the cMUD process that is using the most memory and set its priority to High (or just to Above Normal if you want to make sure you can still kill it via Task Manager, although there are other processes that might be running above normal - I think Winamp might, even though it doesn't appear to).

Posted: Mon Nov 05, 2007 5:49 pm

I'll take a quick look into this, but keep in mind the same comments that I made in the other post. When you are running long loops from a command line or trigger like this, Windows is blocked from it's normal messaging during that execution (to prevent text from the MUD from being processed).

This causes lots of side effects. It causes memory usage to rise. It causes the Windows message queue to fill up (which is what causes the "insufficient quota" that Arde gets). It prevents CMUD from cleaning up any threads that are finished, and probably prevents CMUD from cleaning up the database, which could cause the long database update times that you are seeing.

The background thread for updating the *.pkg database on disk is not blocked from running. But while it is running, it has a lock on the database (you can't modify the database while it's being saved to disk...otherwise you'd get corrupted databases very easily).

I'll take look at the #WAITSIGNAL case since that should be running the loop in the background, which shouldn't cause these problems. However, when loops are running in a background thread, they "give up" their processor slice every 200ms. This allows other threads (and the main UI thread) to get their time. So this *can* cause a script to run slower in the background that it might in the foreground.

In more technical terms, a loop running in a background thread calls Sleep(0) every 200 ms or so. This tells Windows to run any other threads that are waiting.

In any case, while it was useful to find the problem with hanging threads, we should probably avoid a lot of stress-testing that involves really huge loops on the command line. Anything that takes more than a minute or so to execute should never be executed directly on the command line (remember, it's going to stop all response from the MUD during that time, and most people don't want to stop their MUD output for that long). This kind of testing is going to cause all sorts of red-herrings that do not impact normal operation.

Posted: Tue Nov 06, 2007 3:54 am

200 ms seems like an awful long time to let a process run unchecked.

New Linux and FreeBSD schedulers run much smaller values than that for good interactive performance. Windows XP uses 10 ms for it's job scheduler. Lower number might even help with concurrency reducing the starvation on other threads?

Dunno it might be fine my mind has been wrapped up in 8-bit microcontrollers and writting an entire program that has to run under 25 ms.

Posted: Tue Nov 06, 2007 5:38 am

Yeah, but it's a tradeoff. With a value less than 200ms the background threads get a lot slower because they are context switching more. But it's definitely something I'll be fine-tuning over time.

Wizard Joined: 14 Aug 2004 Posts: 1269

Hmm, Llwethen has made me think of something - in a mud that doesn't implement a minimum delay between commands, 200 ms is a long time. Someone can come in and hit you before you even see them as the background thread is running and busy and the main thread hasn't updated the screen. That could be the difference between life and death.

Posted: Wed Nov 07, 2007 5:47 am

This isn't a delay. What I mean is that if you have a script stuck in a long loop, the loop will give up it's time-slice every 200ms. So this only effects long-running background scripts. Also, this is just a "forced" way to give up a time-slice. Windows itself will already multi-task the multiple threads, so it's not like CMUD is going to sit there for 200 ms without responding to anything.

However, with that said, keep in mind that while any script is running on the command line (in the foreground), CMUD isn't going to accept any text from the MUD until the foreground script is finished. But this only happens when a foreground thread is running, not a background thread.

Wizard Joined: 14 Aug 2004 Posts: 1269

Yes, I was talking about long-running background scripts, but if the main thread will display new text and allow input that's OK. Maybe I'm getting up my own arse here since there aren't a whole lot of scripts that should take more than 200 ms.