Add a format_provider for the Timeout class

and use it in the appropriate log statements.

Formatting of chrono types in log messages was very clunky. This should
make it much nicer to use and give better output. For details of the
formatting options see the chrono formatter in llvm.

llvm-svn: 294738

7 files changed, 56 insertions, 69 deletions

diff --git a/lldb/include/lldb/Utility/Timeout.h b/lldb/include/lldb/Utility/Timeout.h
index 6c6fd009acb..7b627a45fc6 100644
--- a/lldb/include/lldb/Utility/Timeout.h
+++ b/lldb/include/lldb/Utility/Timeout.h
@@ -11,7 +11,8 @@
 #define liblldb_Timeout_h_
 
 #include "llvm/ADT/Optional.h"
-#include <chrono>
+#include "llvm/Support/Chrono.h"
+#include "llvm/Support/FormatProviders.h"
 
 namespace lldb_private {
 
@@ -52,4 +53,19 @@ public:
 
 } // namespace lldb_private
 
+namespace llvm {
+template<typename Ratio>
+struct format_provider<lldb_private::Timeout<Ratio>, void> {
+  static void format(const lldb_private::Timeout<Ratio> &timeout,
+                     raw_ostream &OS, StringRef Options) {
+    typedef typename lldb_private::Timeout<Ratio>::value_type Dur;
+
+    if (!timeout)
+      OS << "<infinite>";
+    else
+      format_provider<Dur>::format(*timeout, OS, Options);
+  }
+};
+}
+
 #endif // liblldb_Timeout_h_
