The problem
Often when programming in Arduino you need some logging to the serial port. Most often this is done with a lot of “Serial.println” statements. To make some nice output the logging code easily becomes quite big. Here is an example that illustrates the problem:
#define NUMBER_OF_APPLES 100 uint8_t applesPerPerson = findApplesPerPerson( peopleAmount ); Serial.print( "If " ); Serial.print( peopleAmount ); Serial.print( " people shares " ); Serial.print( NUMBER_OF_APPLES ); Serial.print( " apple they each get " ); Serial.println( applesPerPerson );
So many lines of code just to show what’s going on. The debugging takes the focus away from the code!
My Solution
I designed a header file that can be imported into your sketch. It is very lightweight and is built on c++ directives and templates. The example above could be written like this:
#define NUMBER_OF_APPLES 100 uint8_t applesPerPerson = findApplesPerPerson( peopleAmount ); Serial << "If " << peopleAmount << " people shares " << NUMBER_OF_APPLES << " apples they each get " << applesPerPerson << endl;
But even better is to use log levels. Here is an example of doing excessive logging in a very simple program, without removing focus from the real code:
#include "Logging.h" #define NUMBER_OF_APPLES 100 void setup() { Serial.begin( 115200 ); LOG_NOTICE( "SETUP", "Arduino just booted" ); } void loop() { uint8_t peopleAmount = random( 0, 3 ); LOG_NOTICE( "LOOP", "The amount of people is: " << peopleAmount << " right now." ); uint8_t applesPerPerson = findApplesPerPerson( peopleAmount ); Serial << "If " << peopleAmount << " people shares " << NUMBER_OF_APPLES << " apples they each get " << applesPerPerson << endl; LOG_NOTICE( "LOOP", "Now sleeping for 10 seconds" ); delay( 10000 ); } uint8_t findApplesPerPerson(const uint8_t peopleAmount) { LOG_DEBUG( "CALC", "We got the amount " << peopleAmount << " people"); if ( peopleAmount == 0 ) { LOG_ERROR( "CALC", "Can't divide by zero!" ); return 0; } else { uint8_t result = NUMBER_OF_APPLES / peopleAmount; LOG_DEBUG( "CALC", NUMBER_OF_APPLES << " divided by " << peopleAmount << " is " << result ); return result; } }
If this program is run and the loglevel in the header file is set to 0, the output will be like this:
If 1 people shares 100 apples they each get 100 If 2 people shares 100 apples they each get 50 If 0 people shares 100 apples they each get 0
But if you for example set the loglevel to 6, you would get this:
000:00:00:00:000 NOTIC (SETUP) : Arduino just booted 000:00:00:00:000 NOTIC (LOOP) : The amount of people is: 1 right now. If 1 people shares 100 apples they each get 100 000:00:00:00:020 NOTIC (LOOP) : Now sleeping for 10 seconds 000:00:00:10:027 NOTIC (LOOP) : The amount of people is: 2 right now. If 2 people shares 100 apples they each get 50 000:00:00:10:042 NOTIC (LOOP) : Now sleeping for 10 seconds 000:00:00:20:048 NOTIC (LOOP) : The amount of people is: 0 right now. 000:00:00:20:055 ERROR (CALC) : Can't divide by zero! If 0 people shares 100 apples they each get 0 000:00:00:20:064 NOTIC (LOOP) : Now sleeping for 10 seconds
Benefits
Just by changing one line in the header file, you choose how much logging you want to output. This makes it much more tempting to leave the debugging statements in the code (also being used as self explaining code instead of comments).
Because it’s all made with #define statements, it means that it only takes program/sram space when it’s actually enabled by setting the loglevel at compile time.
The Headerfile
Here is the code of the logging.h file:
#ifndef _LOGGING_h #define _LOGGING_h #define LOGLEVEL 6 #define LOG_TIME_FORMAT 2 // Streaming operator for serial print use. template<class T> inline Print &operator <<( Print &obj, T arg ) { obj.print( arg ); return obj; } #define endl "\r\n" /* Generate and print the trailing log timestamp. 1 = (1234), showing time in seconds since boot. Generates lightweight inline code. 2 = (001:02:03:04:005) ( day 1, hour 2, minute 3, second 4, millisecond 5 ). Much bigger code, but very readable */ #if LOG_TIME_FORMAT == 1 #define LOG_FORMAT_TIME do { Serial << millis() / 1000; } while (0) #elif LOG_TIME_FORMAT == 2 #define MS_IN_DAY 86400000 #define MS_IN_HOUR 3600000 #define MS_IN_MINUTE 60000 #define MS_IN_SECOND 1000 #define LOG_FORMAT_TIME do \ { \ long logTime = millis(); \ unsigned short days = logTime / MS_IN_DAY; \ unsigned char hours = ( logTime % MS_IN_DAY ) / MS_IN_HOUR; \ unsigned char minutes = ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) / MS_IN_MINUTE; \ unsigned char seconds = ( ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) % MS_IN_MINUTE ) / MS_IN_SECOND; \ unsigned short ms = ( ( ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) % MS_IN_MINUTE ) % MS_IN_SECOND ); \ char logFormattedTime[17]; \ sprintf( logFormattedTime, "%03u:%02u:%02u:%02u:%03u", days, hours, minutes, seconds, ms ); \ Serial << logFormattedTime; \ } while (0) #endif // LOG_TIME_FORMAT // Default do no logging... #define LOG_EMERGENCY(svc, content) do {} while (0) #define LOG_ALERT(svc, content) do {} while (0) #define LOG_CRITICAL(svc, content) do {} while (0) #define LOG_ERROR(svc, content) do {} while (0) #define LOG_WARNING(svc, content) do {} while (0) #define LOG_NOTICE(svc, content) do {} while (0) #define LOG_INFO(svc, content) do {} while (0) #define LOG_DEBUG(svc, content) do {} while (0) // Depending on log level, add code for logging #if LOGLEVEL >= 0 #define LOG_EMERGENCY(svc, content) do { LOG_FORMAT_TIME; Serial << " EMERGENCY (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >=1 #define LOG_ALERT(svc, content) do { LOG_FORMAT_TIME; Serial << " ALART (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 2 #define LOG_CRITICAL(svc, content) do { LOG_FORMAT_TIME; Serial << " CRITICAL (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 3 #define LOG_ERROR(svc, content) do { LOG_FORMAT_TIME; Serial << " ERROR (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 4 #define LOG_WARNING(svc, content) do { LOG_FORMAT_TIME; Serial << " WARNING (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 5 #define LOG_NOTICE(svc, content) do { LOG_FORMAT_TIME; Serial << " NOTIC (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 6 #define LOG_INFO(svc, content) do { LOG_FORMAT_TIME; Serial << " INFO (" << svc << ") : " << content << endl; } while(0) #if LOGLEVEL >= 7 #define LOG_DEBUG(svc, content) do { LOG_FORMAT_TIME; Serial << " DEBUG (" << svc << ") : " << content << endl; } while(0) #endif // LOGLEVEL >= 7 #endif // LOGLEVEL >= 6 #endif // LOGLEVEL >= 5 #endif // LOGLEVEL >= 4 #endif // LOGLEVEL >= 3 #endif // LOGLEVEL >= 2 #endif // LOGLEVEL >= 1 #endif // LOGLEVEL >= 0 #endif
The only thing you need to set is the LOGLEVEL and the LOG_TIME_FORMAT in the top. If you want to save memory you can change to LOG_TIME_FORMAT to 1 which only shows the time unformattet in seconds since boot.
The loglevels are:
0: EMERGENCY 1: ALERT 2: CRITICAL 3: ERROR 4: WARNING 5: NOTICE 6: INFO 7: DEBUG
Try compiling your sketch at different loglevels and watch how your consumed memory changes! No more excuses to remove debugging code from your sketch 🙂
Looks very useful, thank you for putting this together. Will start using this in my sketches
Great!
As I started programming microcontrollers in assembly, I don’t know how powerful more structured languages are.
Thank you for the library!