Access file as quickly as possible

[cho934]

Hi,

I'm trying to optimise the access to the file value0 for angle sensors, or IR sensors. Because my motion system need these data every 5ms.

ifstream is currently used, I already managed some little change to decrease access time, but it's not enough (I opened the file once at the beginning, and during the loop, I just read).

Do you know how to be faster to retrieve the value (int) inside the file ? Maybe using POSIX like described here https://stackoverflow.com/questions/17925051/fast-textfile-reading-in-c What do you think ?

You seem to use a cache, but I don't understand, Are you sure that the cache is really used using this current code in ev3dev.cpp ?

// A global cache of files.
std::ifstream& ifstream_cache(const std::string &path) {
  static lru_cache<std::string, std::ifstream> cache(FSTREAM_CACHE_SIZE);
  static std::mutex mx;

  std::lock_guard<std::mutex> lock(mx);
  return cache[path];
}

BR, Cho.

[ddemidov]

The LRU cache was added in https://github.com/ev3dev/ev3dev-lang/pull/25. The benchmarks there suggest the cache does help with the peformance. One other thing to try would be to cache FILE handles instead of std::ifstream objects, and use fscanf instead of iostream (for an example, see https://www.geeksforgeeks.org/cincout-vs-scanfprintf/).

Also, see some discussion in https://github.com/ev3dev/ev3dev/issues/324. It could be that ev3dev polling interval is the limiting factor for you, and not the library performance.

[cho934]

Here are the extend class to use posix functions and increase performance by 40.

How to integrate it better ?

You can use the functions to open/read/close each time or use the splitted functions to optimize calls in your own. It increases of course a little bit more the performance.

ev3dev_extend.h

#ifndef DRIVER_EV3_EV3DEV_EXTEND_HPP_
#define DRIVER_EV3_EV3DEV_EXTEND_HPP_
#include <string>
class device_extend
{
public:
    void set_attr_int_posix(int fd, int value);
    int get_attr_int_posix(int fd);
    void set_attr_string_posix(int fd, std::string name);
    std::string get_attr_string_posix(int fd);
    int open_posix_in(std::string pathfile);
    int open_posix_out(std::string pathfile);
    void close_posix(int fd);

    int open_get_attr_int_close_posix(std::string name);
    std::string open_get_attr_string_close_posix(std::string pathfile);
};
#endif /* DRIVER_EV3_EV3DEV_EXTEND_HPP_ */

ev3dev_extend.cpp

#include "ev3dev_extend.hpp"
#include <fcntl.h>
#include <stddef.h>
#include <unistd.h>
#include <cstdio>
#include <cstring>
#include <iostream>
#include <vector>

int device_extend::open_get_attr_int_close_posix(std::string pathfile)
{
    int in = open_posix_in(pathfile);
    int data = get_attr_int_posix(in);
    close_posix(in);
    return data;
}

std::string device_extend::open_get_attr_string_close_posix(std::string pathfile)
{
    int in = open_posix_in(pathfile);
    try {
        std::string data = get_attr_string_posix(in);
        close_posix(in);
        return data;
    } catch (...) {
        close_posix(in);
        throw;
    }
}

void device_extend::set_attr_int_posix(int fd, int value)
{
    try {
        char tmp[10] = { 0x0 }; //maximum digits
        sprintf(tmp, "%d", value);
        ::lseek(fd, 0, SEEK_SET);
        ::write(fd, tmp, strlen(tmp));
        if (errno == ENODEV) {
            printf("[set_attr_int_posix] ENODEV !!!\n");
        }
    } catch (...) {
        throw;
    }
}

void device_extend::set_attr_string_posix(int fd, std::string name)
{
    try {
        const char *tmp = name.c_str();
        ::lseek(fd, 0, SEEK_SET);
        ::write(fd, tmp, strlen(tmp));
        if (errno == ENODEV) {
            printf("[set_attr_string_posix] ENODEV !!!\n");
        }
    } catch (...) {
        throw;
    }
}