diff --git a/lldb/source/Core/Communication.cpp b/lldb/source/Core/Communication.cpp
index a631a5e096b..2f4aa9f0776 100644
--- a/lldb/source/Core/Communication.cpp
+++ b/lldb/source/Core/Communication.cpp
@@ -115,12 +115,11 @@ bool Communication::HasConnection() const {
 size_t Communication::Read(void *dst, size_t dst_len,
                            const Timeout<std::micro> &timeout,
                            ConnectionStatus &status, Error *error_ptr) {
-  lldb_private::LogIfAnyCategoriesSet(
-      LIBLLDB_LOG_COMMUNICATION,
-      "%p Communication::Read (dst = %p, dst_len = %" PRIu64
-      ", timeout = %u usec) connection = %p",
-      this, dst, (uint64_t)dst_len, timeout ? timeout->count() : -1,
-      m_connection_sp.get());
+  Log *log = GetLogIfAllCategoriesSet(LIBLLDB_LOG_COMMUNICATION);
+  LLDB_LOG(
+      log,
+      "this = {0}, dst = {1}, dst_len = {2}, timeout = {3}, connection = {4}",
+      this, dst, dst_len, timeout, m_connection_sp.get());
 
   if (m_read_thread_enabled) {
     // We have a dedicated read thread that is getting data for us
diff --git a/lldb/source/Core/Listener.cpp b/lldb/source/Core/Listener.cpp
index b1910e12a42..0e7d5ce4306 100644
--- a/lldb/source/Core/Listener.cpp
+++ b/lldb/source/Core/Listener.cpp
@@ -352,11 +352,7 @@ bool Listener::GetEventInternal(
     uint32_t num_broadcaster_names, uint32_t event_type_mask,
     EventSP &event_sp) {
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_EVENTS));
-  if (log != nullptr)
-    log->Printf("%p Listener::GetEventInternal (timeout = %llu us) for %s",
-                static_cast<void *>(this), static_cast<unsigned long long>(
-                                               timeout ? timeout->count() : -1),
-                m_name.c_str());
+  LLDB_LOG(log, "this = {0}, timeout = {1} for {2}", this, timeout, m_name);
 
   std::unique_lock<std::mutex> lock(m_events_mutex);
 
diff --git a/lldb/source/Host/posix/ConnectionFileDescriptorPosix.cpp b/lldb/source/Host/posix/ConnectionFileDescriptorPosix.cpp
index 70c0e1ad14c..cbf8aaf8de2 100644
--- a/lldb/source/Host/posix/ConnectionFileDescriptorPosix.cpp
+++ b/lldb/source/Host/posix/ConnectionFileDescriptorPosix.cpp
@@ -561,10 +561,7 @@ ConnectionFileDescriptor::BytesAvailable(const Timeout<std::micro> &timeout,
   // ever get used more generally we will need to lock here as well.
 
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_CONNECTION));
-  if (log)
-    log->Printf(
-        "%p ConnectionFileDescriptor::BytesAvailable (timeout_usec = %lu)",
-        static_cast<void *>(this), long(timeout ? timeout->count() : -1));
+  LLDB_LOG(log, "this = {0}, timeout = {1}", this, timeout);
 
   // Make a copy of the file descriptors to make sure we don't
   // have another thread change these values out from under us
diff --git a/lldb/source/Plugins/Process/gdb-remote/GDBRemoteCommunication.cpp b/lldb/source/Plugins/Process/gdb-remote/GDBRemoteCommunication.cpp
index e20994a9a0c..1e1bc066cbf 100644
--- a/lldb/source/Plugins/Process/gdb-remote/GDBRemoteCommunication.cpp
+++ b/lldb/source/Plugins/Process/gdb-remote/GDBRemoteCommunication.cpp
@@ -334,10 +334,9 @@ GDBRemoteCommunication::WaitForPacketNoLock(StringExtractorGDBRemote &packet,
     size_t bytes_read = Read(buffer, sizeof(buffer), timeout, status, &error);
 
     LLDB_LOGV(log,
-              "Read(buffer, sizeof(buffer), timeout = {0} us, "
+              "Read(buffer, sizeof(buffer), timeout = {0}, "
               "status = {1}, error = {2}) => bytes_read = {3}",
-              long(timeout ? timeout->count() : -1),
-              Communication::ConnectionStatusAsCString(status), error,
+              timeout, Communication::ConnectionStatusAsCString(status), error,
               bytes_read);
 
     if (bytes_read > 0) {
diff --git a/lldb/source/Target/Process.cpp b/lldb/source/Target/Process.cpp
index 290bab74b5f..c1a518cad78 100644
--- a/lldb/source/Target/Process.cpp
+++ b/lldb/source/Target/Process.cpp
@@ -982,10 +982,7 @@ StateType Process::WaitForProcessToStop(const Timeout<std::micro> &timeout,
     return state;
 
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_PROCESS));
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu)", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1));
+  LLDB_LOG(log, "timeout = {0}", timeout);
 
   if (!wait_always && StateIsStoppedState(state, true) &&
       StateIsStoppedState(GetPrivateState(), true)) {
@@ -1261,11 +1258,7 @@ StateType Process::GetStateChangedEvents(EventSP &event_sp,
                                          const Timeout<std::micro> &timeout,
                                          ListenerSP hijack_listener_sp) {
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_PROCESS));
-
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu, event_sp)...", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1));
+  LLDB_LOG(log, "timeout = {0}, event_sp)...", timeout);
 
   ListenerSP listener_sp = hijack_listener_sp;
   if (!listener_sp)
@@ -1277,15 +1270,11 @@ StateType Process::GetStateChangedEvents(EventSP &event_sp,
           timeout)) {
     if (event_sp && event_sp->GetType() == eBroadcastBitStateChanged)
       state = Process::ProcessEventData::GetStateFromEvent(event_sp.get());
-    else if (log)
-      log->Printf("Process::%s got no event or was interrupted.", __FUNCTION__);
+    else
+      LLDB_LOG(log, "got no event or was interrupted.");
   }
 
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu, event_sp) => %s", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1),
-        StateAsCString(state));
+  LLDB_LOG(log, "timeout = {0}, event_sp) => {1}", timeout, state);
   return state;
 }
 
@@ -1314,11 +1303,7 @@ StateType
 Process::GetStateChangedEventsPrivate(EventSP &event_sp,
                                       const Timeout<std::micro> &timeout) {
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_PROCESS));
-
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu, event_sp)...", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1));
+  LLDB_LOG(log, "timeout = {0}, event_sp)...", timeout);
 
   StateType state = eStateInvalid;
   if (m_private_state_listener_sp->GetEventForBroadcasterWithType(
@@ -1328,14 +1313,8 @@ Process::GetStateChangedEventsPrivate(EventSP &event_sp,
     if (event_sp && event_sp->GetType() == eBroadcastBitStateChanged)
       state = Process::ProcessEventData::GetStateFromEvent(event_sp.get());
 
-  // This is a bit of a hack, but when we wait here we could very well return
-  // to the command-line, and that could disable the log, which would render the
-  // log we got above invalid.
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu, event_sp) => %s", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1),
-        state == eStateInvalid ? "TIMEOUT" : StateAsCString(state));
+  LLDB_LOG(log, "timeout = {0}, event_sp) => {1}", timeout,
+           state == eStateInvalid ? "TIMEOUT" : StateAsCString(state));
   return state;
 }
 
