hphp/runtime/base/perf-mem-event.cpp

   1 /*
   2    +----------------------------------------------------------------------+
   3    | HipHop for PHP                                                       |
   4    +----------------------------------------------------------------------+
   5    | Copyright (c) 2010-present Facebook, Inc. (http://www.facebook.com)  |
   6    +----------------------------------------------------------------------+
   7    | This source file is subject to version 3.01 of the PHP license,      |
   8    | that is bundled with this package in the file LICENSE, and is        |
   9    | available through the world-wide-web at the following url:           |
  10    | http://www.php.net/license/3_01.txt                                  |
  11    | If you did not receive a copy of the PHP license and are unable to   |
  12    | obtain it through the world-wide-web, please send a note to          |
  13    | license@php.net so we can mail you a copy immediately.               |
  14    +----------------------------------------------------------------------+
  15 */
  16
  17 #include "hphp/runtime/base/perf-mem-event.h"
  18
  19 #include "hphp/runtime/base/apc-local-array.h"
  20 #include "hphp/runtime/base/array-data.h"
  21 #include "hphp/runtime/base/header-kind.h"
  22 #include "hphp/runtime/base/member-reflection.h"
  23 #include "hphp/runtime/base/memory-manager.h"
  24 #include "hphp/runtime/base/memory-manager-defs.h"
  25 #include "hphp/runtime/base/mixed-array.h"
  26 #include "hphp/runtime/base/packed-array.h"
  27 #include "hphp/runtime/base/string-data.h"
  28 #include "hphp/runtime/base/typed-value.h"
  29 #include "hphp/runtime/vm/class.h"
  30 #include "hphp/runtime/vm/func.h"
  31 #include "hphp/runtime/vm/globals-array.h"
  32 #include "hphp/runtime/vm/named-entity.h"
  33 #include "hphp/runtime/vm/reverse-data-map.h"
  34 #include "hphp/runtime/vm/unit.h"
  35 #include "hphp/runtime/vm/vm-regs.h"
  36
  37 #include "hphp/runtime/vm/jit/mcgen.h"
  38 #include "hphp/runtime/vm/jit/tc.h"
  39 #include "hphp/runtime/vm/jit/tc-internal.h"
  40
  41 #include "hphp/util/alloc.h"
  42 #include "hphp/util/match.h"
  43 #include "hphp/util/perf-event.h"
  44 #include "hphp/util/stack-trace.h"
  45 #include "hphp/util/struct-log.h"
  46 #include "hphp/util/trace.h"
  47
  48 #include <boost/algorithm/string/predicate.hpp>
  49
  50 #include <folly/ScopeGuard.h>
  51 #ifdef FACEBOOK
  52 #include <folly/Demangle.h>
  53 #include <folly/experimental/symbolizer/Symbolizer.h>
  54 #endif
  55
  56 namespace HPHP {
  57
  58 TRACE_SET_MOD(perf_mem_event);
  59
  60 using namespace jit;
  61
  62 ///////////////////////////////////////////////////////////////////////////////
  63
  64 namespace {
  65
  66 /*
  67  * Version number for the entries.
  68  *
  69  * Bump this whenever the log format changes, so that it's easy to filter out
  70  * old, incompatible results.
  71  */
  72 constexpr auto kVersion = 3;
  73
  74 /*
  75  * Update `record' with the data member that `internal' is in, relative to
  76  * `base', returning whether or not a corresponding member is found.
  77  */
  78 template<class T>
  79 bool try_member(const T* base, const void* internal,
  80                 StructuredLogEntry& record) {
  81   if (auto const memb = nameof_member(base, internal)) {
  82     record.setStr("member", memb);
  83     return true;
  84   }
  85   return false;
  86 }
  87
  88 /*
  89  * Per-type log entry updaters.
  90  *
  91  * These all assume that `addr' is a pointer that is logically internal to the
  92  * base object.
  93  */
  94
  95 void fill_record(const Class* cls, const void* addr,
  96                  StructuredLogEntry& record) {
  97   record.setStr("name", cls->name()->data());
  98
  99   if (cls->classVec() <= addr && addr < cls->mallocEnd()) {
 100     auto const idx = (reinterpret_cast<uintptr_t>(addr)
 101                      - reinterpret_cast<uintptr_t>(cls->classVec()))
 102                      / sizeof(*cls->classVec());
 103     record.setStr("member", "m_classVec");
 104     record.setInt("index", idx);
 105   }
 106   // Introspect members after dealing with the variable-length terminal
 107   // array member.
 108   if (try_member(cls, addr, record)) return;
 109
 110   if (cls->funcVec() <= addr && addr < cls) {
 111     auto const idx = (reinterpret_cast<uintptr_t>(cls)
 112                      - reinterpret_cast<uintptr_t>(addr))
 113                      / sizeof(*cls->funcVec());
 114     record.setStr("member", "funcVec");
 115     record.setInt("index", idx);
 116   }
 117 }
 118
 119 void fill_record(const Func* func, const void* addr,
 120                  StructuredLogEntry& record) {
 121   record.setStr("name", func->fullName()->data());
 122
 123   auto const func_end = reinterpret_cast<const char*>(func)
 124                         + Func::prologueTableOff();
 125   if (func_end <= addr && addr < func->mallocEnd()) {
 126     auto const idx = (reinterpret_cast<const char*>(addr) - func_end)
 127                      / sizeof(AtomicLowPtr<uint8_t>);
 128     record.setStr("member", "m_prologueTable");
 129     record.setInt("index", idx);
 130   }
 131   // Introspect members after dealing with the variable-length terminal
 132   // array member.
 133   try_member(func, addr, record);
 134 }
 135
 136 void fill_record(const Unit* unit, const void* addr,
 137                  StructuredLogEntry& record) {
 138   record.setStr("name", unit->filepath()->data());
 139   try_member(unit, addr, record);
 140 }
 141
 142 void fill_record(const StringData* sd, const void* addr,
 143                  StructuredLogEntry& record) {
 144   record.setStr("data", sd->data());
 145   if (try_member(sd, addr, record)) return;
 146
 147   auto const idx = uintptr_t(addr) - uintptr_t(sd->data());
 148   if (idx < 0) return;
 149
 150   record.setInt("index", idx);
 151 }
 152
 153 void fill_record(const ArrayData* arr, const void* addr,
 154                  StructuredLogEntry& record) {
 155   if (try_member(arr, addr, record)) return;
 156
 157   auto const tv = reinterpret_cast<const TypedValue*>(addr);
 158   auto const idx = tv - packedData(arr);
 159   if (idx < 0) return;
 160
 161   record.setInt("ikey", idx);
 162
 163   if (idx < arr->size()) {
 164     if (auto const memb = nameof_member(tv, addr)) {
 165       record.setStr("value_memb", memb);
 166     }
 167     record.setStr("value_type", tname(tv->m_type));
 168   }
 169 }
 170
 171 void fill_record(const MixedArray* arr, const void* addr,
 172                  StructuredLogEntry& record) {
 173   if (try_member(arr, addr, record)) return;
 174
 175   auto const data = reinterpret_cast<const MixedArray::Elm*>(arr + 1);
 176   auto const idx = (uintptr_t(addr) - uintptr_t(data))
 177                    / sizeof(MixedArray::Elm);
 178
 179   if (idx < arr->iterLimit()) {
 180     auto const elm = &data[idx];
 181
 182     if (auto const memb = nameof_member(elm, addr)) {
 183       record.setStr("value_memb", memb);
 184     }
 185     if (elm->isTombstone()) {
 186       record.setStr("skey", "<tombstone>");
 187       record.setStr("value_type", "<tombstone>");
 188     } else {
 189       if (elm->hasIntKey()) {
 190         record.setInt("ikey", elm->ikey);
 191       } else {
 192         assertx(elm->hasStrKey());
 193         record.setStr("skey", elm->skey->data());
 194       }
 195       record.setStr("value_type", tname(elm->data.m_type));
 196     }
 197   }
 198 }
 199
 200 ///////////////////////////////////////////////////////////////////////////////
 201
 202 /*
 203  * Update `record' for `tca', known to point into the TC.
 204  */
 205 bool record_tc_mem_event(TCA tca, StructuredLogEntry& record) {
 206   record.setStr("location", "jit_code");
 207
 208   auto const ustub = tc::ustubs().describe(tca);
 209   if (!boost::starts_with(ustub, "0x")) {
 210     record.setStr("kind", "ustub");
 211     record.setStr("name", ustub.substr(0, ustub.find('+')));
 212   }
 213
 214   return true;
 215 }
 216
 217 /*
 218  * Update `record' for an `addr' known to be internal to the VM metadata object
 219  * given by `res'.
 220  */
 221 bool record_vm_metadata_mem_event(data_map::result res, const void* addr,
 222                                   StructuredLogEntry& record) {
 223   auto const pos = reinterpret_cast<const char*>(addr);
 224
 225   assertx(!res.empty());
 226   match<void>(
 227     res,
 228     [&](const Class* cls) {
 229       record.setInt("offset", pos - reinterpret_cast<const char*>(cls));
 230       record.setStr("kind", "Class");
 231       fill_record(cls, addr, record);
 232     },
 233     [&](const Func* func) {
 234       record.setInt("offset", pos - reinterpret_cast<const char*>(func));
 235       record.setStr("kind", "Class");
 236       record.setStr("kind", "Func");
 237       fill_record(func, addr, record);
 238     },
 239     [&](const NamedEntity* ne) {
 240       record.setInt("offset", pos - reinterpret_cast<const char*>(ne));
 241       record.setStr("kind", "NamedEntity");
 242       try_member(ne, addr, record);
 243     },
 244     [&](const StringData* sd) {
 245       record.setInt("offset", pos - reinterpret_cast<const char*>(sd));
 246       record.setStr("kind", "StringData");
 247       fill_record(sd, addr, record);
 248     },
 249     [&](const Unit* unit) {
 250       record.setInt("offset", pos - reinterpret_cast<const char*>(unit));
 251       record.setStr("kind", "Unit");
 252       fill_record(unit, addr, record);
 253     }
 254   );
 255   return true;
 256 }
 257
 258 /*
 259  * Update `record' for an `addr' in low memory.
 260  */
 261 bool record_low_mem_event(const void* addr, StructuredLogEntry& record) {
 262   record.setStr("location", "low_mem");
 263
 264   // See if `addr' refers to some VM metadata object.
 265   auto const res = data_map::find_containing(addr);
 266   if (!res.empty()) {
 267     return record_vm_metadata_mem_event(res, addr, record);
 268   }
 269
 270   // Try to symbolize `addr' if possible.
 271 #ifdef FACEBOOK
 272   using namespace folly::symbolizer;
 273   Symbolizer symbolizer;
 274   SymbolizedFrame frame;
 275
 276   auto const iddr = reinterpret_cast<uintptr_t>(addr);
 277   symbolizer.symbolize(iddr, frame);
 278
 279   auto const name = folly::demangle(frame.name);
 280   if (!name.empty()) record.setStr("symbol", name);
 281 #endif
 282
 283   return true;
 284 }
 285
 286 /*
 287  * Update `record' for an `addr' known to be in the request heap object given
 288  * by `hdr'.
 289  */
 290 bool record_request_heap_mem_event(const void* addr,
 291                                    const HeapObject* hdr,
 292                                    StructuredLogEntry& record) {
 293   record.setStr("location", "request_heap");
 294   record.setStr("kind", header_names[uint8_t(hdr->kind())]);
 295   record.setInt("offset", reinterpret_cast<const char*>(addr) -
 296                           reinterpret_cast<const char*>(hdr));
 297
 298   switch (hdr->kind()) {
 299     case HeaderKind::String:
 300       fill_record(static_cast<const StringData*>(hdr), addr, record);
 301       break;
 302
 303     case HeaderKind::Packed:
 304     case HeaderKind::VecArray:
 305       fill_record(static_cast<const ArrayData*>(hdr), addr, record);
 306       break;
 307
 308     case HeaderKind::Mixed:
 309     case HeaderKind::Dict:
 310       fill_record(static_cast<const MixedArray*>(hdr), addr, record);
 311       break;
 312
 313     case HeaderKind::Keyset:
 314       try_member(static_cast<const SetArray*>(hdr), addr, record);
 315       break;
 316
 317     case HeaderKind::Apc:
 318       try_member(static_cast<const APCLocalArray*>(hdr), addr, record);
 319       break;
 320     case HeaderKind::Globals:
 321       try_member(static_cast<const GlobalsArray*>(hdr), addr, record);
 322       break;
 323     case HeaderKind::Empty:
 324       break;
 325     case HeaderKind::RecordArray:
 326       // TODO: T47449944
 327       break;
 328     case HeaderKind::RFunc: // TODO(T63348446)
 329       break;
 330
 331     case HeaderKind::Object:
 332     case HeaderKind::NativeObject:
 333     case HeaderKind::Closure:
 334     case HeaderKind::WaitHandle:
 335     case HeaderKind::AsyncFuncWH:
 336     case HeaderKind::AwaitAllWH:
 337     case HeaderKind::Resource:
 338     case HeaderKind::ClsMeth:
 339
 340     case HeaderKind::Vector:
 341     case HeaderKind::Map:
 342     case HeaderKind::Set:
 343     case HeaderKind::Pair:
 344     case HeaderKind::ImmVector:
 345     case HeaderKind::ImmMap:
 346     case HeaderKind::ImmSet:
 347
 348     case HeaderKind::AsyncFuncFrame:
 349     case HeaderKind::NativeData:
 350     case HeaderKind::ClosureHdr:
 351     case HeaderKind::MemoData:
 352
 353     case HeaderKind::Record:
 354       break;
 355
 356     case HeaderKind::Cpp:
 357     case HeaderKind::SmallMalloc:
 358     case HeaderKind::BigMalloc:
 359     case HeaderKind::Slab:
 360     case HeaderKind::Free:
 361     case HeaderKind::Hole:
 362       break;
 363   }
 364   return true;
 365 }
 366
 367 /*
 368  * Update `record' for an `addr' known to be on the native C++ or the VM eval
 369  * stack.
 370  *
 371  * All our stacks are black boxes, so we can't do much categorization.
 372  */
 373 bool record_cpp_stack_mem_event(const void* /*addr*/,
 374                                 StructuredLogEntry& record) {
 375   record.setStr("location", "cpp_stack");
 376   return true;
 377 }
 378 bool record_vm_stack_mem_event(const void* /*addr*/,
 379                                StructuredLogEntry& record) {
 380   record.setStr("location", "vm_stack");
 381   return true;
 382 }
 383
 384 }
 385
 386 ///////////////////////////////////////////////////////////////////////////////
 387
 388 void record_perf_mem_event(PerfEvent kind, const perf_event_sample* sample) {
 389   perf_event_pause();
 390   SCOPE_EXIT { perf_event_resume(); };
 391
 392   auto const addr = reinterpret_cast<const void*>(sample->addr);
 393
 394   auto record = StructuredLogEntry{};
 395   record.setInt("version", kVersion);
 396   record.setStr("event", [&] {
 397     switch (kind) {
 398       case PerfEvent::Load:  return "load";
 399       case PerfEvent::Store: return "store";
 400     }
 401     not_reached();
 402   }());
 403   record.setInt("addr", uintptr_t(addr));
 404
 405   auto const data_src = sample->tail()->data_src;
 406   auto const info = perf_event_data_src(kind, data_src);
 407   record.setInt("data_src", data_src);
 408   record.setStr("mem_lvl", info.mem_lvl);
 409   record.setStr("tlb", info.tlb);
 410   record.setInt("mem_hit", info.mem_hit);
 411   record.setInt("snoop", info.snoop);
 412   record.setInt("snoop_hit", info.snoop_hit);
 413   record.setInt("snoop_hitm", info.snoop_hitm);
 414   record.setInt("locked", info.locked);
 415   record.setInt("tlb_hit", info.tlb_hit);
 416
 417   auto const should_log = [&] {
 418     auto const tca = reinterpret_cast<TCA>(const_cast<void*>(addr));
 419
 420     if (addr == nullptr) {
 421       return false;
 422     }
 423     if (jit::mcgen::initialized() && jit::tc::code().isValidCodeAddress(tca)) {
 424       return record_tc_mem_event(tca, record);
 425     }
 426     if (uintptr_t(addr) <= 0xffffffff) {
 427       return record_low_mem_event(addr, record);
 428     }
 429     if (uintptr_t(addr) - s_stackLimit < s_stackSize) {
 430       return record_cpp_stack_mem_event(addr, record);
 431     }
 432     if (isValidVMStackAddress(addr)) {
 433       return record_vm_stack_mem_event(addr, record);
 434     }
 435
 436     if (auto const thing = tl_heap->find(addr)) {
 437       if (UNLIKELY(thing->kind() != HeaderKind::Slab)) {
 438         return record_request_heap_mem_event(addr, thing, record);
 439       }
 440       auto const slab = static_cast<const Slab*>(thing);
 441       auto const obj = slab->find(addr);
 442       return record_request_heap_mem_event(addr, obj ? obj : slab, record);
 443     }
 444     if (tl_heap->contains(const_cast<void*>(addr))) {
 445       record.setStr("location", "request_heap");
 446       return true;
 447     }
 448
 449     record.setStr("location", "(unknown)");
 450     return true;
 451   }();
 452
 453   if (should_log) {
 454     // Symbolize the callchain for the event.
 455     auto const st = StackTrace(
 456       reinterpret_cast<void* const*>(sample->ips),
 457       sample->nr
 458     );
 459     auto frames = std::vector<folly::StringPiece>{};
 460     folly::split("\n", st.toString(), frames);
 461     record.setVec("stacktrace", frames);
 462
 463     FTRACE(1, "perf_mem_event: {}\n", show(record).c_str());
 464     StructuredLog::log("hhvm_mem_access", record);
 465   }
 466 }
 467
 468 ///////////////////////////////////////////////////////////////////////////////
 469
 470 }