Profiling features

[peufeu2]

Greetings!

I really like this library, one of the best for arduino!

I'm using it with ESP32 for my home heating controller, it has 20 coroutines at the moment.

I wanted the input filtering and debouncing coroutine to execute every 10-20ms. So I had to hunt slow stuff in the other coroutines to prevent them from executing for longer than that.

In order to do that, I've added a few features, so here are the files, in case you find them useful.

There are 3 #defines to enable the features:

#define ACE_ROUTINE_ENABLE_NAME

This juts adds a "const char*name" to the coroutine base class. I initialize it in derived classes.

#define ACE_ROUTINE_USE_32BIT_TIMERS

This one replaces the delay timers with a single 32 bit timer using microseconds. It makes no sense to save a few bytes of RAM/Flash on ESP32. This gives longer possible delays using one single function (COROUTINE_DELAY_MICROS).

#define ACE_ROUTINE_BENCHMARK 20

This one requires the above two #defines to be active. It adds an array mRuntimeStats[] to each coroutine. Every time the scheduler executes this coroutine, it measures its execution time, and increments mRuntimeStats[ log2( time in µs ) ]. So this array contains a histogram of execution times, in a form that doesn't use too much RAM.

I've added functions to encode that as JSON, here's a sample output:

{
"GrugRequest":[0, 50007, 218, 0, 114, 4, 1, 0, 0, 0, 0, 1, 53, 0, 52, 0, 0, 0, 0, 0],
"GrugHTTP":[0, 2, 157, 52, 1, 48208, 1924, 0, 0, 103, 2, 1, 0, 0, 0, 0, 0, 0, 0, 0],
"3ffc1c6c":[0, 0, 50282, 1, 160, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"keyb":[0, 1, 44664, 5535, 150, 100, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"ui":[0, 49861, 362, 4, 88, 3, 0, 0, 132, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"autoconso":[0, 0, 50071, 104, 240, 9, 0, 0, 0, 0, 0, 0, 0, 26, 0, 0, 0, 0, 0, 0],
"pv":[0, 0, 50103, 39, 244, 50, 2, 0, 0, 0, 4, 4, 0, 4, 0, 0, 0, 0, 0, 0],
"pcbt_pf":[0, 0, 49855, 62, 264, 164, 105, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"pcbt_pc":[0, 0, 49896, 7, 274, 262, 11, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"et_bureau":[0, 0, 49853, 54, 271, 262, 10, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"idle":[0, 0, 49920, 151, 366, 13, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"demande":[0, 0, 49995, 1, 186, 256, 12, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"fault":[0, 0, 50154, 62, 222, 12, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"relays":[0, 0, 50250, 0, 192, 8, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"onewire":[0, 0, 44601, 13, 181, 8, 0, 0, 0, 0, 0, 1448, 0, 4163, 36, 0, 0, 0, 0, 0],
"wifi":[0, 0, 49927, 9, 489, 25, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"led":[0, 0, 47589, 1, 2522, 336, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"led_error":[0, 0, 35925, 14271, 162, 92, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"beep":[0, 0, 33410, 0, 16337, 697, 6, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0],
"input_filter":[0, 0, 50182, 47, 211, 10, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
}

That gives a useful plot of the probability distribution of runCoroutine() time:

Thanks to this I've managed to find the coroutines that were taking too long (it was mostly the I2C LCD) and snipe some YIELDs into them, which keeps the maximum runCoroutine() runtime of all of them below 16ms now. So everything runs fine.

Have a nice day!

ace_routine.zip

[peufeu2]

I have also written a much faster micros() function for ESP32 to speed things up. Integrates without any change to AceRoutine via ClockInterface.

https://github.com/peufeu2/ESP32FastMillis

[bxparks]

So the disadvantages of using ESP32FastMillis is that it consumes a hardware timer? Also, I'd recommend pulling out the FastClockInterface into a separate file, so that it's more explicit that it is designed to work with AceRoutine, while the other parts can be used independently.

[peufeu2]

Correct, actually it consumes two timers (one for micros and one for millis). I wasn't using them, ESP32 has four timers, plus 16 PWM channels for LEDs, so it doesn't suffer from a shortage of this sort of peripherals.

On ESP32 running at 80MHz, micros() takes ~155 cycles, and millis() takes 240 cycles. This is ridiculous, mostly due to them using the cycle counter running at the cpu frequency, which needs a 64 bit division by the cpu frequency to get microseconds, which takes a while. Then millis() calls micros() and does another 64-bit division by 1000. In addition esp_timer_get_time isn't marked IRAM_ATTR so the function is in flash, which means if it is not in the cpu cache when it is called, the significant random SPI flash access delay is added.

I discovered this because OneWire wasn't working. It uses delayMicroseconds() for its bit-banging, and that calls micros() at least twice, which means delayMicroseconds(1) takes ~ 330 cycles, which at 80MHz is more than 4µs instead of the requested 1µs. So all the bit-banging timings were wrong, and it got unhappy with plenty of CRC errors!

On the other hand, fastmicros() takes ~18 cycles , which means it can make accurate microsecond delays. I modified OneWire to use it, and all the errors disappeared. I considered using the cpu cycle counter register, but then the delay function would need to know the clock frequency, and calling getCpuFequencyMHz() takes 140 cycles.

and fastmillis() takes ~44 cycles, because the timer prescaler does the division instead of the cpu.

I will cleanup the files as suggested.

[bxparks]

Hi, Thanks for posting, you got a lot of good ideas. Here are my initial thoughts:

General Comments

You are using an impressive number of coroutines, 20. The most that I have used is about 8.

In general, I prefer to avoid using the c-preprocessor macros to activate/deactivate features in my libraries. Partly because changing the macro often forces the entire application and dependent libraries to be recompiled to avoid subtle compile-time and link-time errors. And partly because the Arduino IDE stubbornly refuses to support the -D flag, so it is difficult for most Arduino users to access those features. If possible, I prefer configuration mechanisms that allow the end-user to select those features within the C++ language itself, either at compile-time or at runtime.

ACE_ROUTINE_ENABLE_NAME

AceRoutine automatically added the name string to each coroutine prior to v1.3, but I took that feature out in a flurry of refactoring to save 800-1000 bytes of flash memory on 8-bit processors. In retrospect, I should have made coroutine names an optional feature, instead of taking it out completely. It would cost only 2 bytes of static RAM on 8-bit processors if not used. I have been thinking about adding this feature back in.

ACE_ROUTINE_USE_32BIT_TIMERS

As far as I can tell, the primary reason that you need 32-bit counters is because you need the dynamic range of a 32-bit integer for your histograms. My expectation was that if someone needed to call COROUTINE_DELAY_MICROS() for more than ~65 millis, they could just use COROUTINE_DELAY() instead, because they really don't need microsecond precision when waiting for that length of time. And if they needed to delay for more than 65 seconds, they could use COROUTINE_DELAY_SECONDS() instead.

In your case, you need to have the entire 32-bit dynamic range to update your histogram. Is that a fair assessment? [Having gone through your code while writing the rest of this comment, I get the impression that you don't really need these to be uint32_t, because the determination of the elapsed microseconds for the call to Coroutine::runCoroutine() uses its own uint32_t micros_start variable, which is independent of whether the mDelayStart and mDelayDuration are 16-bits or 32-bits.]

Following my general preference about avoiding compile-time macros to control behavior, I would prefer to avoid using the ACE_ROUTINE_USE_32BIT_TIMERS. I see 2 options:

Option 1: Use uint32_t for 32-bit processors, and continue to use a uint16_t for 8-bit processors. The potential issue is that there would be a slight difference in behavior and semantics of the 3 COROUTINE_DELAY*() macros when a program is compiled on an 8-bit versus a 32-bit processor. Documentation would help, but maybe not, since most people don't read documentation.

Option 2: Change the name of the delay macros to be COROUTINE_DELAY32(), COROUTINE_DELAY_MICROS32(), and COROUTINE_DELAY_SECONDS32() on 32-bit processors. Then the compiler will complain loudly if a program is migrated from a 32-bit processor to an 8-bit processor, or vise-versa, and the programmer is forced to make deliberate changes to make it compatible for the different environments.

My initial thought is that Option 2 would be too disruptive for most people, to save a few narrow edge cases. So I'm leaning towards Option 1.

ACE_ROUTINE_BENCHMARK

This is a cool feature, nicely done. I understand the logarithmic binning and I understand the numbers in the JSON output as a frequency distribution. But I don't think I understand the y-axis of your graph. Did you normalize the frequency distribution so that value for the 1 microsecond bin is always 1? But that doesn't make sense because some of your coroutines have a count of 0 at the 1 microsecond bin, which means -infinity on a log graph.

So with this feature, I would again like to avoid using the ACE_ROUTINE_BENCHMARK macro. And I don't want to hardcode a specific profiling algorithm into my library. I'm thinking that we could extract out the profiling feature into a separate Profiling class which can receive profiling messages from the CoroutineScheduler. The Profiling object can choose to record the information in any way it wants. I imagine end users can create different Profiling objects to record information in different ways.

So roughly, something like this:

class CoroutineProfiler {
public:
  void updateElapsedMicros(uint32_t micros);
};

class Coroutine {
public:
  ...
  void setProfiler(CoroutineProfiler* profiler) { mProfiler = profiler; }
  CoroutineProfiler* getProfiler() const { return mProfiler; }

private:
  ...
  CoroutineProfiler* mProfiler = nullptr;
};


CoroutineSchedule::runCoroutine() {
  ...
  if ((*current)->mProfiler) {
    uint32_t startMicros = T_COROUTINE::coroutineMicros();
    (*current)->runCoroutine();
    uint32_t elapsedMicros = _COROUTINE::coroutineMicros() - startMicros;
    (*current)->mProfiler->updateElapsedMicros(elapsedMicros);
  } else {
    (*current)->runCoroutine();
  }
  ...
}

There's a bunch of design decisions to be made for CoroutineProfiler::updateElapsedMicros():

• Should it be a virtual function to allow different subclasses to be hooked in? Probably, because it needs to support different Profilers.
• Can it be a template argument to CoroutineTemplate? Yes, but that means that end-users would have to create new template instantiations of Coroutine and CoroutineScheduler, just to use a different profiler.
• Should this be available on 8-bit processors? I'm guessing not, because the extra code in CoroutineScheduler and the virtual dispatch to updateElapsedMicros() will cost a significant amount of flash, I'm guessing 200-400 bytes.

But I think you can see where I'm going with this.

PS

Instead of a zip file, maybe you can send me a link to a GitHub repo with the forked code next time? It's easier to see a diff and play with the code using a git repo.

[peufeu2]

Greetings!

I've taken your advice and made a fork in https://github.com/peufeu2/AceRoutine-1

All the latest code is in there, I'd like to know what you think about it.

In general, I prefer to avoid using the c-preprocessor macros

I agree with that! It was a quick'n'dirty test. I've reimplemented it with templates, that allow configuring

• If the coroutine has a name or not

Name is not required for profiling. If it's not there, it will use a hex pointer address, which is... not that helpful if you have more than one.

• What kind of delay management code it uses (32 bit based on micros, or original 16 bit code with millis,seconds,micros)

I put the 32 bit code in Coroutine32bit.h, I added it to the main #include but if it isn't used, then it isn't necessary to #include it.
Currently profiling only works with 32 bit, but it should be possible to make it work with the 16 bit code, with lower accuracy though.

• If it can be profiled or not

Since all coroutines in the application must derive from the same base class, either they all support profiling, or not.

I am very fond of your low-overhead approach, so I wanted to not use a single byte more than the original code if the extra features are disabled. I think that worked, at least on ESP32. So I didn't use virtual functions for a few things that would have been convenient, but would have used extra resources. I did use them in the profiler, because that's gonna use lots of RAM to store the histograms anyway.

This has a few drawbacks, for example if the Name feature is enabled, it is enabled for every coroutine. Oh, well.

Configuration is done in the user code like that:

using Coroutine = ace_routine::CoroutineTemplate< ace_routine::Coroutine_Delay_32bit_Profiler_Impl< ace_routine::NamedCoroutine,ace_routine::ClockInterface >>;
using CoroutineScheduler = ace_routine::CoroutineSchedulerTemplate<Coroutine>;
using Profiler = ace_routine::Profiler;
Profiler *Profiler::root;

That puts the pieces together and enables the features that should be pretty obvious given the class names.

As far as I can tell, the primary reason that you need 32-bit counters is because you need the dynamic range of a 32-bit integer for your histograms.

Yes, it's pretty much the reason.

Another one was to use COROUTINE_DELAY( variable ) and not have to bother with if( it is longer than 32768 ms) and stuff like that.

Having gone through your code while writing the rest of this comment, I get the impression that you don't really need these to be uint32_t, because the determination of the elapsed microseconds for the call to Coroutine::runCoroutine() uses its own uint32_t micros_start variable, which is independent of whether the mDelayStart and mDelayDuration are 16-bits or 32-bits.]

I've changed pretty much everything from my previous code and now it uses mDelayStart. In fact it uses it twice:

When profiling coroutine wait times, when the coroutine is about to run, "micros()-mDelayStart" is how much it waited. The profiler doesn't record that, rather it records how much more it waited relative to the requested mDelayDuration, because that's the interesting thing to record, and there is no point in filling the leftmost part of the histogram with zeros. So, if a coroutine uses several delays with different values, it will work, and the zero X axis of the histogram means "DELAY() delivered exactly what was asked."

When profiling coroutine run times, mDelayStart was unused, so I recycled it to store the time when the coroutine enters the run state. So when it goes back to yield/delay, the profiler uses that to know how long it ran.

I've added another clock in ClockInterface so runtime can be profiled using CPU cycles instead of micros.

Since a profiler is an object that records time intervals, you can make two instances, call them WaitProfiler and RunProfiler, and have stats about both the run-time and the wait-times.

My initial thought is that Option 2 would be too disruptive for most people, to save a few narrow edge cases. So I'm leaning towards Option 1.

I went for option 3, make the user explicitly configure it for 32 bit. But, do users read what they copypaste, that remains to be seen...

I'm thinking that we could extract out the profiling feature into a separate Profiling class which can receive profiling messages from the CoroutineScheduler.

Done ;)

I changed it so it receives messages from the Coroutine, not the Scheduler, because only the coroutine knows if its delay is encoded in millis, micros or seconds. Right now I haven't implemented the profiler that is compatible with the 16-bit counters, but I would not want to prevent that from happening.

The Profiling object can choose to record the information in any way it wants. I imagine end users can create different Profiling objects to record information in different ways.

I've added a few histogram classes, and since ESP32 has a FPU I put one with a non-power-of-2 log histogram... this one should really be disabled on small cpus though.

I've added an example in examples/Profiler, with 2 commented plots to answer your questions about the Y axis. The python script that generates them is trash, but it's usable.

An interesting thing is, these Profiler objects make histograms of integer values. So they can also profile functions, it just needs a bit of boilerplate code to store the cpu cycle counter at the beginning of the function and call the profiler at the end. And I've also used them to make a histogram of logic level transition times on my onewire bus to debug it, see here pstolarz/OneWireNg#38 (comment)

I've tried to add enough comments in the code.

Have a nice day ;)

[bxparks]

Thanks for the updated code. I spent some time going through it. I probably don't have a full understanding of all the details, but I think I have a general idea. So a few things:

1)) If I understand the purpose of ClockInterface::cycles(), it's a level of indirection to allow the profiler (hmm, actually your Coroutine_Delay_32bit_Profiler_Impl) to track elapsed time in different units. But I think it's used inconsistently:

    void profileEnterZero() {
      if( mWaitProfiler )
        mWaitProfiler->profileWait(
          this->coroutineMicros()-this->mDelayStart,
          this->mDelayDuration
        );

should be

    void profileEnterZero() {
      if( mWaitProfiler )
        mWaitProfiler->profileWait(
          this->coroutineCycles() - this->mDelayStart,
          this->mDelayDuration
        );

My initial feeling is that I'm not sure we want to introduce this bit of complexity into the ClockInterface. It feels like it belongs somewhere else. Or maybe we don't even need this complexity. I think tracking duration using a 32-bit microseconds gives us a resolution between 1us to 4000 seconds, which should be good enough.

2)) I sort of understand why profiling the tracking error of the COROUTINE_DELAY() would be useful, but maybe I don't. It seems to me that the tracking error would identify which coroutine is not being executed in a timely fashion, but it doesn't identify which coroutine is actually causing the problem. For that, it seems like that the measurement of Coroutine::runCoroutine() duration would be the one that identifies the coroutine that is causing the trouble.

3)) Related to (2), I am more favorable to your first implementation better, where you placed the profiling instrumentation in the CoroutineScheduler, instead of the Coroutine. Because I usually have my coroutines scattered across multiple files, using both the COROUTINE() macro and the sublcassing class MyRoutine : public Coroutine mechanisms. It would be cumbersome to change all those to use a different Coroutine subclass, just to get profiling. The nice thing about putting the instrumentation in CoroutineScheduler is that it is used in only 2-3 places, usually in the global setup() and loop(). It's much easier to ask the user to upgrade to a different scheduling class (e.g. ProfilingCoroutineScheduler), than to update all their uses of Coroutine to a different Coroutine.

4)) Related to (3), we may not even have to provide a separate profiling CoroutineScheduler. I benchmarked the CPU cost of inserting the code to support a Profiler per coroutine, as I wrote earlier:

void CoroutineScheduler::runCoroutine() {
  ...
      switch ((*mCurrent)->getStatus()) {
        case T_COROUTINE::kStatusYielding:
        case T_COROUTINE::kStatusDelaying:
          if ((*mCurrent)->mProfiler) {
            uint32_t startMicros = T_COROUTINE::coroutineMicros();
            (*mCurrent)->runCoroutine();
            uint32_t elapsedMicros = T_COROUTINE::coroutineMicros() - startMicros;
            (*mCurrent)->mProfiler->updateElapsedMicros(elapsedMicros);
          } else {
            (*mCurrent)->runCoroutine();
          }
         break;
  ...
}

I found that the extra conditional logic (the if ((*mCurrent)->mProfiler)) increases the dispatch time by only 700ns (AVR) to 70ns (ESP32) if mProfiler == nullptr. Even on slow AVR processors, I think we can afford this small overhead.

In terms of flash usage, this bit of code increases flash consumption by 100-140 bytes for either 8-bit or 32-bit processors, even if the Profiler is not used. This is a one-time hit, so I'm thinking that we could live with this. The alternative is to create a separate CoroutineProfilingScheduler class, but it would cause a fair amount of duplication of code.

5)) Supporting human readable names would increase static RAM usage by 3 bytes per coroutine on an AVR, because we need to support both C-strings and F-strings. So we need getCName() and getFName(), setCName(), setFName() and a getNameType(). This feature increases flash usage by 6-10 bytes, per coroutine, even if names are not used. On 32-bit processors, it's 4 bytes of static RAM because the type descriminator fits inside an existing padding byte in the struct.

I feel like being able to assign a human-readable name to a coroutine is a valuable enough feature that it's worth the few extra bytes of static RAM and flash memory. It would be used in the CoroutineScheduler::list() function, as well as any Profiler class.

6)) With regards to 16-bit versus 32-bit mDelayStart and mDelayDuration, a quick scan through the current code suggests that we could make this a template parameter. In other words:

template <typename T_CLOCK, typename T_DELAY>
class CoroutineTemplate {
 ...
};

using Coroutine = CoroutineTemplate<ClockInterface, uint16_t>;

I think changing the T_DELAY to uint32_t would work transparently, because the various COROUTINE_DELAY(), COROUTINE_DELAY_MICROS() macros are typeless macros, so they will automatically handle the mDelayStart and mDelayDuration variables with different types.

7)) I took these ideas and observations and created some new code (seems like about the same time as you were working on yours), and I uploaded it to the profiler branch: https://github.com/bxparks/AceRoutine/tree/profiler. This code is more similar to your original code than your new code.

There is a CoroutineProfiler class which implements a virtual void updateElapsedMicros(uint32_t micros) = 0 interface.

I added one implementation CoroutineLogBinProfiler which updates an array of 32 bins, using the same log2() based bins that you used earlier. I also decoupled the rendering of the profiler objects into a separate CoroutineLogBinRenderer class, because it is likely that users will want to visualize the data in different ways.

One rendering is the JSON format that you used to feed into a python script for plotting. It occurred to me if I simply printed the bin counts as a formatted table, the number of digits in each bin is a poor-man representation of the log10() function of the bin count. In other words, here is the output of CoroutineLogBinRenderer::printTableTo():

(Must be viewed in monospaced font)

              <4us  <8us <16us <32us <64us<128us<256us<512us  <1ms  <2ms  <4ms  <8ms <16ms <33ms    >>  
tempHumidity     0 52496    40     8     0     0     0     0     0     0     0     0     0     0     0
doorChecker      0 52524    11     8     0     0     0     0     0     1     0     0     0     0     0
heartBeater      0 52428    95    21     0     0     0     0     0     0     0     0     0     0     0
mqttCoroutin     0 48482    16  3995    50     0     0     0     0     0     0     0     0     0     1
ledBlinker       0 52478    61     5     0     0     0     0     0     0     0     0     0     0     0

8)) So the feature missing in my implementation, compared to your new code, is the tracking error in COROUTINE_DELAY() and so on. Because this requires adding instrumentation code into the Coroutine class and into the various COROUTINE_DELAY*() macros, I see significant amount of complexity in implementation and usability for the end-users. It's not clear to me that the cost is worth the gain, but maybe you can convince me?

[bxparks]

Oh, by the way, I think your git configuration is messed up. I'm guessing you are using Windows. Because your new files (Coroutine32bit.h, Profiler.h, all the files under examples/Profiler) appear on my system as binary files instead of a text file. So when I check them out, they are full of \r\n line terminators instead of just \n. If they had been added as text files, git would automatically convert the files so that they are \r\n on your system and \n on my Linux system. They also all have their eXecute bit enabled, another indication that they were added as binary files.

[peufeu2]

Great!

1)) If I understand the purpose of ClockInterface::cycles(), it's a level of indirection to allow the profiler (hmm, actually your Coroutine_Delay_32bit_Profiler_Impl) to track elapsed time in different units. But I think it's used inconsistently:

I used cycles to measure coroutine runtime for more accuracy, but I used microseconds to measure wait time, because a 32-bit cycle counter would overflow too quickly on a long delay. So the variable contains a different unit depending on the state (delay/run). It's a bit meh, but it works.

    void profileEnterZero() {
      if( mWaitProfiler )
        mWaitProfiler->profileWait(
          this->coroutineMicros()-this->mDelayStart,
          this->mDelayDuration
        );

So yeah this one is correct, because at this point it comes out of the delay, and mDelayStart was initialized with micros() at the beginning of the delay.

My initial feeling is that I'm not sure we want to introduce this bit of complexity into the ClockInterface. It feels like it belongs somewhere else. Or maybe we don't even need this complexity. I think tracking duration using a 32-bit microseconds gives us a resolution between 1us to 4000 seconds, which should be good enough.

Yes

2)) I sort of understand why profiling the tracking error of the COROUTINE_DELAY() would be useful, but maybe I don't. It seems to me that the tracking error would identify which coroutine is not being executed in a timely fashion, but it doesn't identify which coroutine is actually causing the problem. For that, it seems like that the measurement of Coroutine::runCoroutine() duration would be the one that identifies the coroutine that is causing the trouble.

