Merge topic 'show_weighted_times'

b2242ea9 Help: Update documentation for PROCESSORS test property
5b829c89 CTest: Weight reported test times by PROCESSORS in summaries
a6e32eb0 CTest: Split out labels and subproject labels in summary output

Acked-by: Kitware Robot <kwrobot@kitware.com>
Merge-request: !1226

Help/prop_test/PROCESSORS.rst

@@ -1,8 +1,13 @@
 PROCESSORS
 ----------
 
-How many process slots this test requires
+Set to specify how many process slots this test requires.
 
 Denotes the number of processors that this test will require.  This is
 typically used for MPI tests, and should be used in conjunction with
-the ctest_test PARALLEL_LEVEL option.
+the :command:`ctest_test` ``PARALLEL_LEVEL`` option.
+
+This will also be used to display a weighted test timing result in label and
+subproject summaries in the command line output of :manual:`ctest(1)`. The wall
+clock time for the test run will be multiplied by this property to give a
+better idea of how much cpu resource CTest allocated for the test.

Source/CTest/cmCTestTestHandler.cxx

@@ -535,14 +535,13 @@ int cmCTestTestHandler::ProcessHandler()
                  << static_cast<int>(percent + .5f) << "% tests passed, "
                  << failed.size() << " tests failed out of " << total
                  << std::endl);
-
-    if (!this->CTest->GetLabelsForSubprojects().empty() &&
-        this->CTest->GetSubprojectSummary()) {
-      this->PrintSubprojectSummary();
-    } else if (this->CTest->GetLabelSummary()) {
-      this->PrintLabelSummary();
+    if ((!this->CTest->GetLabelsForSubprojects().empty() &&
+         this->CTest->GetSubprojectSummary())) {
+      this->PrintLabelOrSubprojectSummary(true);
+    }
+    if (this->CTest->GetLabelSummary()) {
+      this->PrintLabelOrSubprojectSummary(false);
     }
-
     char realBuf[1024];
     sprintf(realBuf, "%6.2f sec", clock_finish - clock_start);
     cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
@@ -620,19 +619,32 @@ int cmCTestTestHandler::ProcessHandler()
   return 0;
 }
 
