Region performance tests (% scripts run)

[Profaitchikenz Haiku]

In a post in the server forums it was suggested that we try and assess the behaviour of regions to see if the % scripts run figure does actually equate to acceptable or poor performance. So here goes with in-region communications

This test examines region communications for delays or missed messages using llRegionSay and llSay on two high-negative channels

Four (slightly more) sets of messages are sent each minute, with 13 seconds between them.

The messages are sent together, and immediately after sending them a timer is set to fire in 0,04 seconds (about two frames). If either message is not heard withing this time a timeout fault is logged. (Point about the tight timer is after the scripts).

This test is more of a reassurance factor, I have not detected any errors yet running on
1: Mainland with 70% scripts run (main channel)
2. Mainland with 30% scripts run (main channel)
3. Mainland with 99% scripts run (RC channel)
4. Private island (full region) with 99% scripts run (main channel)

I have not yet tested it on a Homestead

The idea however is to lay to rest some fears that have been expressed about messages being lost or delayed in laggy regions.

There are three prims, a controller and two listeners.

The controller sends an incremented number at an interval to a pair of listeners using llRegionSay and llSay on two channels, and listens for a reply echoing back that same number.

If one of both replies do not arrive within a reasonable time a fail is recorded, or if the timely received message is not the same number.

Each listener that receives a message first echoes it back, then checks to see if it is one greater than the previous message. If so it records a success, if not it records a missed message.

Each prim has hovertext giving the number of success and failures.

If the controller records a fail it logs the time and nature of the failure. When the owner touches the prim any such events are chatted out and the list or events emptied.

Instructions:

Rezz three Prims, name then "Controller", "Listener 1", "Listener 2"

Place the controller and Listener 2 close together, less than 20 metres apart.
Place Listener 1 further away, perhaps 500 metres upwards vertically, but somewhere that you can get to easily.

Drop the script Listener 1 inside Listener 1

// Listener 1 to respond to and use llRegionSay for comms testing

key owner;

integer expected = 0;  //  is set to the last number recieved plus 1 for the expected next message

integer rsChan;     // channel to listen on
integer rsHandle;

integer missed = 0; // count of skipped message sequences

integer key2chan(key ID)
{
    return 0x80000000 | (integer)("0x"+(string)ID);
}

announce(string message)
{
   llSetText(message, <1.0,1.0,1.0>, 1.0); 
}

default
{
    state_entry()
    {
        owner = llGetOwner();
        llSetObjectName("Listener 1");
        rsChan = key2chan(owner) + 1;
        rsHandle = llListen(rsChan, "Controller", "", "");
        announce("Listening");;        
    }
    listen(integer ch, string name, key id, string msg)
    {
        integer msgVal = (integer) msg;
        llRegionSay(rsChan, msg);     // echo it
        if( msgVal == -1)       // reset counters
        {
            expected = 0;
            missed = 0;    
        }
        else
        {
            if( msgVal != expected)  missed += 1;
            expected = msgVal + 1;
        }
        announce("Expecting " + (string) expected + "\nMissed " + (string) missed);
    }
}

Drop the script Listener 2 inside Listener 2.

// Listener 2 to respond to and use llSay for comms testing

key owner;

integer expected = 0;  // is set to the last number recieved plus 1 for the expected next message

integer sChan;     // channel to listen on
integer sHandle;

integer missed = 0; // count of skipped message sequences

integer key2chan(key ID)
{
    return 0x80000000 | (integer)("0x"+(string)ID);
}

announce( string message)
{
    llSetText(message, <1.0,1.0,1.0>, 1.0);
}

default
{
    state_entry()
    {
        owner = llGetOwner();
        llSetObjectName("Listener 2");
        sChan = key2chan(owner) - 1;
        sHandle = llListen(sChan, "Controller", "", "");
        announce("Listening");  
    }
    listen(integer ch, string name, key id, string msg)
    {
        integer msgVal = (integer) msg;
        llSay(sChan, msg);     // echo it
        if( msgVal == -1)       // reset counters
        {
            expected = 0;
            missed = 0;    
        }
        else
        {
            if( msgVal != expected)  missed += 1;
            expected = msgVal + 1;
        }
        announce("Expecting " + (string) expected + "\nMissed " + (string) missed);
    }
}

Drop the script Controller inside the controller, which should commence once it has heard from the two listeners.

// controller for region comms tests

key owner;

integer rsChan;     // channel for llRegionSay
integer rsHandle;

integer sChan;      // channel for llSay
integer sHandle;

integer counter;    // sequential integer to be sent as test message, doubles as number of test attempts

integer rsFails = 0;   // RegionsSay incorrect reply
integer sFails = 0;    // llSay incorrect reply 
integer timeouts = 0;   // nothing heard before fast timeout

