jpcsupplies / Economy_mod

Basic Economy System for Space Engineers
13 stars 12 forks source link

Performance issues with Server Sim speed #100

Open midspace opened 8 years ago

midspace commented 8 years ago

I have done some initial investigation by adding some logging into the Buy and Sell code, and narrowed down the performance hit to the portion where the cargo are been interrogated.

I'll have to break down the code further to see if any one part of it is at more at fault. They could all be, or a couple could be, or just one.

The choices are to improve the performance of this code, or try and put it to the background (or both). The trouble is, some parts of the code must run on the main thread where it will affect Sim Speed regardless of what we do.

                        // Build list of all cargo blocks that player is attached to as pilot or passenger.
                        List<IMySlimBlock> cargoBlocks = new List<IMySlimBlock>();
                        var controllingCube = sellingPlayer.Controller.ControlledEntity as IMyCubeBlock;
                        if (controllingCube != null)
                        {
                            var grids = controllingCube.CubeGrid.GetAttachedGrids(AttachedGrids.Static);

                            var blocks = new List<IMySlimBlock>();
                            foreach (var grid in grids)
                            {
                                grid.GetBlocks(blocks, b => b != null
                                    && b.FatBlock != null
                                    && !b.FatBlock.BlockDefinition.TypeId.IsNull
                                    && b.FatBlock is IMyCargoContainer);

                                foreach (var block in blocks)
                                {
                                    var relation = block.FatBlock.GetUserRelationToOwner(sellingPlayer.PlayerID);
                                    if (relation != MyRelationsBetweenPlayerAndBlock.Enemies
                                        && relation != MyRelationsBetweenPlayerAndBlock.Neutral)
                                        cargoBlocks.Add(block);
                                }
                            }
                        }
midspace commented 8 years ago

The following is a sample of a server log running an offline game, with a complex world with about ~0.60 Sim speed. So it is complex. This is with the current codebase after the performance improvements.

As you can see, from start to finish, a buy action from the marketplace is ranging from <1 millisecond, to <5 milliseconds.

The <1 millisecond is very acceptable. but up to 5 milliseconds is not. I will have to consider moving the code to the background thread, but that will make the code more complex.

2015-12-20 15:54:16.061 - START - Message Serialization
2015-12-20 15:54:16.064 - END - Message Serialization
2015-12-20 15:54:16.064 - Received - MessageMarketItemValue
2015-12-20 15:54:16.066 - Value Request for 'MyObjectBuilder_Ingot:Uranium' from '76561197961224864'
2015-12-20 15:54:16.068 - SendMessageToPlayer 76561197961224864 ServerSide MessageClientTextMessage.
2015-12-20 15:54:16.097 - HandleMessage
2015-12-20 15:54:16.097 - START - Message Serialization
2015-12-20 15:54:16.100 - END - Message Serialization
2015-12-20 15:54:32.455 - HandleMessage
2015-12-20 15:54:32.455 - START - Message Serialization
2015-12-20 15:54:32.458 - END - Message Serialization
2015-12-20 15:54:32.458 - Received - MessageBuy
2015-12-20 15:54:32.464 - Action /Buy started by Steam Id '76561197961224864'.
2015-12-20 15:54:32.466 - Action /Buy finalizing by Steam Id '76561197961224864' -- adding to inventory.
2015-12-20 15:54:32.471 - SendMessageToPlayer 76561197961224864 ServerSide MessageClientTextMessage.
2015-12-20 15:54:32.471 - Action /Buy complete by Steam Id '76561197961224864' -- items bought.
2015-12-20 15:54:32.495 - HandleMessage
2015-12-20 15:54:32.495 - START - Message Serialization
2015-12-20 15:54:32.495 - END - Message Serialization
2015-12-20 15:54:40.779 - HandleMessage
2015-12-20 15:54:40.779 - START - Message Serialization
2015-12-20 15:54:40.780 - END - Message Serialization
2015-12-20 15:54:40.780 - Received - MessageBuy
2015-12-20 15:54:40.780 - Action /Buy started by Steam Id '76561197961224864'.
2015-12-20 15:54:40.780 - Action /Buy finalizing by Steam Id '76561197961224864' -- adding to inventory.
2015-12-20 15:54:40.793 - SendMessageToPlayer 76561197961224864 ServerSide MessageClientTextMessage.
2015-12-20 15:54:40.794 - Action /Buy complete by Steam Id '76561197961224864' -- items bought.
2015-12-20 15:54:40.822 - HandleMessage
2015-12-20 15:54:40.822 - START - Message Serialization
2015-12-20 15:54:40.822 - END - Message Serialization
2015-12-20 15:54:51.463 - HandleMessage
2015-12-20 15:54:51.463 - START - Message Serialization
2015-12-20 15:54:51.463 - END - Message Serialization
2015-12-20 15:54:51.463 - Received - MessageBuy
2015-12-20 15:54:51.463 - Action /Buy started by Steam Id '76561197961224864'.
2015-12-20 15:54:51.463 - Action /Buy finalizing by Steam Id '76561197961224864' -- adding to inventory.
2015-12-20 15:54:51.464 - SendMessageToPlayer 76561197961224864 ServerSide MessageClientTextMessage.
2015-12-20 15:54:51.464 - Action /Buy complete by Steam Id '76561197961224864' -- items bought.
2015-12-20 15:54:51.493 - HandleMessage
2015-12-20 15:54:51.493 - START - Message Serialization
2015-12-20 15:54:51.493 - END - Message Serialization
2015-12-20 15:55:08.203 - HandleMessage
2015-12-20 15:55:08.203 - START - Message Serialization
2015-12-20 15:55:08.203 - END - Message Serialization
2015-12-20 15:55:08.203 - Received - MessageBuy
2015-12-20 15:55:08.203 - Action /Buy started by Steam Id '76561197961224864'.
2015-12-20 15:55:08.203 - Action /Buy finalizing by Steam Id '76561197961224864' -- adding to inventory.
2015-12-20 15:55:08.203 - SendMessageToPlayer 76561197961224864 ServerSide MessageClientTextMessage.
2015-12-20 15:55:08.204 - Action /Buy complete by Steam Id '76561197961224864' -- items bought.
2015-12-20 15:55:08.227 - HandleMessage
jpcsupplies commented 8 years ago

