Resolution of internal timers used for returning solution timings

Hi,

I am currently in the process if trying to do some benchmarking using acados through its Matlab interface in Windows 10.
What I have implemented is a simple MPC for bringing a 5 state unicycle model to the origin.
As the horizon is not overly long, acados solves the problem fairly quick, which leads to the problem I am facing.

It seems that acados is not reliably reporting the solver timings if they are below 1ms.
I am able to measure the time the call to the acados solve() function takes using Matlab’s tic/toc.
Acados, however, returns mostly 0 for the elapsed times, sometimes exactly 1ms.
To me, this look like the internal acados timer has a resolution of 1ms.

The model I am considering is probably to simple to reap the full benefits of acados, but I would still like to clarify if what I see is expected behavior.
Is there a way to get better resolution for the timers?
I would in particular be also interested in the timings for the different solver phases, i.e. QP solution, linearization, etc., which are show the same behavior.

Hi,

So you tried to get the timings like this? https://github.com/acados/acados/blob/80b3461b49c39f92f98057bdc00734d268d6aa9e/examples/acados_matlab_octave/masses_chain_model/example_ocp.m#L257-L266

Here time_tot is the timing of the last call to the solver?

This shows how matlab and internal acados timings can be compared.
For example on my machine, I get:
status = 0, sqp_iter = 4, time_ext = 32.928000 [ms], time_int = 27.968000 [ms] (time_lin = 20.584000 [ms], time_qp_sol = 6.302000 [ms] (time_qp_solver_call = 4.520000 [ms]), time_reg = 0.000000 [ms])
for this example.
Where time_ext is the matlab timing and time_int the internal one from acados.

The timings are measured with this C file, which I did not play with myself. But it should calculate the timings accurately for the common operating systems.


Note that you need to build acados with Release not Debug in CMake.

Cheers!

Thanks for your effort!

Yes, exactly. I call the ocp.get() method after each call to ocp.solve() to save the latest timings and iteration count. Currently I am not using time_tot as it does not return useful values in my case.

To be sure that I did that, I pulled the latest source and built acados again using this guide. I added not other flags and CMake told me that its building in Release mode.

When I run the acados linear mass spring model example, these lines return something like
time_ext = 2.606500 [ms], time_int = 2.000000 [ms] (time_lin = 0.999000 [ms], time_qp_sol = 0.000000 [ms], time_reg = 0.000000 [ms])
or
time_ext = 2.494100 [ms], time_int = 0.999000 [ms] (time_lin = 0.000000 [ms], time_qp_sol = 0.999000 [ms], time_reg = 0.000000 [ms])
for me.

I think its suspicious that its only reporting (roughly) full milliseconds or 0 for the internal timings. Maybe the timer simple does not have the resolution to measure sub millisecond timings, even though from the timing.c file you linked I get the impression that it should measure to at least microseconds.

Edit: To add to this point, if I reduce the horizon length to make the problem faster to solve, at some point acados starts returning 0 ms for all internal timings.

Thanks!

I had another look at the timing.c file you suggested and decided to dig a bit deeper to see if I can find where my issue might come from. I implemented a simple test program in C to test the resolution of the relevant time function:

#include <stdio.h>
#include <sys/time.h>

int main(int argc, char *argv[]) {
    int i;
    unsigned long diff;
    struct timeval tic;
    struct timeval toc;

    gettimeofday(&tic, NULL);
    for (i = 0; i < 1000000; i++) {
        gettimeofday(&toc, NULL);
        diff = toc.tv_usec - tic.tv_usec;

        if (diff != 0) {
           printf("Diff in useconds: %ld\n", diff);
        }

        tic = toc;
    }
}

If I compile this program using mingw32 gcc on my Windows machine, it only prints 999 or 1000, consistent with what acados returns. So the issue is not really with acados, but the underlying implementation of gettimeofday() in Mingw32 / Windows.

I see that there is an alternative timer implementation for Windows in timing.c. Maybe Matlab would also be compatible with Microsoft’s C compiler, but its at least not described in the installation guide. Otherwise I may have to switch to Linux, I guess.

Sorry for the repeated postings, but I found a way around the timer resolution problem. The ANSI C approach that is implemented in timing.c has a much higher resolution when used with MinGW than the C99 mode.

I have implemented a simple quick fix that works for me. With this change I get reliable timings with sub millisecond resolution from acados both for the simple_ocp.m example and for my scripts.

Thanks again for your pointer to timing.c!

Hi Christian,

thanks for checking that on your system.
The change looks good to me!
I just merged your change with this PR Python integrator interface improvements by FreyJo · Pull Request #702 · acados/acados · GitHub

Best,
Jonathan

1 Like

Hi Jonathan,

thanks a lot!
I ran the linear mass spring example again to verify and it works as expected now:

old: time_int = 1.000000 [ms] (time_lin = 0.000000 [ms], time_qp_sol = 0.000000 [ms], time_reg = 0.000000 [ms])
new: time_int = 1.095000 [ms] (time_lin = 0.357700 [ms], time_qp_sol = 0.568000 [ms], time_reg = 0.000200 [ms])

Best,
Christian

1 Like