float interval = 13.0;  // seconds between each transmission
float timeout = 0.04;   '// seconds to allow for reply, approx 2 frames

string action;
string results;

integer reply1; // look for both having replied before sending a new message
integer reply2;

list reports = [];

// Convert to human-readable HH:MM:SS format
string clock_time()
{
    integer now = (integer)llGetWallclock();
    integer seconds = now % 60;
    integer minutes = (now / 60) % 60;
    integer hours = now / 3600;
    // reset newday at 23:00 hours so that at midnight the day advances

    return llGetSubString("0" + (string)hours, -2, -1) + ":" 
        + llGetSubString("0" + (string)minutes, -2, -1) + ":" 
        + llGetSubString("0" + (string)seconds, -2, -1);
}
 
report(string what)
{
    string details = clock_time() + " " + what;
    reports += [details]; 
}

integer key2chan(key ID)
{
    return 0x80000000 | (integer)("0x"+(string)ID);
}

announce(string message)
{
    llSetText(message, <1.0,1.0,1.0>, 1.0);
}

default
{
    state_entry()
    {
        owner = llGetOwner();
        llSetObjectName("Controller");
        llSetTimerEvent(0.0);
        rsChan = key2chan(owner) + 1;
        rsHandle = llListen(rsChan, "Listener 1", "", "");
        sChan = key2chan(owner) - 1;
        sHandle = llListen(sChan, "Listener 2", "", "");
        counter = 0;
        reply1 = -2;    // on a reset we will be getting back -1
        reply2 = -2;
        action = "starting";    // send -1 to both listeners with no timeouts
        announce(action);
        llRegionSay(rsChan,(string) -1);
        llSay(sChan, (string) -1);
    }
    
    listen(integer ch, string name, key id, string msg)
    {
        llSetTimerEvent(0.0);
        if( ch == rsChan) reply1 = (integer) msg;
        else if( ch == sChan) reply2 = (integer) msg;
        if( action ==  "starting")
        {
            if( reply1 == reply2)
            {
                action = "sending";
                counter = 0;
                results = "";
                llSetTimerEvent(1.0);   // send the first message ASAP
            }
        }
        else if( action == "waiting")
        {
            if( ch == rsChan)
            {
                if( counter != reply1)
                {
                    ++rsFails;
                    report("RegionSay reply mismatrch");
                }
            }
            else if( ch == sChan)
            {
                if( counter != reply2)
                {
                    ++sFails;
                    report("Say reply mismatch");
                } 
            }
            if( reply1 > -1 && reply2 > -1)
            {
                results = "Sent " + (string) counter + "\n RegionSay Fails " + (string) rsFails + "\n Say Fails " + (string) sFails + "\n Timeouts " + (string) timeouts;
                announce(results);
                ++counter;
                action = "sending";
                llSetTimerEvent(interval); 
                reply1 = -1;
                reply2 = -1;
            }
        }
    }
    touch_end(integer touches)
    {
        key toucher = llDetectedKey(touches - 1);
        if( toucher == owner )
        {
            integer iiMax = llGetListLength(reports);
            if( iiMax == 0)
            {
                llOwnerSay("Nothing to report");
            }
            else
            {
                integer ii = 0;
                for(; ii < iiMax; ii++)
                {
                    llOwnerSay(llList2String(reports, ii) );
                }
                reports = [];
            }   
        }           
    }
    timer()
    {
        llSetTimerEvent(0.0);
        if( action == "sending")
        {
            llRegionSay(rsChan,(string) counter);
            llSay(sChan,(string) counter);     
            action = "waiting";
            llSetTimerEvent(timeout);       
        }
        else if(action == "waiting")
        {
            announce("Timed out!");
            report("Reply timeout");
            ++timeouts;
            ++counter;
            action = "sending";
            llSetTimerEvent(interval);
        }
    }
}

If you need to restart the monitoring, simply reset the controller script.

Tight timer loops

Kelly Linden stated in 2011 that there was no point in a timer resolution smaller then 0.02 seconds, and that for practical purposes 0.1 seconds was about the finest resolution. However, my experiments have shown that 0.04 is possible even in quite a busy script, and for the light loadings in the controller script 0.04 seems Ok.
 

Edited December 10, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

The Time has come, the Walrus said...

This next test is much simpler, a single prim with a single script, making a single measurement, one second.

I'm currently waiting on a better explanation of what "% scripts run" means, but this script assumes it can get everything done that it needs to in a single pass and implement a wall clock accurate to a second. If for some reason it gets delayed too much, it's going to start losing time.

// Implement a 1-second counter and an internal clock, compare it with an external clock

key owner;

integer WCnow;      // wallCLock time

integer WCstart;    // kickoff time in seconds

