js/src/gc/Statistics.cpp

Thu, 22 Jan 2015 13:21:57 +0100

author
Michael Schloh von Bennewitz <michael@schloh.com>
date
Thu, 22 Jan 2015 13:21:57 +0100
branch
TOR_BUG_9701
changeset 15
b8a032363ba2
permissions
-rw-r--r--

Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6

michael@0 1 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*-
michael@0 2 * vim: set ts=8 sts=4 et sw=4 tw=99:
michael@0 3 * This Source Code Form is subject to the terms of the Mozilla Public
michael@0 4 * License, v. 2.0. If a copy of the MPL was not distributed with this
michael@0 5 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
michael@0 6
michael@0 7 #include "gc/Statistics.h"
michael@0 8
michael@0 9 #include "mozilla/PodOperations.h"
michael@0 10
michael@0 11 #include <ctype.h>
michael@0 12 #include <stdarg.h>
michael@0 13 #include <stdio.h>
michael@0 14
michael@0 15 #include "jscrashreport.h"
michael@0 16 #include "jsprf.h"
michael@0 17 #include "jsutil.h"
michael@0 18 #include "prmjtime.h"
michael@0 19
michael@0 20 #include "gc/Memory.h"
michael@0 21 #include "vm/Runtime.h"
michael@0 22
michael@0 23 using namespace js;
michael@0 24 using namespace js::gcstats;
michael@0 25
michael@0 26 using mozilla::PodArrayZero;
michael@0 27
michael@0 28 /* Except for the first and last, slices of less than 42ms are not reported. */
michael@0 29 static const int64_t SLICE_MIN_REPORT_TIME = 42 * PRMJ_USEC_PER_MSEC;
michael@0 30
michael@0 31 class gcstats::StatisticsSerializer
michael@0 32 {
michael@0 33 typedef Vector<char, 128, SystemAllocPolicy> CharBuffer;
michael@0 34 CharBuffer buf_;
michael@0 35 bool asJSON_;
michael@0 36 bool needComma_;
michael@0 37 bool oom_;
michael@0 38
michael@0 39 static const int MaxFieldValueLength = 128;
michael@0 40
michael@0 41 public:
michael@0 42 enum Mode {
michael@0 43 AsJSON = true,
michael@0 44 AsText = false
michael@0 45 };
michael@0 46
michael@0 47 StatisticsSerializer(Mode asJSON)
michael@0 48 : buf_(), asJSON_(asJSON), needComma_(false), oom_(false)
michael@0 49 {}
michael@0 50
michael@0 51 bool isJSON() { return asJSON_; }
michael@0 52
michael@0 53 bool isOOM() { return oom_; }
michael@0 54
michael@0 55 void endLine() {
michael@0 56 if (!asJSON_) {
michael@0 57 p("\n");
michael@0 58 needComma_ = false;
michael@0 59 }
michael@0 60 }
michael@0 61
michael@0 62 void extra(const char *str) {
michael@0 63 if (!asJSON_) {
michael@0 64 needComma_ = false;
michael@0 65 p(str);
michael@0 66 }
michael@0 67 }
michael@0 68
michael@0 69 void appendString(const char *name, const char *value) {
michael@0 70 put(name, value, "", true);
michael@0 71 }
michael@0 72
michael@0 73 void appendNumber(const char *name, const char *vfmt, const char *units, ...) {
michael@0 74 va_list va;
michael@0 75 va_start(va, units);
michael@0 76 append(name, vfmt, va, units);
michael@0 77 va_end(va);
michael@0 78 }
michael@0 79
michael@0 80 void appendDecimal(const char *name, const char *units, double d) {
michael@0 81 if (d < 0)
michael@0 82 d = 0;
michael@0 83 if (asJSON_)
michael@0 84 appendNumber(name, "%d.%d", units, (int)d, (int)(d * 10.) % 10);
michael@0 85 else
michael@0 86 appendNumber(name, "%.1f", units, d);
michael@0 87 }
michael@0 88
michael@0 89 void appendIfNonzeroMS(const char *name, double v) {
michael@0 90 if (asJSON_ || v >= 0.1)
michael@0 91 appendDecimal(name, "ms", v);
michael@0 92 }
michael@0 93
michael@0 94 void beginObject(const char *name) {
michael@0 95 if (needComma_)
michael@0 96 pJSON(", ");
michael@0 97 if (asJSON_ && name) {
michael@0 98 putKey(name);
michael@0 99 pJSON(": ");
michael@0 100 }
michael@0 101 pJSON("{");
michael@0 102 needComma_ = false;
michael@0 103 }
michael@0 104
michael@0 105 void endObject() {
michael@0 106 needComma_ = false;
michael@0 107 pJSON("}");
michael@0 108 needComma_ = true;
michael@0 109 }
michael@0 110
michael@0 111 void beginArray(const char *name) {
michael@0 112 if (needComma_)
michael@0 113 pJSON(", ");
michael@0 114 if (asJSON_)
michael@0 115 putKey(name);
michael@0 116 pJSON(": [");
michael@0 117 needComma_ = false;
michael@0 118 }
michael@0 119
michael@0 120 void endArray() {
michael@0 121 needComma_ = false;
michael@0 122 pJSON("]");
michael@0 123 needComma_ = true;
michael@0 124 }
michael@0 125
michael@0 126 jschar *finishJSString() {
michael@0 127 char *buf = finishCString();
michael@0 128 if (!buf)
michael@0 129 return nullptr;
michael@0 130
michael@0 131 size_t nchars = strlen(buf);
michael@0 132 jschar *out = js_pod_malloc<jschar>(nchars + 1);
michael@0 133 if (!out) {
michael@0 134 oom_ = true;
michael@0 135 js_free(buf);
michael@0 136 return nullptr;
michael@0 137 }
michael@0 138
michael@0 139 InflateStringToBuffer(buf, nchars, out);
michael@0 140 js_free(buf);
michael@0 141
michael@0 142 out[nchars] = 0;
michael@0 143 return out;
michael@0 144 }
michael@0 145
michael@0 146 char *finishCString() {
michael@0 147 if (oom_)
michael@0 148 return nullptr;
michael@0 149
michael@0 150 buf_.append('\0');
michael@0 151
michael@0 152 char *buf = buf_.extractRawBuffer();
michael@0 153 if (!buf)
michael@0 154 oom_ = true;
michael@0 155
michael@0 156 return buf;
michael@0 157 }
michael@0 158
michael@0 159 private:
michael@0 160 void append(const char *name, const char *vfmt,
michael@0 161 va_list va, const char *units)
michael@0 162 {
michael@0 163 char val[MaxFieldValueLength];
michael@0 164 JS_vsnprintf(val, MaxFieldValueLength, vfmt, va);
michael@0 165 put(name, val, units, false);
michael@0 166 }
michael@0 167
michael@0 168 void p(const char *cstr) {
michael@0 169 if (oom_)
michael@0 170 return;
michael@0 171
michael@0 172 if (!buf_.append(cstr, strlen(cstr)))
michael@0 173 oom_ = true;
michael@0 174 }
michael@0 175
michael@0 176 void p(const char c) {
michael@0 177 if (oom_)
michael@0 178 return;
michael@0 179
michael@0 180 if (!buf_.append(c))
michael@0 181 oom_ = true;
michael@0 182 }
michael@0 183
michael@0 184 void pJSON(const char *str) {
michael@0 185 if (asJSON_)
michael@0 186 p(str);
michael@0 187 }
michael@0 188
michael@0 189 void put(const char *name, const char *val, const char *units, bool valueIsQuoted) {
michael@0 190 if (needComma_)
michael@0 191 p(", ");
michael@0 192 needComma_ = true;
michael@0 193
michael@0 194 putKey(name);
michael@0 195 p(": ");
michael@0 196 if (valueIsQuoted)
michael@0 197 putQuoted(val);
michael@0 198 else
michael@0 199 p(val);
michael@0 200 if (!asJSON_)
michael@0 201 p(units);
michael@0 202 }
michael@0 203
michael@0 204 void putQuoted(const char *str) {
michael@0 205 pJSON("\"");
michael@0 206 p(str);
michael@0 207 pJSON("\"");
michael@0 208 }
michael@0 209
michael@0 210 void putKey(const char *str) {
michael@0 211 if (!asJSON_) {
michael@0 212 p(str);
michael@0 213 return;
michael@0 214 }
michael@0 215
michael@0 216 p("\"");
michael@0 217 const char *c = str;
michael@0 218 while (*c) {
michael@0 219 if (*c == ' ' || *c == '\t')
michael@0 220 p('_');
michael@0 221 else if (isupper(*c))
michael@0 222 p(tolower(*c));
michael@0 223 else if (*c == '+')
michael@0 224 p("added_");
michael@0 225 else if (*c == '-')
michael@0 226 p("removed_");
michael@0 227 else if (*c != '(' && *c != ')')
michael@0 228 p(*c);
michael@0 229 c++;
michael@0 230 }
michael@0 231 p("\"");
michael@0 232 }
michael@0 233 };
michael@0 234
michael@0 235 /*
michael@0 236 * If this fails, then you can either delete this assertion and allow all
michael@0 237 * larger-numbered reasons to pile up in the last telemetry bucket, or switch
michael@0 238 * to GC_REASON_3 and bump the max value.
michael@0 239 */
michael@0 240 JS_STATIC_ASSERT(JS::gcreason::NUM_TELEMETRY_REASONS >= JS::gcreason::NUM_REASONS);
michael@0 241
michael@0 242 const char *
michael@0 243 js::gcstats::ExplainReason(JS::gcreason::Reason reason)
michael@0 244 {
michael@0 245 switch (reason) {
michael@0 246 #define SWITCH_REASON(name) \
michael@0 247 case JS::gcreason::name: \
michael@0 248 return #name;
michael@0 249 GCREASONS(SWITCH_REASON)
michael@0 250
michael@0 251 default:
michael@0 252 MOZ_ASSUME_UNREACHABLE("bad GC reason");
michael@0 253 #undef SWITCH_REASON
michael@0 254 }
michael@0 255 }
michael@0 256
michael@0 257 static double
michael@0 258 t(int64_t t)
michael@0 259 {
michael@0 260 return double(t) / PRMJ_USEC_PER_MSEC;
michael@0 261 }
michael@0 262
michael@0 263 struct PhaseInfo
michael@0 264 {
michael@0 265 Phase index;
michael@0 266 const char *name;
michael@0 267 Phase parent;
michael@0 268 };
michael@0 269
michael@0 270 static const Phase PHASE_NO_PARENT = PHASE_LIMIT;
michael@0 271
michael@0 272 static const PhaseInfo phases[] = {
michael@0 273 { PHASE_GC_BEGIN, "Begin Callback", PHASE_NO_PARENT },
michael@0 274 { PHASE_WAIT_BACKGROUND_THREAD, "Wait Background Thread", PHASE_NO_PARENT },
michael@0 275 { PHASE_MARK_DISCARD_CODE, "Mark Discard Code", PHASE_NO_PARENT },
michael@0 276 { PHASE_PURGE, "Purge", PHASE_NO_PARENT },
michael@0 277 { PHASE_MARK, "Mark", PHASE_NO_PARENT },
michael@0 278 { PHASE_MARK_ROOTS, "Mark Roots", PHASE_MARK },
michael@0 279 { PHASE_MARK_DELAYED, "Mark Delayed", PHASE_MARK },
michael@0 280 { PHASE_SWEEP, "Sweep", PHASE_NO_PARENT },
michael@0 281 { PHASE_SWEEP_MARK, "Mark During Sweeping", PHASE_SWEEP },
michael@0 282 { PHASE_SWEEP_MARK_TYPES, "Mark Types During Sweeping", PHASE_SWEEP_MARK },
michael@0 283 { PHASE_SWEEP_MARK_INCOMING_BLACK, "Mark Incoming Black Pointers", PHASE_SWEEP_MARK },
michael@0 284 { PHASE_SWEEP_MARK_WEAK, "Mark Weak", PHASE_SWEEP_MARK },
michael@0 285 { PHASE_SWEEP_MARK_INCOMING_GRAY, "Mark Incoming Gray Pointers", PHASE_SWEEP_MARK },
michael@0 286 { PHASE_SWEEP_MARK_GRAY, "Mark Gray", PHASE_SWEEP_MARK },
michael@0 287 { PHASE_SWEEP_MARK_GRAY_WEAK, "Mark Gray and Weak", PHASE_SWEEP_MARK },
michael@0 288 { PHASE_FINALIZE_START, "Finalize Start Callback", PHASE_SWEEP },
michael@0 289 { PHASE_SWEEP_ATOMS, "Sweep Atoms", PHASE_SWEEP },
michael@0 290 { PHASE_SWEEP_COMPARTMENTS, "Sweep Compartments", PHASE_SWEEP },
michael@0 291 { PHASE_SWEEP_DISCARD_CODE, "Sweep Discard Code", PHASE_SWEEP_COMPARTMENTS },
michael@0 292 { PHASE_SWEEP_TABLES, "Sweep Tables", PHASE_SWEEP_COMPARTMENTS },
michael@0 293 { PHASE_SWEEP_TABLES_WRAPPER, "Sweep Cross Compartment Wrappers", PHASE_SWEEP_TABLES },
michael@0 294 { PHASE_SWEEP_TABLES_BASE_SHAPE, "Sweep Base Shapes", PHASE_SWEEP_TABLES },
michael@0 295 { PHASE_SWEEP_TABLES_INITIAL_SHAPE, "Sweep Initial Shapes", PHASE_SWEEP_TABLES },
michael@0 296 { PHASE_SWEEP_TABLES_TYPE_OBJECT, "Sweep Type Objects", PHASE_SWEEP_TABLES },
michael@0 297 { PHASE_SWEEP_TABLES_BREAKPOINT, "Sweep Breakpoints", PHASE_SWEEP_TABLES },
michael@0 298 { PHASE_SWEEP_TABLES_REGEXP, "Sweep Regexps", PHASE_SWEEP_TABLES },
michael@0 299 { PHASE_DISCARD_ANALYSIS, "Discard Analysis", PHASE_SWEEP_COMPARTMENTS },
michael@0 300 { PHASE_DISCARD_TI, "Discard TI", PHASE_DISCARD_ANALYSIS },
michael@0 301 { PHASE_FREE_TI_ARENA, "Free TI Arena", PHASE_DISCARD_ANALYSIS },
michael@0 302 { PHASE_SWEEP_TYPES, "Sweep Types", PHASE_DISCARD_ANALYSIS },
michael@0 303 { PHASE_SWEEP_OBJECT, "Sweep Object", PHASE_SWEEP },
michael@0 304 { PHASE_SWEEP_STRING, "Sweep String", PHASE_SWEEP },
michael@0 305 { PHASE_SWEEP_SCRIPT, "Sweep Script", PHASE_SWEEP },
michael@0 306 { PHASE_SWEEP_SHAPE, "Sweep Shape", PHASE_SWEEP },
michael@0 307 { PHASE_SWEEP_JITCODE, "Sweep JIT code", PHASE_SWEEP },
michael@0 308 { PHASE_FINALIZE_END, "Finalize End Callback", PHASE_SWEEP },
michael@0 309 { PHASE_DESTROY, "Deallocate", PHASE_SWEEP },
michael@0 310 { PHASE_GC_END, "End Callback", PHASE_NO_PARENT },
michael@0 311 { PHASE_LIMIT, nullptr, PHASE_NO_PARENT }
michael@0 312 };
michael@0 313
michael@0 314 static void
michael@0 315 FormatPhaseTimes(StatisticsSerializer &ss, const char *name, int64_t *times)
michael@0 316 {
michael@0 317 ss.beginObject(name);
michael@0 318 for (unsigned i = 0; phases[i].name; i++)
michael@0 319 ss.appendIfNonzeroMS(phases[i].name, t(times[phases[i].index]));
michael@0 320 ss.endObject();
michael@0 321 }
michael@0 322
michael@0 323 void
michael@0 324 Statistics::gcDuration(int64_t *total, int64_t *maxPause)
michael@0 325 {
michael@0 326 *total = *maxPause = 0;
michael@0 327 for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
michael@0 328 *total += slice->duration();
michael@0 329 if (slice->duration() > *maxPause)
michael@0 330 *maxPause = slice->duration();
michael@0 331 }
michael@0 332 }
michael@0 333
michael@0 334 void
michael@0 335 Statistics::sccDurations(int64_t *total, int64_t *maxPause)
michael@0 336 {
michael@0 337 *total = *maxPause = 0;
michael@0 338 for (size_t i = 0; i < sccTimes.length(); i++) {
michael@0 339 *total += sccTimes[i];
michael@0 340 *maxPause = Max(*maxPause, sccTimes[i]);
michael@0 341 }
michael@0 342 }
michael@0 343
michael@0 344 bool
michael@0 345 Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
michael@0 346 {
michael@0 347 int64_t total, longest;
michael@0 348 gcDuration(&total, &longest);
michael@0 349
michael@0 350 int64_t sccTotal, sccLongest;
michael@0 351 sccDurations(&sccTotal, &sccLongest);
michael@0 352
michael@0 353 double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
michael@0 354 double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
michael@0 355
michael@0 356 ss.beginObject(nullptr);
michael@0 357 if (ss.isJSON())
michael@0 358 ss.appendNumber("Timestamp", "%llu", "", (unsigned long long)timestamp);
michael@0 359 if (slices.length() > 1 || ss.isJSON())
michael@0 360 ss.appendDecimal("Max Pause", "ms", t(longest));
michael@0 361 else
michael@0 362 ss.appendString("Reason", ExplainReason(slices[0].reason));
michael@0 363 ss.appendDecimal("Total Time", "ms", t(total));
michael@0 364 ss.appendNumber("Zones Collected", "%d", "", collectedCount);
michael@0 365 ss.appendNumber("Total Zones", "%d", "", zoneCount);
michael@0 366 ss.appendNumber("Total Compartments", "%d", "", compartmentCount);
michael@0 367 ss.appendNumber("Minor GCs", "%d", "", counts[STAT_MINOR_GC]);
michael@0 368 ss.appendNumber("MMU (20ms)", "%d", "%", int(mmu20 * 100));
michael@0 369 ss.appendNumber("MMU (50ms)", "%d", "%", int(mmu50 * 100));
michael@0 370 ss.appendDecimal("SCC Sweep Total", "ms", t(sccTotal));
michael@0 371 ss.appendDecimal("SCC Sweep Max Pause", "ms", t(sccLongest));
michael@0 372 if (nonincrementalReason || ss.isJSON()) {
michael@0 373 ss.appendString("Nonincremental Reason",
michael@0 374 nonincrementalReason ? nonincrementalReason : "none");
michael@0 375 }
michael@0 376 ss.appendNumber("Allocated", "%u", "MB", unsigned(preBytes / 1024 / 1024));
michael@0 377 ss.appendNumber("+Chunks", "%d", "", counts[STAT_NEW_CHUNK]);
michael@0 378 ss.appendNumber("-Chunks", "%d", "", counts[STAT_DESTROY_CHUNK]);
michael@0 379 ss.endLine();
michael@0 380
michael@0 381 if (slices.length() > 1 || ss.isJSON()) {
michael@0 382 ss.beginArray("Slices");
michael@0 383 for (size_t i = 0; i < slices.length(); i++) {
michael@0 384 int64_t width = slices[i].duration();
michael@0 385 if (i != 0 && i != slices.length() - 1 && width < SLICE_MIN_REPORT_TIME &&
michael@0 386 !slices[i].resetReason && !ss.isJSON())
michael@0 387 {
michael@0 388 continue;
michael@0 389 }
michael@0 390
michael@0 391 ss.beginObject(nullptr);
michael@0 392 ss.extra(" ");
michael@0 393 ss.appendNumber("Slice", "%d", "", i);
michael@0 394 ss.appendDecimal("Pause", "", t(width));
michael@0 395 ss.extra(" (");
michael@0 396 ss.appendDecimal("When", "ms", t(slices[i].start - slices[0].start));
michael@0 397 ss.appendString("Reason", ExplainReason(slices[i].reason));
michael@0 398 if (ss.isJSON()) {
michael@0 399 ss.appendDecimal("Page Faults", "",
michael@0 400 double(slices[i].endFaults - slices[i].startFaults));
michael@0 401
michael@0 402 ss.appendNumber("Start Timestamp", "%llu", "", (unsigned long long)slices[i].start);
michael@0 403 ss.appendNumber("End Timestamp", "%llu", "", (unsigned long long)slices[i].end);
michael@0 404 }
michael@0 405 if (slices[i].resetReason)
michael@0 406 ss.appendString("Reset", slices[i].resetReason);
michael@0 407 ss.extra("): ");
michael@0 408 FormatPhaseTimes(ss, "Times", slices[i].phaseTimes);
michael@0 409 ss.endLine();
michael@0 410 ss.endObject();
michael@0 411 }
michael@0 412 ss.endArray();
michael@0 413 }
michael@0 414 ss.extra(" Totals: ");
michael@0 415 FormatPhaseTimes(ss, "Totals", phaseTimes);
michael@0 416 ss.endObject();
michael@0 417
michael@0 418 return !ss.isOOM();
michael@0 419 }
michael@0 420
michael@0 421 jschar *
michael@0 422 Statistics::formatMessage()
michael@0 423 {
michael@0 424 StatisticsSerializer ss(StatisticsSerializer::AsText);
michael@0 425 formatData(ss, 0);
michael@0 426 return ss.finishJSString();
michael@0 427 }
michael@0 428
michael@0 429 jschar *
michael@0 430 Statistics::formatJSON(uint64_t timestamp)
michael@0 431 {
michael@0 432 StatisticsSerializer ss(StatisticsSerializer::AsJSON);
michael@0 433 formatData(ss, timestamp);
michael@0 434 return ss.finishJSString();
michael@0 435 }
michael@0 436
michael@0 437 Statistics::Statistics(JSRuntime *rt)
michael@0 438 : runtime(rt),
michael@0 439 startupTime(PRMJ_Now()),
michael@0 440 fp(nullptr),
michael@0 441 fullFormat(false),
michael@0 442 gcDepth(0),
michael@0 443 collectedCount(0),
michael@0 444 zoneCount(0),
michael@0 445 compartmentCount(0),
michael@0 446 nonincrementalReason(nullptr),
michael@0 447 preBytes(0),
michael@0 448 phaseNestingDepth(0)
michael@0 449 {
michael@0 450 PodArrayZero(phaseTotals);
michael@0 451 PodArrayZero(counts);
michael@0 452
michael@0 453 char *env = getenv("MOZ_GCTIMER");
michael@0 454 if (!env || strcmp(env, "none") == 0) {
michael@0 455 fp = nullptr;
michael@0 456 return;
michael@0 457 }
michael@0 458
michael@0 459 if (strcmp(env, "stdout") == 0) {
michael@0 460 fullFormat = false;
michael@0 461 fp = stdout;
michael@0 462 } else if (strcmp(env, "stderr") == 0) {
michael@0 463 fullFormat = false;
michael@0 464 fp = stderr;
michael@0 465 } else {
michael@0 466 fullFormat = true;
michael@0 467
michael@0 468 fp = fopen(env, "a");
michael@0 469 JS_ASSERT(fp);
michael@0 470 }
michael@0 471 }
michael@0 472
michael@0 473 Statistics::~Statistics()
michael@0 474 {
michael@0 475 if (fp) {
michael@0 476 if (fullFormat) {
michael@0 477 StatisticsSerializer ss(StatisticsSerializer::AsText);
michael@0 478 FormatPhaseTimes(ss, "", phaseTotals);
michael@0 479 char *msg = ss.finishCString();
michael@0 480 if (msg) {
michael@0 481 fprintf(fp, "TOTALS\n%s\n\n-------\n", msg);
michael@0 482 js_free(msg);
michael@0 483 }
michael@0 484 }
michael@0 485
michael@0 486 if (fp != stdout && fp != stderr)
michael@0 487 fclose(fp);
michael@0 488 }
michael@0 489 }
michael@0 490
michael@0 491 void
michael@0 492 Statistics::printStats()
michael@0 493 {
michael@0 494 if (fullFormat) {
michael@0 495 StatisticsSerializer ss(StatisticsSerializer::AsText);
michael@0 496 formatData(ss, 0);
michael@0 497 char *msg = ss.finishCString();
michael@0 498 if (msg) {
michael@0 499 fprintf(fp, "GC(T+%.3fs) %s\n", t(slices[0].start - startupTime) / 1000.0, msg);
michael@0 500 js_free(msg);
michael@0 501 }
michael@0 502 } else {
michael@0 503 int64_t total, longest;
michael@0 504 gcDuration(&total, &longest);
michael@0 505
michael@0 506 fprintf(fp, "%f %f %f\n",
michael@0 507 t(total),
michael@0 508 t(phaseTimes[PHASE_MARK]),
michael@0 509 t(phaseTimes[PHASE_SWEEP]));
michael@0 510 }
michael@0 511 fflush(fp);
michael@0 512 }
michael@0 513
michael@0 514 void
michael@0 515 Statistics::beginGC()
michael@0 516 {
michael@0 517 PodArrayZero(phaseStartTimes);
michael@0 518 PodArrayZero(phaseTimes);
michael@0 519
michael@0 520 slices.clearAndFree();
michael@0 521 sccTimes.clearAndFree();
michael@0 522 nonincrementalReason = nullptr;
michael@0 523
michael@0 524 preBytes = runtime->gcBytes;
michael@0 525 }
michael@0 526
michael@0 527 void
michael@0 528 Statistics::endGC()
michael@0 529 {
michael@0 530 crash::SnapshotGCStack();
michael@0 531
michael@0 532 for (int i = 0; i < PHASE_LIMIT; i++)
michael@0 533 phaseTotals[i] += phaseTimes[i];
michael@0 534
michael@0 535 if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback) {
michael@0 536 int64_t total, longest;
michael@0 537 gcDuration(&total, &longest);
michael@0 538
michael@0 539 int64_t sccTotal, sccLongest;
michael@0 540 sccDurations(&sccTotal, &sccLongest);
michael@0 541
michael@0 542 (*cb)(JS_TELEMETRY_GC_IS_COMPARTMENTAL, collectedCount == zoneCount ? 0 : 1);
michael@0 543 (*cb)(JS_TELEMETRY_GC_MS, t(total));
michael@0 544 (*cb)(JS_TELEMETRY_GC_MAX_PAUSE_MS, t(longest));
michael@0 545 (*cb)(JS_TELEMETRY_GC_MARK_MS, t(phaseTimes[PHASE_MARK]));
michael@0 546 (*cb)(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[PHASE_SWEEP]));
michael@0 547 (*cb)(JS_TELEMETRY_GC_MARK_ROOTS_MS, t(phaseTimes[PHASE_MARK_ROOTS]));
michael@0 548 (*cb)(JS_TELEMETRY_GC_MARK_GRAY_MS, t(phaseTimes[PHASE_SWEEP_MARK_GRAY]));
michael@0 549 (*cb)(JS_TELEMETRY_GC_NON_INCREMENTAL, !!nonincrementalReason);
michael@0 550 (*cb)(JS_TELEMETRY_GC_INCREMENTAL_DISABLED, !runtime->gcIncrementalEnabled);
michael@0 551 (*cb)(JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS, t(sccTotal));
michael@0 552 (*cb)(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest));
michael@0 553
michael@0 554 double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
michael@0 555 (*cb)(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
michael@0 556 }
michael@0 557
michael@0 558 if (fp)
michael@0 559 printStats();
michael@0 560 }
michael@0 561
michael@0 562 void
michael@0 563 Statistics::beginSlice(int collectedCount, int zoneCount, int compartmentCount,
michael@0 564 JS::gcreason::Reason reason)
michael@0 565 {
michael@0 566 this->collectedCount = collectedCount;
michael@0 567 this->zoneCount = zoneCount;
michael@0 568 this->compartmentCount = compartmentCount;
michael@0 569
michael@0 570 bool first = runtime->gcIncrementalState == gc::NO_INCREMENTAL;
michael@0 571 if (first)
michael@0 572 beginGC();
michael@0 573
michael@0 574 SliceData data(reason, PRMJ_Now(), gc::GetPageFaultCount());
michael@0 575 (void) slices.append(data); /* Ignore any OOMs here. */
michael@0 576
michael@0 577 if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback)
michael@0 578 (*cb)(JS_TELEMETRY_GC_REASON, reason);
michael@0 579
michael@0 580 // Slice callbacks should only fire for the outermost level
michael@0 581 if (++gcDepth == 1) {
michael@0 582 bool wasFullGC = collectedCount == zoneCount;
michael@0 583 if (JS::GCSliceCallback cb = runtime->gcSliceCallback)
michael@0 584 (*cb)(runtime, first ? JS::GC_CYCLE_BEGIN : JS::GC_SLICE_BEGIN,
michael@0 585 JS::GCDescription(!wasFullGC));
michael@0 586 }
michael@0 587 }
michael@0 588
michael@0 589 void
michael@0 590 Statistics::endSlice()
michael@0 591 {
michael@0 592 slices.back().end = PRMJ_Now();
michael@0 593 slices.back().endFaults = gc::GetPageFaultCount();
michael@0 594
michael@0 595 if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback) {
michael@0 596 (*cb)(JS_TELEMETRY_GC_SLICE_MS, t(slices.back().end - slices.back().start));
michael@0 597 (*cb)(JS_TELEMETRY_GC_RESET, !!slices.back().resetReason);
michael@0 598 }
michael@0 599
michael@0 600 bool last = runtime->gcIncrementalState == gc::NO_INCREMENTAL;
michael@0 601 if (last)
michael@0 602 endGC();
michael@0 603
michael@0 604 // Slice callbacks should only fire for the outermost level
michael@0 605 if (--gcDepth == 0) {
michael@0 606 bool wasFullGC = collectedCount == zoneCount;
michael@0 607 if (JS::GCSliceCallback cb = runtime->gcSliceCallback)
michael@0 608 (*cb)(runtime, last ? JS::GC_CYCLE_END : JS::GC_SLICE_END,
michael@0 609 JS::GCDescription(!wasFullGC));
michael@0 610 }
michael@0 611
michael@0 612 /* Do this after the slice callback since it uses these values. */
michael@0 613 if (last)
michael@0 614 PodArrayZero(counts);
michael@0 615 }
michael@0 616
michael@0 617 void
michael@0 618 Statistics::beginPhase(Phase phase)
michael@0 619 {
michael@0 620 /* Guard against re-entry */
michael@0 621 JS_ASSERT(!phaseStartTimes[phase]);
michael@0 622
michael@0 623 #ifdef DEBUG
michael@0 624 JS_ASSERT(phases[phase].index == phase);
michael@0 625 Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
michael@0 626 JS_ASSERT(phaseNestingDepth < MAX_NESTING);
michael@0 627 JS_ASSERT_IF(gcDepth == 1, phases[phase].parent == parent);
michael@0 628 phaseNesting[phaseNestingDepth] = phase;
michael@0 629 phaseNestingDepth++;
michael@0 630 #endif
michael@0 631
michael@0 632 phaseStartTimes[phase] = PRMJ_Now();
michael@0 633 }
michael@0 634
michael@0 635 void
michael@0 636 Statistics::endPhase(Phase phase)
michael@0 637 {
michael@0 638 phaseNestingDepth--;
michael@0 639
michael@0 640 int64_t t = PRMJ_Now() - phaseStartTimes[phase];
michael@0 641 slices.back().phaseTimes[phase] += t;
michael@0 642 phaseTimes[phase] += t;
michael@0 643 phaseStartTimes[phase] = 0;
michael@0 644 }
michael@0 645
michael@0 646 int64_t
michael@0 647 Statistics::beginSCC()
michael@0 648 {
michael@0 649 return PRMJ_Now();
michael@0 650 }
michael@0 651
michael@0 652 void
michael@0 653 Statistics::endSCC(unsigned scc, int64_t start)
michael@0 654 {
michael@0 655 if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1))
michael@0 656 return;
michael@0 657
michael@0 658 sccTimes[scc] += PRMJ_Now() - start;
michael@0 659 }
michael@0 660
michael@0 661 /*
michael@0 662 * MMU (minimum mutator utilization) is a measure of how much garbage collection
michael@0 663 * is affecting the responsiveness of the system. MMU measurements are given
michael@0 664 * with respect to a certain window size. If we report MMU(50ms) = 80%, then
michael@0 665 * that means that, for any 50ms window of time, at least 80% of the window is
michael@0 666 * devoted to the mutator. In other words, the GC is running for at most 20% of
michael@0 667 * the window, or 10ms. The GC can run multiple slices during the 50ms window
michael@0 668 * as long as the total time it spends is at most 10ms.
michael@0 669 */
michael@0 670 double
michael@0 671 Statistics::computeMMU(int64_t window)
michael@0 672 {
michael@0 673 JS_ASSERT(!slices.empty());
michael@0 674
michael@0 675 int64_t gc = slices[0].end - slices[0].start;
michael@0 676 int64_t gcMax = gc;
michael@0 677
michael@0 678 if (gc >= window)
michael@0 679 return 0.0;
michael@0 680
michael@0 681 int startIndex = 0;
michael@0 682 for (size_t endIndex = 1; endIndex < slices.length(); endIndex++) {
michael@0 683 gc += slices[endIndex].end - slices[endIndex].start;
michael@0 684
michael@0 685 while (slices[endIndex].end - slices[startIndex].end >= window) {
michael@0 686 gc -= slices[startIndex].end - slices[startIndex].start;
michael@0 687 startIndex++;
michael@0 688 }
michael@0 689
michael@0 690 int64_t cur = gc;
michael@0 691 if (slices[endIndex].end - slices[startIndex].start > window)
michael@0 692 cur -= (slices[endIndex].end - slices[startIndex].start - window);
michael@0 693 if (cur > gcMax)
michael@0 694 gcMax = cur;
michael@0 695 }
michael@0 696
michael@0 697 return double(window - gcMax) / window;
michael@0 698 }

mercurial