[Modules] Add stats to measure performance of building and loading modules.

[vsapsai]

Summary

Measure amount of high-level or fixed-cost operations performed during
building/loading modules and during header search. High-level operations
like building a module or processing a .pcm file are motivated by
previous issues where clang was re-building modules or re-reading .pcm
files unnecessarily. Fixed-cost operations like stat calls are tracked
because clang cannot change how long each operation takes but it can
perform fewer of such operations to improve the compile time.

Also tracking such stats over time can help us detect compile-time
regressions. Added stats are more stable than the actual measured
compilation time, so expect the detected regressions to be less noisy.

rdar://problem/55715134

[aprantl]

This looks like a good idea — people will probably have some options on the names and descriptions of the statistics :-)

clang/lib/Frontend/CompilerInstance.cpp

60

NumCompiledModules?

clang/lib/Serialization/ASTReader.cpp

151

Number of times ReadASTCore() is invoked?

[vsapsai]

clang/lib/Frontend/CompilerInstance.cpp

60

Sounds good to me, will change.

clang/lib/Serialization/ASTReader.cpp

151

The suggested wording is not entirely correct because I deliberately want to ignore cases when ReadASTCore() was invoked but returned early due to ModuleManager caching. The purpose of NumReadASTCore is to measure non-trivial work done in ReadASTCore().

I agree the description isn't clear enough and cached/non-cached distinction isn't obvious. I plan to use the suggested wording and to clarify it like for NumTryLoadModule. For instance, "Includes only actual core parsing and ignores cached results."

[vsapsai]

Tweak stats' names and descriptions.

[bruno]

This looks pretty useful, thanks for adding this Volodymyr. LGTM.

[tschuett]

Where is the test?

[vsapsai]

In D86895#2288262, @tschuett wrote:

Where is the test?

ALWAYS_ENABLED_STATISTIC has its own unit tests. And tests that use added stats are in another revision in the stack D86896.

[vsapsai]

Thanks for the reviews!

[thakis]

Looks like the test is still failing on windows: http://45.33.8.238/win/26155/step_11.txt

Ptal, and revert for now if it takes a while to fix.

[vsapsai]

In D86895#2340548, @thakis wrote:

Looks like the test is still failing on windows: http://45.33.8.238/win/26155/step_11.txt

Ptal, and revert for now if it takes a while to fix.

Reverted. Have you seen similar problems on Windows before? Because on Windows JSON output seems to be just

         19: {
         20:  "instsimplify.NumSimplified": 1,
dag:11'0      X~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ error: no match found
         21:  "time.irparse.parse.wall": 2.3221969604492188e-04,
dag:11'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
dag:11'1      ?                                                  possible intended match
         22:  "time.irparse.parse.user": 0.0000000000000000e+00,
dag:11'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
         23:  "time.irparse.parse.sys": 0.0000000000000000e+00
dag:11'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
         24: }

while on macOS the output is

{
	"instsimplify.NumSimplified": 1,
	"time.pass.write-bitcode.wall": 1.4090538024902344e-04,
	"time.pass.write-bitcode.user": 9.0999999999999068e-05,
	"time.pass.write-bitcode.sys": 5.1999999999999963e-05,
	"time.pass.assumption-cache-tracker.wall": 9.5367431640625000e-07,
	"time.pass.assumption-cache-tracker.user": 0.0000000000000000e+00,
	"time.pass.assumption-cache-tracker.sys": 0.0000000000000000e+00,
	"time.pass.targetlibinfo.wall": 9.5367431640625000e-07,
	"time.pass.targetlibinfo.user": 0.0000000000000000e+00,
	"time.pass.targetlibinfo.sys": 9.9999999999926537e-07,
	"time.pass.verify.wall": 3.0994415283203125e-06,
	"time.pass.verify.user": 2.0000000000002655e-06,
	"time.pass.verify.sys": 1.0000000000010001e-06,
	"time.pass.instsimplify.wall": 3.1948089599609375e-05,
	"time.pass.instsimplify.user": 2.0000000000000052e-05,
	"time.pass.instsimplify.sys": 1.1000000000000593e-05,
	"time.pass.opt-remark-emitter.wall": 9.5367431640625000e-07,
	"time.pass.opt-remark-emitter.user": 0.0000000000000000e+00,
	"time.pass.opt-remark-emitter.sys": 9.9999999999926537e-07,
	"time.pass.lazy-block-freq.wall": 1.9073486328125000e-06,
	"time.pass.lazy-block-freq.user": 1.0000000000001327e-06,
	"time.pass.lazy-block-freq.sys": 0.0000000000000000e+00,
	"time.pass.lazy-branch-prob.wall": 7.3909759521484375e-06,
	"time.pass.lazy-branch-prob.user": 4.0000000000005309e-06,
	"time.pass.lazy-branch-prob.sys": 2.9999999999995308e-06,
	"time.pass.loops.wall": 1.3828277587890625e-05,
	"time.pass.loops.user": 7.0000000000000617e-06,
	"time.pass.loops.sys": 3.9999999999987962e-06,
	"time.pass.domtree.wall": 8.1062316894531250e-06,
	"time.pass.domtree.user": 2.9999999999995308e-06,
	"time.pass.domtree.sys": 3.0000000000012655e-06,
	"time.irparse.parse.wall": 1.8978118896484375e-04,
	"time.irparse.parse.user": 1.1800000000000005e-04,
	"time.irparse.parse.sys": 6.4999999999999086e-05
}

