Teach the pass manager's execution dump to print the current time before

each line. This is particularly nice for tracking which run of
a particular pass over a particular function was slow.

This also required making the TimeValue string much more useful. First,
there is a standard format for writing out a date and time. Let's use
that rather than strings that would have to be parsed. Second, actually
output the nanosecond resolution that timevalue claims to have.

This is proving useful working on PR19499, so I figured it would be
generally useful to commit.

git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@207385 91177308-0d34-0410-b5e6-96231b3b80d8

diff --git a/lib/IR/LegacyPassManager.cpp b/lib/IR/LegacyPassManager.cpp
index 1ad04982d44ee90bab31d23ea131362cf1b09a34..b6d75b483f8abc4a0ef33c525a14bff547936581 100644 (file)
--- a/lib/IR/LegacyPassManager.cpp
+++ b/lib/IR/LegacyPassManager.cpp
@@ -22,6 +22,7 @@
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Mutex.h"
+#include "llvm/Support/TimeValue.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
@@ -1158,7 +1159,8 @@ void PMDataManager::dumpPassInfo(Pass *P, enum PassDebuggingString S1,
                                  StringRef Msg) {
   if (PassDebugging < Executions)
     return;
-  dbgs() << (void*)this << std::string(getDepth()*2+1, ' ');
+  dbgs() << "[" << sys::TimeValue::now().str() << "] " << (void *)this
+         << std::string(getDepth() * 2 + 1, ' ');
   switch (S1) {
   case EXECUTION_MSG:
     dbgs() << "Executing Pass '" << P->getPassName();

diff --git a/lib/Support/Unix/TimeValue.inc b/lib/Support/Unix/TimeValue.inc
index 80532b0b952489c7a4f3b76010c1b8799670ecae..58c7ba3094d69011d49bce92582eafda80812f48 100644 (file)
--- a/lib/Support/Unix/TimeValue.inc
+++ b/lib/Support/Unix/TimeValue.inc
@@ -26,9 +26,11 @@ std::string TimeValue::str() const {
   struct tm Storage;
   struct tm *LT = ::localtime_r(&OurTime, &Storage);
   assert(LT);
-  char Buffer[25];
-  strftime(Buffer, 25, "%b %e %H:%M %Y", LT);
-  return std::string(Buffer);
+  char Buffer1[sizeof("YYYY-MM-DD HH:MM:SS")];
+  strftime(Buffer1, sizeof(Buffer1), "%Y-%m-%d %H:%M:%S", LT);
+  char Buffer2[sizeof("YYYY-MM-DD HH:MM:SS.MMMUUUNNN")];
+  snprintf(Buffer2, sizeof(Buffer2), "%s.%.9u", Buffer1, this->nanoseconds());
+  return std::string(Buffer2);
 }
 
 TimeValue TimeValue::now() {