Indeed. Unless there are several troublesome coroutines, and the delay that is late is due to the sum of them.

3)) Related to (2), I am more favorable to your first implementation better, where you placed the profiling instrumentation in the CoroutineScheduler, instead of the Coroutine. Because I usually have my coroutines scattered across multiple files, using both the COROUTINE() macro and the sublcassing class MyRoutine : public Coroutine mechanisms. It would be cumbersome to change all those to use a different Coroutine subclass, just to get profiling. The nice thing about putting the instrumentation in CoroutineScheduler is that it is used in only 2-3 places, usually in the global setup() and loop(). It's much easier to ask the user to upgrade to a different scheduling class (e.g. ProfilingCoroutineScheduler), than to update all their uses of Coroutine to a different Coroutine.

I agree with that, but it would prevent profiling when runCoroutine() is used directly. Also I'm not sure what would happen with channels...

I found that the extra conditional logic (the if ((*mCurrent)->mProfiler)) increases the dispatch time by only 700ns (AVR) to 70ns (ESP32) if mProfiler == nullptr. Even on slow AVR processors, I think we can afford this small overhead.

Definitely agree!

I feel like being able to assign a human-readable name to a coroutine is a valuable enough feature that it's worth the few extra bytes of static RAM and flash memory. It would be used in the CoroutineScheduler::list() function, as well as any Profiler class.

