• All submissions to this site are governed by Second Life Project Contribution Agreement. By submitting patches and other information using this site, you acknowledge that you have read, understood, and agreed to those terms.
Issue Details (XML | Word | Printable)

Key: SVC-2958
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Showstopper Showstopper
Assignee: Babbage Linden
Reporter: Wood Fairey
Votes: 216
Watchers: 31
Operations

If you were logged in you would be able to see more operations.
2. Second Life Service - SVC

state_exit() events are slow

Created: 29/Aug/08 09:38 PM   Updated: 16/Sep/08 01:51 PM
Return to search
Component/s: Scripts
Affects Version/s: 1.24 Server
Fix Version/s: None

Issue Links:
Relates

Linden Lab Issue ID: DEV-19935


 Description  « Hide
statements during a state_exit() event are very slow.

The following script (fragment)

state_entry()

{ llOwnerSay("Entered at " + (string)llGetTime()); llOwnerSay("Entered at " + (string)llGetTime()); llOwnerSay("Entered at " + (string)llGetTime()); llOwnerSay("Entered at " + (string)llGetTime()); llOwnerSay("Entered at " + (string)llGetTime()); }

state_exit()

{ llOwnerSay("Exited at " + (string)llGetTime()); llOwnerSay("Exited at " + (string)llGetTime()); llOwnerSay("Exited at " + (string)llGetTime()); llOwnerSay("Exited at " + (string)llGetTime()); llOwnerSay("Exited at " + (string)llGetTime()); }

produced

[21:34] Object: Entered at 2.093657
[21:34] Object: Entered at 2.093657
[21:34] Object: Entered at 2.093657
[21:34] Object: Entered at 2.093657
[21:34] Object: Entered at 2.115575
[21:34] Object: Exited at 5.017289
[21:34] Object: Exited at 5.573433
[21:34] Object: Exited at 6.107403
[21:34] Object: Exited at 6.707955
[21:34] Object: Exited at 7.219592

The slowdown also applies to any function called during a state_exit() event.



 All   Comments   Change History      Sort Order: Ascending order - Click to sort in descending order
Gellan Glenelg added a comment - 29/Aug/08 11:08 PM
Confirmed: when compiled in LSL, state_exit execution is significantly slower than state_entry:

Tested using:
//////////////////////////////////////////////////////////
default
{
touch_start(integer total_number)

{ state other; }

}

state other
{
state_entry()

{ float a = llGetTime(); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("state_entry: " + (string)(llGetTime()-a)); state default; }

state_exit()

{ float a = llGetTime(); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("."); llSleep(1.0); llOwnerSay("state_exit: " + (string)(llGetTime()-a)); }

}
///////////////////////////////////////////////////////

Sample results, omitting "."s (when compiled in LSL):
[23:01] Object: state_entry: 5.414494
[23:01] Object: state_exit: 7.305904
[23:02] Object: state_entry: 5.415421
[23:02] Object: state_exit: 7.320724
[23:02] Object: state_entry: 5.415062
[23:02] Object: state_exit: 7.317482
[23:03] Object: state_entry: 5.420517
[23:03] Object: state_exit: 7.304108
[23:03] Object: state_entry: 5.409958
[23:03] Object: state_exit: 7.302544

Sample results, omitting "."s (when compiled in mono):
[23:04] Object: state_entry: 5.452568
[23:05] Object: state_exit: 5.278564
[23:05] Object: state_entry: 5.430317
[23:05] Object: state_exit: 5.251865
[23:05] Object: state_entry: 5.409817
[23:05] Object: state_exit: 5.252609
[23:05] Object: state_entry: 5.408588
[23:05] Object: state_exit: 5.252937
[23:05] Object: state_entry: 5.410522
[23:05] Object: state_exit: 5.255127


Escort DeFarge added a comment - 30/Aug/08 01:49 PM
Confirmed and replicated the following script compiled to LSL on 1.24....

say(string prefix, integer number) {
while (--number >= 0) { llOwnerSay(prefix + " " + (string)llGetTime()); }
}

default
{
state_entry()

{ llOwnerSay("state: default"); say("Entered", 5); }

touch_start(integer number) { say("Touched", 1); state next; }

state_exit()
{ say("Exited", 5); }
}
state next {
state_entry()
{ llOwnerSay("state: next"); say("Entered", 5); }

touch_start(integer number) { say("Touched", 1); state default; }

state_exit()
{ say("Exited", 5); } }
}

