Skip to content
This repository has been archived by the owner on Feb 28, 2024. It is now read-only.

[BUG-7623] Background inventory fetch stuck in a loop after opening Places floater #15307

Closed
1 task
sl-service-account opened this issue Oct 25, 2014 · 17 comments
Closed
1 task

Comments

@sl-service-account
Copy link

sl-service-account commented Oct 25, 2014

Steps to Reproduce

We've been trying to track down this bug for a few days, finally have it narrowed to the Places floater.

Steps to reproduce (note this doesn't happen on EVERY account, but DOES happen on my account, at least at the time I filed this)

Open Places floater
Rezzed Silly Cannon! object
Open Silly Cannon!
Copy to Inventory
It creates Silly Cannon! folder with a ToS notecard in inventory
Inventory gets stuck in background fetch.

Actual Behavior

Inventory is stuck in a constant state of background fetching. The Inventory floater indicates "28,645 items Fetching..." while the cursor flashes with a Busy indicator when hovering over Inventory. The debug log spits out:

INFO: setAllFoldersFetched: Inventory background fetch completed

FPS is affected by this as well. Note that this happens after the Places floater is closed too, it is just trigged only after Places floater has been opened at least once.

Expected Behavior

Expected that Inventory would create the folder and one notecard and fetch it as it does when Places floater has NOT been opened.

Other information

I really need a diet coke right now.

Attachments

Links

Duplicates

Original Jira Fields
Field Value
Issue BUG-7623
Summary Background inventory fetch stuck in a loop after opening Places floater
Type Bug
Priority Unset
Status Closed
Resolution Accepted
Reporter Cinder Roxley (cinder.roxley)
Created at 2014-10-25T21:06:35Z
Updated at 2020-09-22T19:20:14Z
{
  'Business Unit': ['Platform'],
  'Date of First Response': '2014-10-25T19:16:18.556-0500',
  "Is there anything you'd like to add?": 'I really need a diet coke right now.',
  'Severity': 'Unset',
  'System': 'SL Viewer',
  'Target Viewer Version': 'viewer-development',
  'What just happened?': 'Inventory is stuck in a constant state of background fetching. The Inventory floater indicates "28,645 items Fetching..." while the cursor flashes with a Busy indicator when hovering over Inventory. The debug log spits out:\r\n\r\nINFO: setAllFoldersFetched: Inventory background fetch completed\r\n\r\nFPS is affected by this as well. Note that this happens after the People floater is closed too, it is just trigged only after People floater has been opened at least once.',
  'What were you doing when it happened?': "We've been trying to track down this bug for a few days, finally have it narrowed to the People floater.\r\n\r\nSteps to reproduce (note this doesn't happen on EVERY account, but DOES happen on my account, at least at the time I filed this)\r\n\r\nOpen Places floater\r\nRezzed Silly Cannon! object\r\nOpen Silly Cannon!\r\nCopy to Inventory\r\nIt creates Silly Cannon! folder with a ToS notecard in inventory\r\nInventory gets stuck in background fetch.",
  'What were you expecting to happen instead?': 'Expected that Inventory would create the folder and one notecard and fetch it as it does when People floater has NOT been opened.',
}
@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T00:16:19Z

I can reproduce this 100% of tries on 2 different accounts (Whirly Fizzle with 105k inventory & Kippy Adored with 10k inventory).
The asset "Silly Cannon!" is not needed to reproduce the problem.

  • Login.
  • Rez a cube and add a new script.
  • Open Inventory floater.
  • Open Places floater and leave it open (this seems to be the key step).
  • Right click Cube -> Open -> Copy to inventory

Observed:
Before box contents are copied to inventory, inventory shows as fully fetched: http://i.imgur.com/gtLWn02.png
After opening box and adding contents to inventory, inventory shows "Fetching..." constantly and mouse cursor spins while inside the inventory floater: http://i.imgur.com/8uNVEy2.png
Closing and reopening inventory floater doesnt fix it.
Teleporting to a different region doesnt fix it.
Deleting or adding something new to inventory doesnt fix it.
Opening a secondary inventory window doesnt fix it - both windows show as "Fetching....."

Second Life 3.7.18 (295539) Oct 16 2014 09:21:29 (Second Life Release)
Release Notes

You are at 115.0, 94.0, 21.8 in Testylvania Sandbox located at sim10708.agni.lindenlab.com (216.82.53.70:13008)
SLURL: http://maps.secondlife.com/secondlife/Testylvania%20Sandbox/115/94/22
(global coordinates 332,659.0, 306,270.0, 21.8)
Second Life RC Snack 14.10.17.295641
Retrieving...

CPU: Intel(R) Core(TM) i7-4770K CPU @ 3.50GHz (3491.94 MHz)
Memory: 16268 MB
OS Version: Microsoft Windows 7 64-bit Service Pack 1 (Build 7601)
Graphics Card Vendor: NVIDIA Corporation
Graphics Card: GeForce GTX 750/PCIe/SSE2

Windows Graphics Driver Version: 9.18.0013.4448
OpenGL Version: 4.4.0 NVIDIA 344.48

libcurl Version: libcurl/7.37.0 OpenSSL/1.0.1h zlib/1.2.8
J2C Decoder Version: KDU v7.0
Audio Driver Version: FMOD Ex 4.44.31
Qt Webkit Version: 4.7.1 (version number hard-coded)
Voice Server Version: Vivox 4.6.0009.20030

Built with MSVC version 1600
Packets Lost: 112/7,655 (1.5%)

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T00:18:42Z

Does not reproduce on Second Life 3.2.8 (248931) Feb 9 2012 09:04:17 (PRE-CHUI)
Reproduces on Second Life 3.5.3 (276452) May 24 2013 02:06:23 (PREMATS)
Reproduces on Second Life 3.7.7 (289441) Apr 22 2014 11:15:59 (PreInteresting)

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T00:37:01Z

Also to note: When this repro is done on default release, Second Life 3.7.18 (295539) Oct 16 2014 09:21:29 (Second Life Release), there is no excessive log spam generated while the inventory is stuck in a constantly fetching state.

However, performing the above repro on the HTTP RC viewer, Second Life 3.7.19 (295700) Oct 20 2014 13:37:20 (Second Life Release), triggers many hundreds of lines of log spam that do not stop until you relog.

<SNIP>
2014-10-26T00:34:57Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:58Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:34:59Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
2014-10-26T00:35:00Z INFO: LLInventoryModelBackgroundFetch::setAllFoldersFetched: Inventory background fetch completed
<SNIP> 

Attached Whirly_HTTP_log.log

Second Life 3.7.19 (295700) Oct 20 2014 13:37:20 (Second Life Release)
Release Notes

You are at 115.0, 94.0, 21.8 in Testylvania Sandbox located at sim10708.agni.lindenlab.com (216.82.53.70:13008)
SLURL: http://maps.secondlife.com/secondlife/Testylvania%20Sandbox/115/94/22
(global coordinates 332,659.0, 306,270.0, 21.8)
Second Life RC Snack 14.10.17.295641
Release Notes

CPU: Intel(R) Core(TM) i7-4770K CPU @ 3.50GHz (3491.94 MHz)
Memory: 16268 MB
OS Version: Microsoft Windows 7 64-bit Service Pack 1 (Build 7601)
Graphics Card Vendor: NVIDIA Corporation
Graphics Card: GeForce GTX 750/PCIe/SSE2

Windows Graphics Driver Version: 9.18.0013.4448
OpenGL Version: 4.4.0 NVIDIA 344.48

libcurl Version: libcurl/7.38.0 OpenSSL/1.0.1h zlib/1.2.8
J2C Decoder Version: KDU v7.0
Audio Driver Version: FMOD Ex 4.44.31
Qt Webkit Version: 4.7.1 (version number hard-coded)
Voice Server Version: Vivox 4.6.0009.20030

Built with MSVC version 1600
Packets Lost: 0/4,264 (0.0%)

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T01:05:04Z

I wonder if this repro was the cause for VWR-28897 all along?

@sl-service-account
Copy link
Author

Monty Linden commented at 2014-10-26T05:44:31Z

Hmmm, I was worried about spam on this message but never encountered a situation that ran away like this. With a pre-HTTP viewer (one without inventory changes), if you perform the reproducing actions, do you get continuous inventory activity? Without the spam but inventory never seems to settle?

The workaround for this may be to use an LL_INFOS_ONCE() logger. It doesn't fix the underlying problem with inventory running forever due to whatever is going on with Places.

@sl-service-account
Copy link
Author

Monty Linden commented at 2014-10-26T05:51:22Z

Ah, reading email more carefully, I see this does reproduce (without spam) on release. I'd say -28897 is related, how many experience this?

@sl-service-account
Copy link
Author

Cinder Roxley commented at 2014-10-26T15:24:55Z

The issue doesn't cause any additional network activity between the viewer and the simulator. Quelling the log spam would be good except that this can also cause a noticeable frame rate drop, and the user sees their mouse cursor rapidly switching between busy indicator and normal when hovering over any inventory panel (Inventory floater, landmarks panel, received items, etc) along with the false indication that inventory fetching is taking place.

I've narrowed the issue further to LLLandmarksPanel. If the Landmarks panel is removed from the Places panel, this issue cannot be reproduced. Landmarks panel doesn't seem to have gotten much love since it was first released in V2 and is rife with code duplication from V2 svn days.

My assumption is that during the many rounds of inventory improvement, LLLandmarksPanel was left out of the fun and is no longer doing the right thing. (Such as starting a background inventory fetch when expanding it's panels which should no longer be necessary with AIS3, I would think.)

@sl-service-account
Copy link
Author

Cinder Roxley commented at 2014-10-26T15:26:31Z

Not sure how broadly this is experienced. I assume that anybody opening the Places panel and receives new inventory is affected.

@sl-service-account
Copy link
Author

Monty Linden commented at 2014-10-26T16:21:52Z

I hope there's no additional network activity. I can imagine the viewer issuing empty inventory fetch requests as fast as possible. :-)

Real problem is in the landmarks panel (and possibly elsewhere if it was copied). But I am curious if just killing the log spam improves things. LLLog has always been expensive. In the inventory work, I unified a bunch of cut-n-paste logging into a single one central to all paths. This was a side-effect when one of those paths originally didn't log but spun madly.

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T17:17:07Z, updated at 2014-10-26T17:20:42Z

On my system (same sysinfo as above) the performance drop when this bug is triggered is the same on default release as on the HTTP RC viewer.
The performance drop is fairly significant however.
I'm getting repeatably the same FPS readings when doing the following steps under conditions as identical as I can make them each session, sparse region with only myself there...

Default release Second Life 3.7.18 (295539) Oct 16 2014 09:21:29 (Second Life Release)

  • Login with fully cached inventory, clear any awaiting inventory offers and notices then relog.

  • Wait for objects/texture/own avatar loading to settle - FPS ~77

  • Open inventory floater and go to Recent tab - FPS ~ 100 (note I did these steps to work around the BUG-7614 problem - FPS will be lower until Recent items tab of inventory is opened in a session)

  • Open Places panel - no change to FPS

  • Open a box and copy contents to inventory to trigger this bug - FPS ~ 60

  • Closing inventory floater and places panel - no change to FPS - it stays down at 60 until relog.
    So this is an approx 40 FPS drop for me o.O

    ETA: Tested on Whirly Fizzle account which has 105k inventory.

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T17:21:31Z

If HTTP Inventory is disabled, I cannot reproduce the inventory ever getting into this constantly fetching state.

@sl-service-account
Copy link
Author

Monty Linden commented at 2014-10-26T17:40:05Z

So logging doesn't subjectively make it worse, it's just a huge sign post in the log files? Well, that's one way to draw attention to a two-year-old bug report...

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T17:51:18Z

lol
As far as I can tell, on my system the log spam does not appear to decrease performance.
But possibly a noisy log may decrese performance more on a slower system?

How many experience this?
This does crop up fairly often in support cases but not at viral levels.
Hard to say really how many are affected.
I suspect there are probably other triggers for this set of symptoms apart from this repro.
Personally, I have not been seeing this problem with my inventory stuck in a constantly fetching state very often, but I'm also not a big user of the places panel. I teleport directly from inventory LMs or search usually.

@sl-service-account
Copy link
Author

ObviousAltIsObvious commented at 2014-10-26T18:45:07Z

Well, this is kind of annoying. I can't reproduce this places floater thing on four different accounts today, but did have inventory stuck in forever-loading twice earlier in the week (can't remember if places floater was up or not at the time).

@sl-service-account
Copy link
Author

Cinder Roxley commented at 2014-10-26T19:10:22Z, updated at 2014-10-26T19:10:53Z

Places floater doesn't need to be up to repro, the landmark panel just needs to have been created. Now I'm thinking it might have something to do with the zany and creative way filtering works in the Landmarks panel, but that's just a guess. I haven't been able to pinpoint exactly what functions are causing this.

The FPS drop is due to gIdleCallbacks running in the main thread. Once the Landmarks panel gets inventory stuck in this constant fetching state, so many addition function calls end up running in the main thread.

@sl-service-account
Copy link
Author

Whirly Fizzle commented at 2014-10-26T19:19:04Z, updated at 2014-10-26T19:27:47Z

Looks like this does somewhat depend on the account.

I cannot reproduce this at all on account "FizzleFire Resident" which is pretty much default noob .. no custom inventory items, no Landmarks at all apart from the ones in the Library, no friends, no groups.

However, the bug triggered on this account by simply adding 1 single landmark to inventory.
Inventory and places floater were open and I'd copied a few box contents to inventory. Failed to repro the bug, so deleted the new folders & purged Trash. Inventory still behaving.
Then I went to World -> landmark this place.
As soon as the new LM was created in my inventory, the bug hit. Inventory is stuck "Fetching....." with the spinny mouse cursor: http://i.imgur.com/iQndhaR.jpg

Original bug is now repeatable easily on this account after logging in with 1 single custom landmark.
Also noticed the mouse cursor constantly spins when held inside the Places floater, not just within the Inventory floater.

@sl-service-account
Copy link
Author

ObviousAltIsObvious commented at 2014-10-27T09:30:46Z

Reproduces reliably now, after a settings enema.

This may not be exactly the same as VWR-28897, the grinding on this case with the landmarks seems much more intensive than with other times this has popped up.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

1 participant