Merge pull request #45 from vas-dav/logging

Logging

source/shoh/src/main.cpp

@@ -29,16 +29,3 @@ int main(void)
 
   return 1;
 }
-
-extern "C"
-{
-  void
-  vConfigureTimerForRunTimeStats (void)
-  {
-    Chip_SCT_Init (LPC_SCT1);
-    LPC_SCT1->CONFIG = SCT_CONFIG_32BIT_COUNTER;
-    LPC_SCT1->CTRL_U = SCT_CTRL_PRE_L (255)
-                            | SCT_CTRL_CLRCTR_L; // set prescaler to 256 (255 +
-                                                 // 1), and start timer
-  }
-}

source/shoh/src/peripherals/Clock.cpp

@@ -0,0 +1,160 @@
+/*
+ * Clock.cpp
+ *
+ *  Created on: 14 May 2023
+ */
+
+#include "Clock.h"
+#include "FreeRTOS.h"
+#include "task.h"
+
+static const uint64_t max_counter_value = 0xffffffff;
+
+static uint64_t counter_overflows = 0;
+
+extern "C" {
+  /**
+   * @brief Interrupt is used by the Clock class to monitor
+   * the time elapsed since the start.
+   * It triggers on counter overflow.
+   */
+	void SCT0_1_IRQHandler (void)
+	{
+		counter_overflows++;
+		portBASE_TYPE xHigherPriorityWoken = pdFALSE;
+		Chip_SCT_ClearEventFlag(LPC_SCT1, SCT_EVT_0);
+		portEND_SWITCHING_ISR(xHigherPriorityWoken);
+	}
+
+  /** 
+   * @brief This function is used by FreeRTOS to configure the collection of
+   * time used by tasks.
+   */
+  void
+  vConfigureTimerForRunTimeStats (void)
+  {
+    Chip_SCT_Init (LPC_SCT1);
+    /* Sets match to trigger when all bits of counter are 1 */
+    Chip_SCT_SetMatchCount(LPC_SCT1, SCT_MATCH_0, 0xffffffff);
+    /* Set corresponding match register to event */
+    LPC_SCT1->EVENT[0].CTRL |= 0x1 | (0x1 << 12);
+    /* Enable event */
+    LPC_SCT1->EVENT[0].STATE |= 0x1;
+
+    /* Set the interrupt */
+    Chip_SCT_EnableEventInt(LPC_SCT1, SCT_EVT_0);
+
+    /* Clear timer of any pending interrupts */
+    NVIC_ClearPendingIRQ(SCT0_1_IRQn);
+
+    /* Enable timer interrupt */
+    NVIC_EnableIRQ(SCT0_1_IRQn);
+
+    /* Start timer */
+    LPC_SCT1->CONFIG = SCT_CONFIG_32BIT_COUNTER;
+    LPC_SCT1->CTRL_U = SCT_CTRL_CLRCTR_L;
+  }
+}
+
+/**
+ * @brief Construct a new Clock:: Clock object
+ * @attention Should be initialised by the first task as early as possible.
+ * _overflows(1) is important, since there is a starting overflow.
+ */
+Clock::Clock() : _raw_time(0), _overflows(1), _last_counter_value(0) {}
+
+Clock::~Clock() {}
+
+/**
+ * @brief Handles counter overflows and updates clock value.
+ * Time difference between updateClock() calls should not be overly
+ * large, if it will be enough to get overflow amount of overflows
+ * 2 times between the function calls the clock will desync.
+ * *Barely possible with counter overflows every 89 sec, but still.
+ */
+void Clock::updateClock()
+{
+  uint64_t diff_overflows = 0;
+  //Remember old number of overflows.
+  uint64_t old_overflows = this->_overflows;
+
+  this->_guard.lock();
+  //Stop the counter.
+  Chip_SCT_SetControl(LPC_SCT1, 0x1 << 1);
+  //Capture number of counter overflows.
+  this->_overflows = counter_overflows;
+  //Capture the counter value.
+  uint64_t cur_count_u = LPC_SCT1->COUNT_U;
+  //Resume the counter.
+  Chip_SCT_ClearControl(LPC_SCT1, 0x1 << 1);
+  this->_guard.unlock();
+
+  //Handle overflows.
+  diff_overflows = (old_overflows <= this->_overflows)
+       //Usually it is new amount of overflows - old.
+       ? (this->_overflows - old_overflows)
+       //It is possible that overflows counter will overflow.
+       : (0xffffffffffffffff - old_overflows + this->_overflows);
+  
+  //First case -> no overflow
+  if(!diff_overflows)
+  {
+    //Get the difference between values and convert to milliseconds. (t(ms) = 1000 / f)
+    _raw_time += (double)((cur_count_u - this->_last_counter_value) * 1000)
+               / (double)(Chip_Clock_GetMainClockRate());
+  }
+  //Second case -> overflow
+  else
+  {
+    _raw_time += (double)(
+    //Add full counter values for all overflows except one.
+    (max_counter_value * (diff_overflows - 1)
+    //Add the difference between counter values having overflow in mind.
+    + (cur_count_u + (max_counter_value - _last_counter_value)))
+    //Convert to milliseconds.
+    * 1000)
+    / (double)(Chip_Clock_GetMainClockRate());
+  }
+
+  //Remember last counter value.
+  //It is important if we won't have an overflow next time.
+  this->_last_counter_value = cur_count_u;
+}
+
+TimeFromStart Clock::getTimeFromStart()
+{
+  this->updateClock();
+  return this->convertToTimeFromStart(this->_raw_time);
+}
+
+TimeFromStart Clock::convertToTimeFromStart(double raw_time)
+{
+  //The conversion is slow, but reliable.
+  TimeFromStart tfs;
+  tfs.days = raw_time / 86400000;
+  tfs.hours = raw_time / 3600000 - tfs.days * 24; //Can be ((long long int)raw_time % 86400000)
+  tfs.minutes = raw_time / 60000 - tfs.days * 1440
+                                 - tfs.hours * 60; //Can be ((long long int)raw_time % 3600000)
+  tfs.seconds = raw_time / 1000 - tfs.days * 86400
+                                - tfs.hours * 3600
+                                - tfs.minutes * 60; //Can be ((long long int)raw_time % 60000)
+  tfs.milliseconds = raw_time - tfs.days * 86400000
+                              - tfs.hours * 3600000
+                              - tfs.minutes * 60000
+                              - tfs.seconds * 1000; //Can be ((long long int)raw_time % 1000)
+  return tfs;
+}
+
+double Clock::getTimeFromStartRaw()
+{
+  this->updateClock();
+  return this->_raw_time;
+}
+
+inline double Clock::convertToTimeFromStartRaw(TimeFromStart tfs)
+{
+  return (double)(tfs.days * 86400000 + tfs.hours * 3600000
+                                      + tfs.minutes * 60000
+                                      + tfs.seconds * 1000
+                                      + tfs.milliseconds);
+}

