Mantis Bug Tracker
Main | My View | View Issues | Change Log | Roadmap | Summary | My Account
  

View Issue Details [ Jump to Notes ] [ Issue History ] [ Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0008127opensim[REGION] Script Functionspublic2017-02-06 21:322017-05-17 21:11
ReporterKayaker Magic 
Assigned To 
PriorityhighSeveritymajorReproducibilityalways
StatusnewResolutionopen 
PlatformVariousOSMicrosoft .NETOS Version0.8 and up
Product Version0.9.0 
Target VersionFixed in Version 
Summary0008127: List fetching functions (eg llList2Vector) are dog slow on Microsoft servers
DescriptionThis Mantis has been extensively edited.
The test script has been simplified to a list of float and statistics are calculated now.

The basic problem is that one would expect the following three lines in a script to run very fast:
         llResetTime();
         r=llList2Float(test,(integer)llFrand(500.0)); //random fetch
         float time = llGetTime(); //how long did that take?
And on some servers it does, but on others it is 1,000 to 10,000 times slower
In my experience, the slow results have always been when running OpenSim on a Microsoft Server.
Going back to older and older versions of OpenSim I see the problem has been around a while.

Here are some recent (May 17, 2017) timing results:

Operating System, OpenSim Version, List fetch time
Windows 10, 0.8 post fixes, 0.0035
Windows 10, 0.8.2.1 release, 0.0028
Windows 7, 0.8 post fixes, 0.0036
Windows Server, 0.9.1.0, 0.0055
Amazon Linux, 0.8.2.1 Kitely, 0.000011
Suse Linux, 0.9.1.0 Dev, 0.000000

The last test was on the server in my barn running the very latest version fetched from git:
commit c28430d52771ed6950e8482095a72ee8ef0c168d

I assume a time of zero means things are so fast that it is below the resolution of llGetTime. I tested other things and verified that llGetTime does work correctly on that system.


Steps To Reproduce    The following test program times how fast fetches are. Put the script in a prim, it will construct a list, then time how long it takes to do random fetches from it. The results in seconds are displayed as floating text above the prim.
Additional Information    //llListFetch timing test
    //Rev 2.0: simple list, mean and variance of results
    //Note: timer is only used to generate a bunch of test results
    //there is no dependency on the accuracy of timer events
    //only llGetTime is used to measure the time to perform a fetch
float sum=0.0;
float sum2=0.0;
float n=0;
list test=[];
default
{
     state_entry()
     {
         integer i;
         for (i=0;i<500;i++) //create a mixed list
             test += [llFrand(500.0)];
         llSetTimerEvent(0.5);
     }
     on_rez(integer param)
     {
         llResetScript();
     }
     timer()
     {
         float r;
         llResetTime();
         r=llList2Float(test,(integer)llFrand(500.0)); //random fetch
         float time = llGetTime(); //how long did that take?
         sum += time;
         sum2 += time*time;
         n += 1.0;
         llSetText("last="+(string)time+" n="+(string)((integer)n)+"\nmean="+(string)(sum/n)+" var="+(string)(sum2/n-sum*sum/n/n),<0,1,0>,1.0); //display results
     }
}
 
TagsNo tags attached.
Git Revision or version numberc28430d52771ed6950e8482095a72ee8ef0c168d
Run Mode Grid (Multiple Regions per Sim)
Physics EngineubODE
Script Engine
Environment.NET / Windows64
Mono Version3.6
ViewerFireStorm
Attached Files

- Relationships

-  Notes
(0031593)
BillBlight (developer)
2017-02-06 23:42
edited on: 2017-02-06 23:59

 Are lists not limited to 255 lines(entries) just like other line items ?

I changed your test from 500 to 255 and the timing is more like .006 ..

UPDATE: Tried this with a list length of 255 and of 128 ..

@255
[23:51] Object: 0.006000
[23:51] Object: 0.007000
[23:51] Object: 0.006000
[23:51] Object: 0.006000
[23:51] Object: 0.007000

@128
[23:55] Object: 0.003000
[23:55] Object: 0.003000
[23:55] Object: 0.003000
[23:55] Object: 0.003000
[23:55] Object: 0.003000

It seems like it could grow exponential depending on list length.
(0031598)
Mata Hari (reporter)
2017-02-10 07:11

 I have also found all list functions MUCH slower under 0.9x than they were under 0.8.x although that may have also coincided with a .NET update I did so it would be worth comparing an identical run under 0.8.2.1 in your mono setup and seeing if there's any difference.
(0031600)
Total Sorbet (reporter)
2017-02-13 12:49

 @Kayaker

I ran your code and im getting a time of 0.000000

However you are using a list containing vectors and integers yet are attempting to fetch value into a vector in each instance.

"v=llList2Vector(test,1|(integer)llFrand(500.0)); //random fetch"

I tried the following code:

list test=[];

default
    {
    state_entry()
        {
        llSay(0,"Script running");
        integer i=500;
        while(i--){test+=[1,"a string",PI,ZERO_VECTOR];}
        llSetTimerEvent(0.5);
        }
    timer()
        {
        list v;
        integer r;
        integer len=llGetListLength(test);
        integer i=10000;
        llResetTime();
        while(i--){r=(integer)llFrand(len);v=llList2List(test,r,r);}
        llSetText((string)llGetTime(),<0,1,0>,1.0);
        }
    }

Ive found it can do 10,000 "fetches" in 10 to 20ms under 0.9.x
(0031625)
Kayaker Magic (reporter)
2017-03-14 09:45
edited on: 2017-03-14 09:47

 Watcher64: No, there is no limit on the size of a list, although I do recall there is a limit on how many items you can initialize a list with when you declare it.

TotalSorbet: No, my code is only fetching the vectors. (Hint: 1 inclusive or'ed with any number is always odd). HOWEVER, your observation that fetching a sub-list from a list is fast is very interesting. It suggests a work-around to the problem: Fetch the item(s) you want from a big list into a smaller one where fetching the individual items is faster.

I have since discovered that if you have a simple list (all the same type of items such as floats), fetching items is fast. While my original program that fetched one type from a mixed list of integers and vectors is still slow.

But it turns out that fetching from a simple list is fast on some servers, and slow on others. An inadequate sampling of servers indicates that fetching from a simple list on a Linux based system is fast, while fetching from simple list on a Microsoft server based system is slow. This suggests there is a difference in the way Mono and .NET are implementing lists! Run the script below on Linux and Microsoft based regions. So far the Linux servers get a typical fetch time of 0.000004 seconds or lower, the Microsoft servers get a time that averages around 0.010000.

//timing test for fetching from a list of just floats
list rans=[];
default
{
    state_entry()
    {
        integer i;
        for (i=0;i<1024;i++)
            rans += [llFrand(1.0)];
        llSetTimerEvent(0.5);
    }
    
    timer()
    {
        llResetTime();
        float ran=llList2Float(rans,(integer)llFrand(1024.0));
        llSetText((string)llGetTime(),<1,0,0>,1.0);
    }
}
(0031641)
Total Sorbet (reporter)
2017-03-18 14:39

 ah.. a sneaky 1|.. got me :p
(0031675)
Kayaker Magic (reporter)
2017-04-02 15:12

 I went back an did some more timing tests on Linux vs Microsoft servers and discovered that my initial test works blindingly fast on Linux servers! At first I was not paying attention to which server I was running the tests on. The whole problem turns out to be how .NET implements the lists!

Then I went back to the Microsoft server and tried to work around the issue by fetching sub-lists first, then fetching the values I wanted out of the smaller list. This did not help, the fetches were still dog slow on the Microsoft server.
(0031676)
UbitUmarov (administrator)
2017-04-02 19:10

 this scripts timing sounds to me more a GetTime() issue.
on Linux it has a resolution of about 1ms, on windows something btw 10 to 20ms.
try this on master. I did increase GetTime() resolution a few months ago.
on 0.9 Lists I expect ADD heavy and slow, not fetch.
(0031677)
UbitUmarov (administrator)
2017-04-02 19:15

 for reasons i don't remember i do round getime to 3 digits, so 1ms resolution.
(0031861)
Kayaker Magic (reporter)
2017-05-17 08:50

 This mantis has been extensively edited.
When I first submitted this Mantis I did not know why I sometimes got fast list fetches, other times slow. I thought it might be one thing or another until I realized I was working on several grids, some that had Linux servers others Microsoft. In my experience the list fetches on Microsoft servers were 3 to 4 orders of magnitude slower than the fetches on the Linux servers.
(0031862)
UbitUmarov (administrator)
2017-05-17 09:24

 your last script, at the time I type gives 0, on my win7 box, with master, debug version and and running in VS debugger.
(region is not doing anything else)

with the change..
...
        integer i;
        for(i = 0 ; i<10000 ;i++)
          r=llList2Float(test,(integer)llFrand(500.0)); //random fetch
        float time = llGetTime(); //how long did that take?
...
 I get 0.009s time

with i<100000
I get from 0,088 to 0.092s

I repeat what I said on last meeting.
llGetTime() has low resolution on windows with older opensim versions

that was changed
SHA-1: d07f48605f90a0f0485d0ac11ec5641bbb88a28a
* change llGetTime() source clock
2016-11-06
SHA-1: 6f1080368d23d8e3952b5ffd3c3cc05f540d6402
* reduce the resolution of llGetTime and llGetAndResetTime, to 1ms
2016-11-25

this higher resolution may not be available on all machines, either bc of no hardware support or bc its disable (High performance counters)
try the loop, but remember that the script event is killed in about 0.3s so keep the loop time lower than that.
(0031863)
Kayaker Magic (reporter)
2017-05-17 11:11

 I'm confused: If llGetTime has lower resolution, I would expect it to return 0 in my test without your change. That is the result that you get. However, when I run the test on my Win 7 or Win 10 systems I get higher numbers from llGetTime, as if it has resolution similar to Linux and llList2Float is slow. If my Windows systems have higher resolution in llGetTime, I would expect making your change would give exactly the same results (if correcting n for the loop). I did that test on several systems with the following results:
OpSys, OpenSim Version, test result
Win 10, 0.8 post fix, 0.0031
Win 10, 0.8.2.1 release, 0.0033
Win 7, 0.8 post fix, 0.0015
Win 7, 0.8.2.1 release, 0.0023

I cannot re-run the test on the Windows Server based grid because that grid was brought down by the Ransomewear virus. But these results are similar to my last numbers, I assume the 0.9.0.0 Dev numbers will be similar when I can test there again. All 4 of these tests were done with Sim On A Stick moved between two computers. I tried to run it on a Windows XP system, but it failed to find the right version of .net on that system.
(0031864)
Kayaker Magic (reporter)
2017-05-17 11:14

 I also had to change the loop on i to only 1000 because if I used 10000 the timer event ran for over 30 seconds before exiting! This is because llList2Float takes soooo long to execute that I cannot call it many times in a single event. Wait, that is the ORIGINAL PROBLEM that this mantis is all about. Here is the test I am using now:

    //llListFetch timing test
    //Rev 2.1 Put in loop to catch llGetTime resolution issue
    //Rev 2.0: simple list, mean and variance of results
    //Note: timer is only used to generate a bunch of test results
    //there is no dependancy on the accuracy of timer events
    //only llGetTime is used to measure the time to perform a fetch
float sum=0.0;
float sum2=0.0;
float n=0;
list test=[];
 default
 {
     state_entry()
     {
         integer i;
         for (i=0;i<500;i++) //create a mixed list
             test += [llFrand(500.0)];
         llSetTimerEvent(0.5);
     }
     on_rez(integer param)
     {
         llResetScript();
     }
     timer()
     {
         float r;
         integer i;
         llResetTime();
         for (i=0;i<1000;i++)
            r=llList2Float(test,(integer)llFrand(500.0)); //random fetch
         float time = llGetTime(); //how long did that take?
         sum += time;
         sum2 += time*time;
         n += 1000.0;
         llSetText("last="+(string)time+" n="+(string)((integer)n)+"\nmean="+(string)(sum/n)+" var="+(string)(sum2/n-sum*sum/n/n),<0,1,0>,1.0); //display results
     }
 }
(0031865)
UbitUmarov (administrator)
2017-05-17 12:00

 well don't know :(
I do need to use a loop of 10000 to see ms numbers on my now old 3.5GHz I7 ( also running viewer etc etc)
(0031866)
Kayaker Magic (reporter)
2017-05-17 12:01

 Ubit: Are you running OpenSim with mono on your Win 7 system? I am using the native .NET .

Yours is the first Windows system I have seen that does not show this problem, but I have not tried many. There are lots of OpenSim systems on OSGrid that are run on Windows systems and they all may have this problem, it is worth tracking down.

I have another 'test' where I first noticed this issue: I have a script that does many list fetches in the course of a run. I tun this script on my Linux server while watching the clock on the wall. The script takes 2 minutes to complete. Then I run the same script unchanged on a MycroftSoft system while watching the clock on the wall and the script takes 20 hours to complete. I comment out most of the list fetches and run again on the MycroftSoft system and it takes orders of magnitude less time according to the clock on the wall. (I can't comment out all llList2Floats without compromising the functioning of the script). I have no issues with the resolution of the clock on the wall.

I just repeated this test on my SOAS installation on my Windows 7 system with a shorter data-set so I didn't have to wait 20 hours:

System, OpenSim version, timing test
SUSE Linux, 0.9.2.0 Latest git, 0minutes 6seconds
Win 7, 0.8.2.1 release, 11min 17sec
Win 7, 0.8.2.1 release, 2min 29sec (some llList2Foat's commented out)

 It is difficult for me to set up 0.9.2.0 to run in SOAS but I will try to do that next.
(0031867)
UbitUmarov (administrator)
2017-05-17 12:13

 its hard for anyone to setup 0.9.2. we are still at 0.9.1 well I think ;)
Running native .net and inside the vs2015 debugger
aapdomain = false
(0031868)
UbitUmarov (administrator)
2017-05-17 12:41

 it is AppDomainLoading = true
with it my timings sky up to 1.4ms PER LOOP
(0031869)
UbitUmarov (administrator)
2017-05-17 12:59

 my numbers now running from console ( outside the debugger)

bin compiled in Debug mode:
AppDomainLoading = true -> 1.4ms per LOOP
AppDomainLoading = false -> 66ms per 100 000 LOOPS

bin compiled in Release mode:
AppDomainLoading = true -> 1.4ms per LOOP
AppDomainLoading = false -> 44ms per 100 000 LOOPS

so yeah.. Domain crossings are killers.
(0031870)
Kayaker Magic (reporter)
2017-05-17 15:16

 SOAS will not work with OpenSim 0.9.2.0, at least not for me.
The Windows Server system is still down from the ransomware virus.
So I installed the latest download from OSGrid on my Win 7 system with the intent to upgrade it to the latest from the git hub.
When I finally got it working (before upgrading to the latest from git), the result is that list fetches now take 0.000002 seconds average.
THE PROBLEM APPEARS TO BE FIXED in 0.9.1.0 Dev, git hash 8bdd4c3ed9cef20bcee931b287c9c4124b409186 from May 12, the one that OSGrid is distributing.
Have there been any fixes in the last few months that had a beneficial effect on how lists are handled?
It was apparently not fixed in the version on the Windows server I first saw this problem on. That server is still down and I am trying to see if someone can tell me what the got hash was for the OpenSim that they were running.
(0031871)
UbitUmarov (administrator)
2017-05-17 16:27

 did you read above about AppDomainLoading setting?
did you checked it?
(0031872)
Kayaker Magic (reporter)
2017-05-17 21:11
edited on: 2017-05-17 21:43

 The value of AppDomainLoading in the SOAS kit is the default true. I tried setting it to false with the following results in Win7/.NET OpenSim 0.8 Post Fix:

AppDomainLoading=true, llList2Float takes 0.0031 seconds
AppDomainLoading=false, llList2Float takes 0.0026 seconds
   It does not seem to have much effect on this older version.

The value of AppDomainLoading in the latest OSGrid OpenSim.ini file is false. I tried setting it to true with results similar to what Ubit reported above: (Both test below done on OSgrid 0.9.1.0 (Dev) 8bdd4c3: 2017-05-12 (Win/.NET))

AppDomainLoading=false, llList2Float takes 0.000002 seconds
AppDomainLoading=true, llList2Float takes 0.0022 seconds

AppDomainLoading=true makes my scripts run 1000 times slower! The script is in a cube sitting on the ground, it is not moving it is not crossing SIM borders, I would not have expected this.

- Issue History
Date Modified Username Field Change
2017-02-06 21:32 Kayaker Magic New Issue
2017-02-06 23:42 BillBlight Note Added: 0031593
2017-02-06 23:45 BillBlight Note Edited: 0031593 View Revisions
2017-02-06 23:59 BillBlight Note Edited: 0031593 View Revisions
2017-02-10 07:11 Mata Hari Note Added: 0031598
2017-02-13 12:49 Total Sorbet Note Added: 0031600
2017-03-14 09:45 Kayaker Magic Note Added: 0031625
2017-03-14 09:47 Kayaker Magic Note Edited: 0031625 View Revisions
2017-03-18 14:39 Total Sorbet Note Added: 0031641
2017-04-02 15:12 Kayaker Magic Note Added: 0031675
2017-04-02 19:10 UbitUmarov Note Added: 0031676
2017-04-02 19:15 UbitUmarov Note Added: 0031677
2017-05-09 11:53 Kayaker Magic Environment Mono / Linux64 => .NET / Windows64
2017-05-09 11:53 Kayaker Magic Summary List fetching functions (eg llList2Vector) are dog slow => List fetching functions (eg llList2Vector) are dog slow on Microsoft servers
2017-05-09 11:53 Kayaker Magic Description Updated View Revisions
2017-05-09 12:06 Kayaker Magic OS Linux Mono => Microsoft .NET
2017-05-17 08:50 Kayaker Magic Git Revision or version number => c28430d52771ed6950e8482095a72ee8ef0c168d
2017-05-17 08:50 Kayaker Magic Note Added: 0031861
2017-05-17 08:50 Kayaker Magic OS Version 0.9.0 => 0.8 and up
2017-05-17 08:50 Kayaker Magic Platform Open Simulator 0.9 => Various
2017-05-17 08:50 Kayaker Magic Description Updated View Revisions
2017-05-17 08:50 Kayaker Magic Steps to Reproduce Updated View Revisions
2017-05-17 08:50 Kayaker Magic Additional Information Updated View Revisions
2017-05-17 09:24 UbitUmarov Note Added: 0031862
2017-05-17 11:11 Kayaker Magic Note Added: 0031863
2017-05-17 11:14 Kayaker Magic Note Added: 0031864
2017-05-17 12:00 UbitUmarov Note Added: 0031865
2017-05-17 12:01 Kayaker Magic Note Added: 0031866
2017-05-17 12:13 UbitUmarov Note Added: 0031867
2017-05-17 12:41 UbitUmarov Note Added: 0031868
2017-05-17 12:59 UbitUmarov Note Added: 0031869
2017-05-17 15:16 Kayaker Magic Note Added: 0031870
2017-05-17 16:27 UbitUmarov Note Added: 0031871
2017-05-17 21:11 Kayaker Magic Note Added: 0031872
2017-05-17 21:43 Kayaker Magic Note Edited: 0031872 View Revisions

Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker