False Positive with Refined Storage External Storage

[Darkere]

Description:

We were recently looking into server lag and found that the Refined Storage External Storage increase the event bus times by about 2ms each. After some more profiling, however, I was not able to pinpoint the issue with other profiling options.

Only after running both laggoggles and Sampler at the same time was I able to reproduce it.

Here are some samples: Without laggoggles: https://www.dropbox.com/s/4rv0318675embwx/checkwithoutlaggoggles.nps?dl=0

With running laggoggles inbetween: https://www.dropbox.com/s/jiw448kjiywbc0v/checkwithlaggoggles.nps?dl=0

In particular this is the part I am concerned about:

How to reproduce:

1. Start up ATM3:Remix
2. place down an external storage on a chest and a creative controller for testing
3. run laggogles

Other notes:

What might end up helping with tracking this down is the fact that this does not happen on a test game that has just Refined Storage and Laggoggles installed, which makes me think it might be some special handling for another mod that causes this.

Relevant RS issue https://github.com/raoulvdberge/refinedstorage/issues/2034

[TerminatorNL]

I am very confused. It seems that an event was triggered on the Forge Event bus, and LagGoggles is simply profiling it.

I'll look into this some more tomorrow...

Thank you for your detailed report.

[TerminatorNL]

After some more digging, I think I figured it out:

CORRECT ME IF I AM WRONG!

RefinedStorage copies every item on external storage devices using the seemingly innocent method: copy() on itemstacks.

Leading to this:

    public ItemStack(Item itemIn, int amount, int meta, @Nullable NBTTagCompound capNBT)
    {
        this.capNBT = capNBT;
        this.item = itemIn;
        this.itemDamage = meta;
        this.stackSize = amount;

        if (this.itemDamage < 0)
        {
            this.itemDamage = 0;
        }

        this.updateEmptyState();
        this.forgeInit();
    }

Leading to:

    /**
     * Set up forge's ItemStack additions.
     */
    private void forgeInit()
    {
        Item item = getItemRaw();
        if (item != null)
        {
            this.delegate = item.delegate;
            net.minecraftforge.common.capabilities.ICapabilityProvider provider = item.initCapabilities(this, this.capNBT);
            this.capabilities = net.minecraftforge.event.ForgeEventFactory.gatherCapabilities(this, provider);
            if (this.capNBT != null && this.capabilities != null) this.capabilities.deserializeNBT(this.capNBT);
        }
    }

Leading to...

    @Nullable
    public static CapabilityDispatcher gatherCapabilities(ItemStack stack, ICapabilityProvider parent)
    {
        return gatherCapabilities(new AttachCapabilitiesEvent<ItemStack>(ItemStack.class, stack), parent);
    }

Leading to...

    @Nullable
    private static CapabilityDispatcher gatherCapabilities(AttachCapabilitiesEvent<?> event, @Nullable ICapabilityProvider parent)
    {
        MinecraftForge.EVENT_BUS.post(event);
        return event.getCapabilities().size() > 0 || parent != null ? new CapabilityDispatcher(event.getCapabilities(), parent) : null;
    }

And there you have it! A second event being fired for every ItemStack being copied. LagGoggles wraps this event during profiling, which probably causes alot of lag when both refined storage and LagGoggles are installed at the same time, and LagGoggles is profiling. This explains LagGoggles being on the radar in VisualVM.

My suggestion is to stop copying all external ItemStacks every tick @raoulvdberge, but that's all up to you.

I think this information should be sufficient. If you have more questions, simply continue this thread.

[Darkere]

Oh wow, thank you so much for your help. Still got some questions though.

I still wonder why this doesn't happen with just RS and laggoggles installed.

Because the gatherCapabilities(ItemStack stack, ICapabilityProvider parent) doesn't appear to cause another call that actually fires the event in that case.

Although me not knowing how sampler/visualvm works I could just be completely wrong.

Link to that test: https://www.dropbox.com/s/4uf3cbydn3vnoj6/laggooglestest2.nps?dl=0

[TerminatorNL]

It should fire an event, keep in mind that LagGoggles only causes significant overhead on events if the profiler is enabled. If the profiler is not enabled, all code concerning profiling and extracting data is disabled.

Circling back to your question:

I still wonder why this doesn't happen with just RS and laggoggles installed.

I suspect this only happens when LagGoggles is actively profiling, you can try running sampler when:

1. You have LagGoggles actively profiling.
2. You don't have LagGoggles actively profiling.

There should be a performance impact when LagGoggles is actively profiling, but LagGoggles isn't running 24/7, and should not be your main cause of TPS drops.

Also, can I take a moment to say that I'm happy with these detailed reports? It's nice to see people use a more advanced profiling tool to help track down a cpu hog!

[Darkere]

I suppose I should have clarified that the initial reason for making this issue was that it only happens while LagGoggles is profiling.

I see the point in making a comparison though.

This is from my test game just RS and LagGoggles.

Sampler report while running LagGoggles profiling: https://www.dropbox.com/s/wonsyn137juevs2/WithLGProfiling.nps?dl=0 Sampler report without running profiling: https://www.dropbox.com/s/uswohyckuyh5ets/noLGprofiling2.nps?dl=0

[TerminatorNL]

Aha! I see what you're after now!

I'll account for this in the rewrite, the time spent on this event is unfair, because other mods can hook in on events fired during this event, which makes LagGoggles effectively count double the amount of time spent. I guess you could say this is a false positive on LagGoggles' side.