integer MYnow;      // calculated time


string clock_time(integer when)
{
    integer seconds = when % 60;
    integer minutes = (when / 60) % 60;
    integer hours = when / 3600;

    return llGetSubString("0" + (string)hours, -2, -1) + ":" 
        + llGetSubString("0" + (string)minutes, -2, -1) + ":" 
        + llGetSubString("0" + (string)seconds, -2, -1);
}

announce(string message)
{
    llSetText(message, <1.0,1.0,1.0>,1.0);
}

showTimes()
{

    WCnow = (integer) llGetWallclock();
    string details = "Wall clock " +  clock_time( WCnow );
    if(WCnow < WCstart)
    {
     	WCstart = WCnow; // midnight has been and gone
    }
    details += " Elapsed seconds " + (string)  (WCnow - WCstart);
    details += "\nMy clock " + clock_time(MYnow);
    details += " Elapsed Seconds " + (string) (MYnow - WCstart) ;
    integer drift = WCnow - MYnow;
    details += "\nDrift " + (string) drift; 
    announce(details);
}

default
{
    state_entry()
    {
        owner = llGetOwner();
        announce("Looking for 00 seconds");
        do
        {
            WCstart = (integer) llGetWallclock();
        } while( WCstart % 60 != 0);
        MYnow = WCstart;
        llSetTimerEvent(1.0);
        announce("Starting");
    }

    timer()
    {
        MYnow += 1;
        if( MYnow % 60 == 0)
        {
            showTimes();
        }
    }
}

 

Edited December 10, 2021 by Profaitchikenz Haiku
corrected script for midnight

[Profaitchikenz Haiku]

The third test is purely number-driven, there are no timers or events once the test commences, so it's purely down to how much the script can get to run in the region scheduler, it won't be held up itself waiting for events.

(To the mathematicians, I know there are faster, more elegant, more efficient algorithms, but for the purposes of this test I just want a pedestrian old slogger to grind away at the problem).

Make a prim, drop this in, touch and go

// find all the prime numbers by a brute-force square-root upper bound method
// exclude those numbers ending with digits 024568
// exclude numbers whose sum of all digits is evenly divisible by three
// take the square root of the test number and try dividing by all known primes less than that value, exclude if one gives remainder 0
// stop at 1000 bytes of memory free
// time the routine

key owner;

integer startTime;
integer endTime;

list primes = [1,2,3,5,7];
integer freemem;

announce(string message)
{
    llSetText(message, <1.0,1.0,1.0>,1.0);
}

findPrimes()
{
    integer value = 9;
    integer end = 10101; // wildly optimistic, you'll be out of memory a qaurter of the way there
    string digits;
    integer len;
    integer isPrime;
    string notPrimes = "024568";     // numbers ending with one of these digits can never be prime
    integer ii;
    
    do
    {
       isPrime = 0;  // assume it isn't, as primes are rare
       digits = (string) value;
       len = llStringLength(digits);

       if( llSubStringIndex(notPrimes, llGetSubString(digits, len-1,len-1) ) < 0)
       {
           integer sum = 0;
           for( ii = 0; ii < len; ii++)
           {
               sum += (integer) llGetSubString(digits, ii, ii);
            }
           if( sum % 3 != 0)
           {
                ii = llGetListLength(primes) - 1;
                integer remainder;
                integer testVal;
                integer sqrtVal = (integer) llSqrt(value);
                
                while( llList2Integer(primes, ii) > sqrtVal) ii--;  // faster than just taking the half-value to be tested               
               do
               {
                   testVal = llList2Integer(primes, ii);
                   remainder = value % testVal;
                }while( (--ii > 0) && (remainder != 0) );   // don't let ii reach zero as everything is divisible by 1
                if( remainder != 0)
                {
                    primes += value;
                    freemem = llGetFreeMemory();
                    announce("Free Memory " + (string) freemem + " Prime " + (string) value);
                } //else llOwnerSay("Was divisible by " + (string) testVal);
            } //else llOwnerSay("Divisible by 3");
        }//else llOwnerSay("Ends with known non-prime digit");
        value +=1;
    } while(value < end && freemem > 1000);
    endTime = (integer) llGetWallclock();
    announce((string) llGetListLength(primes) + " Prime numbers found in " + (string) (endTime - startTime) + " seconds");
}


default
{
    state_entry()
    {
        owner = llGetOwner();
        freemem = llGetFreeMemory();
        announce("Free Memory " + (string) freemem);
    }

    touch_start(integer touches)
    {
        key toucher = llDetectedKey(touches - 1);
        if( toucher == owner)
        {
            startTime = (integer) llGetWallclock();
            findPrimes();
        }
    }
}

 

 

Edited December 9, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

