Script control() event timing is better than expected

Creating scripts
Post Reply
User avatar
Kayaker Magic
Posts: 354
Joined: Sun Dec 01, 2013 8:40 am
Has thanked: 52 times
Been thanked: 393 times

Script control() event timing is better than expected

Post by Kayaker Magic »

The control() event is supposed to be called continuously while the keys you have captured are being held down. I thought that “continuously” meant that this event was called about 11 times a second, or about once every 0.0909 seconds. This is an often mentioned “heartbeat” time in the simulators. But apparently I am wrong, since even SL is faster than this at control events!

I have used this to turn the binary nature of the controls into a somewhat analog value by counting how many times control() is called in a 1 second period (as measured by timer()). When turning a boat, for example, tapping on the left_arrow key only results in a couple of control() events in a second, while mashing down on the key and holding it gives you 11 counts in a second (I thought). The higher the number, the faster I turn the boat.

I recently saw some effects in one of my scripted objects that suggested that control() timing is very different on different worlds here in Kitely. I wrote a script to measure this (listed below). The results were astonishing! On some Kitely worlds I was seeing as many as 100 control() events per second! This is amazingly good performance, but of course it fails to work right with my assumption of 11 events per second. Unfortunately, when I tried doing the timing test on other Kitely worlds I got very different results, as low as 7 events per second. Strangely, I got very good results on my own worlds where I have too many scripts that use too much time (according to Ilan). So having lots and lots of large scripts is not what causes the control() time to be so slow. Perhaps there is one bad script out there on some of these worlds that hogs so much time that it slows down control() response time on other better behaved scripts? (I lump my scripts into the better behaved category, of course!)

Here are some results from running the test script on several different grids and worlds. The times column is control() events per second, higher times are good I suppose, variability is bad.

Times Grid Region
100 Kitely Test Bed (1x1, empty, private)
90 Kitely Merchant Sandbox (2x2, empty)
62 Kitely Panthalassa (3x3 very full of busy scripts, lots of prims)
17 Kitely Never Ending Story (4x4, lots of prims, unknown scripts)
15* Kitely Frostbite Thane (4x4, lots of prims, unknown scripts)
67 OSGrid International Sailing (6x6, OS 0.9, medium load of scripts, lots of prims)
20 OSGrid Panthalassa (3x3, OS 0.9, lots of prims and scripts)
86 OSGrid Panthalassa1 (3x3, OS 0.9, empty region)
82 OSGrid Sandbox 12 (1x1, OS 0.9, empty)
44 SL Port Lux (1x1, moderate number of prims and scripts)
8 Inworldz Pomo (1x1, lots of scripts and prims)

*The statistic for this region slowly cycled between 7/second, rising to 20/second then slowly back down to start over again on about a 20 second cycle.

What I am going to have to do is measure this maximum number every time a vehicle starts. Then use this maximum number instead of the assumption of 11 per second. That will fail on Frostbite, where the number changes over time, but will work most places.

Code: Select all

//put this script in a prim, sit on it,
//try tapping and holding the forward-arrow key (or the w key)
//hold it for different periods of time
//the timer() time should be around 1 second, but gets longer on very busy regions
//Holding the key down continuously I thought would give a count of 11 and a time of 0.0909.
//But I am seeing counts as high as 100! Events per second!

integer times=0;        //how many times control is called in a second
float   avetime=0.0;    //average time between control events
float   lastime;        //last time control was called
float   lastsec;        //time of the last timer() event
default
{
    state_entry()
    {
        llSitTarget(<0,0,2>,ZERO_ROTATION);     //seat the avatar above the prim
    } //state_entry
    changed(integer flag)
    {
        if (flag&CHANGED_LINK)
        {
            if (llAvatarOnSitTarget()!=NULL_KEY)    //detect the avatar sitting
            {
                llRequestPermissions(llAvatarOnSitTarget(),PERMISSION_TAKE_CONTROLS);
                llSetTimerEvent(1.0);       //count controls in one second
                lastsec=llGetTime();        //used to watch the timer time
            }
            else        //(this isn't the best way, but for a single prim test this works)
            {
                llReleaseControls();        //give the avatar back the controls
                llSetTimerEvent(0.0);       //stop working when they stand up
                llSetText("",<0,0,0>,0.0);  //erase the old data display
            }
        }
    } //changed
    run_time_permissions(integer flag)
    {
        if (flag&PERMISSION_TAKE_CONTROLS)          //when permission granted,
            llTakeControls(CONTROL_FWD,TRUE,FALSE); //capture the fwd-arrow key
    } //run_time_permissions
    control(key id, integer level, integer edge)
    {
        if (level&CONTROL_FWD)                  //if the fwd-arrow key is pressed
        {
            times += 1;                         //count how often you notice it is down
            float curtime=llGetTime();
            if (times>1)
                avetime += curtime-lastime;         //how long since the last time 
            lastime=curtime;
        }
    } //control
    timer()
    {
        float cursec=llGetTime();
        float delta=cursec-lastsec;    //this should be around 1 second
        lastsec=llGetTime();
        string mess = "timer="+(string)delta+" (should be around 1.0)";
        mess += "\ncontrol events = "+(string)times+" (never larger than 11)";
        if (times>1)
        {
            mess += "\ntime between events = "+(string)(avetime/(float)(times-1))+ " (should be around 0.09)";
        }
        times=0;
        avetime=0.0;
        llSetText(mess,<1,1,1>,1.0);
    } //timer
}
These users thanked the author Kayaker Magic for the post (total 3):
Ilan TochnerKeith SelmesSelby Evans
User avatar
Ilan Tochner
Posts: 6503
Joined: Sun Dec 23, 2012 8:44 am
Has thanked: 4942 times
Been thanked: 4454 times
Contact:

