|
Ceres Wanderer
Joined: 25 May 2006 Posts: 88
|
Posted: Mon Oct 23, 2006 7:12 pm
[1.11] Possible performance bugs |
Just to clarify - I KNOW THIS IS A BETA.
If I understand correctly CMUD is supposed to compile altered scripts once after the alteration. I believe this is not happening or that there may be something else drastically causing scripts to run slower after a time.
I have rewritten the code specidied in this thread to take advantage of local variables where possible.
Before my final speed test I closed and restarted CMUD and was amazed by the results:
18:37:09:848 Contents detected.
18:37:09:864 Contents processed the orange canary|the orange canary|the orange canary|the orange canary|the pink elephant|the pink elephant|the pink elephant|the fluffy pineapple|the fluffy pineapple.
0.016 seconds
18:33:52:457 Contents detected.
18:33:52:473 Contents processed the agitated architect|the pink elephant|the fluffy rabbit|the fluffy rabbit.
0.016 seconds
This was amazing as before altering the CMUD code to use local variables it was 5 to 10 times slower than almost identical zMud script, so I was going to add another post to the aforementioned thread but decided I didn't really need the text after 'Contents processed'.
I edited the CMUD code and rerun the tests with the very same #SHOW messages from the command line, this is the results:
18:41:17:629 Contents detected.
18:41:17:957 Contents processed
0.328 seconds
18:41:20:801 Contents detected.
18:41:21:098 Contents processed
0.297 seconds
18:41:22:942 Contents detected.
18:41:23:223 Contents processed
0.281 seconds
19:00:59:285 Contents detected.
19:00:59:598 Contents processed
0.226 seconds
I ran the test at least another 20 times and the results were never less than 0.200 seconds and averaged 0.238 seconds.
Then I closed and restarted CMUD to test again without altering the scripts:
19:08:56:598 Contents detected.
19:08:56:692 Contents processed
0.094 seconds
19:09:09:879 Contents detected.
19:09:09:895 Contents processed
0.016 seconds
19:09:12:223 Contents detected.
19:09:12:239 Contents processed
0.016 seconds
19:10:43:676 Contents detected.
19:10:43:692 Contents processed
0.016 seconds
After the initial slower 0.094 run it settled into a mostly consistant 0.016 seconds wuth an odd occurance of up to 0.050 seconds.
Furthermore I wanted to test if prolonged running would also influence the results so I set an alarm to operate an alias which would issue one of two alternate #SHOW messages, one every five seconds, to fire my script. I left this running for 30 minutes and here are the final four results:
20:01:44:489 Contents detected.
20:01:44:801 Contents processed
0.312 seconds
20:01:49:489 Contents detected.
20:01:49:707 Contents processed
0.218 seconds
20:01:54:489 Contents detected.
20:01:54:770 Contents processed
0.281 seconds
20:01:59:489 Contents detected.
20:01:59:723 Contents processed
0.234 seconds
Clearly there could be some underlying issues here. |
|
Last edited by Ceres on Tue Oct 24, 2006 6:17 pm; edited 1 time in total |
|
|
|
Tech GURU
Joined: 18 Oct 2000 Posts: 2733 Location: Atlanta, USA
|
Posted: Mon Oct 23, 2006 7:32 pm |
Out of curiousity at what time interval did it start to slowdown? Was it gradual or instantaneous? I'm sure Zugg would like to know to debug this and I'm just curious myself.
Also did you try the test with differnet time intervals? Example 1 minute, 10 seconds etc.
I guess I could use your code and run a few tests myself. I guess I'm trying to sort out if it's a matter of number of executions, or time elapsed before performance starts to degrade. I'll run some additional tests and post the results. |
|
_________________ Asati di tempari! |
|
|
|
Zugg MASTER
Joined: 25 Sep 2000 Posts: 23379 Location: Colorado, USA
|
Posted: Mon Oct 23, 2006 7:56 pm |
Yes, I'd love more information about this. Your script is so complicated that it's hard to figure out what could cause something like this myself. My guess is that somehow, with your loops and stuff, some other thread is getting spawned with multiple instances of your triggers and aliases running, all causing a slowdown.
|
|
|
|
Ceres Wanderer
Joined: 25 May 2006 Posts: 88
|
Posted: Mon Oct 23, 2006 8:28 pm |
No time for more testing today but I'll post the rewritten code if your inclined to test it yourselves, This is the regex trigger:
Code: |
Code removed as it was not the cause |
The Alias:
Code: |
Code removed as it was not the cause |
The alias relies upon these two variables:
Code: |
Code removed as it was not the cause |
The timed test script was a 5 second alarm which activated the TestScript alias. The alias code is:
Code: |
Code removed as it was not the cause |
Please let me know if you manage to narrow this down and as always suggestions on optimising the code are always welcome. |
|
Last edited by Ceres on Tue Oct 24, 2006 11:05 am; edited 1 time in total |
|
|
|
Ceres Wanderer
Joined: 25 May 2006 Posts: 88
|
Posted: Tue Oct 24, 2006 5:25 am |
Just restarted CMUD and began the test again, the speed didn't return and in fact got worse +0.300 seconds every time.
Then restarted my PC before starting the CMUD session - speed was restored with consistant 0.016 results.
I'll let the alarm test run again for a while and let you know what happens. |
|
|
|
Ceres Wanderer
Joined: 25 May 2006 Posts: 88
|
Posted: Tue Oct 24, 2006 5:46 am |
I think I have narrowed it down - my previous post in regards to rebooting my machine may have been a red herring.
It seems that having the Package Editor open (set to be always on top) is enough to make the processing of my script 15 to 20 times slower.
Sorry I missed that common element earlier. |
|
|
|
Azador Newbie
Joined: 21 Sep 2006 Posts: 1
|
Posted: Tue Oct 24, 2006 8:26 am |
I can confirm a noticeable slowdown when the Package Editor is open.
|
|
|
|
Tech GURU
Joined: 18 Oct 2000 Posts: 2733 Location: Atlanta, USA
|
Posted: Tue Oct 24, 2006 12:22 pm |
Zugg has mentioned this in previous posts and in his current blog. Because of how the underlying components updates having the Package Editor open can cause a significant performance hit. He's currently working on it, but it's been a fustrating process so far.
As an aside, I can't get the trigger to fire unless I remove the ^ and $. But each time I look at it I can't figure out why that is. More tests tonight. |
|
_________________ Asati di tempari! |
|
|
|
Ceres Wanderer
Joined: 25 May 2006 Posts: 88
|
Posted: Tue Oct 24, 2006 6:23 pm |
I have done further testing on this using te script I used to assess the advantages by using Local variables in this thread.
It seems to me that when using Local variables the slowdown is only about 10% however in the script using regular variable it can be between 15 and 20 times slower.
I hope that helps Zugg to track down this gremlin. |
|
|
|
|
|