+1

6)) With regards to 16-bit versus 32-bit mDelayStart and mDelayDuration, a quick scan through the current code suggests that we could make this a template parameter. In other words:
I think changing the T_DELAY to uint32_t would work transparently, because the various COROUTINE_DELAY(), COROUTINE_DELAY_MICROS() macros are typeless macros, so they will automatically handle the mDelayStart and mDelayDuration variables with different types.

Yes!

It's not clear to me that the cost is worth the gain, but maybe you can convince me?

I'm not sure either. I like both options!

I'll have to check the git configuration: the files are on a linux PC, but I've edited them from windows with SublimeText too...

[bxparks]

So yeah this one is correct, because at this point it comes out of the delay, and mDelayStart was initialized with micros() at the beginning of the delay.

So that was not readily obvious from my reading of the code, which indicates to me that it's probably more complex than I would like, so I'm going to leave this out for now.

I agree with that, but it would prevent profiling when runCoroutine() is used directly. Also I'm not sure what would happen with channels...

I fixed that problem by adding a new method, Coroutine::runCoroutineWithProfiler() into the Coroutine class. So on 8-bit environments, where users may not want to pay the extra overhead of the CoroutineScheduler, they can choose to activate profiling by changing the calls to Coroutine::runCoroutineWithProfiler(). I think that's a reasonable workaround because they get to choose whether they want to pay for this feature or not.

