Add ring logging for interesting debugging events

This adds a new trace macro to allow tracing to the ring buffer in release builds. It also performs normal tracing, too, like TRACE(n, ...). Converted a number of trace/log messages in the debugger to the new macro so we have this data when we get a core file. I've converted things that we've found useful lately, but this will be adjusted over time quite a lot as we discover new things that help us find problems more quickly, or find messages that turn our to be useless or spammy.

hphp/runtime/eval/debugger/debugger.cpp

@@ -243,7 +243,7 @@ void Debugger::Interrupt(int type, const char *program,
                          InterruptSite *site /* = NULL */,
                          const char *error /* = NULL */) {
   assert(RuntimeOption::EnableDebugger);
-  TRACE(2, "Debugger::Interrupt\n");
+  TRACE_RB(2, "Debugger::Interrupt type %d\n", type);
 
   DebuggerProxyPtr proxy = GetProxy();
   if (proxy) {

hphp/runtime/eval/debugger/debugger_proxy.cpp

@@ -40,7 +40,7 @@ DebuggerProxy::DebuggerProxy(SmartPtr<Socket> socket, bool local)
 }
 
 DebuggerProxy::~DebuggerProxy() {
-  TRACE(2, "DebuggerProxy::~DebuggerProxy\n");
+  TRACE_RB(2, "DebuggerProxy::~DebuggerProxy starting\n");
   m_stopped = true;
   m_signalThread.waitForEnd();
 
@@ -49,6 +49,7 @@ DebuggerProxy::~DebuggerProxy() {
   }
 
   delete m_injTables;
+  TRACE_RB(2, "DebuggerProxy::~DebuggerProxy complete\n");
 }
 
 const char *DebuggerProxy::getThreadType() const {
@@ -242,7 +243,7 @@ bool DebuggerProxy::needVMInterrupts() {
 
 // Handle an interrupt from the VM.
 void DebuggerProxy::interrupt(CmdInterrupt &cmd) {
-  TRACE(2, "DebuggerProxy::interrupt\n");
+  TRACE_RB(2, "DebuggerProxy::interrupt\n");
   // Make any breakpoints that have passed breakable again.
   changeBreakPointDepth(cmd);
 
@@ -328,7 +329,7 @@ void DebuggerProxy::startSignalThread() {
 // If another thread in the sandbox fails to stop and consume the signal then
 // it will be passed to the dummy sandbox instead.
 void DebuggerProxy::pollSignal() {
-  TRACE(2, "DebuggerProxy::pollSignal\n");
+  TRACE_RB(2, "DebuggerProxy::pollSignal: starting\n");
   while (!m_stopped) {
     sleep(1);
 
@@ -337,6 +338,7 @@ void DebuggerProxy::pollSignal() {
     if (m_signum != CmdSignal::SignalNone && m_dummySandbox) {
       Lock lock(m_signumMutex);
       if (m_signum != CmdSignal::SignalNone) {
+        TRACE_RB(2, "DebuggerProxy::pollSignal: sending to dummy sandbox\n");
         m_dummySandbox->notifySignal(m_signum);
         m_signum = CmdSignal::SignalNone;
       }
@@ -349,7 +351,8 @@ void DebuggerProxy::pollSignal() {
     // Send CmdSignal over to the client and wait for a response.
     CmdSignal cmd;
     if (!cmd.onServer(this)) {
-      TRACE(1, "Failed to send CmdSignal to client, socket error");
+      TRACE_RB(2, "DebuggerProxy::pollSignal: "
+               "Failed to send CmdSignal to client\n");
       break;
     }
 
@@ -359,40 +362,45 @@ void DebuggerProxy::pollSignal() {
     while (!DebuggerCommand::Receive(m_thrift, res,
                                      "DebuggerProxy::pollSignal()")) {
       if (m_stopped) {
-        TRACE(1, "DebuggerProxy signal thread asked to stop while "
-              "waiting for CmdSignal back from the client");
+        TRACE_RB(2, "DebuggerProxy::pollSignal: "
+                 "signal thread asked to stop while waiting "
+                 "for CmdSignal back from the client\n");
         break;
       }
     }
     if (!res) {
       if (!m_stopped) {
-        TRACE(1, "Failed to get CmdSignal back from client, socket error");
+        TRACE_RB(2, "DebuggerProxy::pollSignal: "
+                 "Failed to get CmdSignal back from client\n");
       }
       break;
     }
 
     CmdSignalPtr sig = dynamic_pointer_cast<CmdSignal>(res);
     if (!sig) {
-      TRACE(1, "bad response from signal polling: %d", res->getType());
+      TRACE_RB(2, "DebuggerProxy::pollSignal: "
+               "bad response from signal polling: %d", res->getType());
       break;
     }
 
     m_signum = sig->getSignal();
 
     if (m_signum != CmdSignal::SignalNone) {
-      TRACE(2, "DebuggerProxy::pollSignal got interrupt signal from client\n");
+      TRACE_RB(2, "DebuggerProxy::pollSignal: "
+               "got interrupt signal from client\n");
       Debugger::RequestInterrupt(shared_from_this());
     }
   }
   if (!m_stopped) {
-    TRACE(1, "DebuggerProxy signal thread has lost communication with the "
-             "client, stopping proxy.");
+    TRACE_RB(2, "DebuggerProxy::pollSignal: "
+             "lost communication with the client, stopping proxy\n");
     forceQuit();
   }
+  TRACE_RB(2, "DebuggerProxy::pollSignal: ended\n");
 }
 
 void DebuggerProxy::forceQuit() {
-  TRACE(2, "DebuggerProxy::forceQuit\n");
+  TRACE_RB(2, "DebuggerProxy::forceQuit\n");
   DSandboxInfo invalid;
   Lock l(this);
   m_sandbox = invalid;
@@ -571,10 +579,10 @@ void DebuggerProxy::checkStop() {
 }
 
 void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
-  TRACE(2, "DebuggerProxy::processInterrupt\n");
+  TRACE_RB(2, "DebuggerProxy::processInterrupt\n");
   // Do the server-side work for this interrupt, which just notifies the client.
   if (!cmd.onServer(this)) {
-    Logger::Error("Failed to send CmdInterrupt to client, socket error");
+    TRACE_RB(1, "Failed to send CmdInterrupt to client\n");
     Debugger::RemoveProxy(shared_from_this()); // on socket error
     return;
   }
@@ -590,22 +598,27 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
     }
     checkStop();
     if (res) {
+      TRACE_RB(2, "Proxy got cmd type %d\n", res->getType());
       // Any control flow command gets installed here and we continue execution.
       m_flow = dynamic_pointer_cast<CmdFlowControl>(res);
       if (m_flow) {
         m_flow->onSetup(this, cmd);
         if (!m_flow->complete()) {
+          TRACE_RB(2, "Incomplete flow command %d remaining on proxy for "
+                   "further processing\n", m_flow->getType());
           if (m_threadMode == Normal) {
             switchThreadMode(Sticky);
           }
         } else {
           // The flow cmd has determined that it is done with its work and
           // doesn't need to remain for later processing.
+          TRACE_RB(2, "Flow command %d completed\n", m_flow->getType());
           m_flow.reset();
         }
         return;
       }
       if (res->is(DebuggerCommand::KindOfQuit)) {
+        TRACE_RB(2, "Received quit command\n");
         Debugger::RemoveProxy(shared_from_this());
         forceQuit();
         throw DebuggerClientExitException();
@@ -616,19 +629,18 @@ void DebuggerProxy::processInterrupt(CmdInterrupt &cmd) {
       // Perform the server-side work for this command.
       if (res) {
         if (!res->onServer(this)) {
-          Logger::Error("Failed to execute cmd %d from client, socket error",
-                        res->getType());
+          TRACE_RB(1, "Failed to execute cmd %d from client\n", res->getType());
           cmdFailure = true;
         }
       } else {
-        TRACE(1, "Failed to receive cmd from client, socket error");
+        TRACE_RB(1, "Failed to receive cmd from client\n");
         cmdFailure = true;
       }
     } catch (const DebuggerException &e) {
       throw;
     } catch (...) {
-      Logger::Error("Cmd type %d onServer() threw non DebuggerException",
-                    res->getType());
+      TRACE_RB(1, "Cmd type %d onServer() threw non DebuggerException",
+               res->getType());
       cmdFailure = true;
     }
     if (cmdFailure) {

hphp/runtime/ext/ext_apc.cpp

@@ -316,7 +316,7 @@ public:
 
 static size_t s_const_map_size = 0;
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void apc_load(int thread) {
   static void *handle = NULL;
   if (handle ||
@@ -422,7 +422,7 @@ static int count_items(const char **p, int step) {
   return count;
 }
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void const_load_impl(struct cache_info *info,
                      const char **int_keys, long long *int_values,
                      const char **char_keys, char *char_values,
@@ -518,7 +518,7 @@ void const_load_impl(struct cache_info *info,
   }
 }
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void apc_load_impl(struct cache_info *info,
                    const char **int_keys, long long *int_values,
                    const char **char_keys, char *char_values,
@@ -643,7 +643,7 @@ void apc_load_impl(struct cache_info *info,
 ///////////////////////////////////////////////////////////////////////////////
 // Constant and APC priming with compressed data
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void const_load_impl_compressed
     (struct cache_info *info,
      int *int_lens, const char *int_keys, long long *int_values,
@@ -781,7 +781,7 @@ void const_load_impl_compressed
   }
 }
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void apc_load_impl_compressed
     (struct cache_info *info,
      int *int_lens, const char *int_keys, long long *int_values,

hphp/runtime/ext/ext_fb.cpp

@@ -1659,7 +1659,7 @@ void const_load_set(CStrRef key, CVarRef value) {
   const_data.set(key, value, true);
 }
 
-KEEP_SECTION
+EXTERNALLY_VISIBLE
 void const_load() {
   // after all loading
   const_load_set("zend_array_size", const_data.size());

hphp/runtime/vm/bytecode.cpp

@@ -3138,9 +3138,9 @@ void VMExecutionContext::preventReturnsToTC() {
     while (ar) {
       if (!isReturnHelper(ar->m_savedRip) &&
           (tx64->isValidCodeAddress((TCA)ar->m_savedRip))) {
-        TRACE(2, "Replace RIP with RetFromInterpretedFrame helper in fp %p"
-              ", savedRip 0x%lx, func %s\n", ar, ar->m_savedRip,
-              ar->m_func->fullName()->data());
+        TRACE_RB(2, "Replace RIP in fp %p, savedRip 0x%lx, "
+                 "func %s\n", ar, ar->m_savedRip,
+                 ar->m_func->fullName()->data());
         if (ar->m_func->isGenerator()) {
           ar->m_savedRip =
             (uintptr_t)tx64->getRetFromInterpretedGeneratorFrame();

hphp/runtime/vm/debugger_hook.cpp

@@ -14,16 +14,14 @@
    +----------------------------------------------------------------------+
 */
 
-#include "hphp/util/util.h"
-
+#include "hphp/runtime/vm/debugger_hook.h"
+#include "hphp/runtime/vm/translator/translator.h"
+#include "hphp/runtime/eval/debugger/break_point.h"
 #include "hphp/runtime/eval/debugger/debugger.h"
 #include "hphp/runtime/eval/debugger/debugger_proxy.h"
-#include "hphp/runtime/eval/debugger/break_point.h"
 #include "hphp/runtime/eval/runtime/file_repository.h"
-#include "hphp/runtime/vm/unit.h"
-#include "hphp/runtime/vm/translator/translator.h"
-#include "hphp/runtime/vm/debugger_hook.h"
 #include "hphp/util/logger.h"
+#include "hphp/util/util.h"
 
 namespace HPHP {
 
@@ -51,7 +49,7 @@ void phpDebuggerOpcodeHook(const uchar* pc) {
   // we don't need an interrupt for, e.g., stepping over a line of code.
   if (UNLIKELY(g_vmContext->m_lastLocFilter != nullptr) &&
       g_vmContext->m_lastLocFilter->checkPC(pc)) {
-    TRACE(5, "same location as last interrupt\n");
+    TRACE_RB(5, "same location as last interrupt\n");
     return;
   }
   // Are we hitting a breakpoint?
@@ -61,7 +59,7 @@ void phpDebuggerOpcodeHook(const uchar* pc) {
     if (LIKELY(!DEBUGGER_FORCE_INTR)) {
       return;
     }
-    TRACE(5, "DEBUGGER_FORCE_INTR\n");
+    TRACE_RB(5, "DEBUGGER_FORCE_INTR\n");
   }
   Eval::Debugger::InterruptVMHook();
   TRACE(5, "out phpDebuggerOpcodeHook()\n");

hphp/runtime/vm/debugger_hook.h

@@ -18,6 +18,7 @@
 #define incl_HPHP_DEBUGGER_HOOK_H_
 
 #include "hphp/util/base.h"
+#include "hphp/runtime/vm/unit.h"
 
 namespace HPHP {
 namespace Eval{

hphp/util/ringbuffer.cpp

@@ -34,6 +34,7 @@ __thread int  tl_rbPtr;
 __thread char tl_ring[kMaxRBBytes];
 __thread const char _unused[] = "\n----END OF RINGBUFFER---\n";
 
+KEEP_SECTION
 void vtraceRingbuffer(const char* fmt, va_list ap) {
   char buf[4096];
   char* bufP = &buf[0];
@@ -190,6 +191,8 @@ void dumpEntry(const RingBufferEntry* e) {
 //
 //    (gdb) call HPHP::Trace::dumpRingBufferMasked(100,
 //       (1 << HPHP::Trace::RBTypeFuncEntry))
+
+KEEP_SECTION
 void dumpRingBufferMasked(int numEntries, uint32_t types) {
   int startIdx = (g_ringIdx.load() - numEntries) % kMaxRBEntries;
   while (startIdx < 0) {
@@ -206,6 +209,7 @@ void dumpRingBufferMasked(int numEntries, uint32_t types) {
   }
 }
 
+KEEP_SECTION
 void dumpRingBuffer(int numEntries) {
   dumpRingBufferMasked(numEntries, -1u);
 }

hphp/util/trace.cpp

@@ -139,6 +139,13 @@ void traceRelease(const char* fmt, ...) {
   va_end(ap);
 }
 
+void traceRingBufferRelease(const char *fmt, ...) {
+  va_list ap;
+  va_start(ap, fmt);
+  vtraceRingbuffer(fmt, ap);
+  va_end(ap);
+}
+
 void trace(const std::string& s) {
   trace("%s", s.c_str());
 }

hphp/util/trace.h

@@ -167,6 +167,14 @@ std::string prettyNode(const char* name, const P1& p1, const P2& p2) {
 
 void traceRelease(const char*, ...);
 void traceRelease(const std::string& s);
+
+// Trace to the global ring buffer in all builds, and also trace normally
+// via the standard TRACE(n, ...) macro.
+#define TRACE_RB(n, ...)                            \
+  HPHP::Trace::traceRingBufferRelease(__VA_ARGS__); \
+  TRACE(n, __VA_ARGS__);
+void traceRingBufferRelease(const char* fmt, ...);
+
 extern int levels[NumModules];
 const char* moduleName(Module mod);
 static inline bool moduleEnabledRelease(Module tm, int level = 1) {

hphp/util/util.h

@@ -57,12 +57,13 @@ namespace HPHP { namespace Util {
 #define ATTRIBUTE_COLD
 #endif
 
-#define ALWAYS_INLINE  __attribute__((always_inline))
-#define NEVER_INLINE  __attribute__((noinline))
+#define ALWAYS_INLINE      __attribute__((always_inline))
+#define NEVER_INLINE       __attribute__((noinline))
 #define INLINE_SINGLE_CALLER ALWAYS_INLINE
-#define UNUSED         __attribute__((unused))
-#define FLATTEN        __attribute__((flatten))
-#define HOT_FUNC       __attribute__ ((section (".text.hot.builtin")))
+#define UNUSED             __attribute__((unused))
+#define FLATTEN            __attribute__((flatten))
+#define HOT_FUNC           __attribute__ ((section (".text.hot.builtin")))
+#define EXTERNALLY_VISIBLE __attribute__((externally_visible))
 
 #ifdef DEBUG
 #define DEBUG_ONLY /* nop */
@@ -73,17 +74,20 @@ namespace HPHP { namespace Util {
 #define HOT_FUNC_VM HOT_FUNC
 
 /*
- * we need to keep some unreferenced functions from being removed by
+ * We need to keep some unreferenced functions from being removed by
  * the linker. There is no compile time mechanism for doing this, but
  * by putting them in the same section as some other, referenced function
  * in the same file, we can keep them around.
  *
  * So this macro should be used to mark at least one function that is
  * referenced, and other functions that are not referenced in the same
- * file
+ * file.
+ *
+ * Note: this may not work properly with LTO. We'll revisit when/if we
+ * move to it.
  */
 #define KEEP_SECTION \
-  __attribute__((externally_visible))
+  __attribute__((section(".text.keep")))
 
 /**
  * Split a string into a list of tokens by character delimiter.