std::string device_extend::get_attr_string_posix(int fd)
{
    try {
        std::vector<char> inBuffer(1024);
        size_t inFileSize = ::lseek(fd, 0, SEEK_END);
        ::lseek(fd, 0, SEEK_SET);

        for (size_t bytesLeft = inFileSize, chunk = inBuffer.size(); bytesLeft > 0; bytesLeft -= chunk) {
            if (bytesLeft < chunk) {
                chunk = bytesLeft;
            }
            ::read(fd, &inBuffer[0], chunk);
        }
        std::string s(inBuffer.begin(), inBuffer.end());
        return s;
    } catch (...) {
        throw;
    }
}

int device_extend::get_attr_int_posix(int fd)
{
    std::string s = get_attr_string_posix(fd);
    int data = std::stoi(s, nullptr, 0); //convert to int
    return data;
}

int device_extend::open_posix_in(std::string pathfile)
{
    const char *inFile = pathfile.c_str();
    int in = ::open(inFile, O_RDONLY, 0666);
    if (in < 0) {
        std::cout << "open_posix_in :: Can't open output file: " << inFile << std::endl;
        return -1;
    }
    return in;
}

int device_extend::open_posix_out(std::string pathfile)
{
    const char *outFile = pathfile.c_str();
    int out = ::open(outFile, O_WRONLY, 0666);
    if (out < 0) {
        std::cout << "open_posix_out :: Can't open output file: " << outFile << std::endl;
        return -1;
    }
    return out;
}

void device_extend::close_posix(int fd)
{
    ::close(fd);
}

[ddemidov]

The performance gains look interesting. All file operations in ev3dev.cpp are implemented in terms of std::ifstreasm/std::ofstream objects. I guess you could try to implement a thin wrapper class for the posix operations, which then could be stored in LRU cache and used instead of STL IO classes. Looks like only attribute getters and setters in device class should be affected by the change.

[cho934]

The performance gains look interesting. All file operations in ev3dev.cpp are implemented in terms of std::ifstreasm/std::ofstream objects. I guess you could try to implement a thin wrapper class for the posix operations, which then could be stored in LRU cache and used instead of STL IO classes. Looks like only attribute getters and setters in device class should be affected by the change.

That's why I created the extended class, you can see above. The files ev3dev.cpp and ev3dev.h seem to be auto-generated. I didn't want to broke it. I don't know how to use LRU cache, I need help to do it or if someone do it, I can test ;)

[ddemidov]

Did you try to compare the performance of POSIX API with that of <cstdio>?

I mean, in your code there is a lot of calls to sprintf() to temporary buffers with subsequent calls to posix write(), which could in principle be shortcircuited to a single call to fprintf().

The files ev3dev.cpp and ev3dev.h seem to be auto-generated.

Not anymore: 2f7c128

[ddemidov]

if someone do it, I can test ;)

@cho934, #56 uses <cstdio> instead of <fstream> for I/O, so it should be easy for you to compare the performance. It passes the tests, but I did not try to run it on the EV3.

[cho934]

if someone do it, I can test ;)

@cho934, #56 uses <cstdio> instead of <fstream> for I/O, so it should be easy for you to compare the performance. It passes the tests, but I did not try to run it on the EV3.

Sorry I don't understand. I'm using above in the class ev3dev_extend. To summarize, I tested plenty of different ways to read/write and do some benchmarks on the EV3. I used this : https://github.com/lemire/Code-used-on-Daniel-Lemire-s-blog/blob/master/2012/06/26/ioaccess.cpp and this : https://lemire.me/blog/2012/06/26/which-is-fastest-read-fread-ifstream-or-mmap/

=> The result is that POSIX functions are the fastest, that's why I created this class to contribute and give to the community my conclusions ;)

[ddemidov]

The code in #56 is loosely based on your code (thanks for that, by the way!), and replaces <fstream> functionality which is known to be slow with the one from <cstdio>. Specifically, it introduces two classes, file_reader and file_writer which are thin wrappers around <cstdio> functions (fopen, fgets, fscanf, etc). These classes can also be rewritten to use posix calls directly, as you do in your code, but, as I wrote earlier, it does not look like using pure posix calls should be much faster here, as you are combining those with calls to sprintf() and sscanf() anyway.

