From cdd603091bd0675d98b060c0dc35d1e53980cc1c Mon Sep 17 00:00:00 2001
From: probonopd <probonopd@users.noreply.github.com>
Date: Sat, 26 Feb 2022 10:07:23 +0100
Subject: [PATCH] Add define `PROFILE` and code to show CPU usage

https://github.com/probonopd/MiniDexed/issues/12#issuecomment-1051853664
Thanks @rsta2
---
 src/Makefile      |  3 ++-
 src/minidexed.cpp | 37 +++++++++++++++++++++++++++++++++++
 src/perftimer.cpp | 50 +++++++++++++++++++++++++++++++++++++++++++++++
 src/perftimer.h   | 30 ++++++++++++++++++++++++++++
 4 files changed, 119 insertions(+), 1 deletion(-)
 create mode 100644 src/perftimer.cpp
 create mode 100644 src/perftimer.h

diff --git a/src/Makefile b/src/Makefile
index c6e053f..86f62a0 100644
--- a/src/Makefile
+++ b/src/Makefile
@@ -5,7 +5,8 @@
 CIRCLE_STDLIB_DIR = ../circle-stdlib
 SYNTH_DEXED_DIR = ../Synth_Dexed/src
 
-OBJS = main.o kernel.o minidexed.o pckeyboard.o $(SYNTH_DEXED_DIR)/synth_dexed.o
+OBJS = main.o kernel.o minidexed.o pckeyboard.o $(SYNTH_DEXED_DIR)/synth_dexed.o \
+       perftimer.o
 
 INCLUDE += -I $(SYNTH_DEXED_DIR)
 
diff --git a/src/minidexed.cpp b/src/minidexed.cpp
index c522300..d8851ae 100644
--- a/src/minidexed.cpp
+++ b/src/minidexed.cpp
@@ -2,10 +2,12 @@
 // minidexed.cpp
 //
 #include "minidexed.h"
+#include "perftimer.h"
 #include <circle/devicenameservice.h>
 #include <stdio.h>
 
 #define MIDI_DUMP
+#define PROFILE
 
 #define MIDI_NOTE_OFF	0b1000
 #define MIDI_NOTE_ON	0b1001
@@ -17,6 +19,10 @@ CMiniDexed *CMiniDexed::s_pThis = 0;
 
 extern uint8_t voices_bank[1][32][156];
 
+#ifdef PROFILE
+CPerformanceTimer GetChunkTimer ("GetChunk", 1000000U * CHUNK_SIZE/2 / SAMPLE_RATE);
+#endif
+
 bool CMiniDexed::Initialize (void)
 {
   if (!m_Serial.Initialize(31250))
@@ -33,6 +39,10 @@ bool CMiniDexed::Initialize (void)
 
 void CMiniDexed::Process(boolean bPlugAndPlayUpdated)
 {
+#ifdef PROFILE
+	GetChunkTimer.Dump ();
+#endif
+
 	if (m_pMIDIDevice != 0)
 	{
 		return;
@@ -193,6 +203,10 @@ bool CMiniDexedPWM::Initialize (void)
 
 unsigned CMiniDexedPWM::GetChunk(u32 *pBuffer, unsigned nChunkSize)
 {
+#ifdef PROFILE
+  GetChunkTimer.Start();
+#endif
+
   unsigned nResult = nChunkSize;
 
   int16_t int16_buf[nChunkSize/2];
@@ -209,6 +223,11 @@ unsigned CMiniDexedPWM::GetChunk(u32 *pBuffer, unsigned nChunkSize)
     *pBuffer++ = nSample;		// 2 stereo channels
     *pBuffer++ = nSample;
   }
+
+#ifdef PROFILE
+  GetChunkTimer.Stop();
+#endif
+
   return(nResult);
 };
 
@@ -224,6 +243,10 @@ bool CMiniDexedI2S::Initialize (void)
 
 unsigned CMiniDexedI2S::GetChunk(u32 *pBuffer, unsigned nChunkSize)
 {
+#ifdef PROFILE
+  GetChunkTimer.Start();
+#endif
+
   unsigned nResult = nChunkSize;
 
   int16_t int16_buf[nChunkSize/2];
@@ -238,6 +261,11 @@ unsigned CMiniDexedI2S::GetChunk(u32 *pBuffer, unsigned nChunkSize)
     *pBuffer++ = nSample;		// 2 stereo channels
     *pBuffer++ = nSample;
   }
+
+#ifdef PROFILE
+  GetChunkTimer.Stop();
+#endif
+
   return(nResult);
 };
 
@@ -253,6 +281,10 @@ bool CMiniDexedHDMI::Initialize (void)
 
 unsigned CMiniDexedHDMI::GetChunk(u32 *pBuffer, unsigned nChunkSize)
 {
+#ifdef PROFILE
+  GetChunkTimer.Start();
+#endif
+
   unsigned nResult = nChunkSize;
 
   int16_t int16_buf[nChunkSize/2];
@@ -273,5 +305,10 @@ unsigned CMiniDexedHDMI::GetChunk(u32 *pBuffer, unsigned nChunkSize)
     *pBuffer++ = nSample;		// 2 stereo channels
     *pBuffer++ = nSample;
   }
+
+#ifdef PROFILE
+  GetChunkTimer.Stop();
+#endif
+
   return(nResult);
 };
