MantisBT - opensim
View Issue Details
0008031opensim[REGION] Scripting Enginepublic2016-10-05 18:582019-02-06 11:29
mewtwo0641 
kcozens 
normalmajoralways
closedfixed 
master (dev code) 
master (dev code) 
Standalone (Multiple Regions)
BulletSim
.NET / Windows64
None
N/A
0008031: Very slow simulator start up time with regions containing lots of scripts
Since commit 5afc5fe343172c315adec97cd8348357a196d5d2 OpenSim load time has increased quite noticeably when there are a lot of scripts to be loaded. In my observations prior to this commit start up times were around 3 or 4 minutes for all regions and all scripts to be loaded. After this commit, on the same database with exact same OpenSim.ini settings, exact same regions, and exact same scripts to be loaded; This start up time has ballooned to 20 - 30 minutes for all scripts to load and for the CPU use to stabilize enough for logging in.


I've pinned it down to DoOnRezScript() in /OpenSim/Region/ScriptEngine/XEngine/XEngine.cs

...
// do not load a assembly on top of a lot of to release memory
// also yield a bit
GC.Collect(2);
...

The garbage collection on every script that's loaded seems to be slowing things down dramatically.

To test this, I commented out the GC.Collect(2); line, recompiled, removed the ScriptEngines directory, and started OpenSim again and load times are back to "normal" at around average of 3 to 4 minutes.

After verifying that load times are back to a reasonable amount of time I uncommented the GC.Collect(2); line, recompiled, removed the ScriptEngines directory, and started OpenSim and observed that load time is again taking a very long time to finish.

This also affects 0.9.0 RC1
No tags attached.
Issue History
2016-10-05 18:58mewtwo0641New Issue
2016-10-05 19:05mewtwo0641Description Updatedbug_revision_view_page.php?rev_id=5748#r5748
2016-10-05 19:12kcozensNote Added: 0031186
2016-10-05 19:13kcozensAssigned To => kcozens
2016-10-05 19:13kcozensStatusnew => confirmed
2016-10-05 19:19UbitUmarovNote Added: 0031187
2016-10-05 20:19mewtwo0641Note Added: 0031188
2016-10-05 20:19mewtwo0641Note Edited: 0031188bug_revision_view_page.php?bugnote_id=31188#r5750
2016-10-05 20:33UbitUmarovNote Added: 0031189
2016-10-05 21:36mewtwo0641Note Added: 0031190
2016-10-05 22:50UbitUmarovNote Added: 0031191
2016-10-06 14:41mewtwo0641Note Added: 0031192
2016-10-06 14:42mewtwo0641Note Edited: 0031192bug_revision_view_page.php?bugnote_id=31192#r5752
2016-10-06 14:57UbitUmarovNote Added: 0031193
2016-10-06 14:59UbitUmarovNote Added: 0031194
2016-10-06 14:59mewtwo0641Note Added: 0031195
2016-11-03 06:38UbitUmarovNote Added: 0031226
2016-11-09 20:38mewtwo0641Note Added: 0031266
2016-11-09 20:39mewtwo0641Statusconfirmed => resolved
2016-11-09 20:39mewtwo0641Fixed in Version => master (dev code)
2016-11-09 20:39mewtwo0641Resolutionopen => fixed
2019-02-06 11:29BillBlightNote Added: 0034491
2019-02-06 11:29BillBlightStatusresolved => closed

Notes
(0031186)
kcozens   
2016-10-05 19:12   
I've also had a similar report of longer than normal load times in git master.
(0031187)
UbitUmarov   
2016-10-05 19:19   
Yes that is the cause for the additional time.
That is only done during the region load scripts compile, not after that.
If the scripts binaries are already in directory ScriptEngines that delay only not happen, of course.
There should no reason to delete the contents ScriptEngines on every region restart, except on a upgrade of its code (on a severe problem with scripts, sometimes its possible to just delete the bad ones)
That code does improve the state of the memory allocation at the end of the region load process in a way that even forced gc after that doesn't
(0031188)
mewtwo0641   
2016-10-05 20:19   
I simply deleted the ScriptEngines folder for sake of testing, however, I do still notice increased load time without first removing the ScriptEngines (OpenSim loading the pre-compiled binaries) folder with GC.Collect() there compared to it not being there. It's not quite as long as when OpenSim has to recompile everything but it's still significantly longer.

