Incorrect block tick measurement

[LatvianModder]

These are the 2 pieces of code in question:

observable/common/src/main/java/observable/mixin/ServerLevelMixin.java

Lines 34 to 36 in 02206ce

	long start = System.nanoTime();
	state.tick(level, pos, random);
	Observable.INSTANCE.getPROFILER().processBlock(state, pos, level, System.nanoTime() - start);

observable/common/src/main/kotlin/observable/server/Profiler.kt

Lines 43 to 50 in 02206ce

	fun processBlock(blockState: BlockState, pos: BlockPos, level: Level, time: Long) {
	val blockMap = blockTimingsMap.getOrPut(level.dimension()) { HashMap() }
	val timingInfo = blockMap.getOrPut(pos) {
	TimingData(0, 0, HashSet(), blockState.block.descriptionId)
	}
	timingInfo.time += time
	timingInfo.ticks++
	}

Profiler adds all of TimingData setup creation (HashMaps, etc) in the same boat as state.tick().

The correct order of operations would be something along the lines of:

TimingData timingInfo = Observable.INSTANCE.getPROFILER().getTimingData(state, pos, level);
timingInfo.ticks++;
long start = System.nanoTime();
state.tick(level, pos, random);
timingInfo.time += System.nanoTime() - start;

Create timing data instance with all the info first, then measure start time, then run tick(), then add to timing info. The timingInfo.ticks++; could be at end, because its so trivial, but I still like to move it there.

[tasgon]

Profiler adds all of TimingData setup creation (HashMaps, etc) in the same boat as state.tick().

Are you sure about this? As far as I understand, expressions in function parameters are eagerly evaluated before the function is actually called, and the bytecode seems to reflect that:

However, you are right, it does seem that there are a few extra instructions being evaluated in there, so I'll try to optimize it further (e.g. getting a reference to the profiler instance on the stack before starting the timer, or maybe reordering the parameters to get those ALOADs after the second invocation of System.nanoTime()). I do worry that this may be heading into the realm of over-engineering, though. What do you think?

[LatvianModder]

In normal case, I would say overengineering/micro-optimizing is bad, but if its a profiler, go all the way 😛 Its also more about what happens inside processBlock, not in the mixin, especially both of those getOrPut calls. Which is why I would move all the "heavy" work before the start nano. We were testing block tick lag on our server and noticed that even basic blocks that shouldnt do anything had tick problems, which is why I checked the mod. I mostly just want to know if those blocks really are slow, if something is messing with block tick logic or if it really was observable

[tasgon]

In normal case, I would say overengineering/micro-optimizing is bad, but if its a profiler, go all the way 😛

Alright, I'll try to take care of those things soon, although,

Its also more about what happens inside processBlock, not in the mixin, especially both of those getOrPut calls.

I still don't quite understand how processBlock affects the timing data. Unless I'm reading the bytecode wrong, the total duration (that is, System.nanoTime() - start) is computed before processBlock is called, isn't it?

We were testing block tick lag on our server and noticed that even basic blocks that shouldnt do anything had tick problems

Also another note, if it seems that block tick can be excessive, note that by default tick times are not normalized, so block tick times will be computed only by the amount of time the ticks took to run divided by the amount of ticks the block ticked for (which is usually only ~1-2 ticks) instead of the number of ticks the profiler ran for, so it can seem that blocks/fluid ticks such as water flows are extremely excessive. You can change the behavior of this by clicking the 'Normalize' button in the settings window. Thinking about it now, maybe it would be better to have normalization on by default?

[LatvianModder]

Wait, no, you're right, wtf. I dont know why, but before I read it as System.nanoTime() - start being executed after all the map things, where timingInfo.time += time is. I think I assumed you pass the start time, not delta. False alarm, you can just close this now lol. Still not sure why something that should be 1-2 uS takes like 50 uS/t. The action it does (tick / entity) only happens every 3ish seconds so it shouldnt be that high for tick. But thats not related to Observable im pretty sure. Either minecraft being weird or my code.

[tasgon]

Alright, I'll close this, but is your concern that it's taking a constant 50 us/t throughout the entire profiling duration? Because if so, it's probably not. Did you try normalizing the profiling results?