add a logging functionality that only logs a certain number of times before increasing the log level that it reports at

Author: interpret-ml

src/core/ebmcore/AttributeCombinationInternal.h

@@ -20,6 +20,7 @@ class AttributeCombinationCore final {
    size_t m_cItemsPerBitPackDataUnit;
    size_t m_cAttributes;
    size_t m_iInputData;
+   unsigned int m_cLogMessages;
    AttributeCombinationEntry m_AttributeCombinationEntry[1];
 
    TML_INLINE static AttributeCombinationCore * Allocate(const size_t cAttributes, const size_t iAttributeCombination) {
@@ -32,6 +33,7 @@ class AttributeCombinationCore final {
       }
       pAttributeCombination->m_cAttributes = cAttributes;
       pAttributeCombination->m_iInputData = iAttributeCombination;
+      pAttributeCombination->m_cLogMessages = 2;
       return pAttributeCombination;
    }
 

src/core/ebmcore/InteractionDetection.cpp

@@ -31,12 +31,15 @@ class TmlInteractionState {
    AttributeInternalCore * const m_aAttributes;
    DataSetInternalCore * m_pDataSet;
 
+   unsigned int m_cLogMessages;
+
    TmlInteractionState(const bool bRegression, const size_t cTargetStates, const size_t cAttributes)
       : m_bRegression(bRegression)
       , m_cTargetStates(cTargetStates)
       , m_cAttributes(cAttributes)
       , m_aAttributes(IsMultiplyError(sizeof(AttributeInternalCore), cAttributes) ? nullptr : static_cast<AttributeInternalCore *>(malloc(sizeof(AttributeInternalCore) * cAttributes)))
-      , m_pDataSet(nullptr) {
+      , m_pDataSet(nullptr)
+      , m_cLogMessages (1000) {
       assert(0 < cAttributes); // we can't allocate zero byte arrays.  This is checked when we were initially called, but I'm leaving it here again as documentation
    }
 
@@ -203,11 +206,13 @@ TML_INLINE IntegerDataType CompilerRecursiveGetInteractionScore<k_cCompilerOptim
 }
 
 EBMCORE_IMPORT_EXPORT IntegerDataType EBMCORE_CALLING_CONVENTION GetInteractionScore(PEbmInteraction ebmInteraction, IntegerDataType countAttributesInCombination, const IntegerDataType * attributeIndexes, FractionalDataType * interactionScoreReturn) {
-   LOG(TraceLevelVerbose, "Entered GetInteractionScore");
    LOG(TraceLevelVerbose, "GetInteractionScore parameters: ebmInteraction=%p, countAttributesInCombination=%" IntegerDataTypePrintf ", attributeIndexes=%p, interactionScoreReturn=%p", static_cast<void *>(ebmInteraction), countAttributesInCombination, static_cast<const void *>(attributeIndexes), static_cast<void *>(interactionScoreReturn));
 
    assert(nullptr != ebmInteraction);
    TmlInteractionState * pEbmInteractionState = reinterpret_cast<TmlInteractionState *>(ebmInteraction);
+
+   LOG_COUNTED(&pEbmInteractionState->m_cLogMessages, TraceLevelInfo, TraceLevelVerbose, "Entered GetInteractionScore");
+
    assert(1 <= countAttributesInCombination);
    assert(nullptr != attributeIndexes);
 

src/core/ebmcore/Logging.h

@@ -24,7 +24,7 @@ extern void InteralLogWithArguments(signed char traceLevel, const char * const p
    do { /* using a do loop here gives us a nice look to the macro where the caller needs to use a semi-colon to call it, and it can be used after a single if statement without curly braces */ \
       constexpr signed char LOG__traceLevel = (traceLevel); /* we only use traceLevel once, which avoids pre and post decrement issues with macros */ \
       static_assert(TraceLevelOff < LOG__traceLevel, "traceLevel can't be TraceLevelOff or lower for call to LOG(traceLevel, pLogMessage, ...)"); \
-      static_assert(LOG__traceLevel <= TraceLevelVerbose, "traceLevel can't be higher than TraceLevelDebug for call to LOG(traceLevel, pLogMessage, ...)"); \
+      static_assert(LOG__traceLevel <= TraceLevelVerbose, "traceLevel can't be higher than TraceLevelVerbose for call to LOG(traceLevel, pLogMessage, ...)"); \
       if(UNLIKELY(LOG__traceLevel <= g_traceLevel)) { \
          assert(nullptr != g_pLogMessageFunc); \
          constexpr size_t LOG__cArguments = std::tuple_size<decltype(std::make_tuple(__VA_ARGS__))>::value; \
@@ -38,22 +38,35 @@ extern void InteralLogWithArguments(signed char traceLevel, const char * const p
       /* the "(void)0, 0" part supresses the conditional expression is constant compiler warning */ \
    } while((void)0, 0)
 
-#define LOG_COUNTED(pLogCount, traceLevelBefore, pLogMessage, ...) \
+#define LOG_COUNTED(pLogCountDecrement, traceLevelBefore, traceLevelAfter, pLogMessage, ...) \
    do { /* using a do loop here gives us a nice look to the macro where the caller needs to use a semi-colon to call it, and it can be used after a single if statement without curly braces */ \
-      constexpr signed char LOG__traceLevel = (traceLevel); /* we only use traceLevel once, which avoids pre and post decrement issues with macros */ \
-      static_assert(TraceLevelOff < LOG__traceLevel, "traceLevel can't be TraceLevelOff or lower for call to LOG(traceLevel, pLogMessage, ...)"); \
-      static_assert(LOG__traceLevel <= TraceLevelVerbose, "traceLevel can't be higher than TraceLevelDebug for call to LOG(traceLevel, pLogMessage, ...)"); \
-      if(UNLIKELY(LOG__traceLevel <= g_traceLevel)) { \
-         unsigned int * const LOG__pLogCount = (pLogCount); \
-         if(0 < *LOG__pLogCount) { \
-            --(*LOG__pLogCount); \
+      constexpr signed char LOG__traceLevelBefore = (traceLevelBefore); /* we only use traceLevelBefore once, which avoids pre and post decrement issues with macros */ \
+      static_assert(TraceLevelOff < LOG__traceLevelBefore, "traceLevelBefore can't be TraceLevelOff or lower for call to LOG_COUNTED(pLogCount, traceLevelBefore, traceLevelAfter, pLogMessage, ...)"); \
+      static_assert(LOG__traceLevelBefore <= TraceLevelVerbose, "traceLevelBefore can't be higher than TraceLevelVerbose for call to LOG_COUNTED(pLogCount, traceLevelBefore, traceLevelAfter, pLogMessage, ...)"); \
+      constexpr signed char LOG__traceLevelAfter = (traceLevelAfter); /* we only use traceLevelAfter once, which avoids pre and post decrement issues with macros */ \
+      static_assert(TraceLevelOff < LOG__traceLevelAfter, "traceLevelAfter can't be TraceLevelOff or lower for call to LOG_COUNTED(pLogCount, traceLevelBefore, traceLevelAfter, pLogMessage, ...)"); \
+      static_assert(LOG__traceLevelAfter <= TraceLevelVerbose, "traceLevelAfter can't be higher than TraceLevelVerbose for call to LOG_COUNTED(pLogCount, traceLevelBefore, traceLevelAfter, pLogMessage, ...)"); \
+      static_assert(LOG__traceLevelBefore < LOG__traceLevelAfter, "We only support increasing the required trace level after N iterations and it doesn't make sense to have equal values, otherwise just use LOG(..)"); \
+      if(UNLIKELY(LOG__traceLevelBefore <= g_traceLevel)) { \
+         constexpr size_t LOG__cArguments = std::tuple_size<decltype(std::make_tuple(__VA_ARGS__))>::value; \
+         constexpr static char LOG__originalMessage[] = (pLogMessage); /* we only use pLogMessage once, which avoids pre and post decrement issues with macros */ \
+         unsigned int * const LOG__pLogCountDecrement = (pLogCountDecrement); /* we only use pLogCountDecrement once, which avoids pre and post decrement issues with macros */ \
+         if(0 < *LOG__pLogCountDecrement) { \
+            --(*LOG__pLogCountDecrement); \
             assert(nullptr != g_pLogMessageFunc); \
-            constexpr size_t LOG__cArguments = std::tuple_size<decltype(std::make_tuple(__VA_ARGS__))>::value; \
-            constexpr static char LOG__originalMessage[] = (pLogMessage); /* we only use pLogMessage once, which avoids pre and post decrement issues with macros */ \
             if(0 == LOG__cArguments) { /* if there are no arguments we might as well send the log directly without reserving stack space for vsnprintf and without log length limitations for stack allocation */ \
-               (*g_pLogMessageFunc)(LOG__traceLevel, LOG__originalMessage); \
+               (*g_pLogMessageFunc)(LOG__traceLevelBefore, LOG__originalMessage); \
             } else { \
-               InteralLogWithArguments(LOG__traceLevel, LOG__originalMessage, ##__VA_ARGS__); \
+               InteralLogWithArguments(LOG__traceLevelBefore, LOG__originalMessage, ##__VA_ARGS__); \
+            } \
+         } else { \
+            if(UNLIKELY(LOG__traceLevelAfter <= g_traceLevel)) { \
+               assert(nullptr != g_pLogMessageFunc); \
+               if(0 == LOG__cArguments) { /* if there are no arguments we might as well send the log directly without reserving stack space for vsnprintf and without log length limitations for stack allocation */ \
+                  (*g_pLogMessageFunc)(LOG__traceLevelAfter, LOG__originalMessage); \
+               } else { \
+                  InteralLogWithArguments(LOG__traceLevelAfter, LOG__originalMessage, ##__VA_ARGS__); \
+               } \
             } \
          } \
       } \

src/core/ebmcore/Training.cpp

@@ -518,7 +518,8 @@ union CachedThreadResourcesUnion {
    }
 
    ~CachedThreadResourcesUnion() {
-      LOG(TraceLevelError, "ERROR ~CachedThreadResourcesUnion called.  It's union destructors should be called explicitly");
+      // TODO: figure out why this is being called, and if that is bad!
+      //LOG(TraceLevelError, "ERROR ~CachedThreadResourcesUnion called.  It's union destructors should be called explicitly");
 
       // we don't have enough information here to delete this object, so we do it from our caller
       // we still need this destructor for a technicality that it might be called
@@ -994,7 +995,6 @@ TML_INLINE IntegerDataType CompilerRecursiveTrainingStep<k_cCompilerOptimizedTar
 }
 
 EBMCORE_IMPORT_EXPORT IntegerDataType EBMCORE_CALLING_CONVENTION TrainingStep(PEbmTraining ebmTraining, IntegerDataType indexAttributeCombination, FractionalDataType learningRate, IntegerDataType countTreeSplitsMax, IntegerDataType countCasesRequiredForSplitParentMin, const FractionalDataType * trainingWeights, const FractionalDataType * validationWeights, FractionalDataType * validationMetricReturn) {
-   LOG(TraceLevelVerbose, "Entered TrainingStep");
    LOG(TraceLevelVerbose, "TrainingStep parameters: ebmTraining=%p, indexAttributeCombination=%" IntegerDataTypePrintf ", learningRate=%" FractionalDataTypePrintf ", countTreeSplitsMax=%" IntegerDataTypePrintf ", countCasesRequiredForSplitParentMin=%" IntegerDataTypePrintf ", trainingWeights=%p, validationWeights=%p, validationMetricReturn=%p", static_cast<void *>(ebmTraining), indexAttributeCombination, learningRate, countTreeSplitsMax, countCasesRequiredForSplitParentMin, static_cast<const void *>(trainingWeights), static_cast<const void *>(validationWeights), static_cast<void *>(validationMetricReturn));
 
    TmlState * pTmlState = reinterpret_cast<TmlState *>(ebmTraining);
@@ -1004,6 +1004,8 @@ EBMCORE_IMPORT_EXPORT IntegerDataType EBMCORE_CALLING_CONVENTION TrainingStep(PE
    size_t iAttributeCombination = static_cast<size_t>(indexAttributeCombination);
    assert(iAttributeCombination < pTmlState->m_cAttributeCombinations);
 
+   LOG_COUNTED(&pTmlState->m_apAttributeCombinations[iAttributeCombination]->m_cLogMessages, TraceLevelInfo, TraceLevelVerbose, "Entered TrainingStep");
+
    assert(!std::isnan(learningRate));
    assert(!std::isinf(learningRate));
    assert(0 < learningRate);