...produces the following results....
[13:46] Object: state: default
[13:46] Object: Entered 0.001223
[13:46] Object: Entered 0.024586
[13:46] Object: Entered 0.024586
[13:46] Object: Entered 0.044923
[13:46] Object: Entered 0.067178
[13:46] Object: Touched 4.541522
[13:46] Object: Exited 5.187782
[13:46] Object: Exited 5.853748
[13:46] Object: Exited 6.522691
[13:46] Object: Exited 7.190498
[13:47] Object: Exited 7.856604
[13:47] Object: state: next
[13:47] Object: Entered 8.392305
[13:47] Object: Entered 8.412863
[13:47] Object: Entered 8.412863
[13:47] Object: Entered 8.436759
[13:47] Object: Entered 8.457339
[13:47] Object: Touched 10.840280
[13:47] Object: Exited 11.484820
[13:47] Object: Exited 12.151639
[13:47] Object: Exited 12.819146
[13:47] Object: Exited 13.509143
[13:47] Object: Exited 14.178793
[13:47] Object: state: default
[13:47] Object: Entered 14.710886
[13:47] Object: Entered 14.733949
[13:47] Object: Entered 14.733949
[13:47] Object: Entered 14.755330
[13:47] Object: Entered 14.778624


RobbyRacoon Olmstead added a comment - 30/Aug/08 04:32 PM
In [Combat: Samurai Island] products, this is causing upwards of a five second delay during combat, making all weapons effectively useless.

It's good to know that Linden Lab now knows the cause, but the workaround of removing critical code from state_exit() is prohibitively expensive in terms of testing and deployment to over nineteen thousand customers.

Please, please, please, please look into this issue as soon as possible.


Lex Neva added a comment - 30/Aug/08 06:39 PM
I'm assigning to Soft in hopes that this can get action before the next triage, since it's so critical.

Strife Onizuka added a comment - 30/Aug/08 08:17 PM - edited
If I were guessing, I'd venture that this would likely be related to excessive usage of TypeOf and GetType; generating Type objects on the fly is costly.

Lear Cale added a comment - 30/Aug/08 08:53 PM
Strife, it happens for a simple loop, like this:

integer ix;
integer count = 100;

for (ix = 0; ix < count; ++ix) {
}

Code runs about one hundred times slower in state_exit handler. This did NOT happen prior to 1.24 servers.

This problem needs immediate attention. The problem happens for LSL or Mono-compiled code.


RobbyRacoon Olmstead added a comment - 31/Aug/08 12:25 PM - edited
Linked to [SVC-1276 Mono beta issues] per comment by Babbage Linden on my blog

RobbyRacoon Olmstead added a comment - 31/Aug/08 12:26 PM - edited
Linked to [SVC-2750 State changes are several times slower on MONO servers]

Possibly related? In any case, both issues deal with state changes and performance.


RobbyRacoon Olmstead added a comment - 31/Aug/08 12:32 PM
Given the seriousness of the issue and the high cost of creating a workaround, I'd very much like to get an acknowledgment of this issue from an LL developer, so that we can tell our customers that Linden Lab has the issue on their radar.

Thank you very much.


Wood Fairey added a comment - 31/Aug/08 02:18 PM
It seems that Babbage Linden, on 11/Aug/08 10:52 AM, said, about SVC-2750:

"I think what's happening here is that state changes are being clamped to 1 per frame."

Clearly this is not the issue shown here. Anything done while in state_exit takes longer. Below is a test script and results.

If you do not want to read that, the short story is:

A state transition takes 0.02 seconds (?!)
Every operation while in state_exit() takes a very long time to run. I am not bothering to count the operations, but each iteration takes about 0.41 seconds in the sim I was in when called in state_exit() and less than 0.000001 seconds in state_entry().

I wonder if a moth catcher has fallen into state_exit()?

float entryEntry;
float entryExit;
float exitEntry;
float exitExit;
float defaultStart;
float insaneStart;
integer first = 1;
integer N = 2;

integer
test()
{
integer i;
integer k = 0;

for (i = 0; i < N; ++i)
k += i;
return k;
}

default
{
state_entry()
{
defaultStart = llGetTime();
if (first) { first = 0; insaneStart = llGetTime(); state insane; }

llOwnerSay("\nN is " + (string)N +
"\nLast Entry: " + (string)(entryExit - entryEntry) +
"\nLast Exit: " + (string)(exitExit - exitEntry) +
"\nGoing Insane: " + (string)(entryEntry - insaneStart) +
"\nReturning Sane: " + (string)(defaultStart - entryExit));
++N;
}

touch_start(integer total_number)

{ insaneStart = llGetTime(); state insane; }

}

state insane {
state_entry()

{ entryEntry = llGetTime(); test(); entryExit = llGetTime(); state default; }

state_exit()

{ exitEntry = llGetTime(); test(); exitExit = llGetTime(); }

}

The results were:

N is 2
Last Entry: 0.000000
Last Exit: 1.891130
Going Insane: 0.088676
Returning Sane: 2.558797

N is 3
Last Entry: 0.000000
Last Exit: 2.327432
Going Insane: 0.044499
Returning Sane: 2.972273

N is 4
Last Entry: 0.000000
Last Exit: 2.673080
Going Insane: 0.066175
Returning Sane: 3.362556

N is 5
Last Entry: 0.000000
Last Exit: 3.176846
Going Insane: 0.021635
Returning Sane: 3.760851

