Doug Ross @ Journal

Instrumenting Code

Here's an example of how I've instrumented code in the past. The main focus of this logic is to provide peer-to-peer services for the BadBlue software. The server can listen for connection requests, which can come in either of two formats: HTTP or Gnutella. HTTP requests are dispatched to web services processing, not covered here.

Gnutella protocol requests are dispatched to, among other places, the snippet of code, below. Each request operates in its own thread (this is Win32, which uses a threading model - not the forked process model of Unix/Linux). Multiple threads are thus connected to multiple peers, simultaneously, all exchanging messages, relaying query results, performing discoveries, etc.

The net result can be a system of some complexity. In order to debug this code -- and to get a glimpse into activities of a running production box -- a tunable logging system was added.

The beginning of the snippet notes that we are initializing, with a logging level of 7. This means that if the administrator has "turned up the instrumentation dial" to 7 or above, this message will be sent to the system log.

A little bit further down, we report errors: a bad port number (logging level of 7, we really don't care too much during normal operations) and an attempt to connect to a restricted IP address (which we always want to report as a noteworthy error).

Note that rather than throwing exceptions, the code breaks out. This enables us to dispense with the overhead of exception processing and provide inline instrumentation of any noteworthy events and errors. But exceptions could be thrown just as easily once the instrumentation has done its job. In C++, there appears to be some overhead for using exceptions (and they're forbidden in certain types of real-time or mission-critical systems), so I trap for miscellaneous exceptions - but don't rely upon them for normal error-handling activities.

The log method, below, provides tunable logging consistent with what I've already described.

I suppose the key point here is not whether you're returning error-codes or throwing exceptions; it is, instead, to have sufficient discipline to provide paranoid levels of error-checking and instrumentation so that you can always determine what kinds of things are happening in your code. Even if you think things are hunky-dory.

// beginning of snippet... // do { try { // Mark initialization. // strLog.Format("[%8.8lX] Thread initializing", m_hThread ); m_pEXTObject->Log(strLog, 7); // Initialize our socket. // if (!m_sockID) { // Do we need to connect ourselves? // if (!m_strConnectAddress.IsEmpty()) { if ((nCursor = m_strConnectAddress.Find(':')) >= 0) { i = atoi(m_strConnectAddress.Mid(nCursor + 1)); strTemp = m_strConnectAddress.Left(nCursor); if (!i || (UINT) i > 0x7FFF) { // strLog.Format("[%8.8lX] Error, bad port (%s)", m_hThread, m_strConnectAddress ); m_pEXTObject->Log(strLog, 7); // break; } if (!m_pEXTObject->CheckIP(strTemp)) { // strLog.Format("[%8.8lX] Connection forbidden: IP address %s", m_hThread, m_strConnectAddress ); m_pEXTObject->Log(strLog, 0); // break; } } else { strTemp = m_strConnectAddress; i = DEF_HTTP_PORT; } // ... // ...end structured processing. // } catch (...) { rc = BBX_MISC_EXCEPTION; } } while (0); m_bTerminating = TRUE; m_dTerminateStarted = COleDateTime::GetCurrentTime(); if (m_bBaseThread) { strLog.Format("[%8.8lX] BT: Error %d, base thread closing", m_hThread, rc ); m_pEXTObject->LogEvent(rc, EVT_WARNING, strLog); } else { strLog.Format("[%8.8lX] Thread closing (%d)", m_hThread, rc ); m_pEXTObject->Log(strLog, 3); } if (m_SocketID != INVALID_SOCKET && m_SocketID != 0) { // SD_SEND, don't allow any more sends m_Thunk_p->shutdown(m_SocketID, 1); m_Thunk_p->closesocket(m_SocketID); m_SocketID = INVALID_SOCKET; m_hFile = (UINT) CFile::hFileNull; } // // Array locking should not be necessary (terminating flag)... // for (i = 0; i < m_cpaOutboundQueue.GetSize(); i++) { pcbaTemp = (CByteArray*) m_cpaOutboundQueue.GetAt(i); if (pcbaTemp != NULL) { delete pcbaTemp; } } // strLog.Format("[%8.8lX] Thread closed", m_hThread ); m_pEXTObject->Log(strLog, 7); // // ...end of snippet // Gnutella logging. // Multi-threaded tunable logging facility. // VOID CExtExtension::Log( LPCTSTR pMessage, DWORD dwLoggingLevel, BOOL bFlush ) { // SP... // CTime timeTemp; CString strLogEntry; do { // Not available? Forget it. // if (m_fileLog.m_hFile == CFile::hFileNull) { break; } // Logging level not sufficient? Forget it. // if (dwLoggingLevel > m_dwLoggingLevel) { break; } // Get our timestamp. // timeTemp = CTime::GetCurrentTime(); // Format a log entry. // strLogEntry.Format( "%s %s\r\n" , timeTemp.Format("%y-%m-%d %H:%M:%S"), pMessage ); m_ccsLog.Lock(); m_strLog += strLogEntry; if (bFlush || m_strLog.GetLength() > MAX_LOG_CACHE_BYTES) { m_fileLog.Write(m_strLog.GetBuffer(0), m_strLog.GetLength()); m_strLog = ""; m_fileLog.Flush(); } m_ccsLog.Unlock(); // ...end SP. // } while (0); }