From 71670deb3c5276a36b83327e6c8dc4612e49cb48 Mon Sep 17 00:00:00 2001 From: MaXFeeD Date: Sun, 11 Feb 2024 02:29:30 +0300 Subject: [PATCH] =?UTF-8?q?feat:=20=D0=94=D0=BE=D0=B1=D0=B0=D0=B2=D0=BB?= =?UTF-8?q?=D0=B5=D0=BD=D0=B0=20=D0=BA=D0=BE=D0=BC=D0=B0=D0=BD=D0=B4=D0=B0?= =?UTF-8?q?=20/profilecallback=20[enabled]=20[showParameters]?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Предназначена для разработчиков и мододелов, отображает время затраченное на выполнение калбеков. - Второй параметр отвечает за отображение аргументов передаваемых в калбеки, может использоваться отдельно. --- .../commands/CallbackProfilingCommand.java | 43 +++++++++++++++++++ .../reider745/commands/CommandsHelper.java | 1 + .../api/mod/ScriptableObjectHelper.java | 6 +++ .../innercore/api/runtime/Callback.java | 36 ++++++++++++++++ 4 files changed, 86 insertions(+) create mode 100644 src/main/java/com/reider745/commands/CallbackProfilingCommand.java diff --git a/src/main/java/com/reider745/commands/CallbackProfilingCommand.java b/src/main/java/com/reider745/commands/CallbackProfilingCommand.java new file mode 100644 index 00000000..6a8cabf4 --- /dev/null +++ b/src/main/java/com/reider745/commands/CallbackProfilingCommand.java @@ -0,0 +1,43 @@ +package com.reider745.commands; + +import cn.nukkit.command.Command; +import cn.nukkit.command.CommandSender; +import cn.nukkit.utils.TextFormat; + +import com.zhekasmirnov.innercore.api.runtime.Callback; + +public class CallbackProfilingCommand extends Command { + + public CallbackProfilingCommand() { + super("profilecallback", "Logging callback execution profiling.", + "/profilecallback [enabled] [showParameters]"); + } + + @Override + public boolean execute(CommandSender commandSender, String commandLabel, String[] args) { + if (!commandSender.isOp()) + return false; + + boolean enabled = false, showParameters = false; + if (args.length == 0) { + enabled = !Callback.profilingEnabled; + } else { + enabled = "true".equalsIgnoreCase(args[0]); + if (args.length > 1) { + showParameters = "true".equalsIgnoreCase(args[1]); + if (Callback.profilingShowParameters != (Callback.profilingShowParameters = showParameters)) { + commandSender.sendMessage( + TextFormat.YELLOW + "Parameter logging " + (showParameters ? "enabled" : "disabled") + "."); + } + } + } + if (Callback.profilingEnabled != (Callback.profilingEnabled = enabled)) { + commandSender + .sendMessage(TextFormat.YELLOW + "Callback profiling " + (enabled ? "enabled" : "disabled") + "."); + if (!enabled && !showParameters) + Callback.profilingShowParameters = false; + } + + return true; + } +} diff --git a/src/main/java/com/reider745/commands/CommandsHelper.java b/src/main/java/com/reider745/commands/CommandsHelper.java index aeec4a26..b23b5fa4 100644 --- a/src/main/java/com/reider745/commands/CommandsHelper.java +++ b/src/main/java/com/reider745/commands/CommandsHelper.java @@ -12,5 +12,6 @@ public class CommandsHelper { map.register("inner_core", new StateCommand()); map.register("inner_core", new InnerCoreNetworkCommand()); map.register("inner_core", new GenChunksCommands()); + map.register("inner_core", new CallbackProfilingCommand()); } } diff --git a/src/main/java/com/zhekasmirnov/innercore/api/mod/ScriptableObjectHelper.java b/src/main/java/com/zhekasmirnov/innercore/api/mod/ScriptableObjectHelper.java index e7f66f09..66c67dde 100644 --- a/src/main/java/com/zhekasmirnov/innercore/api/mod/ScriptableObjectHelper.java +++ b/src/main/java/com/zhekasmirnov/innercore/api/mod/ScriptableObjectHelper.java @@ -7,6 +7,7 @@ import org.json.JSONException; import org.json.JSONObject; import org.mozilla.javascript.Context; import org.mozilla.javascript.NativeArray; +import org.mozilla.javascript.NativeJSON; import org.mozilla.javascript.ScriptableObject; import java.util.List; @@ -204,4 +205,9 @@ public class ScriptableObjectHelper { return json; } + + public static String stringify(ScriptableObject obj, Object space) { + Context context = Compiler.assureContextForCurrentThread(); + return (String) NativeJSON.stringify(context, obj.getParentScope(), obj, null, space); + } } diff --git a/src/main/java/com/zhekasmirnov/innercore/api/runtime/Callback.java b/src/main/java/com/zhekasmirnov/innercore/api/runtime/Callback.java index 29d6da62..ded635a7 100644 --- a/src/main/java/com/zhekasmirnov/innercore/api/runtime/Callback.java +++ b/src/main/java/com/zhekasmirnov/innercore/api/runtime/Callback.java @@ -1,6 +1,8 @@ package com.zhekasmirnov.innercore.api.runtime; +import com.zhekasmirnov.horizon.runtime.logger.Logger; import com.zhekasmirnov.innercore.api.log.ICLog; +import com.zhekasmirnov.innercore.api.mod.ScriptableObjectHelper; import com.zhekasmirnov.innercore.mod.executable.Compiler; import org.mozilla.javascript.Context; import org.mozilla.javascript.Function; @@ -9,6 +11,7 @@ import org.mozilla.javascript.Scriptable; import java.util.ArrayList; import java.util.HashMap; import java.util.List; +import java.util.concurrent.atomic.AtomicLong; /** * Created by zheka on 09.08.2017. @@ -26,6 +29,7 @@ public class Callback { } private static HashMap> callbacks = new HashMap<>(); + public static boolean profilingEnabled = false, profilingShowParameters = false; public static int count(String name) { List encounted = callbacks.getOrDefault(name, null); @@ -50,20 +54,48 @@ public class Callback { public static void invokeCallbackV(String name, Object[] params) { Context ctx = Compiler.assureContextForCurrentThread(); + boolean isTick = name.contains("tick") || name.contains("Tick"); + if (profilingShowParameters && !isTick) { + try { + Logger.debug("Profiling/" + name, + ScriptableObjectHelper.stringify(ScriptableObjectHelper.createArray(params), null)); + } catch (RuntimeException e) { + } + } ArrayList funcs = callbacks.get(name); Scriptable parent; if (funcs != null) { + long profilingNanos = !profilingEnabled || isTick ? 0 : System.nanoTime(); for (CallbackFunction callback : funcs) { parent = callback.function.getParentScope(); callback.function.call(ctx, parent, parent, params); } + if (profilingNanos != 0) { + profilingNanos = System.nanoTime() - profilingNanos; + Logger.debug("Profiling/" + name, + funcs.size() + " functions in " + (profilingNanos / 1000000f) + "ms."); + } } } public static List getCallbackAsRunnableList(String name, final Object[] params) { List result = new ArrayList(); + boolean isTick = name.contains("tick") || name.contains("Tick"); + if (profilingShowParameters && !isTick) { + result.add(() -> { + try { + Logger.debug("Profiling/" + name, + ScriptableObjectHelper.stringify(ScriptableObjectHelper.createArray(params), null)); + } catch (RuntimeException e) { + } + }); + } ArrayList funcs = callbacks.get(name); if (funcs != null) { + AtomicLong profilingNanos = new AtomicLong(); + if (profilingEnabled && !isTick) { + result.add(() -> profilingNanos.set(System.nanoTime())); + } for (CallbackFunction func0 : funcs) { result.add(new Runnable() { public void run() { @@ -72,6 +104,10 @@ public class Callback { } }); } + if (profilingNanos.get() != 0) { + result.add(() -> Logger.debug("Profiling/" + name, funcs.size() + " functions in " + + ((System.nanoTime() - profilingNanos.get()) / 1000000f) + "ms.")); + } } return result; }