Trunk nightly

Fritz · Post by **Fritz** » Wed Jan 27, 2016 5:57 pm

You mean Griff_alloys_and_wreckage.oxz, yes? I have that installed, but have not seen any excessive spawning.

I haven't seen it until yesterday! But I was remembering wrongly: I just found that Griff's OXPs were inactive at the time, because I was sill testing the big debris issue with Spicy Hermits. So I have to correct myself - Griff's Wreckage can't have been the problem!

Here is the list of active OXPs taken from the log file:

Code: Select all

    ../AddOns/Basic-debug.oxp
    ../AddOns/Company Freighters.oxp
    ../AddOns/Cylon_Raider_Mk1_higher_detail_model_V1.01.oxp
    ../AddOns/DisplayReputation 1.3.oxp
    ../AddOns/Engine Sound FG 1.x.oxp
    ../AddOns/Escort Contracts 1.7.x.oxp
    ../AddOns/Fritz.oxp
    ../AddOns/Green Gecko XL.oxp
    ../AddOns/Hermit Memory.oxp
    ../AddOns/LogEvents.oxp
    ../AddOns/oolite.oxp.cim.comms-pack-a.oxz
    ../AddOns/oolite.oxp.FritzG.Navigation_Flashers.oxz
    ../AddOns/oolite.oxp.Norby.missile_booster.oxz
    ../AddOns/oolite.oxp.Norby.ReverseControl.oxz
    ../AddOns/oolite.oxp.smivs.aliens.oxz
    ../AddOns/oolite.oxp.spara.station_ads.oxz
    ../AddOns/oolite.oxp.superbatprime.Ship's_Cat.oxz
    ../AddOns/Python Gunship.oxp
    ../AddOns/Python S.oxp
    ../AddOns/ShipComparison.oxz
    ../AddOns/Shorter Ship Names.oxp
    ../AddOns/spicy_hermits.oxp
    ../AddOns/Star-jelly_v3.0.oxz
    ../AddOns/Stear9 Shipset noshaders.oxp
    ../AddOns/Synchronised Torus 1.x.oxp
    ../AddOns/XenonUI.oxp
    ../AddOns/XenonUIResourcesH.oxp

Not very helpful, I fear!

And that's the part of the log where it started to happen (a group of assassins (?) attacking a Cobra 3):

Code: Select all

22:09:27.606 [LogEvents]: Player got message from Cobra Mark III 3645 : We're being attacked by criminals! Please help!
22:09:34.196 [LogEvents]: Player lost lock on Asteroid 18322
22:09:38.516 [LogEvents]: Player targeted Cobra Mark III 3645 who has 256 energy
22:09:49.541 [LogEvents]: Player lost lock on Cobra Mark III 3645
22:09:52.161 [LogEvents]: Player targeted Mussurana 15282 who has 712 energy
22:09:57.215 [LogEvents]: Player lost lock on Mussurana 15282
22:10:01.152 [LogEvents]: Player targeted Krait 17432 who has 762 energy
22:10:04.555 [LogEvents]: Player lost lock on Krait 17432
22:10:04.555 [LogEvents]: Player targeted Cobra Mark III 14362 who has 256 energy
22:10:14.614 [LogEvents]: Player lost lock on Cobra Mark III 14362
22:10:16.382 [LogEvents]: Player targeted Fer-de-Lance 32060 who has 662 energy
22:10:29.977 [LogEvents]: Player got message from Krait 17432 : Still on the Orange Mover…
22:10:30.227 [LogEvents]: Player lost lock on Fer-de-Lance 32060
22:10:33.980 [LogEvents]: Player targeted Cobra Mark III 14362 who has 256 energy
22:10:35.265 [LogEvents]: Player got message from Cobra Mark III 3645 : Someone must be in range. Please help!
22:10:40.269 [LogEvents]: Player lost lock on Cobra Mark III 14362
22:10:41.019 [LogEvents]: Player targeted Cobra Mark III 3645 who has 256 energy
22:10:43.472 [LogEvents]: Player lost lock on Cobra Mark III 3645
22:10:45.190 [LogEvents]: Player targeted Mussurana 15282 who has 712 energy
22:10:55.582 [LogEvents]: Player got message from Cobra Mark III 3645 : Good shot, Polaris! I owe you a drink when we reach the station.
22:10:55.583 [LogEvents]: Player attacked Mussurana 15282 who has 700 energy
22:10:55.593 [LogEvents]: Player alert condition changed from 2 to 3
22:10:56.769 [LogEvents]: Player got message from Fer-de-Lance 32060 : Break and attack!