6)) With regards to 16-bit versus 32-bit mDelayStart and mDelayDuration, a quick scan through the current code suggests that we could make this a template parameter. In other words:
I think changing the T_DELAY to uint32_t would work transparently, because the various COROUTINE_DELAY(), COROUTINE_DELAY_MICROS() macros are typeless macros, so they will automatically handle the mDelayStart and mDelayDuration variables with different types.

Yes!

I have not implemented the T_DELAY template parameter yet. I'll tackle that after I merge the current set of changes.

I've uploaded my latest code to my profiler branch. I made a whole bunch of optimizations:

• removed calls printf() (i.e. vsnprintf()) which saved an astounding 17kB of flash memory on Teensy 3.2
• added a LogBinJsonRenderer which prints out the histogram in your original JSON format
• renamed profiler classes LogBinProfiler and LogBinTableRenderer
• moved kBinLabels[] array to flash memory, saving between 250-350 bytes of RAM
• added a virtual destructor to CoroutineProfiler to make the compiler happy, but only for 32-bit processors, to avoid increasing flash memory consumption by 600 bytes on 8-bit processors
• added unit tests for LogBinProfiler

If there aren't major objections, I'm going to merge this into develop..., well, maybe after I write some documentation. I need to rest a little after all this coding.

[peufeu2]

