Add a profiling mode to see what parts take up time

Author: Aeltumn

interfaces/src/main/kotlin/com/noxcrew/interfaces/interfaces/InterfaceProperties.kt

@@ -32,6 +32,9 @@ public open class InterfaceProperties<P : Pane> {
     /** The timeout to apply to all coroutines for this menu. */
     public var defaultTimeout: Duration = 2.5.seconds
 
+    /** Enables debug logs for time spent on various actions. */
+    public var debugRenderingTime: Boolean = false
+
     // --- CACHING / EFFICIENCY ---
     /** Whether to redraw the title when re-opening a menu. */
     public var redrawTitleOnReopen: Boolean = true
@@ -108,13 +111,15 @@ public open class InterfaceProperties<P : Pane> {
     /** Sets all values to their simple defaults. This is the default type! */
     public fun useSimpleDefaults() {
         redrawTitleOnReopen = true
+        alwaysReloadProperties = true
         defaultRefreshMode = RefreshMode.ALWAYS
         defaultBlockMode = BlockingMode.ALWAYS
     }
 
     /** Sets all values to support efficient caching of components and minimize automatic refreshes. */
     public fun useCachingDefaults() {
         redrawTitleOnReopen = false
+        alwaysReloadProperties = false
         defaultRefreshMode = RefreshMode.INITIAL
         defaultBlockMode = BlockingMode.INITIAL
     }

interfaces/src/main/kotlin/com/noxcrew/interfaces/menu/PlayerInventoryMenu.kt

@@ -7,32 +7,40 @@ import com.noxcrew.interfaces.exception.StandardInterfacesExceptionHandler
 import com.noxcrew.interfaces.interfaces.PlayerInterface
 import com.noxcrew.interfaces.interfaces.PlayerInterfaceBuilder
 import com.noxcrew.interfaces.interfaces.buildPlayerInterface
+import com.noxcrew.interfaces.utilities.InterfacesProfiler
 import com.noxcrew.interfaces.view.InterfaceView
 import com.noxcrew.interfaces.view.PlayerInterfaceView
 import org.bukkit.entity.Player
+import java.time.Instant
 
 /** The base for a menu that is applied on a player's whole inventory. */
 public abstract class PlayerInventoryMenu : BaseInventoryMenu {
     /** The exception handler to use for this menu. */
     public open val exceptionHandler: InterfacesExceptionHandler = StandardInterfacesExceptionHandler()
 
+    /** Enables debug logs for time spent on various actions. */
+    public open val debugRenderingTime: Boolean = false
+
     /** Configures the GUI for the given [player]. */
     protected abstract suspend fun PlayerInterfaceBuilder.configure(player: Player)
 
     /** Builds the menu. */
     protected open suspend fun buildMenu(player: Player): PlayerInterface = buildPlayerInterface {
         this@buildPlayerInterface.exceptionHandler = this@PlayerInventoryMenu.exceptionHandler
+        this@buildPlayerInterface.debugRenderingTime = this@PlayerInventoryMenu.debugRenderingTime
         configure(player)
     }
 
     override suspend fun open(player: Player, parent: InterfaceView?, reload: Boolean): PlayerInterfaceView? {
+        val start = Instant.now()
         val menu = exceptionHandler.execute(
             InterfacesExceptionContext(
                 player,
                 InterfacesOperation.BUILDING_PLAYER,
                 null,
             ),
         ) { buildMenu(player) } ?: return null
+        if (debugRenderingTime) InterfacesProfiler.logAbstract("building menu", start)
         return open(player, parent, menu, reload) as PlayerInterfaceView?
     }
 }

interfaces/src/main/kotlin/com/noxcrew/interfaces/menu/SimpleInventoryMenu.kt

@@ -7,21 +7,27 @@ import com.noxcrew.interfaces.exception.StandardInterfacesExceptionHandler
 import com.noxcrew.interfaces.interfaces.Interface
 import com.noxcrew.interfaces.interfaces.InterfaceBuilder
 import com.noxcrew.interfaces.pane.Pane
+import com.noxcrew.interfaces.utilities.InterfacesProfiler
 import com.noxcrew.interfaces.view.InterfaceView
 import org.bukkit.entity.Player
+import java.time.Instant
 
 /** The base for a simple built menu. */
 public abstract class SimpleInventoryMenu<B : InterfaceBuilder<out Pane, *>> : BaseInventoryMenu {
     /** The exception handler to use for this menu. */
     public open val exceptionHandler: InterfacesExceptionHandler = StandardInterfacesExceptionHandler()
 
+    /** Enables debug logs for time spent on various actions. */
+    public open val debugRenderingTime: Boolean = false
+
     /** Builds the interface for this type using [configure]. */
     protected abstract suspend fun build(player: Player, configure: suspend B.() -> Unit): Interface<*, *>
 
     /** Configures the GUI for the given [player]. */
     protected abstract suspend fun B.configure(player: Player)
 
     override suspend fun open(player: Player, parent: InterfaceView?, reload: Boolean): InterfaceView? {
+        val start = Instant.now()
         val menu = exceptionHandler.execute(
             InterfacesExceptionContext(
                 player,
@@ -31,10 +37,11 @@ public abstract class SimpleInventoryMenu<B : InterfaceBuilder<out Pane, *>> : B
         ) {
             build(player) {
                 this@build.exceptionHandler = this@SimpleInventoryMenu.exceptionHandler
+                this@build.debugRenderingTime = this@SimpleInventoryMenu.debugRenderingTime
                 configure(player)
             }
         } ?: return null
-
+        if (debugRenderingTime) InterfacesProfiler.logAbstract("building menu", start)
         return open(player, parent, menu, reload)
     }
 }

interfaces/src/main/kotlin/com/noxcrew/interfaces/utilities/InterfacesProfiler.kt

@@ -0,0 +1,36 @@
+package com.noxcrew.interfaces.utilities
+
+import com.noxcrew.interfaces.view.AbstractInterfaceView
+import org.slf4j.LoggerFactory
+import java.time.Duration
+import java.time.Instant
+import java.util.WeakHashMap
+import kotlin.time.toKotlinDuration
+
+/** Assists in profiling interfaces. */
+public object InterfacesProfiler {
+    private val logger = LoggerFactory.getLogger(InterfacesProfiler::class.java)
+
+    private val lastTimes = WeakHashMap<AbstractInterfaceView<*, *, *>, Instant>()
+
+    /** Logs the given [action] for [view]. */
+    public fun log(view: AbstractInterfaceView<*, *, *>, action: String) {
+        if (!view.builder.debugRenderingTime) return
+
+        val lastTime = lastTimes[view]
+        val message = StringBuilder()
+        message.append("Action `$action` has run for ${view.player.name}")
+        if (lastTime != null) {
+            val timeSinceLast = Duration.between(lastTime, Instant.now())
+            message.append(", took ${timeSinceLast.toKotlinDuration()}")
+        }
+        logger.info(message.toString())
+        lastTimes[view] = Instant.now()
+    }
+
+    /** Logs a general action that started at [start]. */
+    public fun logAbstract(action: String, start: Instant) {
+        val timeSinceLast = Duration.between(start, Instant.now())
+        logger.info("Action `$action` has run, took ${timeSinceLast.toKotlinDuration()}")
+    }
+}

interfaces/src/main/kotlin/com/noxcrew/interfaces/view/AbstractInterfaceView.kt

@@ -25,6 +25,7 @@ import com.noxcrew.interfaces.transform.BlockingMode
 import com.noxcrew.interfaces.transform.RefreshMode
 import com.noxcrew.interfaces.utilities.CollapsablePaneMap
 import com.noxcrew.interfaces.utilities.InterfacesCoroutineDetails
+import com.noxcrew.interfaces.utilities.InterfacesProfiler
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Job
 import kotlinx.coroutines.SupervisorJob
@@ -159,6 +160,9 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
         get() = if (::pane.isInitialized) pane else null
 
     init {
+        // Log to the profiler
+        InterfacesProfiler.log(this, "interface being constructed")
+
         // Determine for each trigger what transforms it updates
         val triggers = HashMultimap.create<Trigger, AppliedTransform<P>>()
         for (transform in builder.transforms) {
@@ -355,6 +359,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
     private suspend fun triggerProperties() {
         try {
             queueAllTriggers.set(true)
+            InterfacesProfiler.log(this, "starting to trigger properties")
             execute(
                 InterfacesExceptionContext(
                     player,
@@ -394,6 +399,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
         }
 
         // Either draw the entire interface or just re-render it
+        InterfacesProfiler.log(this, "starting rendering")
         if (firstPaint) {
             queuedTransforms.clear()
             redrawComplete()
@@ -426,6 +432,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
         }
 
         // Await to acquire the mutex before we start rendering
+        InterfacesProfiler.log(this, "starting re-rendering loop")
         paneMutex.lock()
         try {
             execute(
@@ -518,6 +525,8 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
 
     /** Processes all pending transforms. */
     private suspend fun processTransforms() {
+        InterfacesProfiler.log(this, "starting transform processing")
+
         while (pendingTransforms.isNotEmpty()) {
             // Go through all pending transforms one at a time until
             // we're fully done with all of them. Other threads may
@@ -548,6 +557,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
                     } finally {
                         paneMutex.unlock()
                     }
+                    InterfacesProfiler.log(this, "finished rendering transform")
                 }
             }
 
@@ -801,6 +811,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
         // Draw the contents of the inventory synchronously because
         // we don't want it to happen in between ticks and show
         // a half-finished inventory.
+        InterfacesProfiler.log(this, "ready to render sync")
         InterfacesListeners.INSTANCE.runSync {
             executeSync(
                 InterfacesExceptionContext(
@@ -824,6 +835,7 @@ public abstract class AbstractInterfaceView<I : InterfacesInventory, T : Interfa
                 val isOpen = isOpen()
                 drawPaneToInventory(drawNormalInventory = true, drawPlayerInventory = isOpen)
                 callback(createdInventory)
+                InterfacesProfiler.log(this, "finished rendering to inventory")
 
                 if (this is PlayerInterfaceView) {
                     // If this is a player inventory we can't update the inventory without