hphp/hhbbc/debug.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 #include "hphp/hhbbc/debug.h"
  17
  18 #include <string>
  19 #include <utility>
  20 #include <cstdlib>
  21 #include <fstream>
  22
  23 #include <algorithm>
  24 #include <filesystem>
  25 #include <memory>
  26 #include <vector>
  27
  28 #include <folly/portability/Stdlib.h>
  29
  30 #include "hphp/hhbbc/class-util.h"
  31 #include "hphp/hhbbc/context.h"
  32 #include "hphp/hhbbc/index.h"
  33 #include "hphp/hhbbc/misc.h"
  34 #include "hphp/hhbbc/parallel.h"
  35 #include "hphp/hhbbc/parse.h"
  36
  37 namespace HPHP::HHBBC {
  38
  39 namespace fs = std::filesystem;
  40
  41 //////////////////////////////////////////////////////////////////////
  42
  43 namespace {
  44
  45 const StaticString s_invoke("__invoke");
  46
  47 template<class Operation>
  48 void with_file(fs::path dir, const php::Unit& u, Operation op) {
  49   // Paths for systemlib units start with /, which gets interpreted as
  50   // an absolute path, so strip it.
  51   auto filename = u.filename->data();
  52   if (filename[0] == '/') ++filename;
  53
  54   auto const file = dir / fs::path(filename);
  55   fs::create_directories(fs::path(file).remove_filename());
  56
  57   std::ofstream out(file);
  58   if (!out.is_open()) {
  59     throw std::runtime_error(std::string("failed to open file ") +
  60       file.string());
  61   }
  62
  63   op(out);
  64
  65   if (out.bad()) {
  66     throw std::runtime_error(std::string("couldn't write file ") +
  67       file.string());
  68   }
  69 }
  70
  71 using NameTy = std::pair<SString,PropStateElem>;
  72 std::vector<NameTy> sorted_prop_state(const PropState& ps) {
  73   std::vector<NameTy> ret(begin(ps), end(ps));
  74   std::sort(
  75     begin(ret), end(ret),
  76     [&] (NameTy a, NameTy b) { return a.first->compare(b.first) < 0; }
  77   );
  78   return ret;
  79 }
  80
  81 void dump_class_state(std::ostream& out,
  82                       const Index& index,
  83                       const php::Class* c) {
  84   auto const clsName = c->name->toCppString();
  85
  86   auto const add_attrs = [&] (Attr attrs) {
  87     if (!(attrs & AttrInitialSatisfiesTC)) out << " (no-satisfies-tc)";
  88     if (attrs & AttrDeepInit) out << " (deep-init)";
  89   };
  90
  91   if (auto const s = index.lookup_iface_vtable_slot(c); s != kInvalidSlot) {
  92     out << clsName << " vtable slot #" << s << '\n';
  93   }
  94
  95   if (is_closure(*c)) {
  96     auto const invoke = find_method(c, s_invoke.get());
  97     auto const useVars = index.lookup_closure_use_vars(invoke);
  98     for (auto i = size_t{0}; i < useVars.size(); ++i) {
  99       out << clsName << "->" << c->properties[i].name->data() << " :: "
 100           << show(useVars[i]) << '\n';
 101     }
 102   } else {
 103      auto const pprops = sorted_prop_state(
 104       index.lookup_private_props(c)
 105     );
 106     for (auto const& kv : pprops) {
 107       out << clsName << "->" << kv.first->data() << " :: "
 108           << show(kv.second.ty);
 109       add_attrs(kv.second.attrs);
 110       out << '\n';
 111     }
 112
 113     auto const private_sprops = sorted_prop_state(
 114       index.lookup_private_statics(c)
 115     );
 116     for (auto const& kv : private_sprops) {
 117       out << clsName << "::$" << kv.first->data() << " :: "
 118           << show(kv.second.ty);
 119       if (!kv.second.everModified) out << " (persistent)";
 120       add_attrs(kv.second.attrs);
 121       out << '\n';
 122     }
 123
 124     auto const public_sprops = sorted_prop_state(
 125       index.lookup_public_statics(c)
 126     );
 127     for (auto const& kv : public_sprops) {
 128       out << clsName << "::$" << kv.first->data() << " :: "
 129           << show(kv.second.ty);
 130       if (!kv.second.everModified) out << " (persistent)";
 131       add_attrs(kv.second.attrs);
 132       out << '\n';
 133     }
 134   }
 135
 136   std::vector<const php::Const*> constants;
 137   constants.reserve(c->constants.size());
 138   for (auto const& constant : c->constants) {
 139     constants.emplace_back(&constant);
 140   }
 141   std::sort(
 142     begin(constants), end(constants),
 143     [] (const php::Const* a, const php::Const* b) {
 144       return string_data_lt{}(a->name, b->name);
 145     }
 146   );
 147
 148   for (auto const constant : constants) {
 149     if (constant->val) {
 150       auto const ty = from_cell(*constant->val);
 151       out << clsName << "::" << constant->name->data() << " :: "
 152           << (ty.subtypeOf(BUninit) ? "<dynamic>" : show(ty));
 153       if (constant->kind == ConstModifiers::Kind::Type) {
 154         if (constant->resolvedTypeStructure) {
 155           out << " (" << show(dict_val(constant->resolvedTypeStructure)) << ")";
 156           switch ((php::Const::Invariance)constant->invariance) {
 157             case php::Const::Invariance::None:
 158               break;
 159             case php::Const::Invariance::Present:
 160               out << " <present>";
 161               break;
 162             case php::Const::Invariance::ClassnamePresent:
 163               out << " <classname>";
 164               break;
 165             case php::Const::Invariance::Same:
 166               out << " <same>";
 167               break;
 168           }
 169         } else {
 170           out << " <unresolved>";
 171         }
 172       }
 173       out << '\n';
 174     }
 175   }
 176 }
 177
 178 void dump_func_state(std::ostream& out,
 179                      const Index& index,
 180                      const php::Func& f) {
 181   auto const name = f.cls
 182     ? folly::sformat(
 183         "{}::{}()",
 184         f.cls->name, f.name
 185       )
 186     : folly::sformat("{}()", f.name);
 187
 188   auto const [retTy, effectFree] = index.lookup_return_type_raw(&f).first;
 189   out << name << " :: " << show(retTy) <<
 190     (effectFree ? " (effect-free)\n" : "\n");
 191 }
 192
 193 }
 194
 195 //////////////////////////////////////////////////////////////////////
 196
 197 std::string debug_dump_to() {
 198   if (!Trace::moduleEnabledRelease(Trace::hhbbc_dump, 1)) return "";
 199
 200   trace_time tracer("debug dump");
 201
 202   auto dir = [&]{
 203     if (auto const dumpDir = getenv("HHBBC_DUMP_DIR")) {
 204       return fs::path(dumpDir);
 205     } else {
 206       char dirBuf[] = "/tmp/hhbbcXXXXXX";
 207       auto const dtmpRet = mkdtemp(dirBuf);
 208       if (!dtmpRet) {
 209         throw std::runtime_error(
 210           std::string("Failed to create temporary directory") +
 211           strerror(errno));
 212       }
 213       return fs::path(dtmpRet);
 214     }
 215   }();
 216   fs::create_directory(dir);
 217
 218   Trace::ftraceRelease("debug dump going to {}\n", dir.string());
 219   return dir.string();
 220 }
 221
 222 void dump_representation(const std::string& dir,
 223                          const Index& index,
 224                          const php::Unit& unit) {
 225   auto const rep_dir = fs::path{dir} / "representation";
 226   with_file(rep_dir, unit, [&] (std::ostream& out) {
 227     out << show(unit, index);
 228   });
 229 }
 230
 231 void dump_index(const std::string& dir,
 232                 const Index& index,
 233                 const php::Unit& unit) {
 234   if (!*unit.filename->data()) {
 235     // The native systemlibs: for now just skip.
 236     return;
 237   }
 238
 239   auto ind_dir = fs::path{dir} / "index";
 240
 241   with_file(ind_dir, unit, [&] (std::ostream& out) {
 242     std::vector<const php::Class*> classes;
 243     index.for_each_unit_class(
 244       unit,
 245       [&] (const php::Class& c) { classes.emplace_back(&c); }
 246     );
 247     std::sort(
 248       begin(classes), end(classes),
 249       [] (const php::Class* a, const php::Class* b) {
 250         return string_data_lt_type{}(a->name, b->name);
 251       }
 252     );
 253
 254     for (auto const c : classes) {
 255       dump_class_state(out, index, c);
 256
 257       std::vector<const php::Func*> funcs;
 258       funcs.reserve(c->methods.size());
 259       for (auto const& m : c->methods) {
 260         if (!m) continue;
 261         funcs.emplace_back(m.get());
 262       }
 263       std::sort(
 264         begin(funcs), end(funcs),
 265         [] (const php::Func* a, const php::Func* b) {
 266           return string_data_lt{}(a->name, b->name);
 267         }
 268       );
 269       for (auto const f : funcs) dump_func_state(out, index, *f);
 270     }
 271
 272     std::vector<const php::Func*> funcs;
 273     index.for_each_unit_func(
 274       unit,
 275       [&] (const php::Func& f) { funcs.emplace_back(&f); }
 276     );
 277     std::sort(
 278       begin(funcs), end(funcs),
 279       [] (const php::Func* a, const php::Func* b) {
 280         return string_data_lt{}(a->name, b->name);
 281       }
 282     );
 283     for (auto const f : funcs) dump_func_state(out, index, *f);
 284   });
 285 }
 286
 287 //////////////////////////////////////////////////////////////////////
 288
 289 void state_after(const char* when,
 290                  const php::Unit& u,
 291                  const Index& index) {
 292   TRACE_SET_MOD(hhbbc);
 293   Trace::Bump bumper{Trace::hhbbc, kSystemLibBump, is_systemlib_part(u)};
 294   FTRACE(4, "{:-^70}\n{}{:-^70}\n", when, show(u, index), "");
 295 }
 296
 297 void state_after(const char* when, const ParsedUnit& parsed) {
 298   TRACE_SET_MOD(hhbbc);
 299   Trace::Bump bumper{
 300     Trace::hhbbc,
 301     kSystemLibBump,
 302     is_systemlib_part(*parsed.unit)
 303   };
 304
 305   std::vector<const php::Func*> funcs;
 306   std::vector<const php::Class*> classes;
 307   for (auto const& f : parsed.funcs) {
 308     funcs.emplace_back(f.get());
 309   }
 310   for (auto const& c : parsed.classes) {
 311     classes.emplace_back(c.get());
 312   }
 313
 314   FTRACE(
 315     4,
 316     "{:-^70}\n{}{:-^70}\n",
 317     when,
 318     show(*parsed.unit, classes, funcs),
 319     ""
 320   );
 321 }
 322
 323 //////////////////////////////////////////////////////////////////////
 324
 325 namespace {
 326
 327 template <typename Clock>
 328 std::string ts(typename Clock::time_point t) {
 329   char snow[64];
 330   auto tm = Clock::to_time_t(t);
 331   ctime_r(&tm, snow);
 332   // Eliminate trailing newline from ctime_r.
 333   snow[24] = '\0';
 334   return snow;
 335 }
 336
 337 std::string format_bytes(size_t bytes) {
 338   auto s = folly::prettyPrint(
 339     bytes,
 340     folly::PRETTY_BYTES
 341   );
 342   // prettyPrint sometimes inserts a trailing blank space
 343   if (!s.empty() && s[s.size()-1] == ' ') s.resize(s.size()-1);
 344   return s;
 345 }
 346
 347 std::string format_duration(std::chrono::microseconds usecs) {
 348   auto s = prettyPrint(
 349     double(usecs.count()) / 1000000.0,
 350     folly::PRETTY_TIME_HMS,
 351     false
 352   );
 353   if (!s.empty() && s[s.size()-1] == ' ') s.resize(s.size()-1);
 354   return s;
 355 }
 356
 357 std::string client_stats(const extern_worker::Client::Stats& stats) {
 358   auto const pct = [] (size_t a, size_t b) -> std::string {
 359     if (!b) return "--";
 360     return folly::sformat("{:.2f}%", double(a) / b * 100.0);
 361   };
 362
 363   auto const execWorkItems = stats.execWorkItems.load();
 364   auto const allocatedCores = stats.execAllocatedCores.load();
 365   auto const cpuUsecs = stats.execCpuUsec.load();
 366   auto const execCalls = stats.execCalls.load();
 367   auto const storeCalls = stats.storeCalls.load();
 368   auto const loadCalls = stats.loadCalls.load();
 369
 370   return folly::sformat(
 371     "  Execs: {:,} ({:,}) total, {:,} cache-hits ({})\n"
 372     "  Workers: {} usage, {:,} cores ({}/core), {} max used, {} reserved\n"
 373     "  Blobs: {:,} total, {:,} uploaded ({})\n"
 374     "  {:,} downloads ({}), {:,} throttles, (E: {} S: {} L: {}) avg latency\n",
 375     execCalls,
 376     execWorkItems,
 377     stats.execCacheHits.load(),
 378     pct(stats.execCacheHits.load(), execCalls),
 379     format_duration(std::chrono::microseconds{cpuUsecs}),
 380     allocatedCores,
 381     format_duration(
 382       std::chrono::microseconds{allocatedCores ? (cpuUsecs / allocatedCores) : 0}
 383     ),
 384     format_bytes(stats.execMaxUsedMem.load()),
 385     format_bytes(stats.execReservedMem.load()),
 386     stats.blobs.load(),
 387     stats.blobsUploaded.load(),
 388     format_bytes(stats.blobBytesUploaded.load()),
 389     stats.downloads.load(),
 390     format_bytes(stats.bytesDownloaded.load()),
 391     stats.throttles.load(),
 392     format_duration(
 393       std::chrono::microseconds{execCalls ? (stats.execLatencyUsec.load() / execCalls) : 0}
 394     ),
 395     format_duration(
 396       std::chrono::microseconds{storeCalls ? (stats.storeLatencyUsec.load() / storeCalls) : 0}
 397     ),
 398     format_duration(
 399       std::chrono::microseconds{loadCalls ? (stats.loadLatencyUsec.load() / loadCalls) : 0}
 400     )
 401   );
 402 }
 403
 404 extern_worker::Client::Stats::Ptr g_clientStats;
 405
 406 }
 407
 408 trace_time::trace_time(const char* what,
 409                        std::string extra_,
 410                        StructuredLogEntry* logEntry)
 411   : what{what}
 412   , start(clock::now())
 413   , extra{std::move(extra_)}
 414   , logEntry{logEntry}
 415   , beforeRss{Process::GetMemUsageMb() * 1024 * 1024}
 416 {
 417   if (g_clientStats) clientBefore = g_clientStats->copy();
 418
 419   profile_memory(what, "start", extra);
 420   if (!Trace::moduleEnabledRelease(Trace::hhbbc_time, 1)) return;
 421   Trace::ftraceRelease(
 422     "{}: {}: start{}\n"
 423     "  RSS: {}\n",
 424     ts<clock>(start),
 425     what,
 426     !extra.empty() ? folly::sformat(" ({})", extra) : extra,
 427     format_bytes(Process::GetMemUsageMb() * 1024 * 1024)
 428   );
 429 }
 430
 431 trace_time::~trace_time() {
 432   namespace C = std::chrono;
 433   auto const end = clock::now();
 434   auto const elapsed = C::duration_cast<C::milliseconds>(
 435     end - start
 436   );
 437
 438   auto const clientDiff = (g_clientStats && clientBefore)
 439     ? (*g_clientStats - *clientBefore)
 440     : nullptr;
 441
 442   profile_memory(what, "end", extra);
 443
 444   auto const afterRss = Process::GetMemUsageMb() * 1024 * 1024;
 445
 446   if (logEntry) {
 447     auto phase = folly::sformat("hhbbc_{}", what);
 448     while (true) {
 449       auto const pos = phase.find_first_of(" :\"'");
 450       if (pos == std::string::npos) break;
 451       phase[pos] = '_';
 452     }
 453
 454     logEntry->setInt(
 455       phase + "_micros",
 456       C::duration_cast<C::microseconds>(elapsed).count()
 457     );
 458     logEntry->setInt(phase + "_before_rss_bytes", beforeRss);
 459     logEntry->setInt(phase + "_after_rss_bytes", afterRss);
 460     logEntry->setInt(phase + "_rss_delta_bytes", afterRss - beforeRss);
 461     if (clientDiff) clientDiff->logSample(phase, *logEntry);
 462   }
 463
 464   if (!Trace::moduleEnabledRelease(Trace::hhbbc_time, 1)) return;
 465   Trace::ftraceRelease(
 466     "{}: {}: {} elapsed\n"
 467     "  RSS: {}\n{}",
 468     ts<clock>(end), what, format_duration(elapsed),
 469     format_bytes(afterRss),
 470     clientDiff ? client_stats(*clientDiff) : ""
 471   );
 472 }
 473
 474 void trace_time::ignore_client_stats() {
 475   clientBefore.reset();
 476 }
 477
 478 void trace_time::register_client_stats(extern_worker::Client::Stats::Ptr p) {
 479   g_clientStats = std::move(p);
 480 }
 481
 482 //////////////////////////////////////////////////////////////////////
 483
 484 }