Re: Script control() event timing is better than expected

Post by Ilan Tochner »

Hi Kayaker,

World server resource usage can reduce the frequency of the OpenSim heartbeat. Things such as script time, time spent calculating physics, teraforming activity, avatar activity, etc. all add up to create a certain amount of resource usage per frame. This usage can greatly fluctuate on some worlds while remaining quite static on others. Meanwhile, the amount of server resources allocated per world is dependent on each world's World Type. The combination of changing server resource allocation and changing resource usage creates the variability you've measured. The server may be aiming for 100 times per second but it isn't preemptively multitasking so it can only attain a lower number that corresponds to how often it was free to actually execute the heartbeat.
These users thanked the author Ilan Tochner for the post (total 2):
Keith SelmesKayaker Magic
User avatar
Freda Frostbite
Posts: 742
Joined: Sat Mar 29, 2014 2:10 am
Location: Florida, space coast.
Has thanked: 608 times
Been thanked: 769 times

Re: Script control() event timing is better than expected

Post by Freda Frostbite »

I have no clue what you two just said but you sure are cute, saying it.
These users thanked the author Freda Frostbite for the post:
Kayaker Magic
User avatar
Kayaker Magic
Posts: 354
Joined: Sun Dec 01, 2013 8:40 am
Has thanked: 52 times
Been thanked: 393 times

Re: Script control() event timing is better than expected

Post by Kayaker Magic »

Freda Frostbite wrote:I have no clue what you two just said but you sure are cute, saying it.
Cute as we may be, did you notice that your world Frostbite Thane has an event rate that is 10 times slower than my busy and overloaded world Panthalassa? That stunt kite I was demonstrating slows down until it looks like it is flying through molasses on your world and I wonder what other things will slow down for you. You might want to figure out why this is happening.

I noticed that the world Never Ending Story had at least 4 of those Paramour dance balls around the dance floor. Do you have any of those in Frostbite Thane? More than one of them? That is a huge complicated script, I wonder if it is wise to have more than one of them running in a region. Does it show up in the Top Scripts list? You could try temporarily removing it (them) and running my test to see if things improve. I'd be happy to help with that testing.
These users thanked the author Kayaker Magic for the post (total 2):
Ilan TochnerDot Matrix
User avatar
Kayaker Magic
Posts: 354
Joined: Sun Dec 01, 2013 8:40 am
Has thanked: 52 times
Been thanked: 393 times

Re: Script control() event timing is better than expected

Post by Kayaker Magic »

When you overload a simulator with scripts (and I am very good at doing that!) one of the first effects that I notice is the accuracy of timers. That is why in that control() event test I measure how long a one second timer takes, as well as the number of control() events and the average time between control() events. If I see the one second timer taking too long, this means things are so bad that none of the other measurements are useful. For example, if the simulator is so busy that a one second timer takes three seconds, I might get three times as many control() events. Or if the system is that busy it probably isn't going to call control() very often either. I didn't mention it in the first post, but I checked the timer measurement and in most cases it was very close to one second. (SL was more variable, but who cares about SL?)

Before I wrote that control() test, I had (foolishly) assumed that everything ran on the same heartbeat at 11 per second. But apparently control() does not. I have tested the not_at_target() event before, but I repeated the old experiment to see if I was wrong about this event (script below). I ran this test in all the same places with the following results:

Times Grid Region
11 Kitely Test Bed (1x1, empty, private)
11 Kitely Merchant Sandbox (2x2, empty)
11 Kitely Panthalassa (3x3 very full of busy scripts, lots of prims)
11 Kitely Never Ending Story (4x4, lots of prims, unknown scripts)
11 Kitely Frostbite Thane (4x4, lots of prims, unknown scripts)
11 OSGrid Sandbox – 4 Trees (1x1, empty)
15 OSGrid International Sailing (6x6, OS 0.9, medium load of scripts, lots of prims)
11 OSGrid Panthalassa (3x3, OS 0.9, lots of prims and scripts)
11 OSGrid Panthalassa1 (3x3, OS 0.9, empty region)
12 OSGrid Sandbox 12 (1x1, OS 0.9, empty)
22 SL Port Lux (1x1, moderate number of prims and scripts)
11 Inworldz Pomo (1x1, lots of scripts and prims)