If I remember correctly, the frame rate went down between 22:10:43.472 and 22:10:45.190 or (more probably) between 22:10:45.190 and 22:10:55.582.

I won't try to reproduce the error without these OXPs because it is possible that it was a random event that won't occur again for weeks or months, if ever. But I'll come back to this if it happens again.

Fritz · Post by **Fritz** » Wed Jan 27, 2016 8:53 pm

Let's forget this for the moment. Considering what I described in the Spicy Hermit thread, we can assume that somewhere in the system one of these spectacular metal plate explosions went off. If this has increased the entity count to more than 2048, the "weird things" another_commander mentioned could have happened. This could explain why the entity count didn't simply go down again, as with the explosions I witnessed.

Post by **another_commander** » Thu Jan 28, 2016 7:15 am

Fritz wrote:
Let's forget this for the moment. Considering what I described in the Spicy Hermit thread, we can assume that somewhere in the system one of these spectacular metal plate explosions went off. If this has increased the entity count to more than 2048, the "weird things" another_commander mentioned could have happened. This could explain why the entity count didn't simply go down again, as with the explosions I witnessed.

I don't think that this is what happened, because when entities go over 2048 you get a message in the log along the lines of "Universe is full", so you know that it happened.

There is one thing you could try to do if this happens again and you are on trunk: As soon as you see the frame rate dropping and the entities count increasing to unnatural levels, pause the game and press "0" (zero) while paused. This will dump all current universe entities in existence to the log file and might provide a hint as to what exactly those too many entities might be.

spara · Post by **spara** » Thu Jan 28, 2016 11:38 am

I can confirm Fritz's report. Something funny is going on with scaled models. I took all OXPs out, created this shipdata

Code: Select all

