Module: add debug_type to dump debugging messages related to modules being out of date

[manmanren]

Summary

This is a patch I applied internally to debug out-of-date issues. In general is this the right way to add debugging messages in clang frontend?

I wonder how we debug module-related issues. This patch adds DEBUG_TYPE to various source files that are module related, to enable the debugging, we need an assert build of the compiler. Is it better to add a cc1 option to dump debugging messages even for a no-assert (release) build of the compiler?

[v.g.vassilev]

I am not sure whether that's useful for debugging out-of-date issues but this is what I use and it is helpful.

Some debugging aids (suggested by Richard Smith):

-fdiagnostics-show-note-include-stack will tell you which module a note comes from
#pragma clang __debug dump X allows you to produce an AST dump from within a source file, so you can see which modules declare a given name
#pragma clang __debug macro M allows you to dump a macro, which can be useful to see which module(s) export visible include guards for a header

If a name is not visible in a modules build but is visible in a non-modules build, i usually find that's due to one of two things

some part of the machinery that provides it depends on macro definitions leaking into a modular header from outside, or
there is an include cycle involving a modular header and a non-modular header

[v.g.vassilev]

Also, creduce (I've specialized it a bit for modules) helps reducing the modules complexity (https://github.com/vgvassilev/creduce/blob/master/USAGE.md#reducing-clang-c-modules-bugs). After reduction, the debugger is much more useful.

[manmanren]

Thanks a lot for the pointers!

I will definitely try them. What I proposed here is something similar to what llvm does that dumps logging messages, it should be complementary to your debugging aids.

Manman

In D22638#572753, @v.g.vassilev wrote:

I am not sure whether that's useful for debugging out-of-date issues but this is what I use and it is helpful.

Some debugging aids (suggested by Richard Smith):

-fdiagnostics-show-note-include-stack will tell you which module a note comes from
#pragma clang __debug dump X allows you to produce an AST dump from within a source file, so you can see which modules declare a given name
#pragma clang __debug macro M allows you to dump a macro, which can be useful to see which module(s) export visible include guards for a header

If a name is not visible in a modules build but is visible in a non-modules build, i usually find that's due to one of two things

some part of the machinery that provides it depends on macro definitions leaking into a modular header from outside, or
there is an include cycle involving a modular header and a non-modular header

[v.g.vassilev]

How do we proceed with this. Shall we close it?

[v.g.vassilev]

@bruno, what's the fate of this?

lib/Frontend/CompilerInstance.cpp

 #include "clang/Lex/PTHManager.h"
 #include "clang/Lex/Preprocessor.h"
 #include "clang/Sema/CodeCompleteConsumer.h"
 #include "clang/Sema/Sema.h"
 #include "clang/Serialization/ASTReader.h"
 #include "clang/Serialization/GlobalModuleIndex.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/Support/CrashRecoveryContext.h"
+#include "llvm/Support/Debug.h"
 #include "llvm/Support/Errc.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Host.h"
 #include "llvm/Support/LockFileManager.h"
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Program.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/raw_ostream.h"
 #include <sys/stat.h>
 #include <system_error>
 #include <time.h>
 #include <utility>
 
+#define DEBUG_TYPE "module-compilerinstance"
+
 using namespace clang;
 
 CompilerInstance::CompilerInstance(
     std::shared_ptr<PCHContainerOperations> PCHContainerOps,
     bool BuildingModule)
     : ModuleLoader(BuildingModule), Invocation(new CompilerInvocation()),
       ModuleManager(nullptr),
       ThePCHContainerOperations(std::move(PCHContainerOps)),

 
 /// \brief Compile a module file for the given module, using the options 
 /// provided by the importing compiler instance. Returns true if the module
 /// was built without errors.
 static bool compileModuleImpl(CompilerInstance &ImportingInstance,
                               SourceLocation ImportLoc,
                               Module *Module,
                               StringRef ModuleFileName) {
+  DEBUG(llvm::dbgs() << "In compileModuleImpl: " << ModuleFileName << '\n';);
   ModuleMap &ModMap 
     = ImportingInstance.getPreprocessor().getHeaderSearchInfo().getModuleMap();
     
   // Construct a compiler invocation for creating this module.
   IntrusiveRefCntPtr<CompilerInvocation> Invocation
     (new CompilerInvocation(ImportingInstance.getInvocation()));
 
   PreprocessorOptions &PPOpts = Invocation->getPreprocessorOpts();
if (!Module) {
       << ModuleName
       << SourceRange(ImportLoc, ModuleNameLoc);
       ModuleBuildFailed = true;
       return ModuleLoadResult();
     }
 
     std::string ModuleFileName =
         PP->getHeaderSearchInfo().getModuleFileName(Module);
+    DEBUG(llvm::dbgs() << "In loadModule: " << ModuleName
+                       << " we find the Module then ModuleFileName "
+                       << ModuleFileName << '\n';);
     if (ModuleFileName.empty()) {
       if (Module->HasIncompatibleModuleFile) {
         // We tried and failed to load a module file for this module. Fall
         // back to textual inclusion for its headers.
         return ModuleLoadResult(nullptr, /*missingExpected*/true);
       }
 
       getDiagnostics().Report(ModuleNameLoc, diag::err_module_build_disabled)

lib/Serialization/ASTReader.cpp

 #include "clang/Serialization/ASTDeserializationListener.h"
 #include "clang/Serialization/GlobalModuleIndex.h"
 #include "clang/Serialization/ModuleManager.h"
 #include "clang/Serialization/SerializationDiagnostic.h"
 #include "llvm/ADT/Hashing.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/Bitcode/BitstreamReader.h"
 #include "llvm/Support/Compression.h"
+#include "llvm/Support/Debug.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/SaveAndRestore.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
 #include <cstdio>
 #include <iterator>
 #include <system_error>
 
+#define DEBUG_TYPE "module-astreader"
+
 using namespace clang;
 using namespace clang::serialization;
 using namespace clang::serialization::reader;
 using llvm::BitstreamCursor;
 
 
 //===----------------------------------------------------------------------===//
 // ChainedASTReaderListener implementation
for (auto DiagIDMappingPair : MappingSource->getDiagnosticMappings()) {
       if (CurLevel < DiagnosticsEngine::Error)
         continue; // not significant
       Level StoredLevel =
           StoredDiags.getDiagnosticLevel(DiagID, SourceLocation());
       if (StoredLevel < DiagnosticsEngine::Error) {
         if (Complain)
           Diags.Report(diag::err_pch_diagopt_mismatch) << "-Werror=" +
               Diags.getDiagnosticIDs()->getWarningOptionForDiag(DiagID).str();
+        DEBUG(llvm::dbgs() << "In checkDiagnosticGroupMappings: DiagID "
+                           << Diags.getDiagnosticIDs()->getWarningOptionForDiag(DiagID).str() << '\n';);
         return true;
       }
     }
   }
 
   return false;
 }
 
static bool checkDiagnosticMappings(DiagnosticsEngine &StoredDiags,
   // Top-level options
   if (IsSystem) {
     if (Diags.getSuppressSystemWarnings())
       return false;
     // If -Wsystem-headers was not enabled before, be conservative
     if (StoredDiags.getSuppressSystemWarnings()) {
       if (Complain)
         Diags.Report(diag::err_pch_diagopt_mismatch) << "-Wsystem-headers";
+      DEBUG(llvm::dbgs() << "In checkDiagnosticMappings: suppress system warnings"
+                         << ": IsSystem "
+                         << IsSystem << '\n';);
       return true;
     }
   }
 
   if (Diags.getWarningsAsErrors() && !StoredDiags.getWarningsAsErrors()) {
     if (Complain)
       Diags.Report(diag::err_pch_diagopt_mismatch) << "-Werror";
+    DEBUG(llvm::dbgs() << "In checkDiagnosticMappings: warnings as errors"
+                       << ": IsSystem "
+                       << IsSystem << '\n';);
     return true;
   }
 
   if (Diags.getWarningsAsErrors() && Diags.getEnableAllWarnings() &&
       !StoredDiags.getEnableAllWarnings()) {
     if (Complain)
       Diags.Report(diag::err_pch_diagopt_mismatch) << "-Weverything -Werror";
+    DEBUG(llvm::dbgs() << "In checkDiagnosticMappings: enable all warnings"
+                       << ": IsSystem "
+                       << IsSystem << '\n';);
     return true;
   }
 
   if (isExtHandlingFromDiagsError(Diags) &&
       !isExtHandlingFromDiagsError(StoredDiags)) {
     if (Complain)
       Diags.Report(diag::err_pch_diagopt_mismatch) << "-pedantic-errors";
+    DEBUG(llvm::dbgs() << "In checkDiagnosticMappings: pedantic-errors"
+                       << ": IsSystem "
+                       << IsSystem << '\n';);
     return true;
   }
 
   return checkDiagnosticGroupMappings(StoredDiags, Diags, Complain);
 }
 
 bool PCHValidator::ReadDiagnosticOptions(
     IntrusiveRefCntPtr<DiagnosticOptions> DiagOpts, bool Complain) {
case TARGET_OPTIONS: {
                              AllowCompatibleConfigurationMismatch))
         Result = ConfigurationMismatch;
       break;
     }
 
     case DIAGNOSTIC_OPTIONS: {
       bool Complain = (ClientLoadCapabilities & ARR_OutOfDate) == 0;
       if (!AllowCompatibleConfigurationMismatch &&
-          ParseDiagnosticOptions(Record, Complain, Listener))
+          ParseDiagnosticOptions(Record, Complain, Listener)) {
+        DEBUG(llvm::dbgs() << "In ReadOptionsBlock: we return OutOfDate"
+                           << ": client "
+                           << ClientLoadCapabilities << '\n';);
         return OutOfDate;
+      }
       break;
     }
 
     case FILE_SYSTEM_OPTIONS: {
       bool Complain = (ClientLoadCapabilities & ARR_ConfigurationMismatch) == 0;
       if (!AllowCompatibleConfigurationMismatch &&
           ParseFileSystemOptions(Record, Complain, Listener))
         Result = ConfigurationMismatch;
case llvm::BitstreamEntry::EndBlock: {
         if (ValidateSystemInputs ||
             (HSOpts.ModulesValidateOncePerBuildSession &&
              F.InputFilesValidationTimestamp <= HSOpts.BuildSessionTimestamp &&
              F.Kind == MK_ImplicitModule))
           N = NumInputs;
 
         for (unsigned I = 0; I < N; ++I) {
           InputFile IF = getInputFile(F, I+1, Complain);
-          if (!IF.getFile() || IF.isOutOfDate())
+          if (!IF.getFile() || IF.isOutOfDate()) {
+            DEBUG(llvm::dbgs() << "In ReadControlBlock: we return OutOfDate"
+                               << ": " << F.FileName << " client "
+                               << ClientLoadCapabilities << '\n';);
             return OutOfDate;
           }
         }
+      }
 
       if (Listener)
         Listener->visitModuleFile(F.FileName, F.Kind);
 
       if (Listener && Listener->needsInputFileVisitation()) {
         unsigned N = Listener->needsSystemInputFileVisitation() ? NumInputs
                                                                 : NumUserInputs;
         for (unsigned I = 0; I < N; ++I) {
case llvm::BitstreamEntry::SubBlock:
 
           if (DisableValidation ||
               (AllowConfigurationMismatch && Result == ConfigurationMismatch))
             Result = Success;
 
           // If we can't load the module, exit early since we likely
           // will rebuild the module anyway. The stream may be in the
           // middle of a block.
-          if (Result != Success)
+          if (Result != Success) {
+            DEBUG(llvm::dbgs() << "In ReadControlBlock: ReadOptionsBlock returns " << Result
+                               << ": " << F.FileName << " client "
+                               << ClientLoadCapabilities << '\n';);
             return Result;
+          }
         } else if (Stream.SkipBlock()) {
           Error("malformed block record in AST file");
           return Failure;
         }
         continue;
           
       default:
         if (Stream.SkipBlock()) {
case IMPORTS: {
         if (isDiagnosedResult(Result, Capabilities))
           Diag(diag::note_module_file_imported_by)
               << F.FileName << !F.ModuleName.empty() << F.ModuleName;
 
         switch (Result) {
         case Failure: return Failure;
           // If we have to ignore the dependency, we'll have to ignore this too.
         case Missing:
-        case OutOfDate: return OutOfDate;
+        case OutOfDate: {
+          DEBUG(llvm::dbgs() << "In ReadControlBlock: ReadASTCore returns " << Result
+                             << ": " << F.FileName << " client "
+                             << ClientLoadCapabilities << '\n';);
+          return OutOfDate;
+        }
         case VersionMismatch: return VersionMismatch;
         case ConfigurationMismatch: return ConfigurationMismatch;
         case HadErrors: return HadErrors;
         case Success: break;
         }
       }
       break;
     }
case MODULE_DIRECTORY: {
         // change between the build and use.
         if (F.Kind != MK_ExplicitModule) {
           const DirectoryEntry *BuildDir =
               PP.getFileManager().getDirectory(Blob);
           if (!BuildDir || BuildDir != M->Directory) {
             if ((ClientLoadCapabilities & ARR_OutOfDate) == 0)
               Diag(diag::err_imported_module_relocated)
                   << F.ModuleName << Blob << M->Directory->getName();
+            DEBUG(llvm::dbgs() << "In ReadControlBlock: due to module "
+                               << "directory, we return OutOfDate: "
+                               << F.FileName << " client "
+                               << ClientLoadCapabilities << '\n';);
             return OutOfDate;
           }
         }
         F.BaseDirectory = M->Directory->getName();
       } else {
         F.BaseDirectory = Blob;
       }
       break;
     }
 
     case MODULE_MAP_FILE:
       if (ASTReadResult Result =
-              ReadModuleMapFileBlock(Record, F, ImportedBy, ClientLoadCapabilities))
+              ReadModuleMapFileBlock(Record, F, ImportedBy, ClientLoadCapabilities)) {
+        DEBUG(llvm::dbgs() << "In ReadControlBlock: ReadModuleMapFileBlock returns " << Result
+                           << ": " << F.FileName << " client "
+                           << ClientLoadCapabilities << '\n';);
         return Result;
+      }
       break;
 
     case INPUT_FILE_OFFSETS:
       NumInputs = Record[0];
       NumUserInputs = Record[1];
       F.InputFileOffsets =
           (const llvm::support::unaligned_uint64_t *)Blob.data();
       F.InputFilesLoaded.resize(NumInputs);