So could you please rerun your set of tests with ev3dev.cpp from #56 and see if there is a noticeable difference with what you get from ev3dev_extend.h?

[cho934]

You're welcome. Ok, understood now and I saw your code using the LRU_cache in the #56, sorry for the misunderstanding. I can do and plan a new benchmark next week (not available this week-end, and also because my colleague have the robot). ;)

[cho934]

Hi, So the results (in usec) are fast too. But there is an issue : the encoders have the same value all the time (but it turns). And the motor doesn't turn, values are not apply.

Problem with the cache ?

Encoder read 

AsservDriverTest.EV3 INFO   t0-t1=304 t2-t1=1362 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=318 t2-t1=201 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=389 t2-t1=526 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=313 t2-t1=704 t3-t2=10      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=317 t2-t1=482 t3-t2=10      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=1165 t2-t1=246 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=318 t2-t1=425 t3-t2=12      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=312 t2-t1=489 t3-t2=8      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=656 t2-t1=204 t3-t2=10      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=384 t2-t1=221 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=313 t2-t1=201 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=440 t2-t1=2665 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=1811 t2-t1=260 t3-t2=9      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=411 t2-t1=1628 t3-t2=8      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=492 t2-t1=208 t3-t2=10      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=402 t2-t1=209 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=314 t2-t1=201 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=310 t2-t1=365 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=492 t2-t1=634 t3-t2=8      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=315 t2-t1=3946 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=406 t2-t1=427 t3-t2=11      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=315 t2-t1=317 t3-t2=8      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=711 t2-t1=215 t3-t2=10      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=317 t2-t1=360 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=308 t2-t1=1062 t3-t2=8      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=315 t2-t1=202 t3-t2=7      D=0 currentD= -14   ___   G=0 currentG= 7
AsservDriverTest.EV3 INFO   t0-t1=742 t2-t1=233 t3-t2=6      D=0 currentD= -14   ___   G=0 currentG= 7

Motor write test:
AsservDriverTest.EV3 INFO AsservDriverTest::benchmarkPosix() Go
AsservDriverTest.EV3 INFO t0-t1=2625 t2-t1=3453
AsservDriverTest.EV3 INFO t0-t1=152 t2-t1=76
AsservDriverTest.EV3 INFO t0-t1=155 t2-t1=903
AsservDriverTest.EV3 INFO t0-t1=149 t2-t1=81
AsservDriverTest.EV3 INFO t0-t1=314 t2-t1=98
AsservDriverTest.EV3 INFO t0-t1=197 t2-t1=682
AsservDriverTest.EV3 INFO t0-t1=154 t2-t1=83
AsservDriverTest.EV3 INFO t0-t1=148 t2-t1=82
AsservDriverTest.EV3 INFO t0-t1=1851 t2-t1=84
AsservDriverTest.EV3 INFO t0-t1=244 t2-t1=99
AsservDriverTest.EV3 INFO t0-t1=417 t2-t1=115
AsservDriverTest.EV3 INFO t0-t1=220 t2-t1=93
AsservDriverTest.EV3 INFO t0-t1=153 t2-t1=364
AsservDriverTest.EV3 INFO t0-t1=497 t2-t1=305
AsservDriverTest.EV3 INFO t0-t1=358 t2-t1=167
AsservDriverTest.EV3 INFO t0-t1=156 t2-t1=165
AsservDriverTest.EV3 INFO t0-t1=151 t2-t1=77
AsservDriverTest.EV3 INFO t0-t1=868 t2-t1=112
AsservDriverTest.EV3 INFO t0-t1=143 t2-t1=80
AsservDriverTest.EV3 INFO t0-t1=139 t2-t1=79
AsservDriverTest.EV3 INFO t0-t1=206 t2-t1=94
AsservDriverTest.EV3 INFO t0-t1=150 t2-t1=176

[ddemidov]

I think this may be because I forgot to do fseek(0) in the writer class. Does d4dae3e help?

[cho934]

It doesn't help with read (for the encoders).

About the write, it's like just an impulse on the motor, weird...

[ddemidov]