On a few regions the timer stretched out and more not_at_target events sneaked in. I assume those were busy simulators with an under-powered server. On SL the statistics were all over the place, one second timers taking from 0.75 to 1.3 seconds, counts from 3 to 22 not_at_targets per second. But who cares what happens in SL? Other than SL, I am relieved to see that my memory of measuring 11 heartbeats per second turns out to still be correct.

Although I understand that server resource usage can slow down the heartbeat, I am not seeing the heartbeat slow at all in the Kitely worlds that are getting wildly different control() event times. I'd like to know what it is that can slow down control() events so much without slowing down other heartbeat events or timer().

I can't complain too much since I was surprised to find out how fast control() is called! It rarely slowed down as slow as the 11 times per second I expected. Perhaps capturing user key events was considered so important that they run in idle time instead of on a regular heartbeat.

Code: Select all

//put this script in a prim
//it will run and display statistics in floating text

integer times=0;        //how many times not_at_target is called in a second
float   avetime=0.0;    //average time between not_at_target events
float   lastime;        //last time not_at_target was called
float   lastsec;        //time of the last timer() event
default
{
    state_entry()
    {
        llSetTimerEvent(1.0);       //perform the test every second
        lastsec=llGetTime();        //used to watch the timer time
        llTarget(llGetPos()+<0,100,100>,0.1);   //start not_at_target going
        llSetText("",<0,0,0>,0.0);  //clear any old floating text
    } //state_entry
    on_rez(integer param)
    {
        llResetScript();
    }
    not_at_target()
    {
        times += 1;                         //count how often you are called
        float curtime=llGetTime();
        if (times>1)
            avetime += curtime-lastime;         //how long since the last time 
        lastime=curtime;
    } //not_at_target
    timer()
    {
        float cursec=llGetTime();
        float delta=cursec-lastsec;    //this should be around 1 second
        lastsec=llGetTime();
        string mess = "timer="+(string)delta+" (should be around 1.0)";
        mess += "\nnot_at_target events = "+(string)times+" (never larger than 11)";
        if (times>1)
            mess += "\ntime between events = "+(string)(avetime/(float)(times-1))+ " (should be around 0.09)";
        times=0;
        avetime=0.0;
        llSetText(mess,<1,1,1>,1.0);
    } //timer
}
These users thanked the author Kayaker Magic for the post:
Selby Evans
Danieal gustin
Posts: 1
Joined: Tue Jan 03, 2017 10:18 am
Has thanked: 0
Been thanked: 0

Re: Script control() event timing is better than expected

Post by Danieal gustin »

Hi, new from Australia and here unable to understand the meaning of 11 Kitely Test Bed ?? Can I change the bed with bedding according to my script?
Aura Home http://www.rushk.com.au/aura-home Online Australia.
User avatar
Mike Lorrey
Posts: 361
Joined: Sun Sep 04, 2016 5:40 pm
Has thanked: 71 times
Been thanked: 269 times

Re: Script control() event timing is better than expected

Post by Mike Lorrey »

Kayaker Magic wrote:
Freda Frostbite wrote:I have no clue what you two just said but you sure are cute, saying it.
Cute as we may be, did you notice that your world Frostbite Thane has an event rate that is 10 times slower than my busy and overloaded world Panthalassa? That stunt kite I was demonstrating slows down until it looks like it is flying through molasses on your world and I wonder what other things will slow down for you. You might want to figure out why this is happening.

I noticed that the world Never Ending Story had at least 4 of those Paramour dance balls around the dance floor. Do you have any of those in Frostbite Thane? More than one of them? That is a huge complicated script, I wonder if it is wise to have more than one of them running in a region. Does it show up in the Top Scripts list? You could try temporarily removing it (them) and running my test to see if things improve. I'd be happy to help with that testing.
Ah, Perhaps we could script a satellite unit to work with the dance balls, so you could have one ball in a sim with satellites in each dance area working off the one ball as a server? That would minimize the use of the dance balls.
User avatar
Mike Lorrey
Posts: 361
Joined: Sun Sep 04, 2016 5:40 pm
Has thanked: 71 times
Been thanked: 269 times

Re: Script control() event timing is better than expected

Post by Mike Lorrey »

Danieal gustin wrote:Hi, new from Australia and here unable to understand the meaning of 11 Kitely Test Bed ?? Can I change the bed with bedding according to my script?
Look at the headers at the top of the list. Kayaker isn't using a table but has his data laid out like a table. Its 11 events per second, on Kitely Grid, in the region named Test Bed.
Post Reply