Improbable Java slow down in combining doubles and strings

#21

Java best practice is always to use StringBuilder/StringBuffer classes to assemble Strings like you are doing, or (since it became available) String.format() if that makes more sense. Strings are immutable in Java, and certainly way back all the + operator on Strings would do is take the 2 Strings, and create a 3rd as the result. Looks like Java 8 has a nice internal way of dealing with that, and I’m not sure when that got introduced. But it looks like Java 11 out of the box (or at least what we’re running on the RIO) does not have this.

Why 1 second or so the first time? When you first use a class, Java needs to load that class definition, initialise any statics, put constants on the heap etc… And that takes some time. Once they are loaded into the VM, the next call to any of those classes is WAY faster because it’s already there and cached, and any initialisation is done. 1 second does sound a lot though, but at the same time, this is not a desktop machine.

If there’s any way you can move this code into an initialisation method, or a static initialiser, so that it isn’t going to get called and run slowly when you actually want to run the robot, you should do that. But certainly go with String concatenation best practices and use a StringBuilder or StringBuffer to do what you are doing will get you a long way to much faster code.

#22

It’s not necessary to use StringBuilder explicitly. Java 8 compiles “naive” string concatenation code into the equivalent StringBuilder code. Java 11 prefers to compile it down to an InvokeDynamic which chooses at runtime (during the first execution) whether to use the StringBuilder approach or some other approach. That selection process appears to be what’s taking the extra time; later executions are just as fast if not faster than Java 8 and hand-written StringBuilder code. Also, see the last part of my post above; you can force the Java 11 runtime to skip the optimization/selection process and always use StringBuilder in such cases.

1 Like
#23

Cool, thanks, that is a very helpful analysis. We will give the java option a try and see if it eliminates our gremlin.

#24

Thank you Peter_Johnson for the detailed analysis and explanation!

#25

Finally got a chance to try this yesterday.

Adding that parameter to the Java invocation resulted in a crash anytime we used the naive string concatenation.

Replacing all the strings with String.format() did make the unusually long startup delay go away.

We are still not getting the kind of control timing we have gotten in past years. In the past, we’ve been able to run 5 ms control loops. This year, we’ve had to dial those back to 15 ms, and even then, we’ll see 25 ms loop intervals from time to time.

I suspect the GC (I’m seeing routine GC pause times of 20ms in a gclog), but haven’t really nailed it down.

#26

Interesting, I will need to try it with a more complete program. The small test program didn’t have issues. Did it crash the whole JVM?

Are these running in separate threads? What calls are you making (e.g. to CAN)? Have you tried profiling it? I would recommend moving this part of the discussion back to TimedRobot loop overruns and inconsistent loop timing (Java)

#27

Many thanks for bringing this up. Our drive team noticed a delay the first time a command was run and we couldn’t figure it out. After reading this thread we found one println with a string + double causing a 0.8 second delay.

And FYI, another command had a noticeable delay the first time it was run. It uses NetworkTables. The first time NetworkTables is accessed can also cause a delay greater than 1 second.

We have since put a System.out.println(" " + n) and NetworkTableInstance.getDefault() into our robotInit() method.

#28

That should not be the case. And even if it was, the RobotBase constructor calls NetworkTableInstance.getDefault(), so it’s not necessary to call it yourself.