Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0007038opensim[GRID] Asset Servicepublic2014-02-26 06:212014-07-29 13:43
ReporterMata Hari 
Assigned Toorenh 
PriorityhighSeveritymajorReproducibilityalways
StatusclosedResolutionfixed 
PlatformCore2DuoOSlinuxOS VersionUbuntu 13.10
Product Versionmaster (dev code) 
Target VersionFixed in Versionmaster (dev code) 
Summary0007038: Unwearing mesh attachments very slow and generates [SynchronousObjectRequester] message IF mesh contains a script
DescriptionI've noticed that any time a mesh attachment is unworn it almost always generates the message: "[SynchronousRestObjectRequester]: Slow request...<etc>" even if the object has in no way changed. This happens with most mesh attachments unless it's a tiny file (under 2MB) and the delay becomes progressively worse with larger (in terms of file size) meshes. This makes me wonder if every time the mesh is being unworn it is being asked to send the entire mesh data (almost like a new upload) instead of just the object UUID, attachment point, texture UUIDs, etc that is sent for regular prim attachments. If this is the case, is it necessary?

Also, it appears that these are handled sequentially rather than synchronously, so swapping outfits when currently wearing a multiple-piece outfit can often take 30+ seconds and generate multiple console messages. During the sequence the assorted outfit pieces are removed and it isn't until all pieces are "finished" (with console message) that the new outfit starts to be worn...which means you definitely need to find a private place before swapping outfits. Yes, I know that's a good idea anyway, but still... It's slightly faster when I'm standing in a Plaza instead of my own region (presumably because the Plaza is hosted on the same network as the asset server) but it's still considerably slower than making the identical change of outfits in SL.

If any changes were made to the mesh (scale, colour, texture, position, etc) they will be lost unless I wait for the [SynchronousRestObjectRequester] message before rewearing it; and occasionally attempting to rewear it too soon will cause the mesh to become corrupted/lost and must be uploaded again. (Console says item cannot be found).

