diff --git a/src/main/java/ch/njol/skript/SkriptEventHandler.java b/src/main/java/ch/njol/skript/SkriptEventHandler.java index 40e650da25a..7da235a6a1a 100644 --- a/src/main/java/ch/njol/skript/SkriptEventHandler.java +++ b/src/main/java/ch/njol/skript/SkriptEventHandler.java @@ -2,6 +2,8 @@ import ch.njol.skript.lang.SkriptEvent; import ch.njol.skript.lang.Trigger; +import ch.njol.skript.timings.Profiler; +import ch.njol.skript.timings.ProfilerAPI; import ch.njol.skript.timings.SkriptTimings; import ch.njol.skript.util.Task; import com.google.common.collect.ArrayListMultimap; @@ -162,8 +164,17 @@ private static void execute(Trigger trigger, Event event) { Runnable execute = () -> { logTriggerStart(trigger); Object timing = SkriptTimings.start(trigger.getDebugLabel()); + + boolean skipProfiling = ProfilerAPI.isFiringProfilerEvent.get(); + Profiler profiler = skipProfiling ? null : ProfilerAPI.start(trigger.getDebugLabel()); + trigger.execute(event); SkriptTimings.stop(timing); + + if (!skipProfiling) { + ProfilerAPI.stop(profiler); + } + logTriggerEnd(trigger); }; diff --git a/src/main/java/ch/njol/skript/command/ScriptCommand.java b/src/main/java/ch/njol/skript/command/ScriptCommand.java index 48d6c01dbbc..31de74ec2bb 100644 --- a/src/main/java/ch/njol/skript/command/ScriptCommand.java +++ b/src/main/java/ch/njol/skript/command/ScriptCommand.java @@ -205,7 +205,9 @@ public ScriptCommand( this.arguments = arguments; trigger = new Trigger(script, "command /" + name, new SimpleEvent(), ScriptLoader.loadItems(node)); - trigger.setLineNumber(node.getLine()); + int lineNumber = node.getLine(); + trigger.setLineNumber(lineNumber); + trigger.setDebugLabel(script.nameAndPath() + ".sk: line " + lineNumber + " part of command /" + name); bukkitCommand = setupBukkitCommand(); } diff --git a/src/main/java/ch/njol/skript/effects/Delay.java b/src/main/java/ch/njol/skript/effects/Delay.java index 72e1a0dd786..86d05670b5a 100644 --- a/src/main/java/ch/njol/skript/effects/Delay.java +++ b/src/main/java/ch/njol/skript/effects/Delay.java @@ -11,6 +11,8 @@ import ch.njol.skript.lang.SkriptParser.ParseResult; import ch.njol.skript.lang.Trigger; import ch.njol.skript.lang.TriggerItem; +import ch.njol.skript.timings.Profiler; +import ch.njol.skript.timings.ProfilerAPI; import ch.njol.skript.timings.SkriptTimings; import ch.njol.skript.util.Timespan; import ch.njol.skript.variables.Variables; @@ -80,6 +82,14 @@ protected TriggerItem walk(Event event) { Variables.setLocalVariables(event, localVars); Object timing = null; // Timings reference must be kept so that it can be stopped after TriggerItem execution + Profiler profiler = null; + + if (ProfilerAPI.enabled()) { + Trigger trigger = getTrigger(); + if (trigger != null) + profiler = ProfilerAPI.start(trigger.getDebugLabel()); + } + if (SkriptTimings.enabled()) { // getTrigger call is not free, do it only if we must Trigger trigger = getTrigger(); if (trigger != null) @@ -90,6 +100,7 @@ protected TriggerItem walk(Event event) { Variables.removeLocals(event); // Clean up local vars, we may be exiting now SkriptTimings.stop(timing); // Stop timing if it was even started + ProfilerAPI.stop(profiler); }, Math.max(duration.getAs(Timespan.TimePeriod.TICK), 1)); // Minimum delay is one tick, less than it is useless! } return null; diff --git a/src/main/java/ch/njol/skript/effects/EffTeleport.java b/src/main/java/ch/njol/skript/effects/EffTeleport.java index 1dc3fe781b4..5aae44fda8e 100644 --- a/src/main/java/ch/njol/skript/effects/EffTeleport.java +++ b/src/main/java/ch/njol/skript/effects/EffTeleport.java @@ -6,6 +6,8 @@ import ch.njol.skript.lang.*; import ch.njol.skript.lang.SkriptParser.ParseResult; import ch.njol.skript.sections.EffSecSpawn.SpawnEvent; +import ch.njol.skript.timings.Profiler; +import ch.njol.skript.timings.ProfilerAPI; import ch.njol.skript.timings.SkriptTimings; import ch.njol.skript.util.Direction; import ch.njol.skript.variables.Variables; @@ -150,6 +152,7 @@ public boolean init(Expression[] exprs, int matchedPattern, Kleenean isDelaye // Continue the rest of the trigger if there is one Object timing = null; + Profiler profiler = null; if (next != null) { if (SkriptTimings.enabled()) { Trigger trigger = getTrigger(); @@ -158,10 +161,18 @@ public boolean init(Expression[] exprs, int matchedPattern, Kleenean isDelaye } } + if (ProfilerAPI.enabled()) { + Trigger trigger = getTrigger(); + if (trigger != null) { + profiler = ProfilerAPI.start(trigger.getDebugLabel()); + } + } + TriggerItem.walk(next, event); } Variables.removeLocals(event); // Clean up local vars, we may be exiting now SkriptTimings.stop(timing); + ProfilerAPI.stop(profiler); }); return null; } diff --git a/src/main/java/ch/njol/skript/events/EvtProfileEvent.java b/src/main/java/ch/njol/skript/events/EvtProfileEvent.java new file mode 100644 index 00000000000..539fd642ea6 --- /dev/null +++ b/src/main/java/ch/njol/skript/events/EvtProfileEvent.java @@ -0,0 +1,53 @@ +package ch.njol.skript.events; + +import ch.njol.skript.Skript; +import ch.njol.skript.events.bukkit.ProfileCompletedEvent; +import ch.njol.skript.lang.Literal; +import ch.njol.skript.lang.SkriptEvent; +import ch.njol.skript.lang.SkriptParser.ParseResult; +import org.bukkit.event.Event; +import org.jetbrains.annotations.Nullable; +import ch.njol.skript.registrations.EventValues; +import ch.njol.skript.util.Getter; + +public class EvtProfileEvent extends SkriptEvent { + static { + Skript.registerEvent("Profiler Event Available", EvtProfileEvent.class, ProfileCompletedEvent.class, + "(profile|profiler) [event] (complete|completed|available)") + .description("Called after a new profiler event is available") + .since("INSERT VERSION"); + + EventValues.registerEventValue( + ProfileCompletedEvent.class, + String.class, + ProfileCompletedEvent::getName + ); + + EventValues.registerEventValue( + ProfileCompletedEvent.class, + Number.class, + ProfileCompletedEvent::getDurationMs + ); + } + + @Override + public boolean init(Literal[] args, int matchedPattern, ParseResult parser) { + return true; + } + + @Override + public boolean check(Event event) { + return event instanceof ProfileCompletedEvent; + } + + @Override + public boolean isEventPrioritySupported() { + return false; + } + + @Override + public String toString(@Nullable Event event, boolean debug) { + return "profile event complete"; + } + +} diff --git a/src/main/java/ch/njol/skript/events/bukkit/ProfileCompletedEvent.java b/src/main/java/ch/njol/skript/events/bukkit/ProfileCompletedEvent.java new file mode 100644 index 00000000000..51f95fab1f9 --- /dev/null +++ b/src/main/java/ch/njol/skript/events/bukkit/ProfileCompletedEvent.java @@ -0,0 +1,59 @@ +package ch.njol.skript.events.bukkit; + +import org.bukkit.event.Event; +import org.bukkit.event.HandlerList; +import org.jetbrains.annotations.NotNull; + +/** + * Represents a custom event triggered when a profiling section is completed. + * This event holds information about the name of the profiling section and + * the time it took to complete in milliseconds. + */ +public class ProfileCompletedEvent extends Event { + private static final HandlerList handlers = new HandlerList(); + private final String sectionName; + private final double durationMs; + + /** + * Constructs a new ProfileCompletedEvent. + * @param sectionName the name of the profiling section + * @param durationMs the duration in milliseconds the section took to execute + */ + public ProfileCompletedEvent(String sectionName, double durationMs) { + this.sectionName = sectionName; + this.durationMs = durationMs; + } + + /** + * Gets the name of the profiling section that was completed. + * @return the name of the completed profiling section + */ + public String getName() { + return sectionName; + } + + /** + * Gets the duration in milliseconds that the profiling section took to complete. + * @return the execution time of the section in milliseconds + */ + public double getDurationMs() { + return durationMs; + } + + /** + * Gets the list of handlers registered for this event. + * @return the list of handlers + */ + @Override + public @NotNull HandlerList getHandlers() { + return handlers; + } + + /** + * Gets the static handler list for this event class. + * @return the static handler list + */ + public static HandlerList getHandlerList() { + return handlers; + } +} diff --git a/src/main/java/ch/njol/skript/lang/Section.java b/src/main/java/ch/njol/skript/lang/Section.java index cd4a2093faf..4738815443f 100644 --- a/src/main/java/ch/njol/skript/lang/Section.java +++ b/src/main/java/ch/njol/skript/lang/Section.java @@ -10,6 +10,7 @@ import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.skriptlang.skript.lang.script.Script; import java.util.ArrayList; import java.util.Iterator; @@ -137,7 +138,11 @@ protected final Trigger loadCode(SectionNode sectionNode, String name, @Nullable // return the parser to its original state parser.restoreBackup(parserBackup); - return new Trigger(parser.getCurrentScript(), name, skriptEvent, triggerItems); + Script script = parser.getCurrentScript(); + Trigger trigger = new Trigger(script, name, skriptEvent, triggerItems); + trigger.setDebugLabel(script.nameAndPath() + ".sk: line " + sectionNode.getLine() + " as part of section " + name); + + return trigger; } /** diff --git a/src/main/java/ch/njol/skript/lang/SkriptEvent.java b/src/main/java/ch/njol/skript/lang/SkriptEvent.java index c7eb245fb22..162b261dec8 100644 --- a/src/main/java/ch/njol/skript/lang/SkriptEvent.java +++ b/src/main/java/ch/njol/skript/lang/SkriptEvent.java @@ -132,7 +132,7 @@ public boolean load() { trigger = new Trigger(script, expr, this, items); int lineNumber = source.getLine(); trigger.setLineNumber(lineNumber); // Set line number for debugging - trigger.setDebugLabel(script + ": line " + lineNumber); + trigger.setDebugLabel(script.nameAndPath() + ".sk: line " + lineNumber + " (expr " + expr + ")"); } finally { getParser().deleteCurrentEvent(); } diff --git a/src/main/java/ch/njol/skript/timings/Profiler.java b/src/main/java/ch/njol/skript/timings/Profiler.java new file mode 100644 index 00000000000..27f89fff250 --- /dev/null +++ b/src/main/java/ch/njol/skript/timings/Profiler.java @@ -0,0 +1,48 @@ +package ch.njol.skript.timings; + +import ch.njol.skript.Skript; + +/** + * Profiler instance for the ProfilerAPI + * Each profiler times how long it takes for a given trigger to complete, + * along with the invocator script information + */ +public class Profiler { + private final String name; + private long startTime = 0; + private long totalTime = 0; + private boolean running = false; + + public Profiler(String name) { + this.name = name; + } + + public void start() { + if (running) return; // prevent double-starts + startTime = System.nanoTime(); + running = true; + } + + public void stop() { + if (!running) return; // prevent stop without start + long endTime = System.nanoTime(); + long duration = endTime - startTime; + totalTime += duration; + running = false; + + Skript.debug("[Profiler] " + name + " took " + (duration / 1_000_000.0) + " ms"); + } + + public long getTimeNanos() { + return totalTime; + } + + public double getTime() { + return totalTime / 1_000_000.0; + } + + public String getName() { + return name; + } + +} diff --git a/src/main/java/ch/njol/skript/timings/ProfilerAPI.java b/src/main/java/ch/njol/skript/timings/ProfilerAPI.java new file mode 100644 index 00000000000..d43e5a7c865 --- /dev/null +++ b/src/main/java/ch/njol/skript/timings/ProfilerAPI.java @@ -0,0 +1,48 @@ +package ch.njol.skript.timings; + +import ch.njol.skript.Skript; +import ch.njol.skript.events.bukkit.ProfileCompletedEvent; +import ch.njol.skript.timings.Profiler; +import org.bukkit.Bukkit; +import org.jetbrains.annotations.Nullable; + +/** + * Profiler API for timing how long a given event takes + */ +public class ProfilerAPI { + + private static volatile boolean enabled = true; + public static final ThreadLocal isFiringProfilerEvent = ThreadLocal.withInitial(() -> false); + + @Nullable + public static Profiler start(String name) { + if (!enabled()) // Timings disabled :( + return null; + Profiler profiler = new Profiler(name); + profiler.start(); + return profiler; + } + + public static void stop(@Nullable Profiler profiler) { + if (profiler == null) // Timings disabled... + return; + profiler.stop(); + + if (isFiringProfilerEvent.get()) return; + isFiringProfilerEvent.set(true); + try { + Bukkit.getPluginManager().callEvent(new ProfileCompletedEvent(profiler.getName(), profiler.getTime())); + } finally { + isFiringProfilerEvent.set(false); + } + } + + public static boolean enabled() { + return enabled; + } + + public static void setEnabled(boolean flag) { + enabled = flag; + } + +} diff --git a/src/main/java/ch/njol/skript/util/AsyncEffect.java b/src/main/java/ch/njol/skript/util/AsyncEffect.java index 7786185f1ea..9785bb3a878 100644 --- a/src/main/java/ch/njol/skript/util/AsyncEffect.java +++ b/src/main/java/ch/njol/skript/util/AsyncEffect.java @@ -1,5 +1,7 @@ package ch.njol.skript.util; +import ch.njol.skript.timings.Profiler; +import ch.njol.skript.timings.ProfilerAPI; import org.bukkit.Bukkit; import org.bukkit.event.Event; import org.jetbrains.annotations.Nullable; @@ -44,18 +46,27 @@ protected TriggerItem walk(Event e) { if (getNext() != null) { Bukkit.getScheduler().runTask(Skript.getInstance(), () -> { // Walk to next item synchronously Object timing = null; + Profiler profiler = null; if (SkriptTimings.enabled()) { // getTrigger call is not free, do it only if we must Trigger trigger = getTrigger(); if (trigger != null) { timing = SkriptTimings.start(trigger.getDebugLabel()); } } + + if (ProfilerAPI.enabled()) { + Trigger trigger = getTrigger(); + if (trigger != null) { + profiler = ProfilerAPI.start(trigger.getDebugLabel()); + } + } TriggerItem.walk(getNext(), e); Variables.removeLocals(e); // Clean up local vars, we may be exiting now SkriptTimings.stop(timing); // Stop timing if it was even started + ProfilerAPI.stop(profiler); }); } else { Variables.removeLocals(e);