Measure runtime of a method handled by bukkit.event.Listener

Question

I need to accurately measure in ms (#.### ms), exactly how long a void method takes to run, without the measurement impacting the results.

Normally I would simply do something like:

long startTime = System.nanoTime();
methodToTime();
long endTime = System.nanoTime();

long duration = (endTime - startTime);  //divide by 1000000 to get milliseconds.

This won't work because my code never calls the method directly; it only defines it.

import org.bukkit.event.Listener;
import org.bukkit.event.EventHandler;
import org.bukkit.event.EventPriority;

public class BlockListener implements Listener {

    @EventHandler(priority = EventPriority.LOWEST, ignoreCancelled = true)
    public void onPlace(BlockPlaceEvent event) {

    //...
    }
}

In the context of certain methods in this Minecraft Bukkit server I'm working on, 1ms is significant, meaning I need high precision to measure and then optimize time-sensitive methods.

So, surely adding any code inside the method could affect the runtime of the method?

What is the best way to measure this? Please and thank you

Running Paper/Spigot with ProtocolLib (1.16.5)

score 1 · Answer 1 · answered Apr 18 '21 at 15:16

Performance measurement will always affect your performance, that's why it's I would suggest making this feature togglable. Based on this answer, calling System.nanoTime() two times per method will take approximately 200 CPU clock cycles, which is not a big overhead.

But after measuring the execution time, you need to save it somewhere or print a log. Usually, I/O operations are the most expensive, thus it's better to avoid blocking outputs in your method. For this purpose, you can utilize java.util.concurrent.BlockingQueue or other implementations of thread-safe pipes (like Disruptor or JCTools) and log captured results in separate daemon thread.

Implementation proposal

public class ListenerPerformanceAuditor implements Listener {

    private final BlockingQueue<Long> executionTimeQueue;
    private final Listener auditedListener;

    public ListenerPerformanceAuditor(
            Listener auditedListener,
            BlockingQueue<Long> executionTimeQueue
    ) {
        this.auditedListener = auditedListener;
        this.executionTimeQueue = executionTimeQueue;
    }

    public void onPlace(BlockPlaceEvent event) {
        long startTime = System.nanoTime();
        auditedListener.onPlace(event);
        long endTime = System.nanoTime();

        long duration = (endTime - startTime);  //divide by 1000000 to get milliseconds.
        if(!executionTimeQueue.offer(duration)) {
            // if measuring each and every request isn't necessary,
            // this block can be eliminated, otherwise add error handling logic
        }
    }
}

What about printing to stdout with println()? About how long does this take? Would it be similarly insignificant like with the delay from getting nanoTime inside the method? — DogeCode, Apr 18 '21 at 15:42
Printing to console performance is comparable with `ArrayBlockingQueue#offer` performance in single-threaded application, but `System.out.println` is a synchronized operation that may lead to performance degradation in a multi-threaded system when more than one threads try to write into console. Also, you can print directly in `ListenerPerformanceAuditor`, but in a thread pool, so no queue is needed and performance remains stable — geobreze, Apr 18 '21 at 16:12

Measure runtime of a method handled by bukkit.event.Listener

1 Answers1

Implementation proposal