From a605a5c6992472d11e3c69f163267a1fcd166ca2 Mon Sep 17 00:00:00 2001 From: Mike Magruder Date: Wed, 15 May 2013 13:03:37 -0700 Subject: [PATCH] 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 | 2 +- hphp/runtime/eval/debugger/debugger_proxy.cpp | 50 ++++++++++++------- hphp/runtime/ext/ext_apc.cpp | 10 ++-- hphp/runtime/ext/ext_fb.cpp | 2 +- hphp/runtime/vm/bytecode.cpp | 6 +-- hphp/runtime/vm/debugger_hook.cpp | 14 +++--- hphp/runtime/vm/debugger_hook.h | 1 + hphp/util/ringbuffer.cpp | 4 ++ hphp/util/trace.cpp | 7 +++ hphp/util/trace.h | 8 +++ hphp/util/util.h | 20 +++++--- 11 files changed, 79 insertions(+), 45 deletions(-) diff --git a/hphp/runtime/eval/debugger/debugger.cpp b/hphp/runtime/eval/debugger/debugger.cpp index 1c3aeb205..af7e80b84 100644 --- a/hphp/runtime/eval/debugger/debugger.cpp +++ b/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) { diff --git a/hphp/runtime/eval/debugger/debugger_proxy.cpp b/hphp/runtime/eval/debugger/debugger_proxy.cpp index 67ce8d4e6..2ba7562b2 100644 --- a/hphp/runtime/eval/debugger/debugger_proxy.cpp +++ b/hphp/runtime/eval/debugger/debugger_proxy.cpp @@ -40,7 +40,7 @@ DebuggerProxy::DebuggerProxy(SmartPtr 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(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(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) { diff --git a/hphp/runtime/ext/ext_apc.cpp b/hphp/runtime/ext/ext_apc.cpp index f94426c45..5c960afb1 100644 --- a/hphp/runtime/ext/ext_apc.cpp +++ b/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, diff --git a/hphp/runtime/ext/ext_fb.cpp b/hphp/runtime/ext/ext_fb.cpp index 10ac65630..aecb5d05a 100644 --- a/hphp/runtime/ext/ext_fb.cpp +++ b/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()); diff --git a/hphp/runtime/vm/bytecode.cpp b/hphp/runtime/vm/bytecode.cpp index c211eab40..c22e1220d 100644 --- a/hphp/runtime/vm/bytecode.cpp +++ b/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(); diff --git a/hphp/runtime/vm/debugger_hook.cpp b/hphp/runtime/vm/debugger_hook.cpp index f2402349f..656b7adce 100644 --- a/hphp/runtime/vm/debugger_hook.cpp +++ b/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"); diff --git a/hphp/runtime/vm/debugger_hook.h b/hphp/runtime/vm/debugger_hook.h index 13a233d8f..2d6e63096 100644 --- a/hphp/runtime/vm/debugger_hook.h +++ b/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{ diff --git a/hphp/util/ringbuffer.cpp b/hphp/util/ringbuffer.cpp index c53ad6bc2..74f7d784d 100644 --- a/hphp/util/ringbuffer.cpp +++ b/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); } diff --git a/hphp/util/trace.cpp b/hphp/util/trace.cpp index 70ec0300a..353b49acf 100644 --- a/hphp/util/trace.cpp +++ b/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()); } diff --git a/hphp/util/trace.h b/hphp/util/trace.h index 66b9a3220..469bd4dfd 100644 --- a/hphp/util/trace.h +++ b/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) { diff --git a/hphp/util/util.h b/hphp/util/util.h index a4f7edfef..86aa51888 100644 --- a/hphp/util/util.h +++ b/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.