A revision to the prime number method posted above - I hadn't fully implemented the method of summing all the digits to test for division by three.

 

The third test is purely number-driven, there are no timers or events once the test commences, so it's purely down to how much the script can get to run in the region scheduler, it won't be held up itself waiting for events.

(To the mathematicians, I know there are faster, more elegant, more efficient algorithms, but for the purposes of this test I just want a pedestrian old slogger to grind away at the problem).

Make a prim, drop this in, touch and go

// find all the prime numbers in the positive range of SL integers.
// time the routine

key owner;

integer startTime;
integer endTime;

list primes = [1,2,3,5,7];
integer freemem;

announce(string message)
{
    llSetText(message, <1.0,1.0,1.0>,1.0);
}

findPrimes()
{
    integer value = 9;
    integer end = 101010101; // 
    string digits;
    integer len;
    integer isPrime;
    string notPrimes = "024568";
    integer ii;
    
    do
    {
       isPrime = 0;  // assume it isn't, as primes are rare
       digits = (string) value;
       len = llStringLength(digits);
       
       if( llSubStringIndex(notPrimes, llGetSubString(digits, len-1,len-1) ) < 0)
       {
            integer sum = 0;
            do
            {
                for( ii = 0; ii < len; ii++)
                {
                    sum += (integer) llGetSubString(digits, ii, ii);
                }
                digits = (string) sum;
                len = llStringLength(digits);
                if( len > 1) sum = 0;
            } while( len > 1);
          
           if( sum % 3 != 0)
           {
              
                ii = llGetListLength(primes) - 1;
                integer remainder;
                integer testVal;
                integer sqrtVal = (integer) llSqrt(value);
                
                while( llList2Integer(primes, ii) > sqrtVal) ii--;  // faster than just taking the half-value to be tested               
               do
               {
                   testVal = llList2Integer(primes, ii);
                   remainder = value % testVal;
                }while( (--ii > 0) && (remainder != 0) );   // don't let ii reach zero as everything is divisible by 1
                if( remainder != 0)
                {
                    //llOwnerSay("is prime");
                    primes += value;
                    freemem = llGetFreeMemory();
                    announce("Free Memory " + (string) freemem + " Prime " + (string) value);
                }
                //else llOwnerSay("Was divisible by " + (string) testVal);
            }
            //else llOwnerSay("Divisible by 3");
        }
        //else llOwnerSay("Ends with known non-prime digit"); 
        value +=1; 
    } while(value < end && freemem > 1000);
    endTime = (integer) llGetWallclock();
    announce((string) llGetListLength(primes) + " Prime numbers found in " + (string) (endTime - startTime) + " seconds" + " last value " + (string) value);
    if( freemem <= 1000) llOwnerSay("Stopped for low memory");
}


default
{
    state_entry()
    {
        owner = llGetOwner();
        freemem = llGetFreeMemory();
        announce("Free Memory " + (string) freemem);
    }

    touch_start(integer touches)
    {
        key toucher = llDetectedKey(touches - 1);
        if( toucher == owner)
        {
            startTime = (integer) llGetWallclock();
            findPrimes();
        }
    }
}

 

Edited December 10, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

The previous three tests have been largely pointless:

1) Messages : I have yet to detect any instances of llSay and llRegionSay messages on channels other then 0 being delayed or dropped. (Chat-lag on channel 0 is something else, as explained by Oz Linden at a Server User Group meeting it is a rendering issue, all the letters put up in the chat floater are drawn there pixel by pixel, so if there's a mass of drawing to be done, they get put in the queue).

2) Times : There has been drift measured in the tests but not enough to be considered significant (45 seconds lost in 34185 in the worst-affected region is less than 0.2%) Some of the lost seconds can be explained by the momentary hit each time an avatar with scripted attachments enters the region.

3) Prime number-crunching: Although this does show that the worse the region performance the more time is required to compute, this is hardly a surprise, and in addition, SL is not intended to be a heavy-computational platform.

The next test is closer to measuring some of the visible degradation that people have complained about; starting to move, moving, and stopping movement of scripted objects.

It uses Keyframed Motion to send a sphere along several paths of two distinct lengths, using one of two definite times for the motion. 

It uses timers to detect for two particular problems that have been observed in the past:

a) Keyframedmotion does not start promptly enough (if at all) and so moving_start was not received.

b) Keyframed motion took much longer than expected and moving_end was not raised (instancees were seen of the object stopped just a few metres from the intended destination apparently frozen).

In addition, the script records how often the journey took more than 5% longer than expected (this count includes the above moving_end failures but also those where moving_end was received but after the 5% point).

Reports of the runs in various regions will follow in a few days, here is the test for those wishing to try it for themselves.