(0031189)
UbitUmarov   
2016-10-05 20:33   
the changes on commit 5afc5fe343172c315adec97cd8348357a196d5d2 are relative to script compilation, so should have no impact if scripts are present in that directory (and DeleteScriptsOnStartup = false, of course)

Please note that code was changed:
SHA-1: 054cc8f08e00e7f0810d2397403d154ad4d4da87
* Xengine only do GC.Collect if logins disabled
avoiding it at normal run time.
(0031190)
mewtwo0641   
2016-10-05 21:36   
Yes I do understand; but what I'm describing happens at start up time not during normal use. The issue still does appear after 054cc8f08e00e7f0810d2397403d154ad4d4da87 as well during start up. I'll run my tests again with and without the GC.Collect() line, and with ScriptEngines intact (with already compiled DLLs there) for comparison soon and posts the results just to be sure.
(0031191)
UbitUmarov   
2016-10-05 22:50   
Im sorry, the GC.Collect is really active in both cases :(
I repeated my previous tests deleting the directory contents, windows7 regions with around 140 scripts, the reported private memory a few minutes after full load, no avatars:
- with it around 244MB, after 5 force gc console commands 243MB
- without it 500MB, after 5 force gc console commands 384MB.
region start with all scripts compiled:
. with it 247MB, after 5 force gc console commands 247MB
. without it 315MB after 5 force gc console commands 308MB
(0031192)
mewtwo0641   
2016-10-06 14:41   
(edited on: 2016-10-06 14:42)
I did some more extensive testing to come up with some data for time it takes to fully load OpenSim as well as memory use.

These tests were done with no login attempts and no existing agents in region.

The "Time elapsed" result is approximately how long it takes from starting up OpenSim to how long it takes to completely load all scripts and for CPU use to stabilize enough to log in.

Tests 1 and 2 are done with 'if(!m_Scene.LoginsEnabled) GC.Collect(2);' left as is from master
Tests 3 and 4 are done with 'if(!m_Scene.LoginsEnabled) GC.Collect(2);' commented out and recompiled OpenSim

From what I can observe of these tests the memory savings with the GC.Collect(2); line intact is anywhere from about 200 - 300 MB of memory... But at the expense of greatly inflated startup time as well as more CPU use per call of DoOnRezScript() due to garbage collection being done in every call of it. This of course only affects start up, i.e. before logins are enabled.

----------------
Test Results:
----------------

--------
Test 1
--------
Test parameters: ScriptEngines directory deleted before startup, GC.Collect() is being used

Total number of scripts to load: Appx. 1200

Time elapsed: Script load finished in approximately 16 minutes, 20 seconds; CPU stabilized approximately 25 minutes, 15 seconds after script load finished

------------------------------------
Memory Stats after CPU Stabilized:
------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 664 MB
Last heap allocation rate : 4.248 MB/s
Average heap allocation rate: 2.334 MB/s
Process memory: Physical 2292 MB Paged 2724 MB Virtual 6805 MB
Peak process memory: Physical 2292 MB Paged 2727 MB Virtual 6909 MB

------------------------------------------
Memory Stats after 5 'force gc' commands:
------------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 567 MB
Last heap allocation rate : 0 MB/s
Average heap allocation rate: 3.127 MB/s
Process memory: Physical 2292 MB Paged 2723 MB Virtual 6805 MB
Peak process memory: Physical 2292 MB Paged 2736 MB Virtual 6909 MB


--------
Test 2
--------
Test parameters: ScriptEngines left intact from previous test, GC.Collect() is being used

Total number of scripts to load: Appx. 1200

Time elapsed: Script load finished in approximately 11 minutes, 30 seconds; CPU stabilized approximately 14 minutes, 0 seconds after script load finished

------------------------------------
Memory Stats after CPU Stabilized:
------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 1136 MB
Last heap allocation rate : 8.457 MB/s
Average heap allocation rate: 7.683 MB/s
Process memory: Physical 2160 MB Paged 2589 MB Virtual 6664 MB
Peak process memory: Physical 2160 MB Paged 2589 MB Virtual 6694 MB

------------------------------------------
Memory Stats after 5 'force gc' commands:
------------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 635 MB
Last heap allocation rate : 11.253 MB/s
Average heap allocation rate: 7.319 MB/s
Process memory: Physical 1790 MB Paged 2216 MB Virtual 6662 MB
Peak process memory: Physical 2212 MB Paged 2643 MB Virtual 6694 MB


--------
Test 3
--------
Test parameters: ScriptEngines directory deleted before startup, GC.Collect() line commented out

Total number of scripts to load: Appx. 1200

Time elapsed: Script load finished in approximately 5 minutes, 0 seconds; CPU stabilized approximately 6 minutes, 30 seconds after script load finished

------------------------------------
Memory Stats after CPU Stabilized:
------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 1033 MB
Last heap allocation rate : 0 MB/s
Average heap allocation rate: 3.648 MB/s
Process memory: Physical 2758 MB Paged 3202 MB Virtual 6751 MB
Peak process memory: Physical 2758 MB Paged 3254 MB Virtual 6854 MB

------------------------------------------
Memory Stats after 5 'force gc' commands:
------------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 641 MB
Last heap allocation rate : 0 MB/s
Average heap allocation rate: 2.231 MB/s
Process memory: Physical 2460 MB Paged 2895 MB Virtual 6744 MB
Peak process memory: Physical 2758 MB Paged 3254 MB Virtual 6854 MB


--------
Test 4
--------
Test parameters: ScriptEngines directory left intact from previous test, GC.Collect() line commented out

Total number of scripts to load: Appx. 1200

Time elapsed: Script load finished in approximately 4 minutes, 30 seconds; CPU stabilized approximately 5 minutes, 0 seconds after script load finished

------------------------------------
Memory Stats after CPU Stabilized:
------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 871 MB
Last heap allocation rate : 6.733 MB/s
Average heap allocation rate: 10.123 MB/s
Process memory: Physical 2147 MB Paged 2564 MB Virtual 6732 MB
Peak process memory: Physical 2187 MB Paged 2622 MB Virtual 6763 MB

------------------------------------------
Memory Stats after 5 'force gc' commands:
------------------------------------------

MEMORY STATISTICS
Heap allocated to OpenSim : 651 MB
Last heap allocation rate : 9.303 MB/s
Average heap allocation rate: 10.124 MB/s
Process memory: Physical 2138 MB Paged 2564 MB Virtual 6740 MB
Peak process memory: Physical 2192 MB Paged 2622 MB Virtual 6763 MB

(0031193)
UbitUmarov   
2016-10-06 14:57   
Thanks for this values.
I will do a few more testing, eventually.. yeap... another option ;)
(0031194)
UbitUmarov   
2016-10-06 14:59   
forgot to ask AppDomainLoading is true or false?
(0031195)
mewtwo0641   
2016-10-06 14:59   
You're welcome :) AppDomainLoading is set to false for these tests, and TrustBinaries also set to false
(0031226)
UbitUmarov   
2016-11-03 06:38   
added XEngine configuration option CompactMemOnLoad set to false by default.
set to true to enable the garbage collector calls to improve the memory allocation with the cost of the reported longer region startup time.
(0031266)
mewtwo0641   
2016-11-09 20:38   
This seems fixed at the latest master with those new changes; thank you Ubit! :)
(0034491)
BillBlight   
2019-02-06 11:29   
Marked as Resolved but never closed, can be reopened if needed.