Profiling Arduino Code

[anon46966594]

So after a bit of messing about and reading stuff... I found this video and modified his code to print to the serial monitor. (Link to his used code here)

Three caveats ...

1. Yes this is a bit messy still... I/we can probably clean it up a lot.

2. Yes, doing a whole bunch of serial prints will slow down the program as discussed, but if the profiling of each function was consistent, then I think the relative time relationships should still give the insight required.

3. It did involve me declaring a profiling duration and wrapping the loop code.

"Profiling.h"

struct ProfileResult
{
  const char* Name;
  uint32_t Start, End;
  uint32_t ThreadID;
};

struct InstrumentationSession
{
  const char* Name;
};

class Instrumentor
{
  private:
    InstrumentationSession* m_CurrentSession;
    int m_ProfileCount;
  public:
    Instrumentor()
      : m_CurrentSession(nullptr), m_ProfileCount(0)
    {
    }

    void BeginSession(const char* name = "Session", const char* filepath = "results.json")
    {
      WriteHeader();
      m_CurrentSession = new InstrumentationSession{ name };
    }

    void EndSession()
    {
      WriteFooter();
      delete m_CurrentSession;
      m_CurrentSession = nullptr;
      m_ProfileCount = 0;
    }

    void WriteProfile(const ProfileResult& result)
    {
      if (m_ProfileCount++ > 0)
        Serial.print(",");

      String name = result.Name;
      name.replace('"', '\'');

      Serial.println("{");
      Serial.println("\"cat\":\"function\",");
      Serial.print("\"dur\":");
      Serial.print(result.End - result.Start);
      Serial.println(",");
      Serial.println("\"name\":\"" + name + "\",");
      Serial.println("\"ph\":\"X\",");
      Serial.println("\"pid\":0,");
      Serial.println("\"tid\":0,");
      Serial.print("\"ts\":");
      Serial.println(result.Start);
      Serial.println( "}");
    }

    void WriteHeader() {
      Serial.println("{\"otherData\": {},\"traceEvents\":[");
    }

    void WriteFooter() {
      Serial.println( "]}");
    }

    static Instrumentor& Get() {
      static Instrumentor instance;
      return instance;
    }
};

class InstrumentationTimer
{
  public:
    InstrumentationTimer(const char* name)
      : m_Name(name), m_Stopped(false) {
      m_StartTimepoint = micros();
    }

    ~InstrumentationTimer() {
      if (!m_Stopped)
        Stop();
    }

    void Stop() {
      Instrumentor::Get().WriteProfile({ m_Name, m_StartTimepoint, micros(), 0 });
      m_Stopped = true;
    }
  private:
    const char* m_Name;
    bool m_Stopped;
    uint32_t m_StartTimepoint;
};


#if PROFILING
   #define PROFILE_BEGIN() Instrumentor::Get().BeginSession();
   #define PROFILE_FUNCTION() InstrumentationTimer timer(__PRETTY_FUNCTION__);
   #define PROFILE_END() Instrumentor::Get().EndSession();
#else
   #define PROFILE_BEGIN()
   #define PROFILE_FUNCTION()
   #define PROFILE_END()
#endif

Example code

#define  PROFILING 1
#include "Profiling.h"

#define SECONDS 1000
#define PROFILING_DURATION 10 * SECONDS

void foo() {
  PROFILE_FUNCTION()
  delay(1250);
}

void foo2() {
  PROFILE_FUNCTION()
  delay(150);
  foo3();
}

void foo3() {
  PROFILE_FUNCTION()
  delay(350);
}

void setup() {
  Serial.begin(115200);
}

void loop() {
#if PROFILING
  PROFILE_BEGIN();
  while (millis() < PROFILING_DURATION) {
#endif

    // Do Loop Code Here
    foo();
    foo2();
    // End Loop Code Here

#if PROFILING
  }
  PROFILE_END();
  while (1);
#endif
}

This then serial.prints output you can paste into a JSON file, and then load it into chrome://tracing/ to get a nice visual of whats happening and when like this:

Again.... The caveats above... Messy still, printing slows things down etc.

I was wondering if maybe instead of printing while running, we can just 'queue up' the captures, and then iterate over them at the end of the profiling to print the JSON out?

As gcjr said above, get it working, then make it right. Well... it seems to work Can we make it right?