Simple test profiling (#1062)

* First pass support for performance profiling

* Test across all elements

* Fix bug - sourceContents is not used, should use rawSource.

* * Add ability to get prelude from API.
* Allow specifying source language for render-test
* Made it possible to compile a test input file as C++
  * Special handling for reflection
* Added C++ impl to performance-profile.slang

* Remove some clang warnings.

* Output profile timings on appveyor and other TC.

* Remove passing around of StdWriters (can use global).
Small comment improvements.

3 files changed, 127 insertions, 7 deletions

diff --git a/tools/slang-test/slang-test-main.cpp b/tools/slang-test/slang-test-main.cpp
index a2d24a54f..e1309d01f 100644
--- a/tools/slang-test/slang-test-main.cpp
+++ b/tools/slang-test/slang-test-main.cpp
@@ -1914,6 +1914,65 @@ static void _addRenderTestOptions(const Options& options, CommandLine& ioCmdLine
     }
 }
 
+static SlangResult _extractProfileTime(const UnownedStringSlice& text, double& timeOut)
+{
+    // Need to find the profile figure..
+    LineParser parser(text);
+
+    const auto lineStart = UnownedStringSlice::fromLiteral("profile-time=");
+    for (auto line : parser)
+    {
+        if (line.startsWith(lineStart))
+        {
+            UnownedStringSlice remaining(line.begin() + lineStart.size(), line.end());
+            remaining.trim();
+
+            timeOut = StringToDouble(String(remaining));
+            return SLANG_OK;
+        }
+    }
+
+    return SLANG_FAIL;
+}
+
+TestResult runPerformanceProfile(TestContext* context, TestInput& input)
+{
+    auto outputStem = input.outputStem;
+
+    CommandLine cmdLine;
+
+    cmdLine.setExecutablePath(Path::combine(context->options.binDir, String("render-test") + ProcessUtil::getExecutableSuffix()));
+    
+    cmdLine.addArg(input.filePath);
+    cmdLine.addArg("-performance-profile");
+
+    _addRenderTestOptions(context->options, cmdLine);
+
+    for (auto arg : input.testOptions->args)
+    {
+        cmdLine.addArg(arg);
+    }
+
+    ExecuteResult exeRes;
+    TEST_RETURN_ON_DONE(spawnAndWait(context, outputStem, input.spawnType, cmdLine, exeRes));
+    if (context->isCollectingRequirements())
+    {
+        return TestResult::Pass;
+    }
+
+    auto actualOutput = getOutput(exeRes);
+
+    double time;
+    if (SLANG_FAILED(_extractProfileTime(actualOutput.getUnownedSlice(), time)))
+    {
+        return TestResult::Fail;
+    }
+
+    context->reporter->addExecutionTime(time);
+
+    return TestResult::Pass;
+}
+
 TestResult runComputeComparisonImpl(TestContext* context, TestInput& input, const char *const* langOpts, size_t numLangOpts)
 {
 	// TODO: delete any existing files at the output path(s) to avoid stale outputs leading to a false pass
@@ -2342,6 +2401,7 @@ static const TestCommandInfo s_testCommandInfos[] =
     { "CPP_COMPILER_EXECUTE",                   &runCPPCompilerExecute},
     { "CPP_COMPILER_SHARED_LIBRARY",            &runCPPCompilerSharedLibrary},
     { "CPP_COMPILER_COMPILE",                   &runCPPCompilerCompile},
+    { "PERFORMANCE_PROFILE",                    &runPerformanceProfile},
 };
 
 TestResult runTest(
diff --git a/tools/slang-test/test-reporter.cpp b/tools/slang-test/test-reporter.cpp
index f7ab3cf1e..9dd34739b 100644
--- a/tools/slang-test/test-reporter.cpp
+++ b/tools/slang-test/test-reporter.cpp
@@ -142,6 +142,11 @@ void TestReporter::addResult(TestResult result)
     m_numCurrentResults++;
 }
 
+void TestReporter::addExecutionTime(double time)
+{
+    m_currentInfo.executionTime = time;
+}
+
 void TestReporter::addResultWithLocation(TestResult result, const char* testText, const char* file, int line)
 {
     assert(m_inTest);
@@ -254,6 +259,31 @@ static void _appendEncodedTeamCityString(const UnownedStringSlice& in, StringBui
     }
 }
 
