additional time reporting and stardardization

moses-cmd/Main.cpp

@@ -109,16 +109,17 @@ public:
   /** Translate one sentence
    * gets called by main function implemented at end of this source file */
   void Run() {
+    Timer translationTime;
+    translationTime.start();
 
     // report thread number
 #if defined(WITH_THREADS) && defined(BOOST_HAS_PTHREADS)
     TRACE_ERR("Translating line " << m_lineNumber << "  in thread id " << pthread_self() << std::endl);
 #endif
 
-    Timer translationTime;
-    translationTime.start();
     // shorthand for "global data"
     const StaticData &staticData = StaticData::Instance();
+
     // input sentence
     Sentence sentence;
 
@@ -128,6 +129,10 @@ public:
     Manager manager(m_lineNumber, *m_source,staticData.GetSearchAlgorithm());
     manager.ProcessSentence();
 
+    // we are done with search, let's look what we got
+    Timer additionalReportingTime;
+    additionalReportingTime.start();
+
     // output word graph
     if (m_wordGraphCollector) {
       ostringstream out;
@@ -266,6 +271,7 @@ public:
         delete file;
       }
     }
+    additionalReportingTime.stop();
 
     // apply decision rule and output best translation(s)
     if (m_outputCollector) {
@@ -275,9 +281,14 @@ public:
 
       // all derivations - send them to debug stream
       if (staticData.PrintAllDerivations()) {
+        additionalReportingTime.start();
         manager.PrintAllDerivations(m_lineNumber, debug);
+        additionalReportingTime.stop();
       }
 
+      Timer decisionRuleTime;
+      decisionRuleTime.start();
+
       // MAP decoding: best hypothesis
       const Hypothesis* bestHypo = NULL;
       if (!staticData.UseMBR()) {
@@ -379,8 +390,13 @@ public:
 
       // report best translation to output collector
       m_outputCollector->Write(m_lineNumber,out.str(),debug.str());
+
+      decisionRuleTime.stop();
+      VERBOSE(1, "Line " << m_lineNumber << ": Decision rule took " << decisionRuleTime << " seconds total" << endl);
     }
 
+    additionalReportingTime.start();
+
     // output n-best list
     if (m_nbestCollector && !staticData.UseLatticeMBR()) {
       TrellisPathList nBestList;
@@ -421,12 +437,12 @@ public:
     }
 
     // report additional statistics
+    manager.CalcDecoderStatistics();
+    VERBOSE(1, "Line " << m_lineNumber << ": Additional reporting took " << additionalReportingTime << " seconds total" << endl);
+    VERBOSE(1, "Line " << m_lineNumber << ": Translation took " << translationTime << " seconds total" << endl);
     IFVERBOSE(2) {
       PrintUserTime("Sentence Decoding Time:");
     }
-    manager.CalcDecoderStatistics();
-
-    VERBOSE(1, "Line " << m_lineNumber << ": Translation took " << translationTime << " seconds total" << endl);
   }
 
   ~TranslationTask() {
@@ -466,7 +482,6 @@ static void ShowWeights()
 {
   //TODO: Find a way of ensuring this order is synced with the nbest
   fix(cout,6);
-  const StaticData& staticData = StaticData::Instance();
   const vector<const StatelessFeatureFunction*>& slf = StatelessFeatureFunction::GetStatelessFeatureFunctions();
   const vector<const StatefulFeatureFunction*>& sff = StatefulFeatureFunction::GetStatefulFeatureFunctions();
 
@@ -512,7 +527,6 @@ void OutputFeatureWeightsForHypergraph(std::ostream &outputSearchGraphStream)
   outputSearchGraphStream.setf(std::ios::fixed);
   outputSearchGraphStream.precision(6);
 
-  const StaticData& staticData = StaticData::Instance();
   const vector<const StatelessFeatureFunction*>& slf =StatelessFeatureFunction::GetStatelessFeatureFunctions();
   const vector<const StatefulFeatureFunction*>& sff = StatefulFeatureFunction::GetStatefulFeatureFunctions();
   size_t featureIndex = 1;

moses/StaticData.cpp

@@ -881,7 +881,12 @@ void StaticData::InitializeForInput(const InputType& source) const
   const std::vector<FeatureFunction*> &producers = FeatureFunction::GetFeatureFunctions();
   for(size_t i=0; i<producers.size(); ++i) {
     FeatureFunction &ff = *producers[i];
-    ff.InitializeForInput(source);
+    if (! IsFeatureFunctionIgnored(ff)) {
+      Timer iTime;
+      iTime.start();
+      ff.InitializeForInput(source);
+      VERBOSE(3,"InitializeForInput( " << ff.GetScoreProducerDescription() << " ) = " << iTime << endl);
+    }
   }
 }
 
@@ -890,7 +895,9 @@ void StaticData::CleanUpAfterSentenceProcessing(const InputType& source) const
   const std::vector<FeatureFunction*> &producers = FeatureFunction::GetFeatureFunctions();
   for(size_t i=0; i<producers.size(); ++i) {
     FeatureFunction &ff = *producers[i];
-    ff.CleanUpAfterSentenceProcessing(source);
+    if (! IsFeatureFunctionIgnored(ff)) {
+      ff.CleanUpAfterSentenceProcessing(source);
+    }
   }
 }
 

moses/TranslationModel/PhraseDictionary.cpp

@@ -163,6 +163,8 @@ GetTargetPhraseCollectionBatch(const InputPathList &inputPathQueue) const
 // reduce presistent cache by half of maximum size
 void PhraseDictionary::ReduceCache() const
 {
+  Timer reduceCacheTime;
+  reduceCacheTime.start();
   CacheColl &cache = GetCache();
   if (cache.size() <= m_maxCacheSize) return; // not full
 
@@ -177,7 +179,6 @@ void PhraseDictionary::ReduceCache() const
   for( size_t i=0; i < lastUsedTimes.size()-m_maxCacheSize/2; i++ )
     lastUsedTimes.pop();
   clock_t cutoffLastUsedTime = lastUsedTimes.top();
-  clock_t t = clock();
 
   // remove all old entries
   iter = cache.begin();
@@ -188,7 +189,7 @@ void PhraseDictionary::ReduceCache() const
       cache.erase(iterRemove);
     } else iter++;
   }
-  VERBOSE(2,"Reduced persistent translation option cache in " << ((clock()-t)/(float)CLOCKS_PER_SEC) << " seconds." << std::endl);
+  VERBOSE(2,"Reduced persistent translation option cache in " << reduceCacheTime << " seconds." << std::endl);
 }
 
 PhraseDictionary::CacheColl &PhraseDictionary::GetCache() const