Very nice!

I take printf() for granted on 32-bit cpus, but it's true on 8-bitters it's another story...

[bxparks]

Ok, I merged everything into the develop branch. I made a few tweaks in the last iteration to simplify the API:

• LogBinTableRenderer::printTo() is a static function, it calls Coroutine::getRoot() internally so no need to pass it in
• LogBinJsonRenderer::printTo() is the same thing
• created sample code in examples/HelloCoroutineWithProfiler/ and examples/HelloSchedulerWithProfiler/
• added the T_DELAY template parameter to Coroutine<typename T_CLOCK, typename T_DELAY>. I have not tested this and have no immediate plans to do so, because I don't need it, and I have so many other things to do. If you want to play with it, go ahead.
• Added documentation in USER_GUIDE.md#CoroutineProfiling

Moving the profile instrumentation into the Coroutine::runCoroutineWithProfiler() method reduced the latency of CoroutineScheduler::runCoroutine() substantially. According to examples/AutoBenchmark, the additional overhead of the CoroutineScheduler, if CoroutineProfiler is not used is:

• ~100ns (AVR, ESP8266) which I think is 2 clock cycles on a 16MHz AVR
• ~133ns for STM32, and Teensy 3.2
• ~33ns for the ESP32 at 240MHz

I think we can say that adding Profiling adds almost no CPU overhead if it is not used.