{
{
	"alloy_test" = {
		like_ship = "oolite_template_alloy";
		model_scale_factor = 100;
		roles = "alloy_test";
	};
}

started the game and launched. From console I did this

Code: Select all

system.addShips("alloy_test", 1, player.ship, 1E3);
system.addShips("alloy", 10, player.ship, 1E3);

and started shooting alloys. The results were spectacular, literally. I ran this test a few times and the anomalies seem to happen only if the scaled alloy is the first alloy spawned.

So if you spawn a normal alloy first, then the gargantual, all is ok. The other way around messes things up.

Post by **another_commander** » Thu Jan 28, 2016 1:33 pm

I think I've got it. Core bug confirmed and it is cache related, which is always a royal b***h to deal with...

To replicate: Use spara's shipdata.plist entry and shift-start Oolite, then launch from Lave. Using the debug console, spawn one normal alloy and take note of its mass:

:spawn [alloy]

T.mass

The T is just a console shortcut, referring to the last entity that was spawned, in our case, a normal alloy. Now, spawn a test alloy:

:spawn [alloy_test]

T.mass

You will find that the mass reported is the same for both alloys, despite the fact that one is 100 times bigger than the other. But we are not over yet. Try this now. Shift-restart Oolite again and this time spawn the big one first, then the normal one:

:spawn [alloy_test]

T.mass

:spawn [alloy]

T.mass

This time, a huge number for mass is reported for both cases. So, what is going on?

Well, the problem is that Oolite is pulling information about the model mesh and its associated octree, which are used for volume and mass calculations, from the cache. The cache has only one mesh entry for alloy, referring to the model name "alloy.dat" (btw, I was using the old alloy model, just to be sure that nothing weird is caused by the new one). So, whatever mesh data was written to the cache first, is what was going to be read in subsequent calls for alloys. If you had spawned a normal alloy first, you would have a normal alloy mesh and octree, if you had spawned the big one first, the cache would have a huge mesh and octree calculated for it and that's what it was going to use, even if you spawned a normal alloy or an alloy with a different scale factor. That's why in some cases there were awesome explosions happening with alloys, because their mass was something like five times the mass of a Cobra III. This also explains the notable FPS drops, because if a huge mass alloy is destroyed, it will probably spawn other alloys, which, if huge enough, will spawn others, etc. etc. - universe full.

I believe the solution here would be to make it so that the game marks octrees generated using different scale factors as different cache entries. I've experimented a bit with marking each mesh in the cache with the convention "modelname.dat-X", where X is the scale factor in use, rather than the "modelname.dat" which is what we have now. It seems to work, but I would like to test it more before sending the change in. Cache changes are not to be taken lightly.

Stand by for a test executable later today or tomorrow and if you decide to use it to test, make sure you backup your important game files first.

Fritz · Post by **Fritz** » Thu Jan 28, 2016 2:06 pm

Thank you for the explanation! A big mass would also explain why the plates could cause significant damage when hit, and why the fuel scoop "force field" was to weak to attract them. I found that there is a significant difference between scooping cargo pods, Thargons, and asteroid splinters, which are probably mass related too.

Post by **another_commander** » Thu Jan 28, 2016 4:35 pm

Cache Test exe (corresponding to rev.09c7781) for 64-bit Windows is up:
https://drive.google.com/file/d/0BwG6R5 ... sp=sharing

Every time a mesh is requested, it logs its cache status and reports back if needed. If the required mesh is found in the cache, you will see only a report that it is looking for it. If the mesh is not in cache, you should see another line immediately below the first, stating that it has written the mesh in cache. Example log extract, where oolite_alloy.dat-1.000, oolite_alloy.dat-5.000: and oolite_alloy.dat-50.000 are three alloy type meshes, with scale factors 1.0 (normal), 5.0 and 50.0 respectively.

Latest.log wrote:
17:16:54.140 [octree.cache.read]: Trying to read octree for mesh oolite_adder.dat-1.000 from cache.
17:16:54.148 [octree.cache.read]: Trying to read octree for mesh oolite_mamba.dat-1.000 from cache.
17:16:54.158 [octree.cache.read]: Trying to read octree for mesh oolite_moray.dat-1.000 from cache.
17:16:54.166 [octree.cache.read]: Trying to read octree for mesh oolite_moray.dat-1.000 from cache.
17:16:54.196 [octree.cache.read]: Trying to read octree for mesh oolite_ferdelance.dat-1.000 from cache.
17:16:54.203 [octree.cache.write]: Writing octree for mesh oolite_ferdelance.dat-1.000 in cache.
17:16:54.222 [octree.cache.read]: Trying to read octree for mesh oolite_cobra3.dat-1.000 from cache.
17:16:54.419 [octree.cache.read]: Trying to read octree for mesh oolite_cobramk1.dat-1.000 from cache.
17:16:54.764 [octree.cache.read]: Trying to read octree for mesh oolite_transporter.dat-1.000 from cache.
17:16:54.766 [octree.cache.write]: Writing octree for mesh oolite_transporter.dat-1.000 in cache.
17:16:54.873 [octree.cache.read]: Trying to read octree for mesh oolite_worm.dat-1.000 from cache.
17:16:54.878 [octree.cache.write]: Writing octree for mesh oolite_worm.dat-1.000 in cache.
17:17:02.273 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-1.000 from cache.
17:17:02.278 [octree.cache.write]: Writing octree for mesh oolite_alloy.dat-1.000 in cache.
17:17:04.573 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-50.000 from cache.
17:17:04.575 [octree.cache.write]: Writing octree for mesh oolite_alloy.dat-50.000 in cache.
17:17:06.965 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-1.000 from cache.
17:17:10.586 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-5.000 from cache.
17:17:10.587 [octree.cache.write]: Writing octree for mesh oolite_alloy.dat-5.000 in cache.
17:17:11.766 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-5.000 from cache.
17:17:13.093 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-50.000 from cache.
17:17:16.679 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-1.000 from cache.
17:17:26.503 [octree.cache.read]: Trying to read octree for mesh oolite_shuttle.dat-1.000 from cache.
17:17:26.552 [octree.cache.write]: Writing octree for mesh oolite_shuttle.dat-1.000 in cache.

Please test and report back in case of problems. Try to check also memory usage and potential performance impact (which I don't expect to have, but hey).
.

Website · Post by **Cody** » Thu Jan 28, 2016 4:38 pm

As usual, I presume that .exe can be dropped into my trunk nightly install, yes?

Post by **another_commander** » Thu Jan 28, 2016 4:39 pm

Cody wrote:
As usual, I presume that .exe can be dropped into my trunk nightly install, yes?

Yup, just make sure to have the latest nightly revision just to be on the safe side.

Oh, and Shift-restart!

Fritz · Post by **Fritz** » Thu Jan 28, 2016 5:24 pm

Tested it in "real life", and the metal plates / hermit doors seem to be handled correctly:

Code: Select all

// first abandoned hermit spawned:
17:54:07.338 [octree.cache.read]: Trying to read octree for mesh oolite_rock_hermit.dat-1.000 from cache.
17:54:07.369 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-25.000 from cache.
17:54:07.371 [octree.cache.write]: Writing octree for mesh oolite_alloy.dat-25.000 in cache.
// second abandoned hermit spawned:
17:54:07.397 [octree.cache.read]: Trying to read octree for mesh oolite_rock_hermit.dat-1.000 from cache.
17:54:07.401 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-25.000 from cache.
// first kill with metal fragment:
17:55:21.578 [LogEvents]: Player killed Moray Star Boat 26098 with energy damage
17:55:21.587 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-1.000 from cache.
17:55:21.587 [octree.cache.write]: Writing octree for mesh oolite_alloy.dat-1.000 in cache.
// second kill with metal fragment:
17:57:47.571 [LogEvents]: Player killed Krait 11778 with energy damage
17:57:47.578 [octree.cache.read]: Trying to read octree for mesh oolite_alloy.dat-1.000 from cache.

But wreckage could be a problem because it comes in random sizes. Size 1 seems to come more often, but otherwise the cache is relatively useless. Example:

Code: Select all

17:57:47.405 [octree.cache.read]: Trying to read octree for mesh wreck1.dat-0.069 from cache.
17:57:47.406 [octree.cache.write]: Writing octree for mesh wreck1.dat-0.069 in cache.
17:57:47.489 [octree.cache.read]: Trying to read octree for mesh wreck1.dat-1.000 from cache.
17:57:47.493 [octree.cache.read]: Trying to read octree for mesh wreck1.dat-0.070 from cache.
17:57:47.493 [octree.cache.write]: Writing octree for mesh wreck1.dat-0.070 in cache.

Perhaps rounding the random size or the "cache key" to 1 decimal could be a solution.

Website · Post by **Cody** » Thu Jan 28, 2016 6:27 pm

Memory usage seems normal (~1.4GB) and no performance hit that I can see (running all Griff's stuff).
Got a log if required (unlikely) - but I can't see the wood for the octrees! <grins>

Fritz · Post by **Fritz** » Thu Jan 28, 2016 6:52 pm

Yes, if there is any impact on performance, it is caused by the log!

Commander Smivs · Post by **Smivs** » Thu Jan 28, 2016 7:23 pm

That wood be it!

Website · Post by **Cody** » Thu Jan 28, 2016 7:35 pm

<chortles> Hyper-bole!

My OXP's · Post by **phkb** » Fri Jan 29, 2016 12:41 am

I can't believe we've branched out to wordplay.

Oolite Bulletins

Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly

Re: Trunk nightly