I have a library with an internal command line that uses picocli 3.9.6. One of these commands is the log command, which works like most loggers, taking a log level and message, and several other options. It gets called a lot in some applications that use the library, and we noticed a huge decrease in performance from when this command was implemented as a one-off vs. when it was switched to picocli. This is true even when the log level is set such that nothing interesting happens. The core code is the same between both versions.
Our suspicion, then, is that picocli is using reflection to handle each command instance. How can we improve performance? I noticed that picocli 4.x includes an annotation processor, but it's not realistic for us to make our users use Graal. Since the annotations don't change across instances, maybe they can be cached?
The code for the log command can be found here:
I added a testPerformance unit test here: https://github.com/soartech/jsoar/blob/maven/jsoar-core/src/test/java/org/jsoar/kernel/commands/LogCommandTest.java
Running the unit test produces times of ~3s on my machine. If I go back to commit 2bc4d39549eeb4ad69fd45e97f9607475e6426d9 (Oct 30, 2018), which is right before the log command was converted to picocli, and put the test in there (you can replace the entire unit test file with the newer version), I get times of ~0.03s.
I used Java Flight Recorder to see what the hot spots are when executing the LogCommandTest, and I found that, indeed, what shows up at the top was essentially picocli building a model from the annotations.
Looking closer, the current application logic re-initializes a new CommandLine model with a new instance of Log for every invocation of the LogCommand. This is one way to ensures that all values are reset for each invocation, but it turns out to be expensive when the command is invoked a lot. Fortunately it is not the only way.
I propose that instead, you create the CommandLine object once, and reuse it for all subsequent invocations. Picocli is designed to be used this way: before parsing new user input, picocli will reset options and parameters to their default values.
The patch below implements this. I focused on the LogCommand because this is what the OP was about, but you may want to apply a similar change to other performance-sensitive commands that are invoked a lot.
I tested the below and found that the LogCommandTest.testPerformance test went from 5 seconds to 0.5 seconds on my machine. The other tests in LogCommandTest still pass.
Proposed patch:
Index: jsoar-core/src/main/java/org/jsoar/kernel/commands/LogCommand.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- jsoar-core/src/main/java/org/jsoar/kernel/commands/LogCommand.java (revision 576ae0a1420177bad69d2f9e2e0d405c74f87ab0)
+++ jsoar-core/src/main/java/org/jsoar/kernel/commands/LogCommand.java (date 1577052510919)
@@ -23,6 +23,7 @@
import org.jsoar.util.commands.SoarCommandContext;
import org.jsoar.util.commands.SoarCommandInterpreter;
+import picocli.CommandLine;
import picocli.CommandLine.Command;
import picocli.CommandLine.HelpCommand;
import picocli.CommandLine.Model.CommandSpec;
@@ -39,17 +40,22 @@
{
private final Agent agent;
private SoarCommandInterpreter interpreter;
+ private Log log;
+ private CommandLine logCommand;
public LogCommand(Agent agent, SoarCommandInterpreter interpreter)
{
this.agent = agent;
this.interpreter = interpreter;
+ this.log = new Log(agent, interpreter, null);
+ this.logCommand = new CommandLine(log);
}
@Override
public String execute(SoarCommandContext context, String[] args) throws SoarException
{
- Utils.parseAndRun(agent, new Log(agent, interpreter, context), args);
+ this.log.context = context;
+ Utils.parseAndRun(agent, logCommand, args);
return "";
}
@@ -57,7 +63,7 @@
@Override
public Object getCommand()
{
- return new Log(agent,interpreter,null);
+ return logCommand;
}
@Command(name="log", description="Adjusts logging settings",
@@ -67,7 +73,7 @@
private final Agent agent;
private final LogManager logManager;
private final SoarCommandInterpreter interpreter;
- private final SoarCommandContext context;
+ private SoarCommandContext context;
private static String sourceLocationSeparator = ".";
@Spec
Index: jsoar-core/src/main/java/org/jsoar/kernel/commands/Utils.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- jsoar-core/src/main/java/org/jsoar/kernel/commands/Utils.java (revision 576ae0a1420177bad69d2f9e2e0d405c74f87ab0)
+++ jsoar-core/src/main/java/org/jsoar/kernel/commands/Utils.java (date 1577052217242)
@@ -41,10 +41,25 @@
parseAndRun(command, args, ps);
}
-
+
+ /**
+ * Executes the specified command and returns the result.
+ * A command may be a user object or a pre-initialized {@code picocli.CommandLine} object.
+ * For performance-sensitive commands that are invoked often,
+ * it is recommended to pass a pre-initialized CommandLine object instead of the user object.
+ *
+ * @param command the command to execute; this may be a user object or a pre-initialized {@code picocli.CommandLine} object
+ * @param args the command line arguments (the first arg will be removed from this list)
+ * @param ps the PrintStream to print any command output to
+ * @return the command result
+ * @throws SoarException if the user input was invalid or if a runtime exception occurred
+ * while executing the command business logic
+ */
public static List<Object> parseAndRun(Object command, String[] args, PrintStream ps) throws SoarException {
- CommandLine commandLine = new CommandLine(command);
+ CommandLine commandLine = command instanceof CommandLine
+ ? (CommandLine) command
+ : new CommandLine(command);
// The "debug time" command takes a command as a parameter, which can contain options
// In order to inform picocli that the options are part of the command parameter