I'm going to let this simmer for a couple of days before pushing a new release. I often find a bunch of typos and other little fixes before a release.

[bxparks]

I just pushed out v1.5.0 with this feature. I made a few tweaks from my last update.

1)) I added a CoroutineScheduler::loopWithProfiler() method which is the profiling version of CoroutineScheduler::loop(). This is to allow the profiling feature to cost nothing if the user does not use it.

If the original CoroutineSchduler::loop() is invoked, the profiling feature is turned off and no additional flash memory is consumed. This became important on AVR processors, where enabling profiling caused each coroutine to consume ~70 bytes of additional flash memory. If someone used 5-10 coroutines, it seemed that this was a too high of a price to pay (350 to 700 bytes of additional flash).

2)) It looks like I did not run my benchmarking properly when figuring out how much extra runtime overhead was consumed by profiling. When I updated examples/AutoBenchmark, I found that profiling caused a fairly significant increase in latency for AVR processors:

+---------------------------------+--------+-------------+--------+
| Functionality                   |  iters | micros/iter |   diff |
|---------------------------------+--------+-------------+--------|
| EmptyLoop                       |  10000 |       1.900 |  0.000 |
|---------------------------------+--------+-------------+--------|
| DirectScheduling                |  10000 |       2.800 |  0.900 |
| DirectSchedulingWithProfiler    |  10000 |       5.800 |  3.900 |
|---------------------------------+--------+-------------+--------|
| CoroutineScheduling             |  10000 |       7.000 |  5.100 |
| CoroutineSchedulingWithProfiler |  10000 |       9.300 |  7.400 |
+---------------------------------+--------+-------------+--------+

In other words, Coroutine::runCoroutine() becomes about 2.3-3.0 microseconds slower per invocation with profiling enabled. In comparison, the ESP8266 showed only a 200-300 ns overhead. So this was another reason for creating the CoroutineScheduler::loopWithProfiler() method, to make sure that if profiling is not used, the application pays no runtime cost.

3)) I hope everything is explained sufficiently clearly in USER_GUIDE.md#CoroutineProfiling.