Another try: bb8a873 disables io buffering for the opened files. Sorry for not being able to test this myself, I currently have no access to my ev3.

[cho934]

No pb ;)

It's working well. But now the read timing is much more 1ms than before with 300/400us

AsservDriverTest.EV3 INFO testcodeurs()...
AsservDriverTest.EV3 INFO t0-t1=6284 t2-t1=3924 t3-t2=11      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=574 t2-t1=541 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1001 t2-t1=877 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=578 t2-t1=459 t3-t2=7      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1653 t2-t1=1294 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1463 t2-t1=816 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=583 t2-t1=554 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=591 t2-t1=1030 t3-t2=11      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=888 t2-t1=647 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=657 t2-t1=1041 t3-t2=10      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=856 t2-t1=799 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1041 t2-t1=1237 t3-t2=10      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=669 t2-t1=1111 t3-t2=10      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=948 t2-t1=572 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1254 t2-t1=509 t3-t2=13      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1609 t2-t1=519 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1173 t2-t1=496 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=746 t2-t1=471 t3-t2=10      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=581 t2-t1=575 t3-t2=195      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1826 t2-t1=832 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0

For the write, sometimes instead of 300/400us the write tooks 1ms or or or 4ms (1 request on 10)

AsservDriverTest.EV3 INFO t0-t1=502 t2-t1=294
AsservDriverTest.EV3 INFO t0-t1=230 t2-t1=205
AsservDriverTest.EV3 INFO t0-t1=315 t2-t1=205
AsservDriverTest.EV3 INFO t0-t1=252 t2-t1=500
AsservDriverTest.EV3 INFO t0-t1=1023 t2-t1=464
AsservDriverTest.EV3 INFO t0-t1=311 t2-t1=230
AsservDriverTest.EV3 INFO t0-t1=700 t2-t1=257
AsservDriverTest.EV3 INFO t0-t1=381 t2-t1=305
AsservDriverTest.EV3 INFO t0-t1=229 t2-t1=287
AsservDriverTest.EV3 INFO t0-t1=330 t2-t1=226
AsservDriverTest.EV3 INFO t0-t1=314 t2-t1=3465
AsservDriverTest.EV3 INFO t0-t1=2694 t2-t1=365
AsservDriverTest.EV3 INFO t0-t1=245 t2-t1=204
AsservDriverTest.EV3 INFO t0-t1=268 t2-t1=1816
AsservDriverTest.EV3 INFO t0-t1=336 t2-t1=201
AsservDriverTest.EV3 INFO t0-t1=4535 t2-t1=226
AsservDriverTest.EV3 INFO t0-t1=240 t2-t1=301
AsservDriverTest.EV3 INFO t0-t1=253 t2-t1=209
AsservDriverTest.EV3 INFO t0-t1=1334 t2-t1=232
AsservDriverTest.EV3 INFO t0-t1=2748 t2-t1=625
AsservDriverTest.EV3 INFO t0-t1=251 t2-t1=280
AsservDriverTest.EV3 INFO t0-t1=287 t2-t1=303
AsservDriverTest.EV3 INFO t0-t1=310 t2-t1=3295
AsservDriverTest.EV3 INFO t0-t1=790 t2-t1=308
AsservDriverTest.EV3 INFO t0-t1=234 t2-t1=287
AsservDriverTest.EV3 INFO t0-t1=298 t2-t1=220

[cho934]

The long exceptional timings (>4ms) seem linked to my log system.

[ddemidov]

How does this compare to the posix timings?

[cho934]

Here is the same test with my extend class and optimisations of opened files, the average is a little bit less (always under 500us)

Read 2 encoders

AsservDriverTest.EV3 INFO   t0-t1=992 t2-t1=534 t3-t2=8      D=0 currentD= -1   ___   G=0 currentG= 87
AsservDriverTest.EV3 INFO   t0-t1=452 t2-t1=239 t3-t2=7      D=0 currentD= -1   ___   G=0 currentG= 87
AsservDriverTest.EV3 INFO   t0-t1=355 t2-t1=229 t3-t2=9      D=0 currentD= -1   ___   G=0 currentG= 87
AsservDriverTest.EV3 INFO   t0-t1=495 t2-t1=327 t3-t2=11      D=0 currentD= -1   ___   G=0 currentG= 87
AsservDriverTest.EV3 INFO   t0-t1=287 t2-t1=213 t3-t2=7      D=0 currentD= -1   ___   G=0 currentG= 87