ASTReader::ASTReadResult ASTReader::ReadAST(StringRef FileName,
                                             SourceLocation ImportLoc,
                                             unsigned ClientLoadCapabilities) {
   llvm::SaveAndRestore<SourceLocation>
     SetCurImportLocRAII(CurrentImportLoc, ImportLoc);
 
   // Defer any pending actions until we get to the end of reading the AST file.
   Deserializing AnASTFile(this);
 
+  DEBUG(llvm::dbgs() << "In ReadAST: " << FileName << " client "
+                     << ClientLoadCapabilities << '\n';);
+
   // Bump the generation number.
   unsigned PreviousGeneration = incrementGeneration(Context);
 
   unsigned NumModules = ModuleMgr.size();
   SmallVector<ImportedModule, 4> Loaded;
   switch(ASTReadResult ReadResult = ReadASTCore(FileName, Type, ImportLoc,
                                                 /*ImportedBy=*/nullptr, Loaded,
                                                 0, 0, 0,
ModuleMgr.removeModules(ModuleMgr.begin() + NumModules, ModuleMgr.end(),
                             Context.getLangOpts().Modules
                               ? &PP.getHeaderSearchInfo().getModuleMap()
                               : nullptr);
 
     // If we find that any modules are unusable, the global index is going
     // to be out-of-date. Just remove it.
     GlobalIndex.reset();
     ModuleMgr.setGlobalIndex(nullptr);
+    DEBUG(llvm::dbgs() << "In ReadAST: ReadASTCore returns " << ReadResult
+                       << ": " << FileName << " client "  
+                       << ClientLoadCapabilities << '\n';);
     return ReadResult;
   }
   case Success:
     break;
   }
 
   // Here comes stuff that we only do once the entire chain is loaded.
 
   // Load the AST blocks of all of the modules that we loaded.
   for (SmallVectorImpl<ImportedModule>::iterator M = Loaded.begin(),
                                               MEnd = Loaded.end();
        M != MEnd; ++M) {
     ModuleFile &F = *M->Mod;
 
     // Read the AST block.
-    if (ASTReadResult Result = ReadASTBlock(F, ClientLoadCapabilities))
+    if (ASTReadResult Result = ReadASTBlock(F, ClientLoadCapabilities)) {
+      DEBUG(llvm::dbgs() << "In ReadAST: ReadASTBlock returns " << Result
+                         << ": " << FileName << " client " 
+                         << ClientLoadCapabilities << '\n';);
       return Result;
+    }
 
     // Read the extension blocks.
     while (!SkipCursorToBlock(F.Stream, EXTENSION_BLOCK_ID)) {
-      if (ASTReadResult Result = ReadExtensionBlock(F))
+      if (ASTReadResult Result = ReadExtensionBlock(F)) {
+        DEBUG(llvm::dbgs() << "In ReadAST: ReadExtensionBlock returns " << Result
+                           << ": " << FileName << " client "
+                           << ClientLoadCapabilities << '\n';);
         return Result;
       }
+    }
 
     // Once read, set the ModuleFile bit base offset and update the size in 
     // bits of all files we've seen.
     F.GlobalBitOffset = TotalModulesSizeInBits;
     TotalModulesSizeInBits += F.SizeInBits;
     GlobalBitOffsetsMap.insert(std::make_pair(F.GlobalBitOffset, &F));
     
     // Preload SLocEntries.
case ModuleManager::Missing:
     Diag(diag::err_module_file_not_found) << moduleKindForDiagnostic(Type)
                                           << FileName << ErrorStr.empty()
                                           << ErrorStr;
     return Failure;
 
   case ModuleManager::OutOfDate:
     // We couldn't load the module file because it is out-of-date. If the
     // client can handle out-of-date, return it.
-    if (ClientLoadCapabilities & ARR_OutOfDate)
+    if (ClientLoadCapabilities & ARR_OutOfDate) {
+      DEBUG(llvm::dbgs() << "In ReadASTCore: addModule returns " << AddResult
+                         << ": " << FileName << " client "
+                         << ClientLoadCapabilities << '\n';);
       return OutOfDate;
+    }
 
     // Otherwise, return an error.
     Diag(diag::err_module_file_out_of_date) << moduleKindForDiagnostic(Type)
                                             << FileName << ErrorStr.empty()
                                             << ErrorStr;
     return Failure;
   }
 
case CONTROL_BLOCK_ID:
         // FIXME: Should we also perform the converse check? Loading a module as
         // a PCH file sort of works, but it's a bit wonky.
         if ((Type == MK_ImplicitModule || Type == MK_ExplicitModule) &&
             F.ModuleName.empty()) {
           auto Result = (Type == MK_ImplicitModule) ? OutOfDate : Failure;
           if (Result != OutOfDate ||
               (ClientLoadCapabilities & ARR_OutOfDate) == 0)
             Diag(diag::err_module_file_not_module) << FileName;
+          DEBUG(llvm::dbgs() << "In ReadASTCore: ReadControlBlock returns Success but module "
+                             << "name is empty : " << FileName << " client "
+                             << ClientLoadCapabilities << '\n';);
           return Result;
         }
         break;
 
       case Failure: return Failure;
       case Missing: return Missing;
-      case OutOfDate: return OutOfDate;
+      case OutOfDate: {
+        DEBUG(llvm::dbgs() << "In ReadASTCore: ReadControlBlock returns OutOfDate"
+                           << ": " << FileName << " client "
+                           << ClientLoadCapabilities << '\n';);
+        return OutOfDate;
+      }
       case VersionMismatch: return VersionMismatch;
       case ConfigurationMismatch: return ConfigurationMismatch;
       case HadErrors: return HadErrors;
       }
       break;
 
     case AST_BLOCK_ID:
       if (!HaveReadControlBlock) {
case SUBMODULE_UMBRELLA_DIR: {
       std::string Dirname = Blob;
       ResolveImportedPath(F, Dirname);
       if (auto *Umbrella = PP.getFileManager().getDirectory(Dirname)) {
         if (!CurrentModule->getUmbrellaDir())
           ModMap.setUmbrellaDir(CurrentModule, Umbrella, Blob);
         else if (CurrentModule->getUmbrellaDir().Entry != Umbrella) {
           if ((ClientLoadCapabilities & ARR_OutOfDate) == 0)
             Error("mismatched umbrella directories in submodule");
+          DEBUG(llvm::dbgs() << "In ReadSubmoduleBlock: we return OutOfDate"
+                             << ": " << F.FileName << " client "
+                             << ClientLoadCapabilities << '\n';);
           return OutOfDate;
         }
       }
       break;
     }
         
     case SUBMODULE_METADATA: {
       F.BaseSubmoduleID = getTotalNumSubmodules();

lib/Serialization/ASTWriter.cpp

 #include "clang/Serialization/ASTReader.h"
 #include "clang/Serialization/SerializationDiagnostic.h"
 #include "llvm/ADT/APFloat.h"
 #include "llvm/ADT/APInt.h"
 #include "llvm/ADT/Hashing.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/Bitcode/BitstreamWriter.h"
 #include "llvm/Support/Compression.h"
+#include "llvm/Support/Debug.h"
 #include "llvm/Support/EndianStream.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/Support/OnDiskHashTable.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Process.h"
 #include <algorithm>
 #include <cstdio>
 #include <string.h>
 #include <utility>
 
+#define DEBUG_TYPE "module-astwriter"
+
 using namespace clang;
 using namespace clang::serialization;
 
 template <typename T, typename Allocator>
 static StringRef bytes(const std::vector<T, Allocator> &v) {
   if (v.empty()) return StringRef();
   return StringRef(reinterpret_cast<const char*>(&v[0]),
                          sizeof(T) * v.size());

 
 time_t ASTWriter::getTimestampForOutput(const FileEntry *E) const {
   return IncludeTimestamps ? E->getModificationTime() : 0;
 }
 
 uint64_t ASTWriter::WriteAST(Sema &SemaRef, const std::string &OutputFile,
                              Module *WritingModule, StringRef isysroot,
                              bool hasErrors) {
+  DEBUG(llvm::dbgs() << "In WriteAST: " << OutputFile << '\n';);
   WritingAST = true;
 
   ASTHasCompilerErrors = hasErrors;
   
   // Emit the file header.
   Stream.Emit((unsigned)'C', 8);
   Stream.Emit((unsigned)'P', 8);
   Stream.Emit((unsigned)'C', 8);

lib/Serialization/ModuleManager.cpp

 //  modules for the ASTReader.
 //
 //===----------------------------------------------------------------------===//
 #include "clang/Frontend/PCHContainerOperations.h"
 #include "clang/Lex/HeaderSearch.h"
 #include "clang/Lex/ModuleMap.h"
 #include "clang/Serialization/GlobalModuleIndex.h"
 #include "clang/Serialization/ModuleManager.h"
+#include "llvm/Support/Debug.h"
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/raw_ostream.h"
 #include <system_error>
 
 #ifndef NDEBUG
 #include "llvm/Support/GraphWriter.h"
 #endif
 
+#define DEBUG_TYPE "module-manager"
+
 using namespace clang;
 using namespace serialization;
 
 ModuleFile *ModuleManager::lookup(StringRef Name) {
   const FileEntry *Entry = FileMgr.getFile(Name, /*openFile=*/false,
                                            /*cacheFailure=*/false);
   if (Entry)
     return lookup(Entry);
if (Type == MK_ExplicitModule) {
     // If we're not expecting to pull this file out of the module cache, it
     // might have a different mtime due to being moved across filesystems in
     // a distributed build. The size must still match, though. (As must the
     // contents, but we can't check that.)
     ExpectedModTime = 0;
   }
   if (lookupModuleFile(FileName, ExpectedSize, ExpectedModTime, Entry)) {
     ErrorStr = "module file out of date";
+    DEBUG(llvm::dbgs() << "In addModule: size or modtime mismatch "
+                       << FileName << '\n';);
     return OutOfDate;
   }
 
   if (!Entry && FileName != "-") {
     ErrorStr = "module file not found";
     return Missing;
   }
 
if (ModuleEntry->Signature != ExpectedSignature) {
         if (!ModuleEntry->isModule())
           PCHChain.pop_back();
         if (Roots.back() == ModuleEntry)
           Roots.pop_back();
         else
           assert(ImportedBy);
         delete ModuleEntry;
       }
+      DEBUG(llvm::dbgs() << "In addModule: signature mismatch "
+                         << FileName << '\n';);
       return OutOfDate;
     }
   }
   
   if (ImportedBy) {
     ModuleEntry->ImportedBy.insert(ImportedBy);
     ImportedBy->Imports.insert(ModuleEntry);
   } else {