Gave a second thought and got an improved code

Stabilizing firmware/software has its own challenges which keep the troubleshooters biting their nails all the time. We decided to instrument the code and add debug logs in the firmware, which will give us some history of execution and make our life easy while troubleshooting.

The  debug traces,as I developed, were spread in frequently used system calls and each trace contained a timestamp( as traces usually do) .At first instance, it was not accepted with a reason that it may affect system stabilty and performance.

I felt challenged and de-motivated as I was unable to understand that how a read only data will affect this way; but when I gave it a second  thought, I really found that it had side-effects. Following were my mistakes:-

• Timestamping: The routine to get timestamp, used to disable interrupts and thus increase the interrupt latency. As it became a part of frequent system calls, you can imagine the number of times it will disable interrupt.
• Logging redundant information: Logged some data which could have been derived from other logs. The logging overhead should be minimum.
• Using many global variables and operations on them: On a load-store architecture (specially without cache) this will surely add extra processing cycles.
• Use of modulo operator and a table size not a power of two: This also introduced extra instructions.
• Debug log code scattered in different files.

I improved this by:-

• using a reference counter and a transaction based logging instead of timestamping.
• logging minimum and critical data only.
• using register  local variables ( in C) and using bitwise operations.
• keeping log table size a power of two and using & operator instead of % operator.
• centralizing the logging code in a single function in order to get cache benefit.

Will be back with a blog on a fresh and less talked topic, next weekend .........