Note that, as was mentioned in the time test, an avatar with heavy scripts entering a region may well account for some of the failures for moving_end, or the extended journey time.

 

ETA

Typical, mistakes seem to only become visible some time after publication:

The moving_end count includes all of the late counts, not vice-versa as I stated

 

// Test Keyframed motion in a region by repeated moves along known paths
// since the distances are known and the desired time is specified the journey time can be computed
// and compared with the actual times of moving_end
// the course is across the diagonals and along two sides of s 20m x 20 square path.
// rezz a sphere at the Low-X low_y corner of the intended square and it will compute the corners
// move the square and reset the script to get the desired figures
// for parcels with not enough room for a 20x20 square amend xOffset and yOffset as appropriate
// Set Z hieght to try and avoid any collisions with avatars and objects, KFM ignores collisions except 
// with physical objects but we don't want to add more to the region load than is absolutely necessary
//
// Touch to start, then issue commands on channel /-13
// report - chats out the collected stats
// debug - toggles debug on or off for a more detailed view of what is happening when
// stop - ceases action
// reset - ceases action, clears the counters, and goes back to the start+
//
// Reported stats are
// Journeys made - each separate KFM move is a journey
// Start timeout - number of times moving_start failed to be raised withing 0.5 seconds of starting movement
// End timeout - number of times moving_end failed to be raised after the expected movement time plus 15%
// Late - number of times the journey took more than 5% longer than expected (includes the moving_end instances obviously)

key owner;

integer debug = 0;

integer myChan = -13;
integer cHandle;

float xOffset = 20.0;   // adjust these for the size of square/rectangle to be created 
float yOffset = 20.0;   // starting from the initial position

// no need to amend further portions

list points = [];
integer maxPoints;
integer thisPoint;

vector startPos; // thge low-X low-Y corner of a rectangle

vector thisPos;
vector nextPos;
float dist; // distance to be moved from current point to next point

float moveTime; // to be in whole seconds of 5 or 10 seconds chosen at randomn

float timeOut;  // movetime + extra to test for no moving_end

float startTime;
float endTime;
float timeDiff;

integer running;    // non-zero when running the test, used to prevent residual KFM when rezzing or stopping

string timerAction; // records what is to be done when the timer fires

integer journeys = 0;   // count of journeys made
integer noStart = 0;    // count of moving_start timerouts
integer noEnd = 0;      // count of moving_end timeouts
integer tooLong = 0;    // count of journeys taking more than 5% of expected time

Dout(string message)
{
    llOwnerSay(message);
}

announce(string message)
{
    llSetText(message,<1.0,1.0,1.0>,1.0);
}

setPoints()
{
    vector pos = startPos;
    llOwnerSay("Start from " + (string) startPos);
    points = [pos];
    pos += <xOffset, yOffset, 0.0>;   // move across diagonal
    llOwnerSay("Move diagonally to " + (string) pos);
    points += pos;
    pos += <0.0, -yOffset, 0.0>;   // move back along on side
    llOwnerSay("Move back along side to " + (string) pos );
    points += [pos];
    pos += <-xOffset, yOffset, 0.0>;    // move along the other diagonal
    llOwnerSay("Move diagonally to " + (string) pos);
    points += [pos];
    // next point is back to the start
    pos += <0.0, -yOffset, 0.0>;
    llOwnerSay("Start and positions " + (string) startPos + " , " + (string) pos);
    maxPoints = llGetListLength(points);
}