Write 2 motors (second writing is always less...)

AsservDriverTest.EV3 INFO t0-t1=1366 t2-t1=330
AsservDriverTest.EV3 INFO t0-t1=153 t2-t1=97
AsservDriverTest.EV3 INFO t0-t1=152 t2-t1=92
AsservDriverTest.EV3 INFO t0-t1=230 t2-t1=105
AsservDriverTest.EV3 INFO t0-t1=151 t2-t1=92
AsservDriverTest.EV3 INFO t0-t1=432 t2-t1=129
AsservDriverTest.EV3 INFO t0-t1=153 t2-t1=93
AsservDriverTest.EV3 INFO t0-t1=458 t2-t1=461
AsservDriverTest.EV3 INFO t0-t1=153 t2-t1=96

[ddemidov]

My next guess is that our LRU cache has some overhead. The files are keyed by paths, so finding correct file handle involves a number of string comparisons. Your extend class stores the file handles directly, which makes it faster.

Do you have the results for the current (iostream-based) ev3dev.cpp somewhere?

[cho934]

I keep in this test exactly the same test with same priority of threads, otherwise timings are biggers more often. I'm using the last image ev3dev-stretch 'ev3dev-stretch-ev3-generic-2019-10-23.zip) and not anymore my old one. Here are the results with current ev3dev.cpp version using ifstream/ofstream.

Read 2 encoders

AsservDriverTest.EV3 INFO t0-t1=16070 t2-t1=6973 t3-t2=13      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=1448 t2-t1=1476 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO t0-t1=856 t2-t1=425 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
...
AsservDriverTest.EV3 INFO   t0-t1=1486 t2-t1=540 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=1095 t2-t1=543 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=5388 t2-t1=7892 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=539 t2-t1=699 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=542 t2-t1=1277 t3-t2=12      D=0 currentD= 0   ___   G=-1 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=639 t2-t1=431 t3-t2=12      D=0 currentD= 0   ___   G=0 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=899 t2-t1=1468 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=1152 t2-t1=539 t3-t2=7      D=0 currentD= 0   ___   G=1 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=754 t2-t1=741 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=929 t2-t1=765 t3-t2=7      D=0 currentD= 0   ___   G=-1 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=737 t2-t1=478 t3-t2=7      D=0 currentD= 0   ___   G=0 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=1139 t2-t1=1136 t3-t2=8      D=0 currentD= 0   ___   G=1 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=546 t2-t1=1187 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=1113 t2-t1=434 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=564 t2-t1=384 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=748 t2-t1=793 t3-t2=9      D=0 currentD= 0   ___   G=-1 currentG= -1
AsservDriverTest.EV3 INFO   t0-t1=621 t2-t1=1251 t3-t2=13      D=0 currentD= 0   ___   G=1 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=896 t2-t1=546 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0

2nd test

AsservDriverTest.EV3 INFO   t0-t1=1041 t2-t1=1406 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=1513 t2-t1=1218 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=810 t2-t1=6311 t3-t2=16      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=538 t2-t1=902 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=981 t2-t1=1289 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=919 t2-t1=1125 t3-t2=15      D=1 currentD= 1   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=1291 t2-t1=509 t3-t2=8      D=-1 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=545 t2-t1=500 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=2815 t2-t1=2171 t3-t2=10      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=613 t2-t1=681 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=938 t2-t1=438 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=532 t2-t1=4590 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=742 t2-t1=425 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=862 t2-t1=459 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=1350 t2-t1=548 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=528 t2-t1=534 t3-t2=8      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=2037 t2-t1=440 t3-t2=12      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=545 t2-t1=1328 t3-t2=15      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=840 t2-t1=1131 t3-t2=16      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=543 t2-t1=1241 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=3505 t2-t1=3403 t3-t2=11      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=543 t2-t1=775 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=545 t2-t1=956 t3-t2=9      D=0 currentD= 0   ___   G=0 currentG= 0
AsservDriverTest.EV3 INFO   t0-t1=536 t2-t1=2106 t3-t2=178      D=0 currentD= 0   ___   G=0 currentG= 0

