Adding UnitTest timing summary (UT_SHOW_TIMING) (#692)

test/common/EnvVars.cpp

@@ -60,6 +60,7 @@ namespace RcclUnitTesting
     verbose        = GetEnvVar("UT_VERBOSE"     , 0);
     printValues    = GetEnvVar("UT_PRINT_VALUES", 0);
     maxRanksPerGpu = GetEnvVar("UT_MAX_RANKS_PER_GPU", 1);
+    showTiming     = GetEnvVar("UT_SHOW_TIMING",  1);
 
     // Limit number of supported reduction operators to just ncclSum if only allReduce is built
 #ifdef BUILD_ALLREDUCE_ONLY
@@ -168,7 +169,8 @@ namespace RcclUnitTesting
         std::make_pair("UT_REDOPS"           , "List of reduction ops to test"),
         std::make_pair("UT_DATATYPES"        , "List of datatypes to test"),
         std::make_pair("UT_MAX_RANKS_PER_GPU", "Maximum number of ranks using the same GPU"),
-        std::make_pair("UT_PRINT_VALUES"     , "Print array values (# of values to print, < 0 for all)")
+        std::make_pair("UT_PRINT_VALUES"     , "Print array values (# of values to print, < 0 for all)"),
+        std::make_pair("UT_SHOW_TIMING"      , "Show timing table")
       };
 
     printf("================================================================================\n");

test/common/EnvVars.hpp

@@ -18,13 +18,14 @@ namespace RcclUnitTesting
   class EnvVars
   {
   public:
-    bool showNames;   // List test case names during run        [UT_SHOW_NAMES]
-    int  minGpus;     // Set the minimum number of GPUs to use  [UT_MIN_GPUS]
-    int  maxGpus;     // Set the maximum number of GPUs to use  [UT_MAX_GPUS]
-    int  processMask; // Filter single/multi process            [UT_PROCESS_MASK]
-    bool verbose;     // Show verbose TestBed output for debug  [UT_VERBOSE]
-    int  printValues; // Print out input/output/expected arrays [UT_PRINT_VALUES]
-    int  maxRanksPerGpu; // Number of ranks using the same GPU  [UT_MAX_RANKS_PER_GPU]
+    bool showNames;      // List test case names during run        [UT_SHOW_NAMES]
+    int  minGpus;        // Set the minimum number of GPUs to use  [UT_MIN_GPUS]
+    int  maxGpus;        // Set the maximum number of GPUs to use  [UT_MAX_GPUS]
+    int  processMask;    // Filter single/multi process            [UT_PROCESS_MASK]
+    bool verbose;        // Show verbose TestBed output for debug  [UT_VERBOSE]
+    int  printValues;    // Print out input/output/expected arrays [UT_PRINT_VALUES]
+    int  maxRanksPerGpu; // Number of ranks using the same GPU     [UT_MAX_RANKS_PER_GPU]
+    bool showTiming;     // Show timing per case at end            [UT_SHOW_TIMING]
 
     // Constructor that parses and collects environment variables
     EnvVars();

test/common/TestBed.hpp

@@ -26,7 +26,7 @@ namespace RcclUnitTesting
     int                        numActiveRanks;        // Current # of ranks in use
     int                        numCollectivesInGroup; // # of collectives to execute per group call
     bool                       useBlocking;           // RCCL communication with blocking or non-blocking option
-    EnvVars ev;                                       // Environment variables
+    EnvVars                    ev;                    // Environment variables
 
     // Constructor - Creates one child process per detected GPU device that waits for further commands
     TestBed();
@@ -36,7 +36,7 @@ namespace RcclUnitTesting
                    int const numCollectivesInGroup = 1, bool const useBlocking = true);
 
     // Prepare TestBed for use with GPUs on a single child process
-    void InitComms(int const numGpus, 
+    void InitComms(int const numGpus,
                    int const numCollectivesInGroup = 1, bool const useBlocking = true);
 
     // Set collectives arguments for specified collective / rank

test/common/main.cpp

@@ -13,5 +13,30 @@ int main(int argc, char **argv)
   RcclUnitTesting::EnvVars::ShowConfig();
   int retCode = RUN_ALL_TESTS();
   printf("[ INFO     ] Total executed cases: %d\n", RcclUnitTesting::TestBed::NumTestsRun());
+
+  // Show timing information
+  RcclUnitTesting::EnvVars ev;
+  if (ev.showTiming)
+  {
+    printf("[ TIMING   ] %-20s: %-20s: %10s ms (%s)\n", "TEST SUITE", "TEST NAME", "TIME", "STATUS");
+    auto unitTest = ::testing::UnitTest::GetInstance();
+    for (int i = 0; i < unitTest->total_test_suite_count(); i++)
+    {
+      auto suiteInfo = unitTest->GetTestSuite(i);
+      if (!suiteInfo->should_run()) continue;
+
+      for (int j = 0; j < suiteInfo->total_test_count(); j++)
+      {
+        auto testInfo = suiteInfo->GetTestInfo(j);
+        if (!testInfo->should_run()) continue;
+        auto testResult = testInfo->result();
+        if (testResult->Skipped()) continue;
+
+        printf("[ TIMING   ] %-20s: %-20s: %10ld ms (%4s)\n", testInfo->test_suite_name(), testInfo->name(), testResult->elapsed_time(), testResult->Passed() ? "PASS" : "FAIL");
+      }
+      printf("[ TIMING   ] %-20s: %-20s: %10ld ms (%4s)\n", suiteInfo->name(), "TOTAL", suiteInfo->elapsed_time(), suiteInfo->Passed() ? "PASS" : "FAIL");
+    }
+  }
+
   return retCode;
 }