@@ -1343,11 +1322,7 @@ bool Process::GetEventsPrivate(EventSP &event_sp,
                                const Timeout<std::micro> &timeout,
                                bool control_only) {
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_PROCESS));
-
-  if (log)
-    log->Printf(
-        "Process::%s (timeout = %llu, event_sp)...", __FUNCTION__,
-        static_cast<unsigned long long>(timeout ? timeout->count() : -1));
+  LLDB_LOG(log, "timeout = {0}, event_sp)...", timeout);
 
   if (control_only)
     return m_private_state_listener_sp->GetEventForBroadcaster(
@@ -5352,19 +5327,16 @@ Process::RunThreadPlan(ExecutionContext &exe_ctx,
         if (log) {
           if (options.GetTryAllThreads()) {
             if (before_first_timeout) {
-              log->Printf("Process::RunThreadPlan(): Running function with "
-                          "one thread timeout timed out.");
+              LLDB_LOG(log,
+                       "Running function with one thread timeout timed out.");
             } else
-              log->Printf("Process::RunThreadPlan(): Restarting function with "
-                          "all threads enabled "
-                          "and timeout: %" PRIu64
-                          " timed out, abandoning execution.",
-                          timeout ? timeout->count() : -1);
+              LLDB_LOG(log, "Restarting function with all threads enabled and "
+                            "timeout: {0} timed out, abandoning execution.",
+                       timeout);
           } else
-            log->Printf("Process::RunThreadPlan(): Running function with "
-                        "timeout: %" PRIu64 " timed out, "
-                        "abandoning execution.",
-                        timeout ? timeout->count() : -1);
+            LLDB_LOG(log, "Running function with timeout: {0} timed out, "
+                          "abandoning execution.",
+                     timeout);
         }
 
         // It is possible that between the time we issued the Halt, and we get
diff --git a/lldb/unittests/Utility/TimeoutTest.cpp b/lldb/unittests/Utility/TimeoutTest.cpp
index a30c616d411..d1002fb840d 100644
--- a/lldb/unittests/Utility/TimeoutTest.cpp
+++ b/lldb/unittests/Utility/TimeoutTest.cpp
@@ -8,15 +8,23 @@
 //===----------------------------------------------------------------------===//
 
 #include "lldb/Utility/Timeout.h"
+#include "llvm/Support/FormatVariadic.h"
 #include "gtest/gtest.h"
 
 using namespace lldb_private;
 using namespace std::chrono;
 
 TEST(TimeoutTest, Construction) {
-  ASSERT_FALSE(Timeout<std::micro>(llvm::None));
-  ASSERT_TRUE(bool(Timeout<std::micro>(seconds(0))));
-  ASSERT_EQ(seconds(0), *Timeout<std::micro>(seconds(0)));
-  ASSERT_EQ(seconds(3), *Timeout<std::micro>(seconds(3)));
-  ASSERT_TRUE(bool(Timeout<std::micro>(Timeout<std::milli>(seconds(0)))));
+  EXPECT_FALSE(Timeout<std::micro>(llvm::None));
+  EXPECT_TRUE(bool(Timeout<std::micro>(seconds(0))));
+  EXPECT_EQ(seconds(0), *Timeout<std::micro>(seconds(0)));
+  EXPECT_EQ(seconds(3), *Timeout<std::micro>(seconds(3)));
+  EXPECT_TRUE(bool(Timeout<std::micro>(Timeout<std::milli>(seconds(0)))));
+}
+
+TEST(TimeoutTest, Format) {
+  EXPECT_EQ("<infinite>",
+            llvm::formatv("{0}", Timeout<std::milli>(llvm::None)).str());
+  EXPECT_EQ("1000 ms",
+            llvm::formatv("{0}", Timeout<std::milli>(seconds(1))).str());
 }