N is 6
Last Entry: 0.000000
Last Exit: 3.627911
Going Insane: 0.022079
Returning Sane: 4.228088

N is 7
Last Entry: 0.000000
Last Exit: 4.009933
Going Insane: 0.022327
Returning Sane: 4.677006


Periapse Linden added a comment - 02/Sep/08 03:06 PM
Babbage has checked in a fix for this. Vektor is testing the new version now. We intend to complete a rolling restart this week with this fix and fixes for several other serious issues.

RobbyRacoon Olmstead added a comment - 02/Sep/08 03:32 PM
Woo! Thanks guys!

Periapse Linden added a comment - 02/Sep/08 03:44 PM
1.24.4 server, which contains the fix for this issue, is now deployed to the preview grid (aditi).

You're welcome to go and test there. Assuming that 1.24.4 checks out on aditi, it will be fully deployed to the main grid during this week.


Renee Faulds added a comment - 02/Sep/08 03:47 PM
ATTEN: PERIAPSE:

1.24.4 'does not' fix this issue as confirmed as writing.

please revisit this issue


Periapse Linden added a comment - 02/Sep/08 03:58 PM
Renee – we need details.

Vektor Linden is coordinating the testing of all the 1.24.4 fixes.

If you can create a simple repro and paste it here then Vek can quickly confirm and Babbage can go back to the lab again...


Lear Cale added a comment - 02/Sep/08 06:19 PM - edited
My test shows that the problem I saw is fixed in the Aditi grid, on 1.24.4 server.

====================================
integer Max = 1000;

check(string where) {
integer ix;
float t = llGetTime();
for (ix = 0; ix < Max; ++ix) {
}
llSay(0, where + ": " + (string)((llGetTime() - t) / (float)ix));
}

default {
state_entry() { check("state_entry"); }
touch_start(integer total_number) { check("touch_start"); state two; }
state_exit() { check("state_exit"); }
}

state two {
touch_end(integer count) { state default; }
}
============================
Mono-compiled:
[18:15] Object: state_entry: 0.000022
[18:15] Object: touch_start: 0.000022
[18:15] Object: state_exit: 0.000022
LSL-compiled:
[18:17] Object: state_entry: 0.000289
[18:17] Object: touch_start: 0.000267
[18:17] Object: state_exit: 0.000289

Without the fix, state_exit handler takes about 100 times longer, for either type of object code.


Renee Faulds added a comment - 02/Sep/08 06:47 PM - edited
ok ,gdi, I go back and try again...

I rezzed 100 times even and it not happen ! gdi

I swear ! first first time I try it was on the 3rd rez !

would trying to recreate the first time with my alt have a diff?

SL just baffles me at times....I not a coder I just a builder trying to get along.

Renee

EDIT to add: If I were a scripter I wouldn't be building houses, lol.

Kick myself in head - note to self: Self- Kick your head


Lex Neva added a comment - 02/Sep/08 07:02 PM
Renee's referring to rezzing Rez-Faux packages, because rez-faux was hit by this bug. I tested it in 1.24.4, and I couldn't reproduce the problem, so I think the fix is good.

Renee, don't feel bad... I saw that some sims were still running 1.24.3. I bet you just got a 1.24.3 sim during your first test.


Jesse Barnett added a comment - 02/Sep/08 08:28 PM
Renee, didn't matter if you made a mistake, you are still a hero. If everyone using SL would actually take the time to beta test and bug report with repro then SL would be a much better place.

Solace Obviate added a comment - 02/Sep/08 09:36 PM - edited
As an avid Combat Samurai Island (C:SI) melee combat system user for over a year, I took the opportunity to try out v1.24.4 in the preview grid. Our weapons work nearly like normal now. I am not a scripter and i do not know how to read or report in code. But I have an excellent sense for how the combat system content should feel. And this is pretty darn close. I hope some of our C:SI community members can take the opportunity to go to the preview grid and try it out or run some real scripting test. Thanks for the quick response Linden Labs.

Wood Fairey added a comment - 02/Sep/08 09:45 PM
Thank you Periapse and Babbage. Whilst the need of running of my script in the test grid was negated by the quick work and testing of others, I have done so, as I just felt I should. I am happy to unsurprisingly report that the issue seems to have gone away. Thank you for work in ridding this awful and unsightly moth from the inner workings of SL.

Bridie Linden added a comment - 04/Sep/08 01:09 PM
Fixed in 1.24.4, deploy completed 2008-09-03
http://status.secondlifegrid.net/2008/09/03/post224/

Renee Faulds added a comment - 10/Sep/08 11:41 AM
Since the rolling restart on Second Life Server 1.24.4.95600

This ugly bug has reared it's head


Periapse Linden added a comment - 15/Sep/08 03:49 PM
Renee - this passed QA, and other comments indicate that 1.24.4 solved the problem. If this is still happening in 1.24.5 (on main grid) or 1.24.6 (on preview grid) please re-open again and give us something to test with. Thanks.