Performance too slow for control feedback for a moving robot #748
Comments
|
Here's the java code: package ev3.timing;
import ev3dev.actuators.ev3.EV3Led;
import ev3dev.actuators.ev3.EV3Led.Direction;
import ev3dev.actuators.lego.motors.EV3LargeRegulatedMotor;
import ev3dev.sensors.EV3Key;
import ev3dev.sensors.ev3.EV3GyroSensor;
import lejos.hardware.port.MotorPort;
import lejos.hardware.port.SensorPort;
import lejos.robotics.SampleProvider;
public class TimingTest {
//equivalent loop on just ev3 classroom is .3.6 / 100 = 0.0036 per iteration = 3.6 milliseconds - so it's a factor of about 100x
public static void main(String[] args) {
EV3LargeRegulatedMotor leftMotor = new EV3LargeRegulatedMotor(MotorPort.B);
EV3LargeRegulatedMotor rightMotor = new EV3LargeRegulatedMotor(MotorPort.C);
System.out.println("motors created");
EV3GyroSensor gyroSensor = new EV3GyroSensor(SensorPort.S2);
SampleProvider gyroSampleProvider = gyroSensor.getAngleMode();
float[] gyroArray = new float[gyroSensor.sampleSize()];
System.out.println("gyro created");
warmUp(gyroSampleProvider,leftMotor,rightMotor);
long[] timingResults = new long[10];
for(int i = 0 ; i < timingResults.length ; i++) {
long startTime = System.currentTimeMillis();
//readHeading
gyroSampleProvider.fetchSample(gyroArray, 0);
float heading = gyroArray[0];
//read each motor's odometer
int leftOdometer = leftMotor.getTachoCount();
int rightOdometer = rightMotor.getTachoCount();
//set each motor's speed
leftMotor.setSpeed(0);
rightMotor.setSpeed(0);
long endTime = System.currentTimeMillis();
timingResults[i] = endTime - startTime;
//todo set the array value
}
long total = 0 ;
for(long r : timingResults ) {
System.out.println(r);
total = total + r;
}
System.out.println("average is "+(total/timingResults.length)) ;
}
static void warmUp(SampleProvider gyroSampleProvider,EV3LargeRegulatedMotor leftMotor,EV3LargeRegulatedMotor rightMotor) {
long startTime = System.currentTimeMillis();
//readHeading
float[] gyroArray = new float[1];
gyroSampleProvider.fetchSample(gyroArray, 0);
//read each motor's odometer
int leftOdometer = leftMotor.getTachoCount();
int rightOdometer = rightMotor.getTachoCount();
//set each motor's speed
leftMotor.setSpeed(0);
rightMotor.setSpeed(0);
long endTime = System.currentTimeMillis();
}
} |
|
Here's the ev3 classroom code that runs in 2-4 milliseconds per iteration.
|
|
Hi @dwalend, many thanks for the issue. Juan Antonio |
https://github.com/ev3dev-lang-java/ev3dev-lang-java/blob/master/src/main/java/ev3dev/utils/Sysfs.java import java.io.File;
import java.io.IOException;
import java.io.PrintWriter;
import java.nio.charset.Charset;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.nio.file.StandardOpenOption; |
|
I will try to hack something together in C++ in the coming days to see what is the limit of the underlying OS. |
|
I have an initial version of the C++ benchmark available. "Rolling-release" links (pointing at master, not the commit https://github.com/JakubVanek/ev3dev-lang-cpp-bench/commit/b01a3b22d6d4bbc3cecd23c53c214706d4e23e76):
However, I've noticed that even though the benchmark sets the speed attribute, it doesn't order the motors to start moving. Is this intentional? I've followed this in the C++ program. I believe the situation with leJOS/ev3dev-lang-java is similar and you'd have to call |
|
It seems that the compiler in Ubuntu 18.04 is too new to compile for ev3dev-stretch, I'll provide a binary built with a "universal" compiler (download here) that I was using for different C development. |
|
EDIT: I'm going to use a |
That's correct. Starting the motors isn't in the control loop, so I left it out of the benchmark. That gives me a reason better than "I don't want to take the wheels off the robot, and don't want it crashing into stuff on my desk." |
If that doesn't work out - ev3dev has a Docker recipe for a stretch dev system . |
Hmm, I agree, that would be more convenient if that is an option. |
|
Results for the musl version: and this is one of the worse runs, typically it's around |
I think this will not work in the production code -- AFAIK the speed change is committed only after a |
|
Results for the docker-compiled version: Quickly looking at a few runs, the mean is about This is with |
Writing the control loop in C/C++ and then communicating with non-critical logic in Java would most certainly work, although the impact of JIT/GC running next to it would have to be measured. On the other hand, if the logic runs completely in its own thread, it could switch itself to realtime SCHED_RR/SCHED_FIFO scheduling. With that, whatever is running next to it shouldn't present a problem. Using JNI to do just the IO (i.e. replacing Sysfs class with a JNI-backed implementation) is another way to go. This would preserve the existing outer API, but the performance might be slightly lower. |
|
Results of the last C++ version with SCHED_RR scheduling enabled: The variance now looks much lower too. |
|
I think the C/C++ version could be hand-optimized to be even faster, my current goal was to make look the same as the Java benchmark. However, the results should have the same order-of-magnitude. There will be the same context switches etc. (= limitation of ev3dev), just the UTF-8 conversion and similar stuff could be cut out. |
|
Hmm, to be fair to the Java version, proper warmup for microbenchmarking should have much more iterations than one. That being said, the same warmup would then have to be done in the production code too. |
|
I tried to rewrite the program using the ugliest hacks I know and this is what I got (binary, source): I'd consider that nearing the limit of what is achievable with ev3dev. There are still some places that could be optimized (sprintf for int->string conversion isn't optimal), but something of that style would have to be used anyway for it to be useful. |
Up until this one the speeds you saw in C++ lined up with the LEGO classroom scratch. (And thanks for the reminder of why I stopped doing C++. ... You could put assembly code in that for more ugly, but I don't know that you can gain anything.) The warm-up is short for Java - hotspot normally kicks in after 8 iterations. However, the biggest time-sink on the ev3 seems to be that initial loading of classes. I didn't see much drop-off in longer tests, and - like you mentioned - it's not terribly predictable. It looks like there's two orders of magnitude potential gain from the base case in Java to reasonable C code. |
|
I want to pick on this method in Sysfs.java as a first step: public static String readString(final String filePath) {
if(log.isTraceEnabled())
log.trace("cat " + filePath);
try {
final Path path = Paths.get(filePath);
if(existFile(path) && Files.isReadable(path)){
final String result = Files.readAllLines(path, Charset.forName("UTF-8")).get(0);
if(log.isTraceEnabled())
log.trace("value: {}", result);
return result;
}
throw new IOException("Problem reading path: " + filePath);
} catch (IOException e) {
log.error(e.getLocalizedMessage(), e);
throw new RuntimeException("Problem reading path: " + filePath, e);
}
}It's opening and closing the file every time. Would it be possible - as part of initializing the sensor - to do the safety checks at init time, and keep the file open ? (And leave it up to the client code to close when done using the sensor?) That'd save all the IO set-up, and almost all of the memory allocation. The trade is that the sensor would pick up some more - and more complicated state. |
It seems I was wrong again. By removing int<->string conversion altogether, the time is nearly halved: |
|
Assembly would indeed be the next step, but this seems like too much work. |
I have to agree, from this viewpoint the C++ result is a bit of an embarrassment. On the other hand, if this Scratch variant is based on Microsoft MakeCode, I think they might be generating ARMv4T code ahead of time and that could explain their great performance. But if this is based on the stock firmware's VM, then it seems engineers at LEGO optimized it very well.
In that case this warmup looks reasonable, I was thinking the threshold was in the order of 1000s of calls. I can confirm I remember classloading sometimes took a lot of time. |
|
@jabrena I have read those and I still don't follow why the solution as-is isn't thread safe. (Yes, its performance is certainly not optimal, but that does not fall under thread safety).
This does list the immutable nature, but it also acknowledges locking. If all public entrypoints that access the data are synchronized on the same object, then IIUC all accesses are mutually excluded. Correct me if I'm wrong in this. Resource starvation might still occur if multiple threads are reading from a file on a multicore system. This seems to fall to performance instead of thread safety though. Similar. The one valid problem that it lists is that an attacker can lock the static Sysfs monitor and deny all read/write operations this way. Moving the This one has the most information. It does not directly address locking. One of the recommendations is "Avoid Global Variables", but that is for "Strategy 1: Confinement". But this is not the only strategy available. The entire next reading is dedicated to locking: http://web.mit.edu/6.031/www/fa17/classes/21-locks/ To paraphrase the reading: // Thread safety argument:
// all accesses to the cached variables happen within Sysfs methods,
// which are all guarded by Sysfs's static lock.
For deadlocks, a similar argument could be made - the Sysfs lock will always be the last lock to be acquired. Sysfs execution doesn't block on other locks. It does block on system I/O, so writing to a UNIX pipe with Sysfs would break. AFAIK /sys contains no pipes, but it is a potential hazard. I'm intentionally not touching lockless shared structures or creating own low-level locking primitives here because I know these are genuinely hard. |
|
I would again appreciate technical counter-arguments, while I learnt new stuff when reading the materials, I still don't see why the code isn't thread safe (yes, performance is going to be suboptimal). |
|
Sorry, I am not going to invest more time in this discussion. I will continue with the process this weekend. Kind reminder: try to not flood this issue with any comment that you have in your mind. In other case, you will be blocked. |
|
OK, I will try to take a step back. It's true that this argument does not help to resolve the overall issue. |
|
@JakubVanek I am talking about your rude behavior, not about arguments. You choose. I am clear. |
|
Yes, I acknowledge that I behaved rudely and I will try to adjust my future behaviour not to create conflict. |
|
Testing GitKraken, a visual tool to remove non required changes in the branch |
|
@jabrena - how goes the testing? |
|
Hi @dwalend, Tomorrow, I will show some results :) |
|
Status:
Tomorrow, I will upload the json to have the discussion. I configured the JMH to not have a Warmup in order to simulate the scenario for a new Java execution. Options options = new OptionsBuilder()
.include(Sysfs_ExistFile_Benchmark.class.getSimpleName())
.include(Sysfs_writeString_Benchmark.class.getSimpleName())
.include(Sysfs_writeInteger_Benchmark.class.getSimpleName())
.include(Sysfs_readString_Benchmark.class.getSimpleName())
.include(Sysfs_getElements_Benchmark.class.getSimpleName())
.include(Sysfs_existPath_Benchmark.class.getSimpleName())
.resultFormat(ResultFormatType.JSON)
.result("/home/robot/jmh-results.json")
.verbosity(VerboseMode.EXTRA)
.mode(Mode.Throughput)
.timeUnit(TimeUnit.MILLISECONDS)
.warmupTime(TimeValue.seconds(0))
.measurementTime(TimeValue.milliseconds(1))
.measurementIterations(10)
.threads(Runtime.getRuntime().availableProcessors())
.warmupIterations(1)
.shouldFailOnError(false)
.shouldDoGC(true)
.forks(2)
.jvmArgs("-Xmx64m", "-Xms64m", "-XX:+UseSerialGC", "-noverify", "-XX:TieredStopAtLevel=1")
//.addProfiler(StackProfiler.class)
//.addProfiler(GCProfiler.class)
//.addProfiler(LinuxPerfProfiler.class)
//.addProfiler(ClassloaderProfiler.class)
//.addProfiler(CompilerProfiler.class)
//.addProfiler(JmhFlightRecorderProfiler.class)
.build();To disable the logs: |
|
Results using Sysfs & Sysfs2 in an aggregated test: Original Sysfs.java Sysfs2.java It is clear that in average, the new implementation for method: This week, I will replace current method with the new one and I will create a new issue to analyze how to increase the performance at program level. For maximum performance level, disable logs: Some ideas for the next iteration:
@dwalend @JakubVanek any other idea? Merry christmas Juan Antonio |
|
I have some comments related to the JMH configuration:
I'm not sure how this exactly behaves. For SingleShot, there was one warmup iteration. For AverageTime/Throughput, there might be one too (JMH runs warmupIterations loops, each loop runs for warmupTime milliseconds; so it may have tried to run the function once to find that the time allocated had expired).
Given that the operation itself takes more than a millisecond, I think that AverageTime/Throughput got effectively transformed into SingleShot. As above, JMH should do measurementIterations runs of a loop that is let to run for measurementTime ms. This is likely to hide the time counting overheads by calculating an average over multiple inner function calls (the output is that for example iteration 3 managed to do 123 calls in 2,0 seconds).
This looks good.
This does not entirely disable JIT though, this is why I was pushing
Yes, this is a good idea, the last time these profilers didn't work. |
|
The profilers works. Any other idea? |
The performance measurement itself does work, but the last time there were only 0.0 and NaN values in the profiler results. ev3dev-lang-java/docs/performance/jmh-results_4.json Lines 71 to 214 in d36cc72 |
|
Hi @JakubVanek, this is a kind a result from JMH and indeed, I didn´t add to reduce the time invested in the tests but they works. Review in Internet, you will find positive results with JMH. |
I do admit that my initial opinions about JMH based on the first measured data in this thread were wrong. My evaluation was coming from the error margins; I thought this was the best JMH was capable of on EV3. However, after experiments, I found that JMH is capable of providing solid results even on the EV3 (this was done in parallel with the RtControlBench tests, see earlier comments). However, it seems that to get small error margins from JMH, I had to keep some things in mind (this is not specific to JMH though, any measurement of anything would be affected by this).
I'm also not saying that the stack profiler and GC profiler are broken in general, I just want to point out that from the data that I can access, it seems it didn't produce interpretable results in this specific environment. |
|
Oki |
|
@dwalend Any feedback? |
|
I'm pretty pragmatic about how performance is measured. Whatever you like is fine, so long as it matches with the reality of how fast my kid can close a control loop. I saw useful values via System.currentTimeMillis(). If the JMH profiler is available as a library you can probably run the profiler in the same JVM as the code you are observing to save the switching overhead. I'm not sure if that is of interest. And the same for NIO vs JNA vs JNI. Whatever performs best is the right answer. I like the advantage of an all-Java NIO fix because it takes me a lot less to explain what the code does to the kids I'm teaching. "This code reads the sensor the same way it would read a file. It's tweaked out a bit to read the file really fast," is pretty easy. In fact "It reads this many bytes or fewer," is helpful for inviting the kids a level deeper without a huge context switch. The next big step forward in performance is keeping the file handle open, at least on the NIO front. It's a big boost for not a lot of new concepts or complexity. As for what API to supply - KISS is the best answer. Java's culture and community tends to bring in a lot of object-oriented hierarchy complexity that doesn't help a developer understand or use a library. Here on the EV3 it really matters. Restarts are frequent. Loading extra classes is really slow. Each extra layer of abstraction - especially classes - has a big cost, but not a lot of benefit. The kid plugged in the gyro sensor to read the robot's heading. The fact that it has the same API as the color sensor doesn't make up for the complexity of creating a float array to get one number - a number that is always an int. Discover the actual useful commonality and refactor to take advantage of it instead of forcing the internal programming model on people who use your library. Do a good job of exposing everything using a similar pattern, but do a great job with the simple common use cases. I especially want to discourage anything that involves making decisions about concurrency. The big lesson we learned while writing and proofing Concurrency in Practice was that concurrency was a really hard systemic problem best solved in outermost layers of code. Making the choice over-constrains the system. No one can predict what the right answer will be. |
|
Thanks for your comments @dwalend,
Tomorrow, I will clean the branch and I will merge to master and release the library in order to close this issue too: Tomorrow, I will open a new issue to begin with the next level of optimisation.
Agree with you. In the next iteration, we will remove the following blocking delay in a more elegant way: this.detect(LEGO_PORT, port);
if (log.isDebugEnabled()) {
log.debug("Setting port in mode: {}", TACHO_MOTOR);
}
this.setStringAttribute(MODE, TACHO_MOTOR);
Delay.msDelay(1000);
this.detect(TACHO_MOTOR, port);Thanks @dwalend and @JakubVanek for the contributions. Juan Antonio |
|
In progress: |
|
Merged with success in Github Actions. |
Steps:
Sysfs.javaOriginal Request:
The java code attached runs in about 100 to 140 milliseconds per iteration. Similar code using the ev3 classroom from LEGO runs each iteration in 2 to 4 milliseconds. 100 milliseconds is enough time for the robot to travel an inch or 3, which becomes significant quickly.
My question is - is the delay in the ev3 os streaming implementation, or in ev3dev-lang-java:2.6.2-SNAPSHOT code that reads and writes those streams? That'll tell me what to try first to speed it up my own code. If it's at the OS level then probably the best I can do is read and write the buffers in parallel. If it's in Java IO then maybe a JNI approach or an NIO loop could help.
I'm using ev3dev-lang-java:2.6.2-SNAPSHOT - on a stock EV3, not overclocked, with the stock ev3dev OS SDD card. It does touch the lejos SampleProvider to use the gyro sensor, but that seems to pass right through to Sysfs.readFloat(...).
Juan Antonio Breña Moral asked me to open an issue for the ev3dev-lang-java project here.
The text was updated successfully, but these errors were encountered: