feat: Добавлена команда /profilecallback [enabled] [showParameters]

- Предназначена для разработчиков и мододелов, отображает время затраченное на выполнение калбеков.
- Второй параметр отвечает за отображение аргументов передаваемых в калбеки, может использоваться отдельно.

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;
+	}
+}

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());
     }
 }

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);
+    }
 }

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<String, ArrayList<CallbackFunction>> callbacks = new HashMap<>();
+    public static boolean profilingEnabled = false, profilingShowParameters = false;
 
     public static int count(String name) {
         List<CallbackFunction> 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<CallbackFunction> 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<Runnable> getCallbackAsRunnableList(String name, final Object[] params) {
         List<Runnable> result = new ArrayList<Runnable>();
+        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<CallbackFunction> 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;
     }