nextMove()
{
    announce("Journeys " + (string) journeys + "\nStart timeouts " + (string) noStart + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
    thisPoint += 1;
    if( thisPoint >= maxPoints) thisPoint = 0;
    thisPos = llGetPos();
    nextPos = llList2Vector(points, thisPoint);
    dist = llVecDist(thisPos, nextPos);
    if( debug) Dout("Next Point " + (string) thisPoint + " From " + (string) thisPos + " to " + (string) nextPos + " dist " + (string) dist);
    float ranVal = llFrand(1.0);
    if( ranVal > 0.5 ) moveTime = 10.0;
    else moveTime = 5.0;
    timeOut = moveTime + (moveTime * 0.15);  // allow 15% extra time to settle at moving_end
    timerAction = "starting";
    if( debug) Dout("KFM " + (string) (nextPos - thisPos) + " " + (string) ZERO_ROTATION + " time " + (string) moveTime);
    llSetTimerEvent(0.5);   // test for moving_start
    startTime = llGetTime();
    ++journeys;
    llSetKeyframedMotion([nextPos - thisPos, ZERO_ROTATION, moveTime],[]);
}

default
{
    state_entry()
    {
        owner = llGetOwner();
        llSetTimerEvent(0.0);
        timerAction = "";
        running = 0;
        llSetPrimitiveParams([PRIM_PHYSICS_SHAPE_TYPE, PRIM_PHYSICS_SHAPE_CONVEX]);
        llSetKeyframedMotion([],[]);    `// stop any motion if rezzing a previously-moving item taken back to inventory
        if( points == [])
        {
            startPos = llGetPos();
            setPoints();
        }
        cHandle = llListen(myChan, "", owner, "");
        llSetRegionPos(startPos);   // restore to start if reloading from inventory
        thisPoint = 0;
        if( maxPoints > 0)
        {  
            announce("Ready");
            llOwnerSay("Touch to start the test, touch to end it, or say \"stop\" on channel " + (string) myChan);
        }
    }
    listen(integer chan, string name, key id, string msg)
    {
        if( msg == "stop" || msg == "reset" )
        {
            llSetTimerEvent(0.0);
            timerAction = "";
            llSetKeyframedMotion([],[]);
            running = 0;
            if( msg == "reset")
            {
                llSetRegionPos(startPos);
                thisPoint = 0;   
                journeys = 0;
                noStart = 0;
                noEnd = 0;    
            }
            announce("Journeys " + (string) journeys + "\nStart timeouts " + (string) noStart + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
        }
        else if( msg == "report")
        {
            llOwnerSay("Journeys " + (string) journeys);
            llOwnerSay("Start timeouts " + (string) noStart);
            llOwnerSay("End timeouts " + (string) noEnd);
            llOwnerSay("More than 5% late " + (string) tooLong);
        } 
        else if( msg == "debug")
        {
            debug = ~debug;
        }
    }

    touch_start(integer touches)
    {
        key toucher = llDetectedKey(touches - 1);
        if( toucher == owner)
        {
            if (!running)
            {
                running = 1;
                nextMove();
            }
            else
            {
                llSetTimerEvent(0.0);
                timerAction = "";
                llSetKeyframedMotion([],[]);
                running = 0;
                announce("Journeys " + (string) journeys + "\nStart timeouts " + (string) noStart + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
            }
        }
    }
    moving_start()
    {
        if( running)    // ignore edit and setting up moves
        {
            llSetTimerEvent(timeOut);   // now make the whole journey
            timerAction = "moving_end"; 
            if( debug) Dout("Moving_start");
        }
    }
    moving_end()
    {
        llSetTimerEvent(0.0);
        llSetKeyframedMotion([],[]);  
        endTime = llGetTime(); 
        if( debug) Dout("Moving_end");
        // calculate times
        timeDiff = endTime - startTime;     // Actual time
        if( timeDiff > moveTime)
        {
            float diff = timeDiff - moveTime;
            if( diff > (moveTime *.05)) tooLong +=1; // we over ran by 5% or more
        } 
        //llOwnerSay("Expected Time = " + (string) moveTime + " actual time " + (string) (endTime - startTime) );
        if( running) nextMove();    // but if we touched to stop, do nothing
    }
    timer()
    {
        llSetTimerEvent(0.0);
        if( debug) Dout("Timeout for " + timerAction);
        //running = 0;
        if( timerAction == "moving_start")
        {
            ++noStart;
            timerAction = "moving_end";
            llSetTimerEvent(timeOut);   // we can live in hope
        }
        else if( timerAction == "moving_end")
        {
            llSetKeyframedMotion([],[]);
            ++noEnd;
            if( running) nextMove();
            else announce("Journeys " + (string) journeys + "\nStart timeouts " + (string) noStart + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
        }
    }
}

 

Edited December 11, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

The KFM tests have been throwing up some results that are counter-intuitive to say the least

This next test is a slight variation to use llMoveToTarget instead of Keyframed motion, and it threw up something unexpected immediately. When you issue a command to move to a target "critically damped in n seconds" the initial assumption is that it will reach the target in that many seconds.

Watching the object in motion showed that it began to slow down as it moved, and as it got nearer to the target, it slowed more and more. After a lot of fiddling I determined empirically that the time "t" seconds for "damping" gave an actual time to reach the specified range around the target of 3,33 * t, provided the range was 1 metre. Trying to get to within half a metre of the target was going to take even more time so I settled on a range of 1 metre. 

That then threw up yet another problem. The sphere steadily made shorter and shorter journeys because each time it triggered at_target, it was a metre less than the actual destination, and this metre drift accumulated until I could see eventually the sphere would be traveling across or around a square one metre along the side.

Here is a script set up in a premium sandbox with few present to achieve the best ratio of successful journeys to timeouts and late ones. I suggest rezzing it to be one metre higher than the KFMM sphere, since this will be a physical object when in motion and most definitely doesn't want to be colliding with anything.

 

// Test moves to a target position in a region by repeated moves along known paths
// since the distances are known and the speed is specified the journey time can be computed
// and compared with the actual times of moving_end
// the course is across the diagonals and along two sides of s 20m x 20 square path.
// rezz a sphere at the Low-X low_y corner of the intended square and it will compute the corners

key owner;

integer debug = 0;

integer myChan = -17;   // let's not get confused with the KFM test if that's nearby
integer cHandle;

list points = [];
integer maxPoints;
integer thisPoint;

vector startPos;

vector thisPos;
vector nextPos;
float dist;         // distance to be moved from current point to next point

integer tHandle;    // target handle for the move

float moveTime;     // to be in whole seconds of 5 or 10 seconds chosen at randomn

float timeOut;      // movetime + extra to test for no moving_end

float fiddleFactor = 0.35;  // adjustments for the way llMoveToTarget uses x seconds to actually get to within 1 metre,
                            // think Zeno's paradox of motion but instead of halving the remaining distance, 
                            // use 0.35 as the distance reduction

float startTime;
float endTime;
float timeDiff;

integer running;    // non-zero when running the test

string timerAction; // records what is to be done when the timer fires

integer journeys = 0;   // count of journeys made
integer noEnd = 0;      // count of at_target timeouts
integer tooLong = 0;    // count of journey time longer than optimum (will include timeouts)

Dout(string message)
{
    llOwnerSay(message);
}

announce(string message)
{
    llSetText(message,<1.0,1.0,1.0>,1.0);
}

setPoints()
{
    vector pos = startPos;
    llOwnerSay("Start from " + (string) startPos);
    points = [pos];
    pos += <20.0, 20.0, 0.0>;   // move across diagonal
    llOwnerSay("Move diagonally to " + (string) pos);
    points += pos;
    pos += <0.0, -20.0, 0.0>;   // move back along on side
    llOwnerSay("Move back along side to " + (string) pos );
    points += [pos];
    pos += <-20.0, 20.0, 0.0>;    // move along the other diagonal
    llOwnerSay("Move diagonally to " + (string) pos);
    points += [pos];
    // next point is back to the start
    pos += <0.0, -20.0, 0.0>;
    llOwnerSay("Start and positions " + (string) startPos + " , " + (string) pos);
    maxPoints = llGetListLength(points);
}

nextMove()
{
    announce("Journeys " + (string) journeys + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
    thisPoint += 1;
    if( thisPoint >= maxPoints) thisPoint = 0;
    thisPos = llGetPos();
    nextPos = llList2Vector(points, thisPoint);
    dist = llVecDist(thisPos, nextPos);
    if( debug) Dout("Next Point " + (string) thisPoint + " From " + (string) thisPos + " to " + (string) nextPos + " dist " + (string) dist);
    float ranVal = llFrand(1.0);
    if( ranVal > 0.5 ) moveTime = 10.0;
    else moveTime = 5.0;
    timeOut = moveTime * (fiddleFactor * 10);  // speed is reduced as the target is approached resulting in the final 1/3 distance 
                                                // taking perhaps as long as the other 2/3rd?
    timerAction = "moving";
    if( debug) Dout("MoveToTarget " + (string) nextPos + " "  + " time " + (string) moveTime);
    llSetTimerEvent(timeOut);   // test for moving_start
    startTime = llGetTime();
    ++journeys;
    llSetStatus(STATUS_PHYSICS, TRUE);
    tHandle = llTarget(nextPos, 1.0);   // trying to get to 0.5 was a nightmare
    llMoveToTarget(nextPos, moveTime);
}

default
{
    on_rez(integer n)
    {
        llStopMoveToTarget();               // kill any residual motion if taken back into inventory whilst moving
        llSetStatus(STATUS_PHYSICS, FALSE);
        llTargetRemove(tHandle);
        llSetTimerEvent(0.0);
        llResetScript();
    }
    state_entry()
    {
        owner = llGetOwner();
        llSetTimerEvent(0.0);
        timerAction = "";
        running = 0;
        if( points == [])
        {
            startPos = llGetPos();
            setPoints();
        }
        cHandle = llListen(myChan, "", owner, "");
        llSetRegionPos(startPos); 
        thisPoint = 0;
        if( maxPoints > 0)
        {  
            announce("Ready");
            llOwnerSay("Touch to start the test, touch to end it, or say \"stop\" on channel " + (string) myChan);
        }
    }
    listen(integer chan, string name, key id, string msg)
    {
        if( msg == "stop" || msg == "reset" )
        {
            llSetTimerEvent(0.0);
            timerAction = "";
            llStopMoveToTarget();
            llTargetRemove(tHandle);
            llSetStatus(STATUS_PHYSICS, FALSE);
            running = 0;
            if( msg == "reset")
            {
                llOwnerSay("Last Journeys " + (string) journeys);
                llOwnerSay("Last End timeouts " + (string) noEnd);
                llOwnerSay("Last late " + (string) tooLong);
                llSetRegionPos(startPos);
                thisPoint = 0;   
                journeys = 0;
                noEnd = 0;   
                tooLong = 0; 
            }
            announce("Journeys " + (string) journeys + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);            
        }
        else if( msg == "report")
        {
            llOwnerSay("Journeys " + (string) journeys);
            llOwnerSay("End timeouts " + (string) noEnd);
            llOwnerSay("late " + (string) tooLong);
        } 
        else if( msg == "debug")
        {
            debug = ~debug;
        }
    }

    touch_start(integer touches)
    {
        key toucher = llDetectedKey(touches - 1);
        if( toucher == owner)
        {
            if (!running)
            {
                running = 1;
                nextMove();
            }
            else
            {
                llSetTimerEvent(0.0);
                timerAction = "";
                llStopMoveToTarget();
                llTargetRemove(tHandle);
                llSetStatus(STATUS_PHYSICS, FALSE);
                running = 0;
                announce("Journeys " + (string) journeys + "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
            }
        }
    }
    at_target(integer thisTarget, vector targetPos, vector ourPos)
    {
        llSetTimerEvent(0.0);
        endTime = llGetTime(); 
        if( debug) Dout("at_target");
        llStopMoveToTarget();
        llSetStatus(STATUS_PHYSICS, FALSE);   
        // calculate times
        timeDiff = endTime - startTime;     // Actual time
        if( timeDiff > moveTime)
        {
            float diff = timeDiff - (moveTime*3.0);
            if( diff > (moveTime * fiddleFactor)) tooLong +=1; // movement using llMoveToTarget is not at all linear
        }  
        timerAction = ""; 
        llTargetRemove(tHandle);
        llSetRegionPos(targetPos);  // because at_target is only within 1 metre of the position, over time the square will shrink 
                                    // unless we correct the position each time
        if( running) nextMove();          
    }

    timer()
    {
        llSetTimerEvent(0.0);
        if( debug) Dout("Timeout for " + timerAction);
        if( timerAction == "moving")
        {
            llStopMoveToTarget();
            llTargetRemove(tHandle);
            llSetStatus(STATUS_PHYSICS, FALSE);
            timerAction = "";
            ++noEnd;
            if( running) nextMove();
            else announce("Journeys " + (string) journeys +  "\nend timeout " + (string) noEnd + "\nLate " + (string) tooLong);
        }
    }
}

 

Edited December 12, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

Time dilation:

I have been asked why I am not applying the current region time dilation to the timeout periods I am using to look for moving_end or at_target failures.

I looked at them when I was experimenting with the timer test.

In the worst of the regions I was examining, the time dilation was typically 0.995. This means that instead of setting a timer interval of 1.0 seconds, applying the current time dilation figure would have meant setting a timer interval of 1.005 seconds. From the post by Kelly Linden back in 2011, this would have been outside the minimum discrimination of a frame, 1/45 of a second.

In the case of the moving_end timeout for a ten second journey, applying the time dilation figure of 0.995 to a ten-second movement would have resulted in a value of 10.05 seconds. As you will have seen in the script, I ended up having to use an over-run of 15% in order to avoid having constant moving_end timeouts. If I were to have achieved that figure via the time-dilation I would have needed to see 0.85 as the current value.

There is no sign that it is time dilation causing KFM and moveToTarget journeys to take longer than expected, it seems more likely that the region is busy with lots of other things, (or is being lightly idled or somehow having resource shifted from it to another region), as the physics FPS figures and Region FPS figures for the worst case region were also good most of the time. (Sitting typing this whilst watching the stats monitor out of the corner of my eye, I saw the figures drop from the steady 45 and 44.5 to 36 for a second or so, possibly somebody arriving with a Hud or four?).

So the time dilation figures as presented by the stats floater are not bad enough to explain the need to apply a 0.15 correction factor to a 10 second interval, but interestingly enough, that region had 120 seconds drift from a total of 86340 wallclock seconds, and as a percentage, that comes out to 0.14 ....Maybe the time test isn't so useless after all?

ETA

Ah but.... in the best region I am monitoring there is zero drift, and in the premium sandbox where I derived the 0.15 overrun empirically, there was also zero drift. 

Edited December 13, 2021 by Profaitchikenz Haiku

[Profaitchikenz Haiku]

After the restarts today the two mainland regions where I had been recording odd little spells of clock drift have been running for several hours with neither of them showing drift. In addition, the frequency of moving_end timeouts in the KFM test has decreased, and the at_target timeouts have also decreased. (I reset and restarted all the tests once I was able to log back in after the crash).

There may still be some regions with poor performance but at the moment I don't have access to any.