-void cmCTestTestHandler::PrintLabelSummary()
+void cmCTestTestHandler::PrintLabelOrSubprojectSummary(bool doSubProject)
 {
-  cmCTestTestHandler::ListOfTests::iterator it = this->TestList.begin();
+  // collect subproject labels
+  std::vector<std::string> subprojects =
+    this->CTest->GetLabelsForSubprojects();
   std::map<std::string, double> labelTimes;
   std::map<std::string, int> labelCounts;
   std::set<std::string> labels;
-  // initialize maps
   std::string::size_type maxlen = 0;
-  for (; it != this->TestList.end(); ++it) {
+  // initialize maps
+  for (cmCTestTestHandler::ListOfTests::iterator it = this->TestList.begin();
+       it != this->TestList.end(); ++it) {
     cmCTestTestProperties& p = *it;
-    if (!p.Labels.empty()) {
-      for (std::vector<std::string>::iterator l = p.Labels.begin();
-           l != p.Labels.end(); ++l) {
+    for (std::vector<std::string>::iterator l = p.Labels.begin();
+         l != p.Labels.end(); ++l) {
+      // first check to see if the current label is a subproject label
+      bool isSubprojectLabel = false;
+      std::vector<std::string>::iterator subproject =
+        std::find(subprojects.begin(), subprojects.end(), *l);
+      if (subproject != subprojects.end()) {
+        isSubprojectLabel = true;
+      }
+      // if we are doing sub projects and this label is one, then use it
+      // if we are not doing sub projects and the label is not one use it
+      if ((doSubProject && isSubprojectLabel) ||
+          (!doSubProject && !isSubprojectLabel)) {
         if ((*l).size() > maxlen) {
           maxlen = (*l).size();
         }
@@ -642,22 +654,30 @@ void cmCTestTestHandler::PrintLabelSummary()
       }
     }
   }
-  cmCTestTestHandler::TestResultsVector::iterator ri =
-    this->TestResults.begin();
   // fill maps
-  for (; ri != this->TestResults.end(); ++ri) {
+  for (cmCTestTestHandler::TestResultsVector::iterator ri =
+         this->TestResults.begin();
+       ri != this->TestResults.end(); ++ri) {
     cmCTestTestResult& result = *ri;
     cmCTestTestProperties& p = *result.Properties;
-    if (!p.Labels.empty()) {
-      for (std::vector<std::string>::iterator l = p.Labels.begin();
-           l != p.Labels.end(); ++l) {
-        labelTimes[*l] += result.ExecutionTime;
+    for (std::vector<std::string>::iterator l = p.Labels.begin();
+         l != p.Labels.end(); ++l) {
+      // only use labels found in labels
+      if (labels.find(*l) != labels.end()) {
+        labelTimes[*l] += result.ExecutionTime * result.Properties->Processors;
         ++labelCounts[*l];
       }
     }
   }
+  // if no labels are found return and print nothing
+  if (labels.empty()) {
+    return;
+  }
   // now print times
-  if (!labels.empty()) {
+  if (doSubProject) {
+    cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
+                       "\nSubproject Time Summary:", this->Quiet);
+  } else {
     cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\nLabel Time Summary:",
                        this->Quiet);
   }
@@ -667,7 +687,7 @@ void cmCTestTestHandler::PrintLabelSummary()
     label.resize(maxlen + 3, ' ');
 
     char buf[1024];
-    sprintf(buf, "%6.2f sec", labelTimes[*i]);
+    sprintf(buf, "%6.2f sec*proc", labelTimes[*i]);
 
     std::ostringstream labelCountStr;
     labelCountStr << "(" << labelCounts[*i] << " test";
@@ -675,7 +695,6 @@ void cmCTestTestHandler::PrintLabelSummary()
       labelCountStr << "s";
     }
     labelCountStr << ")";
-
     cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\n"
                          << label << " = " << buf << " "
                          << labelCountStr.str(),
@@ -684,92 +703,12 @@ void cmCTestTestHandler::PrintLabelSummary()
       *this->LogFile << "\n" << *i << " = " << buf << "\n";
     }
   }
-  if (!labels.empty()) {
-    if (this->LogFile) {
-      *this->LogFile << "\n";
-    }
-    cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\n", this->Quiet);
+  if (this->LogFile) {
+    *this->LogFile << "\n";
   }
+  cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\n", this->Quiet);
 }
 
-void cmCTestTestHandler::PrintSubprojectSummary()
-{
-  std::vector<std::string> subprojects =
-    this->CTest->GetLabelsForSubprojects();
-
-  cmCTestTestHandler::ListOfTests::iterator it = this->TestList.begin();
-  std::map<std::string, double> labelTimes;
-  std::map<std::string, int> labelCounts;
-  std::set<std::string> labels;
-  // initialize maps
-  std::string::size_type maxlen = 0;
-  for (; it != this->TestList.end(); ++it) {
-    cmCTestTestProperties& p = *it;
-    for (std::vector<std::string>::iterator l = p.Labels.begin();
-         l != p.Labels.end(); ++l) {
-      std::vector<std::string>::iterator subproject =
-        std::find(subprojects.begin(), subprojects.end(), *l);
-      if (subproject != subprojects.end()) {
-        if ((*l).size() > maxlen) {
-          maxlen = (*l).size();
-        }
-        labels.insert(*l);
-        labelTimes[*l] = 0;
-        labelCounts[*l] = 0;
-      }
-    }
-  }
-  cmCTestTestHandler::TestResultsVector::iterator ri =
-    this->TestResults.begin();
-  // fill maps
-  for (; ri != this->TestResults.end(); ++ri) {
-    cmCTestTestResult& result = *ri;
-    cmCTestTestProperties& p = *result.Properties;
-    for (std::vector<std::string>::iterator l = p.Labels.begin();
-         l != p.Labels.end(); ++l) {
-      std::vector<std::string>::iterator subproject =
-        std::find(subprojects.begin(), subprojects.end(), *l);
-      if (subproject != subprojects.end()) {
-        labelTimes[*l] += result.ExecutionTime;
-        ++labelCounts[*l];
-      }
-    }
-  }
-  // now print times
-  if (!labels.empty()) {
-    cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
-                       "\nSubproject Time Summary:", this->Quiet);
-  }
-  for (std::set<std::string>::const_iterator i = labels.begin();
-       i != labels.end(); ++i) {
-    std::string label = *i;
-    label.resize(maxlen + 3, ' ');
-
-    char buf[1024];
-    sprintf(buf, "%6.2f sec", labelTimes[*i]);
-
-    std::ostringstream labelCountStr;
-    labelCountStr << "(" << labelCounts[*i] << " test";
-    if (labelCounts[*i] > 1) {
-      labelCountStr << "s";
-    }
-    labelCountStr << ")";
-
-    cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\n"
-                         << label << " = " << buf << " "
-                         << labelCountStr.str(),
-                       this->Quiet);
-    if (this->LogFile) {
-      *this->LogFile << "\n" << *i << " = " << buf << "\n";
-    }
-  }
-  if (!labels.empty()) {
-    if (this->LogFile) {
-      *this->LogFile << "\n";
-    }
-    cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT, "\n", this->Quiet);
-  }
-}
 void cmCTestTestHandler::CheckLabelFilterInclude(cmCTestTestProperties& it)
 {
   // if not using Labels to filter then return

Source/CTest/cmCTestTestHandler.h

@@ -232,8 +232,7 @@ private:
    */
   virtual void GenerateDartOutput(cmXMLWriter& xml);
 
-  void PrintLabelSummary();
-  void PrintSubprojectSummary();
+  void PrintLabelOrSubprojectSummary(bool isSubProject);
 
   /**
    * Run the tests for a directory and any subdirectories

Tests/RunCMake/CTestCommandLine/LabelCount-stdout.txt

@@ -1,7 +1,7 @@
 100% tests passed, 0 tests failed out of 4
 +
 +Label Time Summary:
-+'bar'    = +[0-9.]+ sec \(3 tests\)
-+'foo'    = +[0-9.]+ sec \(1 test\)
++'bar'    = +[0-9.]+ sec\*proc \(3 tests\)
++'foo'    = +[0-9.]+ sec\*proc \(1 test\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/CTestConfigCTestScript-stdout.txt

@@ -1,7 +1,10 @@
 17% tests passed, 5 tests failed out of 6
 +
 Subproject Time Summary:
-MyExperimentalFeature += +[0-9.]+ sec \(5 tests\)
-MyProductionCode += +[0-9.]+ sec \(1 test\)
+MyExperimentalFeature += +[0-9.]+ sec\*proc \(5 tests\)
+MyProductionCode += +[0-9.]+ sec\*proc \(1 test\)
++
+Label Time Summary:
+NotASubproject += +[0-9.]+ sec\*proc \(6 tests\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/CTestScriptVariable-stdout.txt

@@ -1,7 +1,10 @@
 17% tests passed, 5 tests failed out of 6
 +
 Subproject Time Summary:
-MyExperimentalFeature += +[0-9.]+ sec \(5 tests\)
-MyProductionCode += +[0-9.]+ sec \(1 test\)
+MyExperimentalFeature += +[0-9.]+ sec\*proc \(5 tests\)
+MyProductionCode += +[0-9.]+ sec\*proc \(1 test\)
++
+Label Time Summary:
+NotASubproject += +[0-9.]+ sec\*proc \(6 tests\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/CTestScriptVariableCommandLine-stdout.txt

@@ -1,6 +1,9 @@
 0% tests passed, 1 tests failed out of 1
 +
 Subproject Time Summary:
-MyThirdPartyDependency += +[0-9.]+ sec \(1 test\)
+MyThirdPartyDependency += +[0-9.]+ sec\*proc \(1 test\)
++
+Label Time Summary:
+NotASubproject += +[0-9.]+ sec\*proc \(1 test\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/ModuleVariableCMakeLists-stdout.txt

@@ -1,6 +1,6 @@
 50% tests passed, 1 tests failed out of 2
 +
 Subproject Time Summary:
-MySubproject += +[0-9.]+ sec \(2 tests\)
+MySubproject += +[0-9.]+ sec\*proc \(2 tests\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/ModuleVariableCTestConfig-stdout.txt

@@ -1,6 +1,9 @@
 67% tests passed, 1 tests failed out of 3
 +
 Subproject Time Summary:
-MySubproject += +[0-9.]+ sec \(2 tests\)
+MySubproject += +[0-9.]+ sec\*proc \(2 tests\)
++
+Label Time Summary:
+NotASubproject += +[0-9.]+ sec\*proc \(1 test\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/ModuleVariableCTestConfigNoSummary-stdout.txt

@@ -1,7 +1,6 @@
 67% tests passed, 1 tests failed out of 3
 +
 Label Time Summary:
-MySubproject += +[0-9.]+ sec \(2 tests\)
-NotASubproject += +[0-9.]+ sec \(1 test\)
+NotASubproject += +[0-9.]+ sec\*proc \(1 test\)
 +
 Total Test time \(real\) = +[0-9.]+ sec

Tests/RunCMake/ctest_labels_for_subprojects/ModuleVariableCommandLine-stdout.txt

@@ -1,6 +1,6 @@
 50% tests passed, 1 tests failed out of 2
 +
 Subproject Time Summary:
-MySubproject += +[0-9.]+ sec \(2 tests\)
+MySubproject += +[0-9.]+ sec\*proc \(2 tests\)
 +
 Total Test time \(real\) = +[0-9.]+ sec