clang/lib/Frontend/CompilerInstance.cpp

 #include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/raw_ostream.h"
 #include <time.h>
 #include <utility>
 
 using namespace clang;
 
+#define DEBUG_TYPE "modules"
+
+ALWAYS_ENABLED_STATISTIC(NumCompiledModules, "Number of compiled modules.");
+
 CompilerInstance::CompilerInstance(
     std::shared_ptr<PCHContainerOperations> PCHContainerOps,
     InMemoryModuleCache *SharedModuleCache)
     : ModuleLoader(/* BuildingModule = */ SharedModuleCache),
       Invocation(new CompilerInvocation()),
       ModuleCache(SharedModuleCache ? SharedModuleCache
                                     : new InMemoryModuleCache),
       ThePCHContainerOperations(std::move(PCHContainerOps)) {}

 compileModuleImpl(CompilerInstance &ImportingInstance, SourceLocation ImportLoc,
                   StringRef ModuleName, FrontendInputFile Input,
                   StringRef OriginalModuleMapFile, StringRef ModuleFileName,
                   llvm::function_ref<void(CompilerInstance &)> PreBuildStep =
                       [](CompilerInstance &) {},
                   llvm::function_ref<void(CompilerInstance &)> PostBuildStep =
                       [](CompilerInstance &) {}) {
   llvm::TimeTraceScope TimeScope("Module Compile", ModuleName);
+  ++NumCompiledModules;
 
   // Construct a compiler invocation for creating this module.
   auto Invocation =
       std::make_shared<CompilerInvocation>(ImportingInstance.getInvocation());
 
   PreprocessorOptions &PPOpts = Invocation->getPreprocessorOpts();
 
   // For any options that aren't intended to affect how a module is built,

clang/lib/Serialization/ASTReader.cpp

 #include "llvm/ADT/IntrusiveRefCntPtr.h"
 #include "llvm/ADT/None.h"
 #include "llvm/ADT/Optional.h"
 #include "llvm/ADT/STLExtras.h"
 #include "llvm/ADT/ScopeExit.h"
 #include "llvm/ADT/SmallPtrSet.h"
 #include "llvm/ADT/SmallString.h"
 #include "llvm/ADT/SmallVector.h"
+#include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/ADT/Triple.h"
 #include "llvm/ADT/iterator_range.h"
 #include "llvm/Bitstream/BitstreamReader.h"
 #include "llvm/Support/Casting.h"
 #include "llvm/Support/Compiler.h"

 #include <vector>
 
 using namespace clang;
 using namespace clang::serialization;
 using namespace clang::serialization::reader;
 using llvm::BitstreamCursor;
 using llvm::RoundingMode;
 
+#define DEBUG_TYPE "modules"
+
+ALWAYS_ENABLED_STATISTIC(NumTryLoadModule, "Number of times tried to load a "
+                                           "module. Includes failed attempts "
+                                           "and using cached results.");
+ALWAYS_ENABLED_STATISTIC(NumReadASTCore,
+                         "Number of ReadASTCore() invocations. Includes only "
+                         "actual AST core parsing and ignores cached results.");
+
 //===----------------------------------------------------------------------===//
 // ChainedASTReaderListener implementation
 //===----------------------------------------------------------------------===//
 
 bool
 ChainedASTReaderListener::ReadFullVersionInformation(StringRef FullVersion) {
   return First->ReadFullVersionInformation(FullVersion) ||
          Second->ReadFullVersionInformation(FullVersion);
static bool SkipCursorToBlock(BitstreamCursor &Cursor, unsigned BlockID) {
   }
 }
 
 ASTReader::ASTReadResult ASTReader::ReadAST(StringRef FileName,
                                             ModuleKind Type,
                                             SourceLocation ImportLoc,
                                             unsigned ClientLoadCapabilities,
                                             SmallVectorImpl<ImportedSubmodule> *Imported) {
+  ++NumTryLoadModule;
   llvm::SaveAndRestore<SourceLocation>
     SetCurImportLocRAII(CurrentImportLoc, ImportLoc);
 
   // Defer any pending actions until we get to the end of reading the AST file.
   Deserializing AnASTFile(this);
 
   // Bump the generation number.
   unsigned PreviousGeneration = 0;
ASTReader::ReadASTCore(StringRef FileName,
 
   // Sniff for the signature.
   if (llvm::Error Err = doesntStartWithASTFileMagic(Stream)) {
     Diag(diag::err_module_file_invalid)
         << moduleKindForDiagnostic(Type) << FileName << std::move(Err);
     return Failure;
   }
 
+  ++NumReadASTCore;
   // This is used for compatibility with older PCH formats.
   bool HaveReadControlBlock = false;
   while (true) {
     Expected<llvm::BitstreamEntry> MaybeEntry = Stream.advance();
     if (!MaybeEntry) {
       Error(MaybeEntry.takeError());
       return Failure;
     }

llvm/lib/Support/MemoryBuffer.cpp

 //===--- MemoryBuffer.cpp - Memory Buffer implementation ------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 //
 //  This file implements the MemoryBuffer interface.
 //
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/ADT/SmallString.h"
+#include "llvm/ADT/Statistic.h"
 #include "llvm/Config/config.h"
 #include "llvm/Support/Errc.h"
 #include "llvm/Support/Errno.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/MathExtras.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Process.h"
 #include "llvm/Support/Program.h"
 #include "llvm/Support/SmallVectorMemoryBuffer.h"
 #include <cassert>
 #include <cerrno>
 #include <cstring>
 #include <new>
 #include <sys/types.h>
 #include <system_error>
 #if !defined(_MSC_VER) && !defined(__MINGW32__)
 #include <unistd.h>
 #else
 #include <io.h>
 #endif
 using namespace llvm;
 
+#define DEBUG_TYPE "memory-buffer"
+
+ALWAYS_ENABLED_STATISTIC(NumMmapFile, "Number of mmap-ed files.");
+ALWAYS_ENABLED_STATISTIC(NumAllocFile,
+                         "Number of files read into allocated memory buffer.");
+
 //===----------------------------------------------------------------------===//
 // MemoryBuffer implementation itself.
 //===----------------------------------------------------------------------===//
 
 MemoryBuffer::~MemoryBuffer() { }
 
 /// init - Initialize this MemoryBuffer as a reference to externally allocated
 /// memory, memory that we know is already null terminated.
if (FileSize == uint64_t(-1)) {
       if (EC)
         return EC;
 
       // If this not a file or a block device (e.g. it's a named pipe
       // or character device), we can't trust the size. Create the memory
       // buffer by copying off the stream.
       sys::fs::file_type Type = Status.type();
       if (Type != sys::fs::file_type::regular_file &&
-          Type != sys::fs::file_type::block_file)
+          Type != sys::fs::file_type::block_file) {
+        ++NumAllocFile;
         return getMemoryBufferForStream(FD, Filename);
+      }
 
       FileSize = Status.getSize();
     }
     MapSize = FileSize;
   }
 
   if (shouldUseMmap(FD, FileSize, MapSize, Offset, RequiresNullTerminator,
                     PageSize, IsVolatile)) {
     std::error_code EC;
     std::unique_ptr<MB> Result(
         new (NamedBufferAlloc(Filename)) MemoryBufferMMapFile<MB>(
             RequiresNullTerminator, FD, MapSize, Offset, EC));
-    if (!EC)
+    if (!EC) {
+      ++NumMmapFile;
       return std::move(Result);
     }
+  }
 
   auto Buf = WritableMemoryBuffer::getNewUninitMemBuffer(MapSize, Filename);
   if (!Buf) {
     // Failed to create a buffer. The only way it can fail is if
     // new(std::nothrow) returns 0.
     return make_error_code(errc::not_enough_memory);
   }
 
   // Read until EOF, zero-initialize the rest.
+  ++NumAllocFile;
   MutableArrayRef<char> ToRead = Buf->getBuffer();
   while (!ToRead.empty()) {
     Expected<size_t> ReadBytes =
         sys::fs::readNativeFileSlice(FD, ToRead, Offset);
     if (!ReadBytes)
       return errorToErrorCode(ReadBytes.takeError());
     if (*ReadBytes == 0) {
       std::memset(ToRead.data(), 0, ToRead.size());

llvm/lib/Support/Path.cpp

 //===-- Path.cpp - Implement OS Path Concept ------------------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 //
 //  This file implements the operating system Path API.
 //
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/Path.h"
 #include "llvm/ADT/ArrayRef.h"
+#include "llvm/ADT/Statistic.h"
 #include "llvm/Config/llvm-config.h"
 #include "llvm/Support/Endian.h"
 #include "llvm/Support/Errc.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Process.h"
 #include "llvm/Support/Signals.h"
 #include <cctype>
 #include <cstring>
 
 #if !defined(_MSC_VER) && !defined(__MINGW32__)
 #include <unistd.h>
 #else
 #include <io.h>
 #endif
 
 using namespace llvm;
 using namespace llvm::support::endian;
 
+#define DEBUG_TYPE "file-system"
+
+ALWAYS_ENABLED_STATISTIC(NumStatusCalls, "Number of `status` calls.");
+
 namespace {
   using llvm::StringRef;
   using llvm::sys::path::is_separator;
   using llvm::sys::path::Style;
 
   inline Style real_style(Style style) {
 #ifdef _WIN32
     return (style == Style::posix) ? Style::posix : Style::windows;

llvm/lib/Support/Unix/Path.inc

Result = file_status(typeForMode(Status.st_mode), Perms, Status.st_dev,
                        Status.st_nlink, Status.st_ino,
                        Status.st_atime, atime_nsec, Status.st_mtime, mtime_nsec,
                        Status.st_uid, Status.st_gid, Status.st_size);
 
   return std::error_code();
 }
 
 std::error_code status(const Twine &Path, file_status &Result, bool Follow) {
+  ++NumStatusCalls;
   SmallString<128> PathStorage;
   StringRef P = Path.toNullTerminatedStringRef(PathStorage);
 
   struct stat Status;
   int StatRet = (Follow ? ::stat : ::lstat)(P.begin(), &Status);
   return fillStatus(StatRet, Status, Result);
 }
 
 std::error_code status(int FD, file_status &Result) {
+  ++NumStatusCalls;
   struct stat Status;
   int StatRet = ::fstat(FD, &Status);
   return fillStatus(StatRet, Status, Result);
 }
 
 unsigned getUmask() {
   // Chose arbitary new mask and reset the umask to the old mask.
   // umask(2) never fails so ignore the return of the second call.

llvm/lib/Support/Windows/Path.inc

handle_status_error:
   else if (LastError == ERROR_SHARING_VIOLATION)
     Result = file_status(file_type::type_unknown);
   else
     Result = file_status(file_type::status_error);
   return mapWindowsError(LastError);
 }
 
 std::error_code status(const Twine &path, file_status &result, bool Follow) {
+  ++NumStatusCalls;
   SmallString<128> path_storage;
   SmallVector<wchar_t, 128> path_utf16;
 
   StringRef path8 = path.toStringRef(path_storage);
   if (isReservedName(path8)) {
     result = file_status(file_type::character_file);
     return std::error_code();
   }
ScopedFileHandle h(
                     NULL, OPEN_EXISTING, Flags, 0));
   if (!h)
     return getStatus(INVALID_HANDLE_VALUE, result);
 
   return getStatus(h, result);
 }
 
 std::error_code status(int FD, file_status &Result) {
+  ++NumStatusCalls;
   HANDLE FileHandle = reinterpret_cast<HANDLE>(_get_osfhandle(FD));
   return getStatus(FileHandle, Result);
 }
 
 std::error_code status(file_t FileHandle, file_status &Result) {
+  ++NumStatusCalls;
   return getStatus(FileHandle, Result);
 }
 
 unsigned getUmask() {
   return 0;
 }
 
 std::error_code setPermissions(const Twine &Path, perms Permissions) {