[libclang] Enhance logging capabilities of libclang.

-provide a "raw_ostream'ish" class to make it convenient to output logging info.
-use macros to automate a bit the logging functionality inside libclang functions
-when logging, print a stack trace if "LIBCLANG_LOGGING=2" environment is set.
-add logging to more functions.

llvm-svn: 172089

clang/tools/libclang/CIndex.cpp

@@ -21,6 +21,7 @@
 #include "CXTranslationUnit.h"
 #include "CXType.h"
 #include "CursorVisitor.h"
+#include "CLog.h"
 #include "SimpleFormatContext.h"
 #include "clang/AST/StmtVisitor.h"
 #include "clang/Basic/Diagnostic.h"
@@ -46,6 +47,12 @@
 #include "llvm/Support/Threading.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/Format.h"
+#include "llvm/Config/config.h"
+
+#if HAVE_PTHREAD_H
+#include <pthread.h>
+#endif
 
 using namespace clang;
 using namespace clang::cxcursor;
@@ -2681,6 +2688,12 @@ CXTranslationUnit clang_parseTranslationUnit(CXIndex CIdx,
                                             struct CXUnsavedFile *unsaved_files,
                                              unsigned num_unsaved_files,
                                              unsigned options) {
+  LOG_FUNC_SECTION {
+    *Log << source_filename << ": ";
+    for (int i = 0; i != num_command_line_args; ++i)
+      *Log << command_line_args[i] << " ";
+  }
+
   ParseTranslationUnitInfo PTUI = { CIdx, source_filename, command_line_args,
                                     num_command_line_args, unsaved_files,
                                     num_unsaved_files, options, 0 };
@@ -2744,6 +2757,10 @@ static void clang_saveTranslationUnit_Impl(void *UserData) {
 
 int clang_saveTranslationUnit(CXTranslationUnit TU, const char *FileName,
                               unsigned options) {
+  LOG_FUNC_SECTION {
+    *Log << TU << ' ' << FileName;
+  }
+
   if (!TU)
     return CXSaveError_InvalidTU;
 
@@ -2861,6 +2878,10 @@ int clang_reparseTranslationUnit(CXTranslationUnit TU,
                                  unsigned num_unsaved_files,
                                  struct CXUnsavedFile *unsaved_files,
                                  unsigned options) {
+  LOG_FUNC_SECTION {
+    *Log << TU;
+  }
+
   ReparseTranslationUnitInfo RTUI = { TU, num_unsaved_files, unsaved_files,
                                       options, 0 };
 
@@ -3808,8 +3829,7 @@ CXCursor clang_getCursor(CXTranslationUnit TU, CXSourceLocation Loc) {
   SourceLocation SLoc = cxloc::translateSourceLocation(Loc);
   CXCursor Result = cxcursor::getCursor(TU, SLoc);
 
-  bool Logging = getenv("LIBCLANG_LOGGING");  
+  LOG_FUNC_SECTION {
-  if (Logging) {
     CXFile SearchFile;
     unsigned SearchLine, SearchColumn;
     CXFile ResultFile;
@@ -3818,16 +3838,17 @@ CXCursor clang_getCursor(CXTranslationUnit TU, CXSourceLocation Loc) {
     const char *IsDef = clang_isCursorDefinition(Result)? " (Definition)" : "";
     CXSourceLocation ResultLoc = clang_getCursorLocation(Result);
     
-    clang_getExpansionLocation(Loc, &SearchFile, &SearchLine, &SearchColumn, 0);
+    clang_getFileLocation(Loc, &SearchFile, &SearchLine, &SearchColumn, 0);
-    clang_getExpansionLocation(ResultLoc, &ResultFile, &ResultLine,
+    clang_getFileLocation(ResultLoc, &ResultFile, &ResultLine,
                                &ResultColumn, 0);
     SearchFileName = clang_getFileName(SearchFile);
     ResultFileName = clang_getFileName(ResultFile);
     KindSpelling = clang_getCursorKindSpelling(Result.kind);
     USR = clang_getCursorUSR(Result);
-    fprintf(stderr, "clang_getCursor(%s:%d:%d) = %s(%s:%d:%d):%s%s\n",
+    *Log << llvm::format("(%s:%d:%d) = %s",
                    clang_getCString(SearchFileName), SearchLine, SearchColumn,
-            clang_getCString(KindSpelling),
+                   clang_getCString(KindSpelling))
+        << llvm::format("(%s:%d:%d):%s%s",
                      clang_getCString(ResultFileName), ResultLine, ResultColumn,
                      clang_getCString(USR), IsDef);
     clang_disposeString(SearchFileName);
@@ -3842,10 +3863,10 @@ CXCursor clang_getCursor(CXTranslationUnit TU, CXSourceLocation Loc) {
                                 = clang_getCursorKindSpelling(Definition.kind);
       CXFile DefinitionFile;
       unsigned DefinitionLine, DefinitionColumn;
-      clang_getExpansionLocation(DefinitionLoc, &DefinitionFile,
+      clang_getFileLocation(DefinitionLoc, &DefinitionFile,
                                  &DefinitionLine, &DefinitionColumn, 0);
       CXString DefinitionFileName = clang_getFileName(DefinitionFile);
-      fprintf(stderr, "  -> %s(%s:%d:%d)\n",
+      *Log << llvm::format("  -> %s(%s:%d:%d)",
                      clang_getCString(DefinitionKindSpelling),
                      clang_getCString(DefinitionFileName),
                      DefinitionLine, DefinitionColumn);
@@ -4850,6 +4871,10 @@ static void getTokens(ASTUnit *CXXUnit, SourceRange Range,
 
 void clang_tokenize(CXTranslationUnit TU, CXSourceRange Range,
                     CXToken **Tokens, unsigned *NumTokens) {
+  LOG_FUNC_SECTION {
+    *Log << TU << ' ' << Range;
+  }
+
   if (Tokens)
     *Tokens = 0;
   if (NumTokens)
@@ -5522,9 +5547,17 @@ extern "C" {
 void clang_annotateTokens(CXTranslationUnit TU,
                           CXToken *Tokens, unsigned NumTokens,
                           CXCursor *Cursors) {
-
+  if (NumTokens == 0 || !Tokens || !Cursors) {
-  if (NumTokens == 0 || !Tokens || !Cursors)
+    LOG_FUNC_SECTION { *Log << "<null input>"; }
     return;
+  }
+
+  LOG_FUNC_SECTION {
+    *Log << TU << ' ';
+    CXSourceLocation bloc = clang_getTokenLocation(TU, Tokens[0]);
+    CXSourceLocation eloc = clang_getTokenLocation(TU, Tokens[NumTokens-1]);
+    *Log << clang_getRange(bloc, eloc);
+  }
 
   // Any token we don't specifically annotate will have a NULL cursor.
   CXCursor C = clang_getNullCursor();
@@ -6290,3 +6323,88 @@ CXString clang_getClangVersion() {
 
 } // end: extern "C"
 
+Logger &cxindex::Logger::operator<<(CXTranslationUnit TU) {
+  if (TU) {
+    if (ASTUnit *Unit = static_cast<ASTUnit *>(TU->TUData)) {
+      LogOS << '<' << Unit->getMainFileName() << '>';
+      return *this;
+    }
+  }
+
+  LogOS << "<NULL TU>";
+  return *this;
+}
+
+Logger &cxindex::Logger::operator<<(CXSourceLocation Loc) {
+  CXFile File;
+  unsigned Line, Column;
+  clang_getFileLocation(Loc, &File, &Line, &Column, 0);
+  CXString FileName = clang_getFileName(File);
+  *this << llvm::format("(%s:%d:%d)", clang_getCString(FileName), Line, Column);
+  clang_disposeString(FileName);
+  return *this;
+}
+
+Logger &cxindex::Logger::operator<<(CXSourceRange range) {
+  CXSourceLocation BLoc = clang_getRangeStart(range);
+  CXSourceLocation ELoc = clang_getRangeEnd(range);
+
+  CXFile BFile;
+  unsigned BLine, BColumn;
+  clang_getFileLocation(BLoc, &BFile, &BLine, &BColumn, 0);
+
+  CXFile EFile;
+  unsigned ELine, EColumn;
+  clang_getFileLocation(ELoc, &EFile, &ELine, &EColumn, 0);
+
+  CXString BFileName = clang_getFileName(BFile);
+  if (BFile == EFile) {
+    *this << llvm::format("[%s %d:%d-%d:%d]", clang_getCString(BFileName),
+                         BLine, BColumn, ELine, EColumn);
+  } else {
+    CXString EFileName = clang_getFileName(EFile);
+    *this << llvm::format("[%s:%d:%d - ", clang_getCString(BFileName),
+                          BLine, BColumn)
+          << llvm::format("%s:%d:%d]", clang_getCString(EFileName),
+                          ELine, EColumn);
+    clang_disposeString(EFileName);
+  }
+  clang_disposeString(BFileName);
+  return *this;
+}
+
+Logger &cxindex::Logger::operator<<(CXString Str) {
+  *this << clang_getCString(Str);
+  return *this;
+}
+
+Logger &cxindex::Logger::operator<<(const llvm::format_object_base &Fmt) {
+  LogOS << Fmt;
+  return *this;
+}
+
+cxindex::Logger::~Logger() {
+  LogOS.flush();
+
+  llvm::sys::ScopedLock L(EnableMultithreadingMutex);
+
+  static llvm::TimeRecord sBeginTR = llvm::TimeRecord::getCurrentTime();
+
+  llvm::raw_ostream &OS = llvm::errs();
+  OS << "[libclang:" << Name << ':';
+
+  // FIXME: Portability.
+#if HAVE_PTHREAD_H && __APPLE__
+  mach_port_t tid = pthread_mach_thread_np(pthread_self());
+  OS << tid << ':';
+#endif
+
+  llvm::TimeRecord TR = llvm::TimeRecord::getCurrentTime();
+  OS << llvm::format("%7.4f] ", TR.getWallTime() - sBeginTR.getWallTime());
+  OS << Msg.str() << '\n';
+
+  if (Trace) {
+    llvm::sys::PrintStackTrace(stderr);
+    OS << "--------------------------------------------------\n";
+  }
+}

clang/tools/libclang/CIndexCodeCompletion.cpp

@@ -17,6 +17,7 @@
 #include "CXCursor.h"
 #include "CXString.h"
 #include "CXTranslationUnit.h"
+#include "CLog.h"
 #include "clang/AST/Decl.h"
 #include "clang/AST/DeclObjC.h"
 #include "clang/AST/Type.h"
@@ -48,6 +49,7 @@
 
 using namespace clang;
 using namespace clang::cxstring;
+using namespace clang::cxindex;
 
 extern "C" {
 
@@ -821,6 +823,11 @@ CXCodeCompleteResults *clang_codeCompleteAt(CXTranslationUnit TU,
                                             struct CXUnsavedFile *unsaved_files,
                                             unsigned num_unsaved_files,
                                             unsigned options) {
+  LOG_FUNC_SECTION {
+    *Log << TU << ' '
+         << complete_filename << ':' << complete_line << ':' << complete_column;
+  }
+
   CodeCompleteAtInfo CCAI = { TU, complete_filename, complete_line,
                               complete_column, unsaved_files, num_unsaved_files,
                               options, 0 };

clang/tools/libclang/CIndexHigh.cpp

@@ -11,11 +11,13 @@
 #include "CXCursor.h"
 #include "CXSourceLocation.h"
 #include "CXTranslationUnit.h"
+#include "CLog.h"
 #include "clang/AST/DeclObjC.h"
 #include "clang/Frontend/ASTUnit.h"
 
 using namespace clang;
 using namespace cxcursor;
+using namespace cxindex;
 
 static void getTopOverriddenMethods(CXTranslationUnit TU,
                                     Decl *D,
@@ -341,26 +343,26 @@ extern "C" {
 
 void clang_findReferencesInFile(CXCursor cursor, CXFile file,
                                 CXCursorAndRangeVisitor visitor) {
-  bool Logging = ::getenv("LIBCLANG_LOGGING");
+  LogRef Log = Logger::make(__func__);
 
   if (clang_Cursor_isNull(cursor)) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_findReferencesInFile: Null cursor\n";
+      *Log << "Null cursor";
     return;
   }
   if (cursor.kind == CXCursor_NoDeclFound) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_findReferencesInFile: Got CXCursor_NoDeclFound\n";
+      *Log << "Got CXCursor_NoDeclFound";
     return;
   }
   if (!file) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_findReferencesInFile: Null file\n";
+      *Log << "Null file";
     return;
   }
   if (!visitor.visit) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_findReferencesInFile: Null visitor\n";
+      *Log << "Null visitor";
     return;
   }
 
@@ -391,9 +393,8 @@ void clang_findReferencesInFile(CXCursor cursor, CXFile file,
   CXCursor refCursor = clang_getCursorReferenced(cursor);
 
   if (!clang_isDeclaration(refCursor.kind)) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_findReferencesInFile: cursor is not referencing a "
+      *Log << "cursor is not referencing a declaration";
-                      "declaration\n";
     return;
   }
 

clang/tools/libclang/CXSourceLocation.cpp

@@ -17,9 +17,12 @@
 #include "CXSourceLocation.h"
 #include "CXString.h"
 #include "CXTranslationUnit.h"
+#include "CLog.h"
+#include "llvm/Support/Format.h"
 
 using namespace clang;
 using namespace clang::cxstring;
+using namespace clang::cxindex;
 
 //===----------------------------------------------------------------------===//
 // Internal predicates on CXSourceLocations.
@@ -122,24 +125,25 @@ CXSourceLocation clang_getLocation(CXTranslationUnit tu,
   if (!tu || !file)
     return clang_getNullLocation();
   
-  bool Logging = ::getenv("LIBCLANG_LOGGING");
+  LogRef Log = Logger::make(__func__);
   ASTUnit *CXXUnit = static_cast<ASTUnit *>(tu->TUData);
   ASTUnit::ConcurrencyCheck Check(*CXXUnit);
   const FileEntry *File = static_cast<const FileEntry *>(file);
   SourceLocation SLoc = CXXUnit->getLocation(File, line, column);
   if (SLoc.isInvalid()) {
-    if (Logging)
+    if (Log)
-      llvm::errs() << "clang_getLocation(\"" << File->getName() 
+      *Log << llvm::format("(\"%s\", %d, %d) = invalid",
-      << "\", " << line << ", " << column << ") = invalid\n";
+                           File->getName(), line, column);
     return clang_getNullLocation();
   }
   
-  if (Logging)
+  CXSourceLocation CXLoc =
-    llvm::errs() << "clang_getLocation(\"" << File->getName() 
+      cxloc::translateSourceLocation(CXXUnit->getASTContext(), SLoc);
-    << "\", " << line << ", " << column << ") = " 
+  if (Log)
-    << SLoc.getRawEncoding() << "\n";
+    *Log << llvm::format("(\"%s\", %d, %d) = ", File->getName(), line, column)
+         << CXLoc;
   
-  return cxloc::translateSourceLocation(CXXUnit->getASTContext(), SLoc);
+  return CXLoc;
 }
   
 CXSourceLocation clang_getLocationForOffset(CXTranslationUnit tu,

clang/tools/libclang/Indexing.cpp

@@ -14,6 +14,7 @@
 #include "CXSourceLocation.h"
 #include "CXString.h"
 #include "CXTranslationUnit.h"
+#include "CLog.h"
 #include "clang/AST/ASTConsumer.h"
 #include "clang/AST/DeclVisitor.h"
 #include "clang/Frontend/ASTUnit.h"
@@ -968,6 +969,11 @@ int clang_indexSourceFile(CXIndexAction idxAction,
                           unsigned num_unsaved_files,
                           CXTranslationUnit *out_TU,
                           unsigned TU_options) {
+  LOG_FUNC_SECTION {
+    *Log << source_filename << ": ";
+    for (int i = 0; i != num_command_line_args; ++i)
+      *Log << command_line_args[i] << " ";
+  }
 
   IndexSourceFileInfo ITUI = { idxAction, client_data, index_callbacks,
                                index_callbacks_size, index_options,
@@ -1018,6 +1024,9 @@ int clang_indexTranslationUnit(CXIndexAction idxAction,
                                unsigned index_callbacks_size,
                                unsigned index_options,
                                CXTranslationUnit TU) {
+  LOG_FUNC_SECTION {
+    *Log << TU;
+  }
 
   IndexTranslationUnitInfo ITUI = { idxAction, client_data, index_callbacks,
                                     index_callbacks_size, index_options, TU,