write 2 motors

AsservDriverTest.EV3 INFO t0-t1=11721 t2-t1=4543
AsservDriverTest.EV3 INFO t0-t1=1175 t2-t1=464
AsservDriverTest.EV3 INFO t0-t1=309 t2-t1=175
AsservDriverTest.EV3 INFO t0-t1=350 t2-t1=543
AsservDriverTest.EV3 INFO t0-t1=258 t2-t1=171
AsservDriverTest.EV3 INFO t0-t1=830 t2-t1=570
AsservDriverTest.EV3 INFO t0-t1=1483 t2-t1=3513
AsservDriverTest.EV3 INFO t0-t1=345 t2-t1=191
AsservDriverTest.EV3 INFO t0-t1=256 t2-t1=169
AsservDriverTest.EV3 INFO t0-t1=249 t2-t1=182
AsservDriverTest.EV3 INFO t0-t1=253 t2-t1=270
AsservDriverTest.EV3 INFO t0-t1=983 t2-t1=501
AsservDriverTest.EV3 INFO t0-t1=435 t2-t1=179
AsservDriverTest.EV3 INFO t0-t1=342 t2-t1=244
AsservDriverTest.EV3 INFO t0-t1=491 t2-t1=391
AsservDriverTest.EV3 INFO t0-t1=440 t2-t1=1031
AsservDriverTest.EV3 INFO t0-t1=248 t2-t1=443
AsservDriverTest.EV3 INFO t0-t1=246 t2-t1=261
AsservDriverTest.EV3 INFO t0-t1=509 t2-t1=739
AsservDriverTest.EV3 INFO t0-t1=553 t2-t1=415
AsservDriverTest.EV3 INFO t0-t1=771 t2-t1=222
AsservDriverTest.EV3 INFO t0-t1=1240 t2-t1=541
AsservDriverTest.EV3 INFO t0-t1=558 t2-t1=863
AsservDriverTest.EV3 INFO t0-t1=311 t2-t1=204
AsservDriverTest.EV3 INFO t0-t1=462 t2-t1=196
AsservDriverTest.EV3 INFO t0-t1=255 t2-t1=295
AsservDriverTest.EV3 INFO t0-t1=255 t2-t1=178
AsservDriverTest.EV3 INFO t0-t1=253 t2-t1=178
AsservDriverTest.EV3 INFO t0-t1=250 t2-t1=540
AsservDriverTest.EV3 INFO t0-t1=252 t2-t1=179
AsservDriverTest.EV3 INFO t0-t1=257 t2-t1=184
AsservDriverTest.EV3 INFO t0-t1=3337 t2-t1=1151
AsservDriverTest.EV3 INFO t0-t1=247 t2-t1=374
AsservDriverTest.EV3 INFO t0-t1=550 t2-t1=208
AsservDriverTest.EV3 INFO t0-t1=251 t2-t1=383
AsservDriverTest.EV3 INFO t0-t1=305 t2-t1=287
AsservDriverTest.EV3 INFO t0-t1=679 t2-t1=198
AsservDriverTest.EV3 INFO t0-t1=250 t2-t1=174
AsservDriverTest.EV3 INFO t0-t1=257 t2-t1=554
AsservDriverTest.EV3 INFO t0-t1=7200 t2-t1=262
AsservDriverTest.EV3 INFO t0-t1=637 t2-t1=553
AsservDriverTest.EV3 INFO t0-t1=1320 t2-t1=237
AsservDriverTest.EV3 INFO t0-t1=248 t2-t1=263
AsservDriverTest.EV3 INFO t0-t1=254 t2-t1=397
AsservDriverTest.EV3 INFO t0-t1=251 t2-t1=261
AsservDriverTest.EV3 INFO t0-t1=255 t2-t1=659
AsservDriverTest.EV3 INFO t0-t1=840 t2-t1=296