source/shoh/src/peripherals/Clock.h

@@ -0,0 +1,39 @@
+/*
+ * Clock.h
+ *
+ *  Created on: 14 May 2023
+ */
+
+#ifndef PERIPHERALS_CLOCK_H_
+#define PERIPHERALS_CLOCK_H_
+
+#include "chip.h"
+#include "Fmutex.h"
+
+struct TimeFromStart
+{
+  uint16_t days;
+  uint8_t hours;
+  uint8_t minutes;
+  uint8_t seconds;
+  uint16_t milliseconds;
+};
+
+
+class Clock {
+public:
+  Clock();
+  virtual ~Clock();
+  void updateClock();
+  TimeFromStart getTimeFromStart();
+  TimeFromStart convertToTimeFromStart(double raw_time);
+  double getTimeFromStartRaw();
+  double convertToTimeFromStartRaw(TimeFromStart tfs);
+private:
+  double _raw_time; //ms
+  uint64_t _overflows;
+  uint64_t _last_counter_value;
+  Fmutex _guard;
+};
+
+#endif /* PERIPHERALS_CLOCK_H_ */

source/shoh/src/threads/logging/Log.h

@@ -8,7 +8,9 @@
 #include "FreeRTOS.h"
 #include "task.h"
 #include "queue.h"
+#include "Clock.h"
 
+extern Clock *global_clock;
 extern QueueHandle_t logging_queue;
 
 /* ================= Settings ================== */
@@ -46,8 +48,10 @@ extern QueueHandle_t logging_queue;
         xQueueSend(logging_queue, (void*)message, portMAX_DELAY);  \
     }
 