any luck on the rest of the sim speed issues external to econ ? any of the other mods eating much sim?

I suppose the only way to test is save in the middle of a bunch of ships, exit map, and remove each mod one at a time while watching sim speed after you load the map each time..

I get the impression on maps with next to no mods tho its the game engine itself tho at the moment.

Server side sim makes no sense tho there an 8 core xeon behind our server, running at realtime priority. There should be minor sim issues even if our mods were inefficient.

midspace commented 8 years ago

We've been sorting through some performance issues with Admin Mod, but they are only evident when doing certain things when protection area is enabled.

The world has been helping me test issues with my Solar tracking mod also.

jpcsupplies commented 8 years ago

hmm only protection on ramblers is grind/weapon destruct turned off on the trade station the survey ship, and possibly one of zan or karnis ships, all the other protected objects have since been deleted. I dont use protect area just protected object.. surely that doesnt eat too much sim speed tho ? one is built into the scenario system the other.. im not sure how your anti-grind works there but i expect it just auto repairs or ignores grind attempts on station/ship ID X

midspace commented 8 years ago

Protected Areas were turned on accidently because of flag in the Admin mod. I've turned it off manually on the Ramblers server.

Anti Grind will only affect sim speed if someone attempts to grind a indestructable grid. It doesn't use much logic so affected sim speed should be negligible.

jpcsupplies commented 8 years ago

A player is concerned that something is econ is causing momentary lockups. I am not seeing issues like this except client side which should not hurt other players, and is very minor. But may be worth keeping an eye on.

Demolish50 commented 8 years ago

Your mod is generally heavily used on fountain core. I get momentary "lockups" but I do not believe it to be econ. I'm 99% sure of that.

jpcsupplies commented 8 years ago

I've been seeing momentary client lockups myself, doesn't appear to be economy mod either, i got the impression it was voxels loading on planets, and transitions between field of view states of the planet and asteroids as my distance to them changed.. I was travelling quite fast (up to 300ms) We run admin mod as well which logs economy command use and nobody was using anything at the time. A 2 second lockup is better than a CTD but still irritating.

jpcsupplies commented 8 years ago

@midspace I've noticed lately our sim speed is jumping between 0.08 and 0.30 ive managed to claw it up to the 20's by going around checking remote ships and floating objects and going on deleting sprees on really old, unpowered stuff owned by players who left, (that garbage cleanup should have removed anyway) which claws it back to the 0.20's but i cannot seem to find what is left slowing the game. My theorys are projectors, fly through welders, timers, PB's, planets or the fact our faction/chat/players list has about 1000 entries, only 20 or so are players who even still use the server - which would slow things significantly when players message each other in there.

Offline testing has not found anything obvious other than removing the 10 largest ships in space master brings us back over 0.50 sim.

I even started redesigning the survey ship to cut back on conveyors, and i may check out blue mining for the same given your observation that conveyor cubes are more laggy than tubes but i cant see much difference.

When i was hammering SESE i did notice dropping in a bunch of large industrial or moving part ships nearby pulls sim down pretty fast.. But i would think if they were outside of instance area that should be minimal effect.

Any thoughts? apparently there is a timing/metrics debug in the game but its off by default and ive no idea how it works anyway.

jpcsupplies commented 7 years ago

@midspace noticed the other day, the server sim seems to be taking an unusually large hit when buying selling or flipping blacklist items in the market lately. I don't think any code I altered is even in that area of the system. Must be something keen changed.. any ideas where the hit is coming from? (could be GC/memory leak issues too maybe.. in which case economy could be fine) not even sure where to start looking here :/