Prepend timestamp to log lines when tracing flag is turned on

Source/Common/Include/ProgressTracing.h

@@ -4,10 +4,32 @@
 //
 #pragma once
 
+#include <chrono>
 #include "TimerUtility.h"
 
 namespace Microsoft { namespace MSR { namespace CNTK {
 
+// If the Tracing flag is set, print out a timestamp with no new line at the end
+#define PREPENDTS(stream) \
+    do \
+    { \
+        if (ProgressTracing::GetTimestampingFlag()) \
+        { \
+           std::time_t tt = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); \
+           char mbstr[30]; \
+           if (std::strftime(mbstr, sizeof(mbstr), "%m/%d/%Y %H:%M:%S", std::localtime(&tt))) \
+               fprintf(stream, "%s: ", mbstr);  \
+        } \
+    } while(0)
+
+// Print out a log message.  If the Tracing flag is set, prepend with a timestamp
+#define LOGPRINTF(stream, ...) \
+    do \
+    { \
+        PREPENDTS(stream); \
+        fprintf(stream, __VA_ARGS__); \
+    } while(0)
+
 // ---------------------------------------------------------------------------
 // ProgressTracing -- static helper class for logging a progress indicator
 //
@@ -29,12 +51,13 @@ namespace Microsoft { namespace MSR { namespace CNTK {
 {
     bool m_enabled;
     bool m_tracingFlag;
+    bool m_timestampFlag;
     size_t m_totalNumberOfSteps; // total number of epochs in entire training run
     size_t m_currentStepOffset;  // current offset
     Timer m_progressTracingTimer;
 
     ProgressTracing()
-        : m_enabled(false), m_tracingFlag(false), m_totalNumberOfSteps(0), m_currentStepOffset(0)
+        : m_enabled(false), m_tracingFlag(false), m_timestampFlag(false), m_totalNumberOfSteps(0), m_currentStepOffset(0)
     {
     }
 
@@ -50,12 +73,23 @@ namespace Microsoft { namespace MSR { namespace CNTK {
         return GetStaticInstance().m_tracingFlag;
     }
 
+    static bool GetTimestampingFlag()
+    {
+        return GetStaticInstance().m_timestampFlag;
+    }
+
     static void SetTracingFlag()
     {
         auto& us = GetStaticInstance();
         us.m_tracingFlag = true;
     }
 
+    static void SetTimestampingFlag()
+    {
+        auto& us = GetStaticInstance();
+        us.m_timestampFlag = true;
+    }
+
     // call TraceTotalNumberOfSteps() to set the total number of steps
     // Calling this with totalNumberOfSteps>0 will enable progress tracing.
     static void TraceTotalNumberOfSteps(size_t totalNumberOfSteps)

Source/Common/fileutil.cpp

@@ -609,11 +609,6 @@ void renameOrDie(const std::string& from, const std::string& to)
     // WORKAROUND: "rename" should do this but this is a workaround
     // to the HDFS FUSE implementation's bug of failing to do so
     // workaround for FUSE rename when running on Philly
-    if (ProgressTracing::GetTracingFlag())
-    {
-        fprintf(stderr, "rename %s to %s\n", from.c_str(), to.c_str());
-    }    
-
     unlinkOrDie(to);
     if (rename(from.c_str(), to.c_str()) != 0)
     {

Source/ComputationNetworkLib/ComputationNetworkAnalysis.cpp

@@ -94,7 +94,9 @@ void ComputationNetwork::FormRecurrentLoops(const ComputationNodeBasePtr& rootNo
                 if (node->Input(i)->m_loopId == node->m_loopId && GetRecurrenceSteppingDirection(node) == 0/*not a Delay node*/)
                 {
                     // assert(node->Input(i)->m_indexInLoop == 0);                    // No. It seems this variable really counts the number of parents.
-                    node->Input(i)->m_indexInLoop++; // BUGBUG: this is bumping up the m_indexInLoop, but I don't think it is initialized anywhere other than PurgeStateForFormingRecurrentLoops(). i-1?
+
+                    // BUGBUG: this is bumping up the m_indexInLoop, but I don't think it is initialized anywhere other than PurgeStateForFormingRecurrentLoops(). i-1?
+                    node->Input(i)->m_indexInLoop++;
                 }
             }
         }

Source/ComputationNetworkLib/ComputationNetworkEvaluation.cpp

@@ -114,9 +114,11 @@ ComputationNetwork::PARTraversalFlowControlNode::PARTraversalFlowControlNode(con
         {
             // instead of the node itself, include the sentinel SEQTraversalFlowControlNode in our list
             m_nestedNodes.push_back(recInfo);
+
             // and verify that we only encountered the loop once (all nodes should have been consecutive)
             if (!loopsSeen.insert(recInfo).second)
                 LogicError("PARTraversalFlowControlNode: members of loop %ls are not consecutive in node list.", recInfo->NodeName().c_str());
+
             // consume all nodes that are part of the same loop (they are all consecutive)
             while (nodeIter != allNodes.end() && (*nodeIter)->IsPartOfLoop() && FindInRecurrentLoops(recurrentInfo, *nodeIter) == recInfo)
                 nodeIter++;
@@ -303,8 +305,10 @@ ComputationNetwork::PARTraversalFlowControlNode::PARTraversalFlowControlNode(con
     // look in all recurrent loops of the network
     // TODO: Check for IsPartOfLoop(). Also why not store the loop id in the node for direct lookup?
     for (auto& iter : recurrentInfo)
+    {
         if (std::find(iter->m_nestedNodes.begin(), iter->m_nestedNodes.end(), node) != iter->m_nestedNodes.end()) // TODO: should this loop need to be a method of SEQTraversalFlowControlNode?
             return iter;
+    }
     return nullptr; // not part of a recurrent loop
 }
 
@@ -357,8 +361,10 @@ void ComputationNetwork::PrintComputationTree(const ComputationNodeBasePtr& root
     if (nodes.size() == 0)
         fprintf(stderr, "\n(empty)\n");
     else
+    {
         for (const auto& node : nodes)
             node->PrintSelf(printMatrices);
+    }
 }
 
 // -----------------------------------------------------------------------
@@ -397,9 +403,11 @@ void ComputationNetwork::CompileNetwork()
     // all steps below have to be repeated for all root nodes (=nodes without parents and PreComputeNodes)
     DetermineSetOfAllRoots();
 
-    fprintf(stderr, "\n%d roots:\n", (int) m_allRoots.size());
+    fprintf(stderr, "\n%d roots:\n", (int)m_allRoots.size());
     for (const auto& root : m_allRoots)
+    {
         fprintf(stderr, "\t%ls = %ls\n", root->NodeName().c_str(), root->OperationName().c_str());
+    }
 
     // Note: Steps below are loops over root nodes. We will gradually push those loops through to the functions,
     //       to reduce redundant operation on shared portions of the network.
@@ -473,10 +481,13 @@ void ComputationNetwork::DetermineSetOfAllRoots()
     set<ComputationNodeBasePtr> allKnownRoots;
     for (const auto& node : FinalCriterionNodes())
         allKnownRoots.insert(node);
+
     for (const auto& node : EvaluationNodes())
         allKnownRoots.insert(node);
+
     for (const auto& node : OutputNodes())
         allKnownRoots.insert(node);
+
     for (const auto& iter : m_nameToNodeMap) // PreComputeNodes
     {
         auto node = iter.second;
@@ -513,7 +524,9 @@ void ComputationNetwork::ValidateNetwork()
     // set up MBLayout links of inputs (all others get propagated upwards through Validate())
     // TODO: Once we support mismatching layouts, this will be more involved. For now, everything shares the one layout that the Network knows about.
     for (auto node : InputNodes(nullptr))
+    {
         node->LinkToMBLayout(m_pMBLayout);
+    }
 
     // we call all nodes' Validate() in order to validate, that is, set up MBLayout and FunctionValues dimension
     // A problem is that recurrent loops may require partial validation.
@@ -542,6 +555,7 @@ void ComputationNetwork::ValidateNetwork()
     }
     fprintf(stderr, "\nValidating network, final pass.\n\n");
     toValidate = ValidateNodes(nodes, /*isFirstPass=*/pass == 1, true /*isFinalValidationPass*/);
+
     if (toValidate != 0)
         LogicError("ValidateSubNetwork: ValidateNodes(true) unexpectedly returned with work left to do.");
 
@@ -571,7 +585,7 @@ void ComputationNetwork::ValidateNetwork()
     }
     if (!nonDefaultNodes.empty())
     {
-        fprintf(stderr, "%d out of %d nodes do not share the minibatch layout with the input data.\n", (int) nonDefaultNodes.size(), (int) nodes.size());
+        fprintf(stderr, "%d out of %d nodes do not share the minibatch layout with the input data.\n", (int)nonDefaultNodes.size(), (int)nodes.size());
         // for (auto node : nonDefaultNodes)
         //    fprintf(stderr, "    %ls\n", node->NodeName().c_str());
         // fprintf(stderr, "\n\n");
@@ -631,6 +645,7 @@ size_t ComputationNetwork::ValidateNodes(list<ComputationNodeBasePtr> nodes, boo
             hasVisitedChild |= child->m_visited; // if not a single visited child then no point in validating
             allChildrenVisited &= child->m_visited;
         }
+
         // if there is not at least one visited child
         bool valid = false;
         if (hasVisitedChild || isLeaf) // got at least one child: it makes sense to call Validate()
@@ -652,8 +667,10 @@ size_t ComputationNetwork::ValidateNodes(list<ComputationNodeBasePtr> nodes, boo
             node->m_visited = true;
             // print the new type
             // sanity checks
+
             if (isFinalValidationPass && !unchanged)
                 LogicError("ValidateSubNetwork: %ls %ls operation changed during final validation.", node->NodeName().c_str(), node->OperationName().c_str());
+
             if (isFinalValidationPass && !allChildrenVisited)
                 LogicError("ValidateSubNetwork: %ls %ls operation in final validation although not all children were visited?", node->NodeName().c_str(), node->OperationName().c_str());
             // if all children valid then
@@ -830,7 +847,7 @@ void ComputationNetwork::AllocateAllMatrices(const std::vector<ComputationNodeBa
         else
         {
             nodeIter->RequestMatricesBeforeForwardProp(m_matrixPool);
-            // we only release matrices for the children since the root node's informatioin will be used and should not be shared
+            // we only release matrices for the children since the root node's information will be used and should not be shared
             // with others
             ReleaseMatricesAfterEvalForChildren(nodeIter, parentCount);
         }