+static void _appendTime(double timeInSec, StringBuilder& out)
+{
+    SLANG_ASSERT(timeInSec >= 0.0);
+    if (timeInSec == 0.0 || timeInSec >= 1.0)
+    {
+        out << timeInSec << "s";
+        return;
+    }
+    timeInSec *= 1000.0f;
+    if (timeInSec > 1.0f)
+    {
+        out << timeInSec << "ms";
+        return;
+    }
+    timeInSec *= 1000.0f;
+    if (timeInSec > 1.0f)
+    {
+        out << timeInSec << "us";
+        return;
+    }
+
+    timeInSec *= 1000.0f;
+    out << timeInSec << "ns";
+}
+
 void TestReporter::_addResult(const TestInfo& info)
 {
     m_totalTestCount++;
@@ -294,7 +324,13 @@ void TestReporter::_addResult(const TestInfo& info)
                     assert(!"unexpected");
                     break;
             }
-            printf("%s test: '%S'\n", resultString, info.name.toWString().begin());
+
+            StringBuilder buffer;
+            if (info.executionTime > 0.0f)
+            {
+                _appendTime(info.executionTime, buffer);
+            }
+            printf("%s test: '%S' %s\n", resultString, info.name.toWString().begin(), buffer.getBuffer());
             break;
         }
         case TestOutputMode::TeamCity:
@@ -303,7 +339,7 @@ void TestReporter::_addResult(const TestInfo& info)
             _appendEncodedTeamCityString(info.name.getUnownedSlice(), escapedTestName);
 
             printf("##teamcity[testStarted name='%s']\n", escapedTestName.begin());
-             
+
             switch (info.testResult)
             {
                 case TestResult::Fail:      
@@ -322,12 +358,24 @@ void TestReporter::_addResult(const TestInfo& info)
                 }
                 case TestResult::Pass:     
                 {
-                    if (info.message.getLength())
+                    StringBuilder message;
+                    message << info.message;
+                    // Add execution time if one is set
+                    if (info.executionTime > 0.0)
+                    {
+                        if (message.getLength())
+                        {
+                            message << " ";
+                        }
+                        _appendTime(info.executionTime, message);
+                    }
+
+                    if (message.getLength())
                     {
                         StringBuilder escapedMessage;
-                        _appendEncodedTeamCityString(info.message.getUnownedSlice(), escapedMessage);
+                        _appendEncodedTeamCityString(message.getUnownedSlice(), escapedMessage);
                         printf("##teamcity[testStdOut name='%s' out='%s']\n", escapedTestName.begin(), escapedMessage.begin());
-                    }
+                    }                    
                     break;
                 }
                 case TestResult::Ignored:  
@@ -373,6 +421,8 @@ void TestReporter::_addResult(const TestInfo& info)
                     break;
             }
 
+            // https://www.appveyor.com/docs/build-worker-api/#add-tests
+
             CommandLine cmdLine;
             cmdLine.setExecutableFilename("appveyor");
             cmdLine.addArg("AddTest");
@@ -385,6 +435,15 @@ void TestReporter::_addResult(const TestInfo& info)
             cmdLine.addArg("-Outcome");
             cmdLine.addArg(resultString);
 
+            // If has execution time output it
+            if (info.executionTime > 0.0)
+            {
+                StringBuilder builder;
+                _appendTime(info.executionTime, builder);
+                cmdLine.addArg("-StdOut");
+                cmdLine.addArg(builder);
+            }
+
             ExecuteResult exeRes;
             SlangResult res = ProcessUtil::execute(cmdLine, exeRes);
             
diff --git a/tools/slang-test/test-reporter.h b/tools/slang-test/test-reporter.h
index 95f9950e8..cb4d5e985 100644
--- a/tools/slang-test/test-reporter.h
+++ b/tools/slang-test/test-reporter.h
@@ -66,7 +66,8 @@ class TestReporter
     {
         TestResult testResult = TestResult::Ignored;
         Slang::String name;
-        Slang::String message;                 ///< Message that is specific for the testResult
+        Slang::String message;                  ///< Message that is specific for the testResult
+        double executionTime = 0.0;             ///< <= 0.0 if not defined. Time is in seconds. 
     };
     
     class TestScope
@@ -110,7 +111,7 @@ class TestReporter
     void addResult(TestResult result);
     void addResultWithLocation(TestResult result, const char* testText, const char* file, int line);
     void addResultWithLocation(bool testSucceeded, const char* testText, const char* file, int line);
-
+    void addExecutionTime(double time);
     void endTest();
     
         /// Runs start/endTest and outputs the result