I don't experience any of these issues with regular prim or sculpt attachments.
Steps To ReproduceExample: a mesh dress I made has an original .dae file size of just under 5MB (~17k verts + UV map + normal map but no textures applied). After upload I added different textures to each of its 3 faces (each texture a 512x512 png size ~200k) and 3 matching specular maps (each also 512x512 png with same ~200k size). None of the faces has a custom normal map (they use the maps uploaded in the dae). Every time I unwear it when on my own region there is a 4-6 second delay and then the console shows the [SynchronousRestObjectRequester] message. In comparison, unwearing a 0000180:0000150-prim (about half flexi-prim and half sculpt thus much, much larger in terms of total verts and object count) takes perhaps half a second to update.
Additional InformationThis long delay seems to have begun since ~December (and continues to happen with r/24383 that I'm currently using) but it's possible that it was happening prior to that but with a much shorter delay time.

Sometimes additional console error (red!) messages will also appear and they're not consistently the same...sometimes it's a [LLCLLIENTVIEW] message, other times it's a [XMLRPC-GROUPS-CONNECTOR] message, and other times it's [FORMS]. I can supply examples of all of these just from my log this morning while attempting to texture a simple pair of mesh stockings.
TagsNo tags attached.
Git Revision or version number
Run Mode Grid (Multiple Regions per Sim)
Physics EngineBasicPhysics
EnvironmentUnknown
Mono VersionNone
ViewerFirestorm 4.5.1.38838 OS
Attached Filestxt file icon log of error working with mesh.txt [^] (14,717 bytes) 2014-02-26 06:29 [Show Content]
txt file icon unwear-mesh-attachment.txt [^] (36,046 bytes) 2014-03-26 00:49 [Show Content]
rar file icon Mata mesh log.rar [^] (1,549,393 bytes) 2014-03-27 07:04
rar file icon sample mesh.rar [^] (1,053,379 bytes) 2014-03-27 07:14
rar file icon Mata ini.rar [^] (19,568 bytes) 2014-03-27 07:54

- Relationships
related to 0006987closedMata Hari Very high process memory consumption from mesh attachments (and mesh in general) 

-  Notes
(0025320)
Mata Hari (reporter)
2014-02-26 06:29

Added log of console messages generated just while working on a mesh this morning
(0025465)
Mata Hari (reporter)
2014-03-18 12:15
edited on: 2014-03-18 12:16

This continues to happen with the latest build. It seems the sim is sending the entire mesh data (including geometry) and waiting for a response for each mesh item unworn. Only when an items has finished this cycle does the item replacing it get rezzed on the avi. This ALWAYS happens even when all data for the mesh is in both the region cache and the viewer cache and the mesh has is no way been changed.

EDIT: to further clarify - the communication of data is between the region sim and the OSG servers, not between the viewer and the region sim.

(0025579)
Mata Hari (reporter)
2014-03-25 05:51

This may also possibly be related to 0006755 if at some point during the tp process the current state of worn mesh items is being stored prior to the tp completing since that save could be lengthy when wearing multiple mesh attachments.
(0025582)
orenh (administrator)
2014-03-26 00:48
edited on: 2014-03-26 00:49

I tried this and the mesh asset data was not sent. I'm using latest Git master. I created a mesh object called "Plastic Cup", and attached it to myself. Then I detached it. See the attached file "unwear-mesh-attachment.txt" for the log. I enabled "debug http all 6", so this shows every HTTP message sent and received in OpenSim.

The log shows that the asset data wasn't sent. There's only one slightly large binary block, but that's just the base64-encoded SceneObjectGroup.

(0025583)
aiaustin (developer)
2014-03-26 04:02

Mata Hari... worth adding your detailed "how to reproduce" in the mailing list here?
(0025584)
Mata Hari (reporter)
2014-03-26 04:57

Just redid a complete test with a newly created mesh and saw what Orenh reported....only a small amount of data.

Following up on a comment from Melanie in the mailing list, I then added a script to the mesh

default
{
    state_entry()
    {
        llSay(0, "Script running");
    }
}

Now every time the mesh is unworn the region will resend the *entire* mesh data.



Per Aiaustin's suggestion, steps to reproduce:

1. Create a mesh object that is far more detailed than you would normally create (something in the 40k vert range). Rigged, weighted, UV mapped and normal-mapped, this will result in a dae that's about 10MB in size which will then be easy to spot when testing. Obviously a 10MB mesh is far too large to wear normally but this is the best means to demonstrate the issue. I can supply a test file if someone wants to try this but isn't able to create the dae.

2. Stand in a region where you are able to monitor the outbound and inbound data traffic between the region server and the asset server (for super-easy test, be in a home-hosted region with an ISP connection under 5Mbps that is connected to OSG)

3. Upload the mesh (brew coffee while waiting for it to finish). You'll notice outbound traffic during the upload as the geometry, etc is being sent to the asset server. The total traffic will be a little larger than your original file because LOD and physics also has to be stored. If you're very patient, upload it with silly LOD settings to have it display at nearly maximum mesh resolution at all distances and to use the highest possible quality physics mesh just so the asset is truly enormous (but never do this for a real asset!)

4. Select an attachment point that you normally have something else attached to (the skull, for instance, where most people wear prim hair). Detach whatever is currently there.

5. Attach the mesh to that point. Don't do anything else -- don't texture it or change it in any way. Just attach.

6. Now from inventory, wear whatever normally mounts to that attachment point (assuming your viewer is set to replace objects on attachment points by default) which will cause the mesh to be detached and the other object to be attached.

7. Monitor the outbound data traffic for the region and also see how long it takes your other object to appear.

8. Repeat this over and over again, swapping back and forth between the hair (or whatever) and the mesh while watching the traffic. Depending on your debug settings, also watch the console for messages.

**** NEW STEP ***

9. Now add a generic script (as per above by clicking "new script") to the mesh.

10. repeat the swapping exercise between hair and mesh.

As Orenh reported, at step 8 only a minimal amount of data is being sent from the region to the asset server. At step 10 this balloons into masses of data being sent every time the mesh is unworn.
(0025586)
melanie (administrator)
2014-03-26 05:44

The system is supposed to save the SceneObjectGroup if it has either changed or contains a script. However, that should be only the SOG, not the actual mesh data. Since the actual mesh data can never change, re-saving it is pointless.
(0025590)
orenh (administrator)
2014-03-26 09:58

I tried this with a mesh object that also has a script. It still didn't send the mesh asset. The SceneObjectGroup that it *did* send was a bit larger, due to the script state, but that was still only a few K.

Please provide a log that shows the asset being sent. To do so, update to the latest git master, and then before detaching the attachment run in the OpenSim console: "debug http all 6". Then detach, and include the log from that point to this Mantis. My guess is that it won't show the asset being sent, but it might show that one or more of the HTTP calls that *are* made is slow.
(0025610)
Mata Hari (reporter)
2014-03-27 07:05
edited on: 2014-03-27 07:10

I made a new, somewhat smaller mesh for this test in the hopes that the log file wouldn't exceed the maximum file upload size for Mantis. Exact details of every single step I took are provided here so you know what I did and didn't do.

In Blender 4.70:
- created a basic T-shirt mesh - single object, all one piece
- created 3 material zones (for clothing I usually have at least 2 and usually 3 or 4...on occasion I could have as many as the maximum 8)
- UV mapped all materials (all materials mapped to the same UV, not different ones)
- vertex count was quite low so I applied 2 levels of subsurf to make it a larger file size
- parented it to Avastar SL rig -- this rig is a custom armature that is slightly modified from the basic SL one (to correctly position elbows, knees, etc) but is 100% compatible with SL/Opensim
- weighted it via proximity and then subsequent weight-painting
- I always work in quads so applied triangulate modifier (SL/Opensim only accepts tris)
- export to dae using Avastar's handy export tool
Final mesh dae details:
15820 verts
31276 faces (all triangles)
16468 UVs
3 materials
file size reported by Windows: 5,205KB

In Opensim
System details:
        CPU: Intel(R) Core(TM) i7 CPU 930 @ 2.80GHz (2800.01 MHz)
        Memory: 12279 MB
        OS Version: Microsoft Windows 7 64-bit Service Pack 1 (Build 7601)
        Graphics Card Vendor: ATI Technologies Inc.
        Graphics Card: ATI Radeon HD 5800 Series
        Windows Graphics Driver Version: 9.012-121219a-152192C-ATI
        OpenGL Version: 4.2.12002 Compatibility Profile Context 9.12.0.0
        Installed .NET Frameworks"
            .NET FW 1.1 SP 1
            .NET FW 2.0 SP 2
            .NET FW 3.0 SP 2
            .NET FW 3.5 SP 1
            (.NET FW 4.0 updated to 4.5)
            .NET FW 4.5
            .NET FW 4.5.1

- updated to opensim-af54e6f (r/24541) -- the test I reported yesterday was done on a build made from r/24531 which was 100% current but I figured I might as well update again to pick up yesterday's stuff
This instance handles only 2 regions in OSGrid with MySQL as region storage and flotsam cache. Both regions are currently mostly empty...only a few objects and scripts running, all generic "harmless" ones that don't have any meaningful impact on the sim. All ini are essentially the default OSG ones with a few tweaks to suit my needs (enabling high threat OSSL for myself, etc).
- launched...waited for flotsam cache to build, etc.

In Firestorm:
version: Firestorm 4.6.1 (40478) Mar 10 2014 05:38:17 (Firestorm-Releasex64) with OpenSimulator support
- logged in directly to one of my regions once logins were enabled
- waited (an eternity!) for initial inventory fetch to finish
- uploaded the mesh using the following settings:
    Type: avatar attachment
    LOD: used defaults for all which report
                    High 31276 tri 16309 vert
                    Medium 7818 4237
                    Low 1953 1147
                    Lowest 976 612
    Normals: generate normals NOT checked (export dae already has them)
    Physics: Lowest
    Scale: 1.0
    Textures: include textures checked
    Weight: include skin weight checked
                include joint positions NOT checked
- once mesh upload had completed, attached it to spine
- detached it
- made a copy of it in inventory
- attached the copy
- added a script to the copy (just clicked "New Script" and left the default generic viewer-generated one untouched)
- switched back and forth between the unscripted and scripted meshes a few times to ensure everything was cached, so any future wear/unwear actions would be typical of everyday use
- logged out
- logged back in to the same region
- waited another eternity for initial inventory fetch to finish

In Opensim console
- enabled "debug http all 6" as per your instructions

In Firestorm:
- At the beginning of this test I was already wearing the unscripted mesh on spine - log file contains the same details inserted prior to each "action" but is otherwise a completely unedited continuous log of everything.
- You can quickly step through these by searching for "*** MARKER" (first action is marked by "*** MARKER 1", second by "*** MARKER 2", etc)
Action 1 at 08:48 file line 1 double-clicked on the scripted mesh in my inventory which causes the unscripted mesh to detach and the scripted mesh to attach
Action 2 at 08:50 file line 54 double-clicked on the unscripted mesh in my inventory to wear it and unwear the scripted one
Action 3 at 08:51 file line 148 unwore the unscripted mesh
Action 4 at 08:51:30 file line 226 wore the scripted mesh
Action 5 at 08:52 file line 275 unwore the scripted mesh

In Opensim console
- disabled logging by setting level back to 0

Prepared and submitted this report.

Note that unwearing the non-scripted mesh is rapid and generates fairly small entries. Unwearing the scripted mesh generates an EXTREMELY long line of HEX data as part of the data being sent. If this is just the "script state" being sent then it's insanely large! Maybe it's not the mesh geometry...maybe it's something else. But whatever it is, it's only unwearing scripted mesh that seems to generate it. I had to RAR just this small portion of the log because the un-zipped file size was 2.27MB which exceeds the maximum file upload size in Mantis. When I did the exact same test earlier today using yesterday's mesh, the log was more than 45MB which wouldn't even load in Notepad++.

(0025611)
Mata Hari (reporter)
2014-03-27 07:15

I have now also attached the file "sample mesh.rar" which is the EXACT dae file I used to the above test. It won't fit or animate properly for anyone else since it's custom-made for me, but you're welcome to d/l it and use it for your own testing
(0025612)
orenh (administrator)
2014-03-27 07:17
edited on: 2014-03-27 07:27

Thanks for the log. It shows that the SceneObjectGroup is being saved with the entire mesh embedded inside it, in the SculptData field. You're not imagining things :)

I don't think this field needs to be serialized. I'll have to look further to figure out what should be done.

(0025613)
Mata Hari (reporter)
2014-03-27 07:24

What I also find strange and might be worth looking into, then, is that when you did this same test yesterday you didn't see it. Is there something fundamentally different about your mesh or your sim setup that didn't cause it to send all this data when you tried it?
(0025614)
orenh (administrator)
2014-03-27 07:30

Are you using BulletSim or ODE?
(0025615)
Mata Hari (reporter)
2014-03-27 07:48
edited on: 2014-03-27 07:55

BulletSim

Attached copies of my ini files in case you want the complete details. Passwords are all replaced with ******

(0025617)
orenh (administrator)
2014-03-27 08:40

I can now reproduce this consistently. My original mesh didn't cause this behavior but yours does; must be some difference in the way we uploaded them.

I'm pretty sure we shouldn't serialize SculptData in the SceneObjectGroup, since it's a complete copy of the mesh. (Or, for sculpties, a complete copy of the sculpt texture.) The data can (and should) be loaded when needed using the SculptTexture field, which is the UUID of the mesh or sculptie asset.
(0025618)
Mata Hari (reporter)
2014-03-27 08:50
edited on: 2014-03-27 08:55

Perhaps when you uploaded yours you didn't have any weights? When a rigged mesh attachment is worn it will be deformed by the current avi's shape settings that affect any of the armature bone sizes (and with the new liquid mesh it's deformed by all shape sliders if weighted to collision volume instead of armature) so I guess in that respect its geometry is being altered by this. When unworn it re-shapes itself back to its default geometry and if worn by someone else it will pick up their shape settings so in any event there's no purpose at all in sending geometry to the asset server since the base geometry never changes.

EDIT: from the region server's perspective that geometry change might be important, though, since it needs to be able to send the "real" appearance of the mesh to any agents in the region. Not sure exactly how that's handled, but it would only need to be kept on a temporary basis and shouldn't try to change the stored base asset geometry.

(0025619)
orenh (administrator)
2014-03-27 09:04

See related discussion here: http://opensim-dev.2196679.n2.nabble.com/Stop-saving-SculptData-in-serialized-SceneObjects-td7579079.html [^]
(0025620)
Mata Hari (reporter)
2014-03-27 09:09

Based on your comments there, I now suspect that my report 0006987 is probably related to this same issue since failing to clear the data would gradually chew up available process memory.
(0025621)
orenh (administrator)
2014-03-27 23:54

Fixed in Git master: f360b68

The "SculptData" field is no longer serialized in the XML.

There was also discussion of releasing the memory in the 'SculptData' field after it's no longer needed, but this wasn't implemented. Perhaps some other time.
(0025624)
Mata Hari (reporter)
2014-03-28 04:25

Just wanted to add a comment here...

I applied git f360b68 this morning and tested a complete outfit change and the difference in time is utterly stunning! Completely blown away by how much of a difference this made. Thank you very much Orenh!

Further, I then attempted a tp from my region to a plaza while wearing a somewhat high poly count set of meshes (and the Plaza didn't already have it in region cache) and the tp went rapidly and flawlessly so this fix may also go a long way to resolving tp issues while wearing mesh (0006755)...I'll do some more testing and give feedback there.

- Issue History
Date Modified Username Field Change
2014-02-26 06:21 Mata Hari New Issue
2014-02-26 06:29 Mata Hari File Added: log of error working with mesh.txt
2014-02-26 06:29 Mata Hari Note Added: 0025320
2014-03-18 12:15 Mata Hari Note Added: 0025465
2014-03-18 12:16 Mata Hari Note Edited: 0025465 View Revisions
2014-03-25 05:51 Mata Hari Note Added: 0025579
2014-03-26 00:48 orenh Note Added: 0025582
2014-03-26 00:48 orenh File Added: unwear-mesh-attachment.log
2014-03-26 00:49 orenh File Added: unwear-mesh-attachment.txt
2014-03-26 00:49 orenh File Deleted: unwear-mesh-attachment.log
2014-03-26 00:49 orenh Note Edited: 0025582 View Revisions
2014-03-26 04:02 aiaustin Note Added: 0025583
2014-03-26 04:57 Mata Hari Note Added: 0025584
2014-03-26 05:38 Mata Hari Priority normal => high
2014-03-26 05:38 Mata Hari Severity minor => major
2014-03-26 05:38 Mata Hari Summary Unwearing mesh attachments very slow and generates [SynchronousObjectRequester] message => Unwearing mesh attachments very slow and generates [SynchronousObjectRequester] message IF mesh contains a script
2014-03-26 05:44 melanie Note Added: 0025586
2014-03-26 09:58 orenh Note Added: 0025590
2014-03-27 07:04 Mata Hari File Added: Mata mesh log.rar
2014-03-27 07:05 Mata Hari Note Added: 0025610
2014-03-27 07:07 Mata Hari Note Edited: 0025610 View Revisions
2014-03-27 07:10 Mata Hari Note Edited: 0025610 View Revisions
2014-03-27 07:14 Mata Hari File Added: sample mesh.rar
2014-03-27 07:15 Mata Hari Note Added: 0025611
2014-03-27 07:17 orenh Note Added: 0025612
2014-03-27 07:24 Mata Hari Note Added: 0025613
2014-03-27 07:27 orenh Note Edited: 0025612 View Revisions
2014-03-27 07:30 orenh Note Added: 0025614
2014-03-27 07:48 Mata Hari Note Added: 0025615
2014-03-27 07:53 Mata Hari File Added: Mata ini.rar
2014-03-27 07:53 Mata Hari File Deleted: Mata ini.rar
2014-03-27 07:54 Mata Hari File Added: Mata ini.rar
2014-03-27 07:55 Mata Hari Note Edited: 0025615 View Revisions
2014-03-27 08:40 orenh Note Added: 0025617
2014-03-27 08:50 Mata Hari Note Added: 0025618
2014-03-27 08:55 Mata Hari Note Edited: 0025618 View Revisions
2014-03-27 09:04 orenh Note Added: 0025619
2014-03-27 09:04 orenh Assigned To => orenh
2014-03-27 09:04 orenh Status new => assigned
2014-03-27 09:09 Mata Hari Note Added: 0025620
2014-03-27 09:23 Mata Hari Relationship added related to 0006987
2014-03-27 23:54 orenh Note Added: 0025621
2014-03-27 23:54 orenh Status assigned => resolved
2014-03-27 23:54 orenh Resolution open => fixed
2014-03-28 04:25 Mata Hari Note Added: 0025624
2014-03-28 04:25 Mata Hari Status resolved => patch feedback
2014-03-28 04:26 Mata Hari Status patch feedback => resolved
2014-03-28 04:26 Mata Hari Fixed in Version => master (dev code)
2014-07-29 13:43 chi11ken Status resolved => closed


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker