search

secondlife / jira-archive

2 stars 0 forks source link

[BUG-6530] Slow, Error-Message-Ridden Avatar Loading #14381

Open sl-service-account opened 10 years ago

sl-service-account commented 10 years ago

Steps to Reproduce

Many people seem to be having issues with their avatars remaining clouded on login lately. I've noticed that it can take my avatar several minutes to load. Note that it will load eventually with no action from me; it's not a problem with a scrambled current object folder.

Actual Behavior

This is a log of a recent session consisting only of the time from logging-in to becoming visible. Note that there are several reports of "missing body parts" which were shown as worn in the current outfit folder at the time. Everything eventually loaded after several minutes, immediately after the "wearable parameter mismatch" messages at about 11:11:11 by the time stamps.

Expected Behavior

Data about currently-worn objects should load promptly without errors.

Other information

My internet connection isn't known for its blazing, tigerlike speed but its generally reliable and has worked well for Second Life in general and still does once my avatar loads.

Attachments

Links

Related

Original Jira Fields | Field | Value | | ------------- | ------------- | | Issue | BUG-6530 | | Summary | Slow, Error-Message-Ridden Avatar Loading | | Type | Bug | | Priority | Unset | | Status | Been Triaged | | Resolution | Triaged | | Reporter | Theresa Tennyson (theresa.tennyson) | | Created at | 2014-07-01T11:45:11Z | | Updated at | 2014-07-04T20:25:21Z | ``` { 'Business Unit': ['Platform'], 'Date of First Response': '2014-07-01T07:01:09.071-0500', "Is there anything you'd like to add?": "My internet connection isn't known for its blazing, tigerlike speed but its generally reliable and has worked well for Second Life in general and still does once my avatar loads.", 'System': 'SL Viewer', 'Target Viewer Version': 'viewer-development', 'What just happened?': 'This is a log of a recent session consisting only of the time from logging-in to becoming visible. Note that there are several reports of "missing body parts" which were shown as worn in the current outfit folder at the time. Everything eventually loaded after several minutes, immediately after the "wearable parameter mismatch" messages at about 11:11:11 by the time stamps.', 'What were you doing when it happened?': "Many people seem to be having issues with their avatars remaining clouded on login lately. I've noticed that it can take my avatar several minutes to load. Note that it will load eventually with no action from me; it's not a problem with a scrambled current object folder.", 'What were you expecting to happen instead?': 'Data about currently-worn objects should load promptly without errors.', 'Where': "Log is from a Magnum region but I've seen similar behavior with a different avatar on a main-channel region.", } ```
sl-service-account commented 10 years ago

Whirly Fizzle commented at 2014-07-01T12:01:09Z, updated at 2014-07-01T12:04:39Z

Yeah, I don't know whats going wrong here but there has been a huge increase in the number of BUG reports filed on the LL JIRA recently from people with their avatar stuck as a cloud. As far as I can tell, this started with the release of viewer-interesting - I'd already mentioned this to Alexa a couple of weeks ago.

Those affected are easily fixed with replacing outfit though. Also to note - there does not appear to have been an increase in avatar cloud complaints coming into Firestorm support - but we have not released the viewer-interesting changes yet in Firestorm.

Theresa, do you think this started when viewer-interesting was promoted to release? Or is what you are seeing more recent and coincided with the Memshine viewer being released and AIS3 rolling out to main grid?

Also related: BUG-6192 - User never de-clouds with a large inventory after a fresh inventory fetch

sl-service-account commented 10 years ago

Theresa Tennyson commented at 2014-07-01T12:11:21Z

It's possible that it got worse with the "interesting" changes, but it seems to have gotten really bad with the release of the Sunshine inventory protocol on the servers. I've seen similar behavior on Catznip the other day, which has comparatively old viewer code.

sl-service-account commented 10 years ago

Theresa Tennyson commented at 2014-07-01T12:56:35Z

Okay, this is interesting - I just added an additional log of the same situation, outfit and location, where everything loaded promptly and perfectly - "AvatarLoad" is the bad one, "GoodLoad" is (wait for it...) the good one. I did a number of things between the two logins, such as using a different viewer and logging into a different account, but the environment of the two log files is identical.

sl-service-account commented 10 years ago

Monty Linden commented at 2014-07-01T18:32:53Z

At a quick glance, no specific problem suggests itself. On the server side, I see a few caps requests come in on sim10177 and then nothing. The inventory failures below aren't logged on the server side which suggests they never made it into Linden. Other stats show that the ingress services were healthy and unloaded at the time so there should not have been an impediment.

Problems seem to be centered around HTTP serviced by the PumpIO scheme. It uses libcurl for transport but in an odd fashion. There's a long, long history of PumpIO going off the rails at which point comms stop. This may be another example. I've never been able to reproduce it, there's no obvious trigger, and the code is so awful, it has debug statements every five to 10 lines. If someone is reproducing this reliably, it may be worth hopping on.

The 'empty cap url' message is interesting on it's own. The fuzzy textures problem we're having is also associated with an empty cap url. May just be coincidence, but...