-static void create_log_line(const char * _status,
+static void create_log_line(const TimeFromStart _timestamp,
+                            const char * _status,
                             const char * _location,
+                            const char * _func,
                             const size_t _line,
                             const char * _fmt, ...)
 {
@@ -58,9 +62,15 @@ static void create_log_line(const char * _status,
     va_end(args);
     char buffer [LOG_BUFFER_MAX_CAP] = {0};
     int buffer_len = snprintf(buffer, LOG_BUFFER_MAX_CAP,
-                             "[%s] [File: %s] [Line: %d] %.*s",
+                             "[%02zu:%02zu:%02zu:%02zu:%03zu]:[%s] In [File: %s] [Func: %s] [Line: %zu]\r\n %.*s",
+                             _timestamp.days,
+                             _timestamp.hours,
+                             _timestamp.minutes,
+                             _timestamp.seconds,
+                             _timestamp.milliseconds,
                              _status,
                              _location,
+                             _func,
                              _line,
                              message_len,
                              message);
@@ -68,18 +78,18 @@ static void create_log_line(const char * _status,
     
 }
 
-#define LOG_INFO(fmt, ...)                                        \
+#define LOG_INFO( fmt, ...)                                        \
-    create_log_line(C_INFO, __FILE__, __LINE__, fmt, ##__VA_ARGS__);
+    create_log_line(global_clock->getTimeFromStart(), C_INFO, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__);
 
 #define LOG_WARNING(fmt, ...)                                        \
-    create_log_line(C_WARN, __FILE__, __LINE__, fmt, ##__VA_ARGS__);
+    create_log_line(global_clock->getTimeFromStart(), C_WARN, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__);
 
 #define LOG_ERROR(fmt, ...)                                       \
-    create_log_line(C_ERROR, __FILE__, __LINE__, fmt, ##__VA_ARGS__);
+    create_log_line(global_clock->getTimeFromStart(), C_ERROR, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__);
 
 #if LOG_DEBUG_MESSAGES
 #define LOG_DEBUG(fmt, ...)                                        \
-    create_log_line(C_DEBUG, __FILE__, __LINE__, fmt, ##__VA_ARGS__);
+    create_log_line(global_clock->getTimeFromStart(), C_DEBUG, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__);
 #else
 #define LOG_DEBUG(fmt, ...)
 #endif

source/shoh/src/threads/master/Master.cpp

@@ -14,7 +14,6 @@
 #include "Logging.h"
 #include "UserInterface.h"
 #include "queue.h"
-#include "Logging.h"
 
 static const char* rotary_direction[] = 
 {
@@ -25,12 +24,18 @@ static const char* rotary_direction[] =
 };
 
 QueueHandle_t logging_queue;
+Clock *global_clock = new Clock();
 
 Master::Master(ThreadCommon::QueueManager* qm) : _qm(qm)
 {
 	LOG_DEBUG("Creating Master");
 }
 
+Master::~Master()
+{
+	LOG_ERROR("Master was deleted");
+}
+
 void Master::HandleEventType(Event* e, Event::EventType type)
 {
 	switch (type) 
@@ -40,6 +45,7 @@ void Master::HandleEventType(Event* e, Event::EventType type)
 		case Event::Rotary:
 			//Comes from rotary, goes to manager
 			_qm->send<Event>(ThreadCommon::QueueManager::manager_event_master, e, 0);
+			//LOG_WARNING("Timestamp: %zus, Clock: %zu, Chip freq: %zu", LPC_SCT1->COUNT_U / Chip_Clock_GetMainClockRate(), LPC_SCT1->COUNT_U, Chip_Clock_GetMainClockRate());
 			LOG_DEBUG("Rotary: %s has been forwarded to manager", rotary_direction[e->getDataOf(type)]);
 			break;
 		case Event::InternalTemp:
@@ -79,7 +85,8 @@ void Master::taskFunction() {
 			{
 				HandleEventType(&data, i);
 			}
-		 }	
+		 }
+		global_clock->updateClock();
 	}
 }
 

source/shoh/src/threads/master/Master.h

@@ -20,7 +20,7 @@
 class Master {
 public:
 	Master(ThreadCommon::QueueManager* qm);
-	virtual ~Master() = default;
+	virtual ~Master();
 	void taskFunction();
 
 private: