Large crafting order causes server overload.

[tivec]

Issue description:

I set up a crafting order to make 32 64k disks with all of their prerequisites. Each processor type and its prereq is created in a solderer of its own with four speed upgrades. The crafters do not have speed upgrades.

What happens:

Can't keep up! Did the system time change, or is the server overloaded? Running 4488ms behind, skipping 89 tick(s).

http://i.imgur.com/kjoeatC.png

Once crafting finishes, the server then returns to normal operations.

My machine comfortably runs a server and a client at the same time (32gb ram, i7-4770k, fast disks), and the only times I usually get this kind of error is during extreme world gen.

What you expected to happen:

Server continues running fine even with a large crafting order.

Steps to reproduce:

1. Set up recipes for each processor type in a solderer of its own.
2. Set up recipes for each storage part and a 64k storage disk
3. Request a craft of 32 processes.
4. Watch server log.

   Version (Make sure you are on the latest version before reporting):

   • Minecraft: 1.10.2
   • Forge: 12.18.2.2112
   • Refined Storage: 1.2-beta2

Does this issue occur on a server? [yes/no] Yes

If a (crash)log is relevant for this issue, link it here:

See screenshot, there are no errors noticeable in the log.

[RealGrep]

I wonder if the solution here (other than optimizing further, if possible) is to limit the amount of time per tick it will use. Unless it's O(1) constant time, this will always end up being a problem for a sufficiently large crafting order. Just a thought.

[tivec]

I don't really know how the code is set up, but for this particular crafting order, it had to craft a lot of things in some solderers. A thought just struck me, what if it is trying to check the inventory in the target machine and the query takes longer than expected?

I mean, it doesn't seem to happen if I choose to craft say, 1k wooden planks. It will happily just chug along. It does seem to happen on larger orders with a lot of components and using sub machines. The 64k disks has a pretty hefty recurse and most of them are made in machines, no?

[raoulvdberge]

@tivec What would really help is providing a NPS file (profiling snapshot) from VisualVM. Then we see immediately what is causing the issue.

[tivec]

I'll see what I can do! Give me a few minutes.

[RealGrep]

One good way, I've found, is install http://files.player.to/sampler-1.66.jar . Then you can /sampler start and /sampler stop while it's lagging. Then a simple /sampler export [name of exported nps file here] will write out the .nps file that can be read with VisualVM. In case you're looking for a good way to do it. EDIT: Link to the full thread: http://forum.industrial-craft.net/index.php?page=Thread&threadID=10820

[tivec]

Ah yes, that's excellent. I'll get it running on the server immediately.

[utoc]

I'm seeing this same issue as mentioned above except to add to mine: Its also causing the server watchdog to kick in and crash the server.

Crash report: http://pastebin.com/etH8wGJB Sampler report: http://bbqsauce.terron.com/refinedstorage/crafting.nps

The crafting being done here was via external means and this seems like the root of the issue in my case. The job brought the server down to 4TPS, for 1k TNT

EDIT: The NPS above is from opening the crafting monitor GUI while the job was trying to run.

[tivec]

Here's my sampler report, I started the same process (32 disks) and let it run for a minute or so with frequent "can't keep up" messages. I then stopped the crafting process and exported the sample. Hope it helps!

crafting-sample.zip

Edit: If you want a longer sample, I can leave it running for a bit longer.

[utoc]

Dim 0 : Mean tick time: 723.094 ms. Mean TPS: 1.383

This sample file was for 40 seconds for the crafting of 1000 TNT (leftover from the previous testing crash)

Sample file: http://bbqsauce.terron.com/refinedstorage/crafting1.nps Screenshot from visualvm: http://i.imgur.com/TA69dVD.png

[way2muchnoise]

There seems be lots of places left where I can optimise :D Most of those are easily O(n²) or more.

[way2muchnoise]

@utoc What pattern setup do you have for that TNT?

[brad18]

@way2muchnoise It's my crafting setup. I have a crafter facing into a chest which then feeds items into a bank of mekanism crushers which then export to a chest with an importer connected to it. Inside the crafter I have a recipe for cobble-gravel,gravel-sand and flint-gunpowder. Inside a normal crafter, I have a recipe for 3 gravel-flint. When I set up say a 1k crafting job, I get roughly a 3-5 second lag before it opens the confirmation screen with the number of items etc. Then once I click start, the tps plummets immediately. I can get pictures of the setup if you wish.

Also, not sure if you want a seperate report for this. I've noticed that the system is not tracking inputted items correctly. Say I set up a job for 128 sand via the crushers, it will craft the 128 sand but the crafting monitor will say something like 124 sand remaining and get stuck like that.

[raoulvdberge]

@brad18 What is a 3-5 lag?

[raoulvdberge]

@utoc Were you running any other crafting tasks at the same time while running that TNT autocrafting?

[brad18]

Nope, it was just the tnt. Also I edited my previous message, its 3-5 second lag.

[utoc]

@raoulvdberge - @brad18 is the one with the crafting setup. See his response above; sorry for the confusion, I maintain the pack and he is insistent on being about to craft a lot of TNT ;)

[Towsty]

Crafting 4 64k storage cells

RS 1.2 Beta 3

The majority of it seems to be here:

[way2muchnoise]

I just rewrote a lot of things in 30f0ccd7f2c406da294f90b8b040e5ff57e71a0a . @raoulvdberge will post a little test build soon™ for you guys to test.

[raoulvdberge]

Can you guys try out this build? Rename .zip to .jar

refinedstorage-1.2-beta4-testing.zip

[utoc]

SIGNIFICANT improvement. Well done! We went from 20TPS to an average of 19TPS; In the previous Beta 2, we dropped to 4TPS.

EDIT: Fixed for you way2 ;)

Here is a two minute sample during the crafting of 1K TNT: http://bbqsauce.terron.com/refinedstorage/crafting2.nps

For grins, we tried 100K TNT because who doesn't need that much TNT lying about. The poor little thing struggled; we got down to 18TPS but @brad18 claimed the most lag occured when he opened the crafting monitor GUI. Sampling here: http://bbqsauce.terron.com/refinedstorage/crafting3.nps

Additionally, incoming items from external crafting aren't tracking accurately, do you guys want a separate issue on that?

EDIT: to clarify, we believe all the lag on the 100K crafting job comes from the crafting monitor GUI. If the GUI isn't open, we don't notice a TPS increase.

[raoulvdberge]

Additionally, incoming items from external crafting aren't tracking accurately, do you guys want a separate issue on that?

Yes please!

[Towsty]

Tested crafting 10 64k cells, everything went fine. No real noticeable drop in TPS but when you measure it it still drops a tad as @utoc mentioned. Great improvement!

[way2muchnoise]

We went from 20TPS to an average of 19TPS whereas we had 4TPS before.

This sentence seems wrong but hey, I'll take it :D

[tivec]

I will give the test build a shot a little later today.

[tivec]

Oh wow, that is some impressive increase in performance. Not a single stutter for me, and TPS stayed at 20 throughout crafting 32 64k ells. I can approve of this patch 👍

[way2muchnoise]

Everybody seems happy, so I'll close this.

[Yadokingu]

Is this already implemented in 1.2.8? Because I still get massive lag (making the game unplayable) when trying to craft 3000 vibrant capacitor banks (which I know may be a bit excessive, but I'd still like to do it). It's already pretty bad at around 500 though.

Log: http://paste.feed-the-beast.com/view/5a1e56bf (missed ticks are on the bottom)

[way2muchnoise]

@Yadokingu that is related to #678