2014-07-01T11:08:31Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=2 type=GET ID=1b9fd220-38ef-3264-7593-e2db8461b9ad face=-1 #retries=0 (empty cap url), will retry.
2014-07-01T11:08:32Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=2 type=GET ID=1b9fd220-38ef-3264-7593-e2db8461b9ad face=-1 #retries=1 (empty cap url), will retry.
2014-07-01T11:08:33Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=2 type=GET ID=1b9fd220-38ef-3264-7593-e2db8461b9ad face=-1 #retries=2 (empty cap url), will retry.
2014-07-01T11:08:33Z WARNING: LLURLRequest::process_impl: URLRequest Error: 35, SSL connect error, https://sim10177.agni.lindenlab.com:12043/cap/facf216b-15cf-1721-dcfc-461c3b5349b6
2014-07-01T11:08:33Z INFO: LLPumpIO::processChain: Pump generated pipe err: 'STATUS_ERROR'
2014-07-01T11:08:33Z WARNING: LLInventoryModelFetchDescendentsResponder::httpFailure: [POST:https://sim10177.agni.lindenlab.com:12043/cap/facf216b-15cf-1721-dcfc-461c3b5349b6] [status:499] [reason:STATUS_ERROR] [content:!]
2014-07-01T11:08:33Z INFO: LLInventoryModelFetchDescendentsResponder::httpFailure: [POST:https://sim10177.agni.lindenlab.com:12043/cap/facf216b-15cf-1721-dcfc-461c3b5349b6] [status:499] [reason:STATUS_ERROR] [content:!]
2014-07-01T11:08:34Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=2 type=GET ID=1b9fd220-38ef-3264-7593-e2db8461b9ad face=-1 #retries=3 (empty cap url), will retry.
2014-07-01T11:08:35Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=2 type=GET ID=1b9fd220-38ef-3264-7593-e2db8461b9ad face=-1 #retries=4 for 4 tries, dropping request.
2014-07-01T11:08:36Z WARNING: LLMediaDataClient::serviceQueue: Could not send request request: num=3 type=GET ID=0fd87905-33d0-2c92-3103-527e2df1fae2 face=-1 #retries=0 (empty cap url), will retry.
2014-07-01T11:08:36Z WARNING: LLURLRequest::process_impl: URLRequest Error: 35, SSL connect error, https://sim10177.agni.lindenlab.com:12043/cap/24097120-2aa0-0741-1456-8e1b3abfc16b
sl-service-account commented 10 years ago

Theresa Tennyson commented at 2014-07-02T16:50:40Z

Another possible clue - in the log where it took a long time for me to rezz, I opened the "Current Outfit" folder in my inventory to see if anything looked amiss, and then eventually I appeared. I've done this other times with similar results. This morning I found myself clouded and opened the debug console to see similar messages (basically saying I was missing SKIN SHAPE HAIR EYES). I deliberately did NOT open the current outfit folder and remained as a cloud for a very long time - long enough to do object editing, etc. I did eventually load but only after I opened an inventory folder - however, it was NOT the COF and in fact didn't have any body/clothing-type items in it.

sl-service-account commented 10 years ago

Theresa Tennyson commented at 2014-07-02T17:56:14Z

"PiperCloud.log" is the log of the session I just commented about (different location and avatar from the first report.) De-clouding was 275 seconds in, after opening an inventory folder.

sl-service-account commented 10 years ago

Monty Linden commented at 2014-07-02T20:40:34Z

Checked PiperCloud.log and it follows the same pattern. I checked the simhost and it was unloaded at the time. No contention for the resources that are failing in your viewer session. One of the operations that is failing involves avatar appearance, the other is inventory, so no surprise the problems you see.

What are the make and model of your home networking devices including router and cable/adsl modem? The reason I ask is that at startup, viewer is particularly aggressive about connections and TCP activity. If there's going to be a failure due to marginal networking equipment, this is when it will likely happen.

Possible workarounds:

To the dev that picks this up in maintenance:

sl-service-account commented 10 years ago

Theresa Tennyson commented at 2014-07-02T21:21:23Z

I've got a Motorola SB5101U SURFboard cable modem and a Netgear R6100 router that I use strictly as a pass-through for Second Life - I connect with a cable and don't generally have any other WiFi items running. This problem is actually fairly rare for me - happens on maybe 10% of logins at most - but I know there are others with more frequent problems. It's very unpredictable.

sl-service-account commented 10 years ago

Whirly Fizzle commented at 2014-07-02T21:34:01Z

I just had a failed avatar load after relogging. My avatar was correctly rezzed before I relogged. The viewer gave me the following notification several times after relogging "WARNING: LLToastAlertPanel::LLToastAlertPanel: Alert: Could not put on outfit. The outfit folder contains no clothing, body parts, or attachments."

This is the first time I have ever had this happen where my COF mysteriously lost everything in it apart from 3 attachments after relogging. I am wearing no skin, shape, hairbase or eyes. I don't really trust my results to be very useful because this session was on Aditi, but attaching logs from this session just in case - whirly.log

sl-service-account commented 10 years ago

Whirly Fizzle commented at 2014-07-04T17:52:44Z

I think I may have found one cause of increased bakefails since AIS3 rolled out to the grid - see BUG-6578