Time Delay when entering autonomousPeriodic()

Our team is experiencing an approximate 1 second delay between enabling autonomous and any action occurring in autonomousPeriodic(). This happens no matter what we put in auto… Are other teams experiencing this?

What code do you have in autoInit?

1 Like

At this point in time only the default code provided by the timedRobot template.

Have you put a print statement in the autonomous init or autonomous periodic to actually see how long it takes? Also make sure that there aren’t any loop overruns being reported in the console on the driver station.

Once autonomousInit() is called, it should be immediately followed by an autonomousPeriodic() and then a robotPeriodic() right after that with no delays between the calls.

What language are you using?

We are using Java and experiencing the same delay. Here is a look at the DriverStation log for one of our matches this past weekend.

We cannot figure out why the autoPeriodic is not running, and also why it is taking so long for the command initialization to run in each of the commands. Our Auto pattern starts with:

addParallel(new ParallelCommand());
addSequential(new SequentialCommand());

Based on the feedback from the WPILib crew, the System.out.println() outputs to the log can be misaligned from a timing perspective. I have adjusted the diagram here:

You might have a look at the problem we encountered here:
Improbable Java slow down in combining doubles and strings

Wow. Thank you for that. We are printing doubles at the beginning of the commands using the “+” concatenation operator, but we do that earlier in the code as well (at robotinit). I am not sure that is completely our issue here. Seems like there is more going on than just a String concat. We can change the code to see what happens.

Also, why is there no loop overrun warning message when the system seems to go away for .8sec

I looked at the code. In the SequentialCommand initialize(), we print doubles using the ‘+’ operator for String concat to show what command parms are about to be executed. If the String concat is the issue, should that not have gone away after the prints shown above (since the first print would have occured already and subsequent prints should take minimal time)? Why is there still an additional .5 seconds after the end of the initialize() routines before the first execute() block is called?

We also have code that logs the start and end times of the autoInit() method, and it takes a ridiculous 103ms, but that is nowhere near the .8 seconds that we are experiencing. The autoInit() method prints out some parameters from the system, and uses doubles. We may be able to reduce that somewhat thanks to the hints above, but the main delay persists. Thanks @jwhite.

I have also posted this on the WPILib Gitter site here: https://gitter.im/wpilibsuite/wpilib

Just as another note, we also experienced some unusual delays from the garbage collector, and switching to the legacy garbage collector helped us to some extent.

There are more details in this thread:
Delays in running code; symptoms include watchdog timeouts

I’m planning to do a dive one of these days to try to figure out why we are triggering so much gc; it’s a bit of a puzzler.

Because of TRotateToHeadingCommand.getParmDesc(), which does similar string/double concatenation, and isn’t called until the initialize() of this command is called.

Adding -Djava.lang.invoke.stringConcat=BC_SB to the java command line in robotCommand (per my research here) appears to fix the issue. This can be done in Gradle by adding jvmArgs << "-Djava.lang.invoke.stringConcat=BC_SB" to the frcJavaArtifact block.

we found that printing out a bunch of stuff slows everything down a lot. So we stopped doing that.