Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0008031opensim[REGION] Scripting Enginepublic2016-10-05 18:582016-11-09 20:39
Reportermewtwo0641 
Assigned Tokcozens 
PrioritynormalSeveritymajorReproducibilityalways
StatusresolvedResolutionfixed 
PlatformOSOS Version
Product Versionmaster (dev code) 
Target VersionFixed in Versionmaster (dev code) 
Summary0008031: Very slow simulator start up time with regions containing lots of scripts
DescriptionSince 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
TagsNo tags attached.
Git Revision or version number
Run Mode Standalone (Multiple Regions)
Physics EngineBulletSim
Environment.NET / Windows64
Mono VersionNone
ViewerN/A
Attached Files

- Relationships

-  Notes
(0031186)
kcozens (administrator)
2016-10-05 19:12

I've also had a similar report of longer than normal load times in git master.
(0031187)
UbitUmarov (administrator)
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 (reporter)
2016-10-05 20:19
edited on: 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 (administrator)
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 (reporter)
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 (administrator)
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 (reporter)
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 (administrator)
2016-10-06 14:57

Thanks for this values.
I will do a few more testing, eventually.. yeap... another option ;)
(0031194)
UbitUmarov (administrator)
2016-10-06 14:59

forgot to ask AppDomainLoading is true or false?
(0031195)
mewtwo0641 (reporter)
2016-10-06 14:59

You're welcome :) AppDomainLoading is set to false for these tests, and TrustBinaries also set to false
(0031226)
UbitUmarov (administrator)
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 (reporter)
2016-11-09 20:38

This seems fixed at the latest master with those new changes; thank you Ubit! :)

- Issue History
Date Modified Username Field Change
2016-10-05 18:58 mewtwo0641 New Issue
2016-10-05 19:05 mewtwo0641 Description Updated View Revisions
2016-10-05 19:12 kcozens Note Added: 0031186
2016-10-05 19:13 kcozens Assigned To => kcozens
2016-10-05 19:13 kcozens Status new => confirmed
2016-10-05 19:19 UbitUmarov Note Added: 0031187
2016-10-05 20:19 mewtwo0641 Note Added: 0031188
2016-10-05 20:19 mewtwo0641 Note Edited: 0031188 View Revisions
2016-10-05 20:33 UbitUmarov Note Added: 0031189
2016-10-05 21:36 mewtwo0641 Note Added: 0031190
2016-10-05 22:50 UbitUmarov Note Added: 0031191
2016-10-06 14:41 mewtwo0641 Note Added: 0031192
2016-10-06 14:42 mewtwo0641 Note Edited: 0031192 View Revisions
2016-10-06 14:57 UbitUmarov Note Added: 0031193
2016-10-06 14:59 UbitUmarov Note Added: 0031194
2016-10-06 14:59 mewtwo0641 Note Added: 0031195
2016-11-03 06:38 UbitUmarov Note Added: 0031226
2016-11-09 20:38 mewtwo0641 Note Added: 0031266
2016-11-09 20:39 mewtwo0641 Status confirmed => resolved
2016-11-09 20:39 mewtwo0641 Fixed in Version => master (dev code)
2016-11-09 20:39 mewtwo0641 Resolution open => fixed


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker