Profiling Micropython code

[jaguilar]

Hi, I'm using Micropython on the Lego EV3 brick (Arm9 CPU of some variety). I'm trying to write a PID controller that ideally would loop at around a 1000hz frequency while leaving some processor time for other things. (It's actually three different PID controllers each of which would ideally loop at 333hz.)

I've done those things that are obvious to me, like switching from floating point multiplies/divides to integer scaling. I've scattered @micropython.native and @micropython.viper annotations about wherever I can without an error resulting.

At this point, the code is just about fast enough, but it would be more comfortable if it were a little faster. I'm wondering where to direct my efforts. Which lines of code are taking up the most time? Normally at work I would fire up a profiler and I'd be able to get line or even instruction level cpu time counts. But I can't seem to find any similar tooling for Micropython.

So my first question is: is there an instruction-level profiler for Micropython?

If function/method level timing a la @timed_function is the only mechanism that is easily available, I have some follow-up questions:

1. Is there a general guideline as to how expensive function calls are in Micropython? (This affects how small of a piece of code I can instrument with @timedfunction.)
2. Regarding the code generators native and viper, does it matter for performance purposes whether the callee function is also generated with the same code generator? For example, if a viper function calls another viper function, does that introduce a lower amount of overhead compared to a viper function calling a native or unannotated function? Does Viper know how to inline another Viper function?

I would also appreciate any other tips or pointers to discussions about optimizing CPU-heavy code. Bear in mind I am using Micropython 1.11 because that is the latest version that pybricks is shipping on ev3dev. Also, for completeness of information, here is the current state of my code.

[rkompass]

Hello @jaguilar,

I'm interested in this. Partly because I think we need a flexible and good PID solution. One that is able to interface quadrature encoders as well as pwm controls of ordinary and stepper motors in a clear fashion.

Why do you want to have the PID controller loop at 1 kHz? Usually the motor-controlling PWM is in the kHz range.
So assuming 1 ms between PWM pulses you never will see a changed speed within a ms. I think 100Hz should be very fast alreaty.
In the case of heat regulation there should be several seconds o.k..
Do you have a special use case in mind, that requires such high speed?

For the code: At a first glance I saw

@micropython.viper
def log2_ratio_mul(n: int, num: int, shr: int) -> int:
    return (n * num) >> shr

This probably does not speed up things, because the call of the viper function takes a few microseconds. It may even be slower than having this computation in MP. But you may check that with ordinary profiling:
Use ticks_us() and ticks_diff() from the time / utime module. Perhaps append several such instructions after each other:

from time import ticks_us, ticks_diff

@micropython.viper
def log2_ratio_mul(n: int, num: int, shr: int) -> int:
    return (n * num) >> shr

a = 0
b,c,d = 2, 5, 8

def use_viper():
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)
    a = log2_ratio_mul(b, c, d)

def use_mp():
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d
    a = (b * c) >> d

start = ticks_us()
use_viper()
stop = ticks_us()
print('use_viper() took ', ticks_diff(stop, start)/10, 'us')

start = ticks_us()
use_mp()
stop = ticks_us()
print('use_mp() took ', ticks_diff(stop, start)/10, 'us')

results in:

use_viper() took  24.4 us
use_mp() took  15.3 us

here, so this use of viper slowed things down.

Viper shines if working on arrays of data. So if the processing is done in several data sequentially the function call overhead does not count this much.

[GitHubsSilverBullet]

›range()‹ is bad, whereas ›while‹ using a manually decrementing integer is good.
Calling another function in a loop is bad as well.
Using very short viper functions with little computing is bad. Make'em do al lot!

Remember, viper code can be blazing fast, as long as one stays within that function and knows the viper limitations.
Write your viper code like a C programmer (remember, a good C-programmer can write C programs in any language) ;-)

[jaguilar]

@GitHubsSilverBullet Thank you! I won't claim to be a good C-programmer, but I am a C programmer. Is it also worth slamming all the member variables into a single bytearray to minimize the local variable lookup cost? I did benchmark that and didn't see too much of a win from it, but it's also possible I was holding it wrong.

Regarding the idea of programming this module in C/C++: it seems like there are at least three ways to do this: the ffi module, the mpy approach, and also building the module directly into micropython using this approach. I think I don't want to do that last option, on the basis of the micropython instance I have being shipped from the pybricks guys and not wanting to figure out their build system. The mpy and ffi approaches both seem viable. Any sense of which has fewer gotchas?

[rkompass]

I think you have to test a lot yourself.
Specifically I seem to remember that in viper range is translated into a fast for loop. We had this topic once.
But of course it you program the while loop with if/else it is as fast as can be. Almost pure (however not-optimized) C.
Having variables together in an array.array or bytearray speeds things up, without doubt. You save the look-up times for the variables. And with ptr8/ptr16/ptr32 you may access single variables within the array with ease.

[jaguilar]

@rkompass My project is basically done, thanks in no small part to your help. You can see a video of it working on the README page for the project.

https://github.com/jaguilar/gyroboy

You had asked about the PID controller. The code is in the IntPID class. There are still some things that could be cleaned up, like using array instead of bytearray (I wasn't aware of the former until you mentioned it in response to my other question). But it seems to basically work to keep the robot upright. It needs more tuning and possibly a change in the inputs to really work well. I discuss this somewhat in the README.

[rkompass]

Impressing. Nice Video.

[GitHubsSilverBullet]

Specifically I seem to remember that in viper range is translated into a fast for loop.

Nahhh.

But of course it you program the while loop with if/else it is as fast as can be. Almost pure (however not-optimized) C.

#!/usr/bin/python3
# -*- coding: UTF-8 -*-
# vim:fileencoding=UTF-8:ts=4

from time import ticks_us, ticks_diff

@micropython.viper
def a(n):
    for _ in range(int(n)):
        pass

@micropython.viper
def b(n: int):
    while n > 0:
        n -= 1

t0 = ticks_us()
a(1_000_000)
t1 = ticks_us()
print(f'actual time:{ticks_diff(t1, t0):6d} µs')

t0 = ticks_us()
b(1_000_000)
t1 = ticks_us()
print(f'actual time:{ticks_diff(t1, t0):6d} µs')


>>> actual time:224051 µs
>>> actual time:104035 µs

[rkompass]

Haha, thank you @GitHubsSilverBullet,

the for loop is not as fast. But it definitely is not using the MP range function. That would be much slower.

It's always good to update the old memories.

[samneggs]

@GitHubsSilverBullet , while this example is impressive remember this ~215% speed improvement is with an empty loop which is the best it's going to be. Once you add the code within the loop you only get the speed up as a proportion of that code. The more code the less difference between For and While. I tried this with whatever I was currently working on and I got 5% improvement. For me, sometimes readability of a For is more important.
But for a minimalist tight loop definitely use While.

[GitHubsSilverBullet]

improvement is with an empty loop

That really was the point! Being able to compare two empty loops.
Subtract'em and you'll get the pure and simple overhead.
Decide what to use at your own discretion…

[jaguilar]

Later on after we had this discussion I reimplemented things in C and got another 4x speedup (with the business logic included)! It ended up taking less time than all the hacking I did on Viper before I gave up.