diff --git a/src/perftimer.cpp b/src/perftimer.cpp
new file mode 100644
index 0000000..802d81b
--- /dev/null
+++ b/src/perftimer.cpp
@@ -0,0 +1,50 @@
+//
+// perftimer.cpp
+//
+#include "perftimer.h"
+#include <iostream>
+
+CPerformanceTimer::CPerformanceTimer (const char *pName, unsigned nDeadlineMicros)
+:	m_Name (pName),
+	m_nDeadlineMicros (nDeadlineMicros),
+	m_nMaximumMicros (0),
+	m_nLastDumpTicks (0)
+{
+}
+
+void CPerformanceTimer::Start (void)
+{
+	m_nStartTicks = CTimer::GetClockTicks ();
+}
+
+void CPerformanceTimer::Stop (void)
+{
+	unsigned nEndTicks = CTimer::GetClockTicks ();
+	unsigned nMicros = (nEndTicks - m_nStartTicks) / (CLOCKHZ / 1000000);
+
+	if (nMicros > m_nMaximumMicros)
+	{
+		m_nMaximumMicros = nMicros;
+	}
+}
+
+void CPerformanceTimer::Dump (unsigned nIntervalTicks)
+{
+	unsigned nTicks = CTimer::GetClockTicks ();
+
+	if (nTicks - m_nLastDumpTicks >= nIntervalTicks)
+	{
+		m_nLastDumpTicks = nTicks;
+
+		unsigned nMaximumMicros = m_nMaximumMicros;	// may be overwritten from interrupt
+
+		std::cout << m_Name << ": Maximum duration was " << nMaximumMicros <<  "us";
+
+		if (m_nDeadlineMicros != 0)
+		{
+			std::cout << " (" << nMaximumMicros*100 / m_nDeadlineMicros << "%)";
+		}
+
+		std::cout << std::endl;
+	}
+}
diff --git a/src/perftimer.h b/src/perftimer.h
new file mode 100644
index 0000000..436ffa5
--- /dev/null
+++ b/src/perftimer.h
@@ -0,0 +1,30 @@
+//
+// perftimer.h
+//
+#ifndef _perftimer_h
+#define _perftimer_h
+
+#include <string>
+#include <circle/timer.h>
+
+class CPerformanceTimer
+{
+public:
+	CPerformanceTimer (const char *pName, unsigned nDeadlineMicros = 0);
+
+	void Start (void);
+	void Stop (void);
+
+	void Dump (unsigned nIntervalTicks = CLOCKHZ);
+
+private:
+	std::string m_Name;
+	unsigned m_nDeadlineMicros;
+
+	unsigned m_nStartTicks;
+	unsigned m_nMaximumMicros;
+
+	unsigned m_nLastDumpTicks;
+};
+
+#endif