Enable -ftime-report flag (#4736)

This just surfaces and plumbs throug the -ftime-report clang flag in
dxc.exe.

-ftime-report prints timing data for different parts of the compile
to help identify and track down performance issues. When using the
dxcompiler library interface the output for the time report is returned
as a DXC_OUT_TIME_REPORT buffer.

I've set up the -ftime-report tests to run against the DXC command
line. On Windows this usees the hcttestcmds file, on Linux (and windows
if enabled) this will test through a lit shell suite.

include/dxc/Support/HLSLOptions.h

@@ -206,6 +206,7 @@ public:
   bool ForceZeroStoreLifetimes = false; // OPT_force_zero_store_lifetimes
   bool EnableLifetimeMarkers = false; // OPT_enable_lifetime_markers
   bool ForceDisableLocTracking = false; // OPT_fdisable_loc_tracking
+  bool TimeReport = false; // OPT_ftime_report
 
   // Optimization pass enables, disables and selects
   std::map<std::string, bool> DxcOptimizationToggles; // OPT_opt_enable & OPT_opt_disable

include/dxc/Support/HLSLOptions.td

@@ -172,6 +172,9 @@ def fdisable_loc_tracking : Flag<["-"], "fdisable-loc-tracking">,
   Group<hlslcomp_Group>, Flags<[CoreOption]>,
   HelpText<"Disable source location tracking in IR. This will break diagnostic generation for late validation. (Ignored if /Zi is passed)">;
 
+
+def ftime_report : Flag<["-"], "ftime-report">, Group<hlslcomp_Group>, Flags<[CoreOption]>, HelpText<"Print time report">;
+
 /*
 def fno_caret_diagnostics : Flag<["-"], "fno-caret-diagnostics">, Group<hlslcomp_Group>,
  Flags<[CoreOption]>;

include/dxc/Support/dxcapi.impl.h

@@ -97,6 +97,7 @@ inline DxcOutputType DxcGetOutputType(DXC_OUT_KIND kind) {
   case DXC_OUT_HLSL:
   case DXC_OUT_TEXT:
   case DXC_OUT_REMARKS:
+  case DXC_OUT_TIME_REPORT:
     return DxcOutputType_Text;
   default:
     return DxcOutputType_None;
@@ -104,7 +105,7 @@ inline DxcOutputType DxcGetOutputType(DXC_OUT_KIND kind) {
 }
 
 // Update when new results are allowed
-static const unsigned kNumDxcOutputTypes = DXC_OUT_REMARKS;
+static const unsigned kNumDxcOutputTypes = DXC_OUT_LAST;
 static const SIZE_T kAutoSize = (SIZE_T)-1;
 static const LPCWSTR DxcOutNoName = nullptr;
 

include/dxc/dxcapi.h

@@ -476,11 +476,18 @@ typedef enum DXC_OUT_KIND {
   DXC_OUT_REFLECTION = 8,     // IDxcBlob - RDAT part with reflection data
   DXC_OUT_ROOT_SIGNATURE = 9, // IDxcBlob - Serialized root signature output
   DXC_OUT_EXTRA_OUTPUTS  = 10,// IDxcExtraResults - Extra outputs
-  DXC_OUT_REMARKS = 11,       // IDxcBlobUtf8 or IDxcBlobUtf16 - text directed at stdout
+  DXC_OUT_REMARKS = 11,       // IDxcBlobUtf8 or IDxcBlobWide - text directed at stdout
+  DXC_OUT_TIME_REPORT = 12,   // IDxcBlobUtf8 or IDxcBlobWide - text directed at stdout
 
+  DXC_OUT_LAST = DXC_OUT_TIME_REPORT, // Last value for a counter
+
+  DXC_OUT_NUM_ENUMS,
   DXC_OUT_FORCE_DWORD = 0xFFFFFFFF
 } DXC_OUT_KIND;
 
+static_assert(DXC_OUT_NUM_ENUMS == DXC_OUT_LAST + 1,
+              "DXC_OUT_* Enum added and last value not updated.");
+
 CROSS_PLATFORM_UUIDOF(IDxcResult, "58346CDA-DDE7-4497-9461-6F87AF5E0659")
 struct IDxcResult : public IDxcOperationResult {
   virtual BOOL STDMETHODCALLTYPE HasOutput(_In_ DXC_OUT_KIND dxcOutKind) = 0;

lib/DxcSupport/HLSLOptions.cpp

@@ -781,6 +781,7 @@ int ReadDxcOpts(const OptTable *optionTable, unsigned flagsToInclude,
                               !Args.hasFlag(OPT_disable_lifetime_markers, OPT_INVALID, false);
   opts.ForceDisableLocTracking =
       Args.hasFlag(OPT_fdisable_loc_tracking, OPT_INVALID, false);
+  opts.TimeReport = Args.hasFlag(OPT_ftime_report, OPT_INVALID, false);
   opts.EnablePayloadQualifiers = Args.hasFlag(OPT_enable_payload_qualifiers, OPT_INVALID,
                                             DXIL::CompareVersions(Major, Minor, 6, 7) >= 0); 
 

tools/clang/test/DXC/ftime-report.hlsl

@@ -0,0 +1,7 @@
+// RUN: %dxc -E main -T vs_6_0 %s -ftime-report | FileCheck %s
+
+// CHECK:      ; ===-----------------------------------------
+// CHECK-NEXT: ;                       ... Pass execution timing report ...
+// CHECK-NEXT: ; ===-----------------------------------------
+
+void main() {}

tools/clang/test/lit.cfg

@@ -44,7 +44,7 @@ else:
 config.test_format = lit.formats.ShTest(execute_external)
 
 # suffixes: A list of file extensions to treat as test files.
-config.suffixes = ['.c', '.cpp', '.m', '.mm', '.cu', '.ll', '.cl', '.s', '.S', '.modulemap']
+config.suffixes = ['.c', '.cpp', '.m', '.mm', '.cu', '.ll', '.cl', '.s', '.S', '.modulemap', '.hlsl']
 
 # excludes: A list of directories to exclude from the testsuite. The 'Inputs'
 # subdirectories contain auxiliary inputs for various tests in their parent
@@ -267,6 +267,7 @@ config.substitutions.append( ('%clang', ' ' + config.clang + ' ') )
 config.substitutions.append( ('%test_debuginfo', ' ' + config.llvm_src_root + '/utils/test_debuginfo.pl ') )
 config.substitutions.append( ('%itanium_abi_triple', makeItaniumABITriple(config.target_triple)) )
 config.substitutions.append( ('%ms_abi_triple', makeMSABITriple(config.target_triple)) )
+config.substitutions.append( ('%dxc', lit.util.which('dxc', llvm_tools_dir)) )
 
 # The host triple might not be set, at least if we're compiling clang from
 # an already installed llvm.

tools/clang/tools/dxclib/dxc.cpp

@@ -266,29 +266,27 @@ static void WriteDxcExtraOuputs(IDxcResult *pResult) {
   }
 }
 
-static void WriteDxcRemarksToConsole(IDxcOperationResult *pCompileResult) {
+static void WriteDxcOutputToConsole(IDxcOperationResult *pCompileResult, DXC_OUT_KIND kind) {
   CComPtr<IDxcResult> pResult;
   if (SUCCEEDED(pCompileResult->QueryInterface(&pResult))) {
-    DXC_OUT_KIND kind = DXC_OUT_REMARKS;
     if (!pResult->HasOutput(kind)) {
       return;
     }
 
     CComPtr<IDxcBlob> pBlob;
     IFT(pResult->GetOutput(kind, IID_PPV_ARGS(&pBlob), nullptr));
-    llvm::StringRef remarkRef((LPSTR)pBlob->GetBufferPointer(),
-                              pBlob->GetBufferSize());
-    std::istringstream remarkIStream(remarkRef);
-
-    // Printing remarks to console as comments
-    std::string remarkPrintStr;
-    llvm::raw_string_ostream remarkPrintStream(remarkPrintStr);
-    for (std::string line; std::getline(remarkIStream, line);) {
-      remarkPrintStream << "; " << line << "\r\n";
+    llvm::StringRef outputString((LPSTR)pBlob->GetBufferPointer(),
+                            pBlob->GetBufferSize());
+    llvm::SmallVector<llvm::StringRef, 20> lines;
+    outputString.split(lines, "\n");
+    
+    std::string outputStr;
+    llvm::raw_string_ostream SS(outputStr);
+    for (auto line : lines) {
+      SS << "; " << line << "\n";
     }
-    remarkPrintStream.flush();
 
-    WriteUtf8ToConsole(remarkPrintStr.data(), remarkPrintStr.size());
+    WriteUtf8ToConsole(outputStr.data(), outputStr.size());
   }
 }
 
@@ -868,12 +866,15 @@ int DxcContext::Compile() {
   else {
     WriteOperationErrorsToConsole(pCompileResult, m_Opts.OutputWarnings);
   }
+  
+  if (m_Opts.TimeReport)
+    WriteDxcOutputToConsole(pCompileResult, DXC_OUT_TIME_REPORT);
 
   HRESULT status;
   IFT(pCompileResult->GetStatus(&status));
   if (SUCCEEDED(status) || m_Opts.AstDump || m_Opts.OptDump ||
       m_Opts.DumpDependencies) {
-    WriteDxcRemarksToConsole(pCompileResult);
+    WriteDxcOutputToConsole(pCompileResult, DXC_OUT_REMARKS);
     CComPtr<IDxcBlob> pProgram;
     IFT(pCompileResult->GetResult(&pProgram));
     if (pProgram.p != nullptr) {

tools/clang/tools/dxcompiler/dxcompilerobj.cpp

@@ -25,6 +25,7 @@
 #include "clang/CodeGen/CodeGenAction.h"
 #include "llvm/IR/LLVMContext.h"
 #include "llvm/Transforms/Utils/Cloning.h"
+#include "llvm/Support/Timer.h"
 #include "dxc/Support/WinIncludes.h"
 #include "dxc/HLSL/HLSLExtensionsCodegenHelper.h"
 #include "dxc/DxilRootSignature/DxilRootSignature.h"
@@ -1410,6 +1411,7 @@ public:
     }
 
     compiler.getFrontendOpts().Inputs.push_back(FrontendInputFile(pMainFile, IK_HLSL));
+    compiler.getFrontendOpts().ShowTimers = Opts.TimeReport ? 1 : 0;
     // Setup debug information.
     if (Opts.GenerateFullDebugInfo()) {
       CodeGenOptions &CGOpts = compiler.getCodeGenOpts();
@@ -1825,6 +1827,14 @@ HRESULT DxcCompilerAdapter::WrapCompile(
     pResult->CopyOutputsFromResult(pImplResult);
     pResult->SetStatusAndPrimaryResult(hr, pImplResult->PrimaryOutput());
 
+    if (opts.TimeReport) {
+      std::string TimeReport;
+      raw_string_ostream OS(TimeReport);
+      llvm::TimerGroup::printAll(OS);
+      IFT(pResult->SetOutputString(DXC_OUT_TIME_REPORT, TimeReport.c_str(),
+                                   TimeReport.size()));
+    }
+
     outStream.flush();
 
     // Insert any warnings generated here

tools/clang/unittests/HLSL/CompilerTest.cpp

@@ -172,6 +172,7 @@ public:
   TEST_METHOD(CompileWhenIncludeSystemMissingThenLoadAttempt)
   TEST_METHOD(CompileWhenIncludeFlagsThenIncludeUsed)
   TEST_METHOD(CompileThenCheckDisplayIncludeProcess)
+  TEST_METHOD(CompileThenPrintTimeReport)
   TEST_METHOD(CompileWhenIncludeMissingThenFail)
   TEST_METHOD(CompileWhenIncludeHasPathThenOK)
   TEST_METHOD(CompileWhenIncludeEmptyThenOK)
@@ -2812,6 +2813,32 @@ TEST_F(CompilerTest, CompileThenCheckDisplayIncludeProcess) {
 
 }
 
+TEST_F(CompilerTest, CompileThenPrintTimeReport) {
+  CComPtr<IDxcCompiler> pCompiler;
+  CComPtr<IDxcOperationResult> pResult;
+  CComPtr<IDxcBlobEncoding> pSource;
+  CComPtr<TestIncludeHandler> pInclude;
+
+  VERIFY_SUCCEEDED(CreateCompiler(&pCompiler));
+  CreateBlobFromText("float4 main() : SV_Target { return 0.0; }", &pSource);
+
+  LPCWSTR args[] = {L"-ftime-report"};
+  VERIFY_SUCCEEDED(pCompiler->Compile(pSource, L"source.hlsl", L"main",
+                                      L"ps_6_0", args, _countof(args), nullptr,
+                                      0, pInclude, &pResult));
+  VerifyOperationSucceeded(pResult);
+
+  CComPtr<IDxcResult> pCompileResult;
+  CComPtr<IDxcBlob> pReportBlob;
+  pResult->QueryInterface(&pCompileResult);
+  VERIFY_SUCCEEDED(pCompileResult->GetOutput(
+      DXC_OUT_TIME_REPORT, IID_PPV_ARGS(&pReportBlob), nullptr));
+  std::string text(BlobToUtf8(pReportBlob));
+
+  VERIFY_ARE_NOT_EQUAL(string::npos,
+                       text.find("... Pass execution timing report ..."));
+}
+
 TEST_F(CompilerTest, CompileWhenIncludeMissingThenFail) {
   CComPtr<IDxcCompiler> pCompiler;
   CComPtr<IDxcOperationResult> pResult;

utils/hct/hcttestcmds.cmd

@@ -135,6 +135,11 @@ call :run dxc.exe /T ps_6_0 "%testfiles%\smoke.hlsl" /ast-dump
 call :check_file log find TranslationUnitDecl
 if %Failed% neq 0 goto :failed
 
+set testname=time-report
+call :run dxc.exe /T ps_6_0 "%testfiles%\smoke.hlsl" -ftime-report
+call :check_file log find "Pass execution timing report"
+if %Failed% neq 0 goto :failed
+
 set testname=Check Warning
 call :run dxc.exe /T ps_6_0 "%testfiles%\smoke.hlsl" /Dcheck_warning
 call :check_file log find warning: