Next I took Robby's idea and had one object say "start" then "junk" 500 times then "finish". Another object would start a timer when it got the "start" message and report the time when it got the "finish" message. First, I used an unfiltered listener, so any messages sent on that channel would be forwarded to the script. The sender reported that it sent "finish" 0.600243 seconds after it sent "start". The receiver reported 33.476112 seconds between hearing the "start" and "finish" messages. I then recompiled with Mono and ran the test again. This time all the messages were sent in 0.178058 and received in 44.580690. The sending was over 3 times faster, but the receiving was slower with Mono.
Now I modified the script to only set up listeners specifically for "start" and "finish" messages. Without Mono, they were sent in 0.600193 seconds and received in 0.644574. With Mono, 0.133408 and 0.133169. All these numbers have taught me two important things: 1) USE FILTERED LISTENERS!!! 2) ESPECIALLY USE FILTERED LISTENERS WITH MONO!!!!!
Now comes the fun part. I copied the unfiltered listener so that there were 25 of them. Each of them ran at about the same time as the single listener. With 100, they still ran about the same. With 1000, still the same. With 10000 (I'm serious...screenshot below) it was finally a different story. First, the time the sender reported to send the messages shot up to 1.916057 seconds. From that number, I estimated it would take 10 minutes for the listeners to finish. I waited for 15 minutes, expecting a Linden to show up and wonder what the hell I was doing, and still there was no response from the listeners.
Notice "Script perf" is 0 ips. I'm guessing they just haven't updated that to count Mono instructions.With the filters, there wasn't much of a change until 400 prims (I increased the number of prims differently). At that level, the listeners finished between .133783 and .201377 seconds, but one of them took 45.042740 seconds, which is so close to the time for the unfiltered listeners it almost makes me think the server panicked and just started handing that one script all the messages. I doubt that's the case, though, because then scripts which used filters and as a result didn't have to check the incoming message would experience errors if they started getting unfiltered messages. At 800 prims, the range was .156157 - .224534, again with a single script reporting at 46.228270. At this point, I didn't go further because looking through a log of 800 messages was getting difficult. Looking back at the data from the unfiltered runs, there was similar variance in the times as seen here, but when it is taking 45 seconds it is much less significant.
One final weird behavior that I noticed while recreating these tests for the Jira issue (see below). I went back to the ping test and added filters for "ping" and "pingback". I didn't expect to see any difference, since all the messages sent are "ping" and "pingback" (on different channels, so that is already filtered). Indeed, there was no difference when not using Mono. But with Mono, it took longer! The time increased to 0.101741, which is an increase of about .02 seconds or a 25% increase.
In conclusion, I am definitely going to use filters all the time now. I have created a Jira issue about the performance decreases with Mono. Now what can I test!? :P
2 comments:
Here's something else you can test :)
I'm going to make an assumption that your listener scripts did absolutely minimal processing. Am I right?
If so, then we can assume that there's a measurable overhead in figuring out what listeners to give the message to (minimal) as well as firing up the script and calling the listen event (significant).
Listen events are queued, which likely gives rise to a large part of the poor performance of the unfiltered listens, as the "finish message" cannot be processed (and it's time recorded) until all of the other messages have been (minimally) processed.
So what happens with there is more processing going on in the listener? Even something as simple as "Is this message really for me?". As an example, in the case of scripted swords, you cannot listen for messages to make the sword held in the hand visible/invisible by only filtering by the owner, as it is the sheath sending the messages rather than the avatar (ignore for now that you can filter on 'draw' and 'sheath' text). You would then have to have a check for [ if( llGetOwnerKey(id) == llGetOwner() ] or something similar.
I suspect that you will see at least some performance differences if you have some additional processing going on. Imagine a hug script that, upon receiving the "hug [so and so] message" on channel 0 needs to do a sensor ping for [so and so], send them a permission dialog, start the animation, move the avatar into range, etc.
While not all of that processing takes place in the listen event, one curious thing about LSL is that it will queue all chat messages while any part of the script is busy. I believe that the maximum event queue size is 64, but I don't know if that holds for listens.
[Off topic side-note: Control events, by contrast, are not queued. This makes it very hard to create a highly responsive sword script, as you must be *very* careful to not be busy and therefore 'miss' a keystroke. Controls that are pressed while any part of your script is processing are ignored.]
You could probably simulate any of that by simply putting in an llSleep( 0.1 ) call in the listen event when the listener receives one of the "junk" messages.
I'd be interested to know whether adding up the 0.1 second delays and comparing them to the actual time it takes to do the processing has a 1:1 correlation. I doubt it, though I wouldn't expect a huge difference. I'd also love to be able to view the server-side memory usage while the queued events are being stored until they may be processed.
Another thing to test: Chat lag. Make the junk messages sequential counters, and flag "out of sequence" messages. See if the flagged messages occur more frequently with lots of unfiltered listens as opposed to fewer filtered listens.
Interesting tests, Colin! I hope you make a series out of it :)
One thing I thought I noticed before that I just verified is that while all the objects report almost the same time between start and finish, they report in chunks with small but noticeable delays (a second at most) in between. This seems to indicate that when the sim can't handle distributing all the messages, instead of slowing down all the scripts equally it starves some so that it can keep serving others at the full rate. I'm going to look into this more.
Post a Comment