1 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*-
2 * vim: set ts=8 sts=2 et sw=2 tw=80:
3 * This Source Code Form is subject to the terms of the Mozilla Public
4 * License, v. 2.0. If a copy of the MPL was not distributed with this
5 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
6
7 #include "vm/TraceLogging.h"
8
9 #include "mozilla/EndianUtils.h"
10 #include "mozilla/MemoryReporting.h"
11
12 #include <algorithm>
13 #include <string.h>
14 #include <utility>
15
16 #include "jit/BaselineJIT.h"
17 #include "jit/CompileWrappers.h"
18 #include "jit/JitSpewer.h"
19 #include "js/friend/ErrorMessages.h" // js::GetErrorMessage, JSMSG_*
20 #include "js/Printf.h"
21 #include "js/TraceLoggerAPI.h"
22 #include "threading/LockGuard.h"
23 #include "util/GetPidProvider.h" // getpid()
24 #include "util/Text.h"
25 #include "vm/Activation.h" // js::ActivationIterator
26 #include "vm/FrameIter.h" // js::JitFrameIter
27 #include "vm/JSContext.h"
28 #include "vm/JSScript.h"
29 #include "vm/Runtime.h"
30 #include "vm/Time.h"
31 #include "vm/TraceLoggingGraph.h"
32
33 using namespace js;
34
35 static TraceLoggerThreadState* traceLoggerState = nullptr;
36
getTraceLoggerSupported()37 static bool getTraceLoggerSupported() {
38 char* str = getenv("JS_TRACE_LOGGING");
39
40 if (!str) {
41 // Default to unsupported.
42 return false;
43 }
44
45 if (strcmp(str, "false") == 0 || strcmp(str, "no") == 0 ||
46 strcmp(str, "0") == 0) {
47 return false;
48 }
49
50 if (strcmp(str, "true") == 0 || strcmp(str, "yes") == 0 ||
51 strcmp(str, "1") == 0) {
52 fprintf(stderr, "Warning: TraceLogger disabled temporarily, bug 1565788\n");
53 return false;
54 }
55
56 fprintf(stderr, "Warning: I didn't understand JS_TRACE_LOGGING=\"%s\"\n",
57 str);
58 return false;
59 }
60
SizeOfTraceLogState(mozilla::MallocSizeOf mallocSizeOf)61 size_t js::SizeOfTraceLogState(mozilla::MallocSizeOf mallocSizeOf) {
62 return traceLoggerState ? traceLoggerState->sizeOfIncludingThis(mallocSizeOf)
63 : 0;
64 }
65
ResetTraceLogger()66 void js::ResetTraceLogger() {
67 if (!traceLoggerState) {
68 return;
69 }
70
71 traceLoggerState->clear();
72 }
73
DestroyTraceLoggerThreadState()74 void js::DestroyTraceLoggerThreadState() {
75 if (traceLoggerState) {
76 js_delete(traceLoggerState);
77 traceLoggerState = nullptr;
78 }
79 }
80
81 #ifdef DEBUG
AssertCurrentThreadOwnsTraceLoggerThreadStateLock()82 void js::AssertCurrentThreadOwnsTraceLoggerThreadStateLock() {
83 if (traceLoggerState) {
84 traceLoggerState->lock.assertOwnedByCurrentThread();
85 }
86 }
87 #endif
88
DestroyTraceLogger(TraceLoggerThread * logger)89 void js::DestroyTraceLogger(TraceLoggerThread* logger) {
90 MOZ_ASSERT(traceLoggerState);
91 traceLoggerState->destroyLogger(logger);
92 }
93
init()94 bool TraceLoggerThread::init() {
95 if (!events_.init()) {
96 return false;
97 }
98
99 // Minimum amount of capacity needed for operation to allow flushing.
100 // Flushing requires space for the actual event and two spaces to log the
101 // start and stop of flushing.
102 if (!events_.ensureSpaceBeforeAdd(3)) {
103 return false;
104 }
105
106 char* buffer = js_pod_malloc<char>(32);
107 js::ThisThread::GetName(buffer, 32);
108 threadName_.reset(buffer);
109
110 return true;
111 }
112
initGraph()113 void TraceLoggerThread::initGraph() {
114 // Create a graph. I don't like this is called reset, but it locks the
115 // graph into the UniquePtr. So it gets deleted when TraceLoggerThread
116 // is destructed.
117 graph_.reset(js_new<TraceLoggerGraph>());
118 if (!graph_.get()) {
119 return;
120 }
121
122 MOZ_ASSERT(traceLoggerState);
123 bool graphFile = traceLoggerState->isGraphFileEnabled();
124 double delta =
125 traceLoggerState->getTimeStampOffset(mozilla::TimeStamp::NowUnfuzzed());
126 uint64_t start = static_cast<uint64_t>(delta);
127 if (!graph_->init(start, graphFile)) {
128 graph_ = nullptr;
129 return;
130 }
131
132 if (graphFile) {
133 // Report the textIds to the graph.
134 for (uint32_t i = 0; i < TraceLogger_TreeItemEnd; i++) {
135 TraceLoggerTextId id = TraceLoggerTextId(i);
136 graph_->addTextId(i, TLTextIdString(id));
137 }
138 graph_->addTextId(TraceLogger_TreeItemEnd, "TraceLogger internal");
139 for (uint32_t i = TraceLogger_TreeItemEnd + 1; i < TraceLogger_Last; i++) {
140 TraceLoggerTextId id = TraceLoggerTextId(i);
141 graph_->addTextId(i, TLTextIdString(id));
142 }
143 }
144 }
145
disableAllTextIds()146 void TraceLoggerThreadState::disableAllTextIds() {
147 for (uint32_t i = 1; i < TraceLogger_Last; i++) {
148 enabledTextIds[i] = false;
149 }
150 }
151
enableTextIdsForProfiler()152 void TraceLoggerThreadState::enableTextIdsForProfiler() {
153 enableDefaultLogging();
154 }
155
disableTextIdsForProfiler()156 void TraceLoggerThreadState::disableTextIdsForProfiler() {
157 disableAllTextIds();
158 // We have to keep the Baseline and IonMonkey id's alive because they control
159 // whether the jitted codegen has tracelogger start & stop events builtin.
160 // Otherwise, we end up in situations when some jitted code that was created
161 // before the profiler was even started ends up not starting and stoping any
162 // events. The TraceLogger_Engine stop events can accidentally stop the wrong
163 // event in this case, and then it's no longer possible to build a graph.
164 enabledTextIds[TraceLogger_Engine] = true;
165 enabledTextIds[TraceLogger_Interpreter] = true;
166 enabledTextIds[TraceLogger_Baseline] = true;
167 enabledTextIds[TraceLogger_IonMonkey] = true;
168 }
169
enableDefaultLogging()170 void TraceLoggerThreadState::enableDefaultLogging() {
171 enabledTextIds[TraceLogger_AnnotateScripts] = true;
172 enabledTextIds[TraceLogger_Bailout] = true;
173 enabledTextIds[TraceLogger_Baseline] = true;
174 enabledTextIds[TraceLogger_BaselineCompilation] = true;
175 enabledTextIds[TraceLogger_GC] = true;
176 enabledTextIds[TraceLogger_GCAllocation] = true;
177 enabledTextIds[TraceLogger_GCSweeping] = true;
178 enabledTextIds[TraceLogger_Interpreter] = true;
179 enabledTextIds[TraceLogger_IonAnalysis] = true;
180 enabledTextIds[TraceLogger_IonCompilation] = true;
181 enabledTextIds[TraceLogger_IonLinking] = true;
182 enabledTextIds[TraceLogger_IonMonkey] = true;
183 enabledTextIds[TraceLogger_MinorGC] = true;
184 enabledTextIds[TraceLogger_Frontend] = true;
185 enabledTextIds[TraceLogger_ParsingFull] = true;
186 enabledTextIds[TraceLogger_ParsingSyntax] = true;
187 enabledTextIds[TraceLogger_BytecodeEmission] = true;
188 enabledTextIds[TraceLogger_IrregexpCompile] = true;
189 enabledTextIds[TraceLogger_IrregexpExecute] = true;
190 enabledTextIds[TraceLogger_Scripts] = true;
191 enabledTextIds[TraceLogger_Engine] = true;
192 enabledTextIds[TraceLogger_WasmCompilation] = true;
193 enabledTextIds[TraceLogger_Invalidation] = true;
194 }
195
enableIonLogging()196 void TraceLoggerThreadState::enableIonLogging() {
197 enabledTextIds[TraceLogger_IonCompilation] = true;
198 enabledTextIds[TraceLogger_IonLinking] = true;
199 enabledTextIds[TraceLogger_PruneUnusedBranches] = true;
200 enabledTextIds[TraceLogger_FoldTests] = true;
201 enabledTextIds[TraceLogger_SplitCriticalEdges] = true;
202 enabledTextIds[TraceLogger_RenumberBlocks] = true;
203 enabledTextIds[TraceLogger_ScalarReplacement] = true;
204 enabledTextIds[TraceLogger_DominatorTree] = true;
205 enabledTextIds[TraceLogger_PhiAnalysis] = true;
206 enabledTextIds[TraceLogger_MakeLoopsContiguous] = true;
207 enabledTextIds[TraceLogger_ApplyTypes] = true;
208 enabledTextIds[TraceLogger_EagerSimdUnbox] = true;
209 enabledTextIds[TraceLogger_AliasAnalysis] = true;
210 enabledTextIds[TraceLogger_GVN] = true;
211 enabledTextIds[TraceLogger_LICM] = true;
212 enabledTextIds[TraceLogger_RangeAnalysis] = true;
213 enabledTextIds[TraceLogger_LoopUnrolling] = true;
214 enabledTextIds[TraceLogger_FoldLinearArithConstants] = true;
215 enabledTextIds[TraceLogger_EffectiveAddressAnalysis] = true;
216 enabledTextIds[TraceLogger_AlignmentMaskAnalysis] = true;
217 enabledTextIds[TraceLogger_EliminateDeadCode] = true;
218 enabledTextIds[TraceLogger_ReorderInstructions] = true;
219 enabledTextIds[TraceLogger_EdgeCaseAnalysis] = true;
220 enabledTextIds[TraceLogger_EliminateRedundantChecks] = true;
221 enabledTextIds[TraceLogger_AddKeepAliveInstructions] = true;
222 enabledTextIds[TraceLogger_GenerateLIR] = true;
223 enabledTextIds[TraceLogger_RegisterAllocation] = true;
224 enabledTextIds[TraceLogger_GenerateCode] = true;
225 enabledTextIds[TraceLogger_Scripts] = true;
226 }
227
enableFrontendLogging()228 void TraceLoggerThreadState::enableFrontendLogging() {
229 enabledTextIds[TraceLogger_Frontend] = true;
230 enabledTextIds[TraceLogger_ParsingFull] = true;
231 enabledTextIds[TraceLogger_ParsingSyntax] = true;
232 enabledTextIds[TraceLogger_BytecodeEmission] = true;
233 enabledTextIds[TraceLogger_BytecodeFoldConstants] = true;
234 enabledTextIds[TraceLogger_BytecodeNameFunctions] = true;
235 }
236
~TraceLoggerThread()237 TraceLoggerThread::~TraceLoggerThread() {
238 if (graph_.get()) {
239 if (!failed_) {
240 graph_->log(events_, traceLoggerState->startTime);
241 }
242 graph_ = nullptr;
243 }
244 }
245
enable()246 bool TraceLoggerThread::enable() {
247 if (enabled_ > 0) {
248 enabled_++;
249 return true;
250 }
251
252 if (failed_) {
253 return false;
254 }
255
256 enabled_ = 1;
257 logTimestamp(TraceLogger_Enable);
258
259 return true;
260 }
261
fail(JSContext * cx,const char * error)262 bool TraceLoggerThread::fail(JSContext* cx, const char* error) {
263 JS_ReportErrorNumberASCII(cx, GetErrorMessage, nullptr,
264 JSMSG_TRACELOGGER_ENABLE_FAIL, error);
265 failed_ = true;
266 enabled_ = 0;
267
268 return false;
269 }
270
silentFail(const char * error)271 void TraceLoggerThread::silentFail(const char* error) {
272 traceLoggerState->maybeSpewError(error);
273 failed_ = true;
274 enabled_ = 0;
275 }
276
sizeOfExcludingThis(mozilla::MallocSizeOf mallocSizeOf) const277 size_t TraceLoggerThread::sizeOfExcludingThis(
278 mozilla::MallocSizeOf mallocSizeOf) const {
279 size_t size = 0;
280 #ifdef DEBUG
281 size += graphStack_.sizeOfExcludingThis(mallocSizeOf);
282 #endif
283 size += events_.sizeOfExcludingThis(mallocSizeOf);
284 if (graph_.get()) {
285 size += graph_->sizeOfIncludingThis(mallocSizeOf);
286 }
287 return size;
288 }
289
sizeOfIncludingThis(mozilla::MallocSizeOf mallocSizeOf) const290 size_t TraceLoggerThread::sizeOfIncludingThis(
291 mozilla::MallocSizeOf mallocSizeOf) const {
292 return mallocSizeOf(this) + sizeOfExcludingThis(mallocSizeOf);
293 }
294
enable(JSContext * cx)295 bool TraceLoggerThread::enable(JSContext* cx) {
296 using namespace js::jit;
297
298 if (!enable()) {
299 return fail(cx, "internal error");
300 }
301
302 if (enabled_ == 1) {
303 // Get the top Activation to log the top script/pc (No inlined frames).
304 ActivationIterator iter(cx);
305 Activation* act = iter.activation();
306
307 if (!act) {
308 return fail(cx, "internal error");
309 }
310
311 JSScript* script = nullptr;
312 int32_t engine = 0;
313
314 if (act->isJit()) {
315 JitFrameIter frame(iter->asJit());
316
317 while (!frame.done()) {
318 if (frame.isWasm()) {
319 JS_ReportErrorNumberASCII(cx, GetErrorMessage, nullptr,
320 JSMSG_TRACELOGGER_ENABLE_FAIL,
321 "not yet supported in wasm code");
322 return false;
323 }
324 if (frame.asJSJit().isScripted()) {
325 break;
326 }
327 ++frame;
328 }
329
330 MOZ_ASSERT(!frame.done());
331
332 const JSJitFrameIter& jitFrame = frame.asJSJit();
333 MOZ_ASSERT(jitFrame.isIonJS() || jitFrame.isBaselineJS());
334
335 script = jitFrame.script();
336 engine =
337 jitFrame.isIonJS() ? TraceLogger_IonMonkey : TraceLogger_Baseline;
338 } else {
339 MOZ_ASSERT(act->isInterpreter());
340 InterpreterFrame* fp = act->asInterpreter()->current();
341 MOZ_ASSERT(!fp->runningInJit());
342
343 script = fp->script();
344 engine = TraceLogger_Interpreter;
345 }
346 if (script->compartment() != cx->compartment()) {
347 return fail(cx, "compartment mismatch");
348 }
349
350 TraceLoggerEvent event(TraceLogger_Scripts, script);
351 startEvent(event);
352 startEvent(engine);
353 }
354
355 return true;
356 }
357
disable(bool force,const char * error)358 bool TraceLoggerThread::disable(bool force, const char* error) {
359 if (failed_) {
360 MOZ_ASSERT(enabled_ == 0);
361 return false;
362 }
363
364 if (enabled_ == 0) {
365 return true;
366 }
367
368 if (enabled_ > 1 && !force) {
369 enabled_--;
370 return true;
371 }
372
373 if (force) {
374 traceLoggerState->maybeSpewError(error);
375 }
376
377 logTimestamp(TraceLogger_Disable);
378 enabled_ = 0;
379
380 return true;
381 }
382
maybeEventText(uint32_t id)383 const char* TraceLoggerThread::maybeEventText(uint32_t id) {
384 if (TLTextIdIsEnumEvent(id)) {
385 return TLTextIdString(static_cast<TraceLoggerTextId>(id));
386 }
387 return traceLoggerState->maybeEventText(id);
388 }
389
getPayload(uint32_t id)390 TraceLoggerEventPayload* TraceLoggerThreadState::getPayload(uint32_t id) {
391 if (TLTextIdIsEnumEvent(id)) {
392 return nullptr;
393 }
394
395 TextIdToPayloadMap::Ptr p = textIdPayloads.lookup(id);
396 if (!p) {
397 return nullptr;
398 }
399
400 p->value()->use();
401 return p->value();
402 }
403
maybeEventText(uint32_t id)404 const char* TraceLoggerThreadState::maybeEventText(uint32_t id) {
405 LockGuard<Mutex> guard(lock);
406
407 TextIdToPayloadMap::Ptr p = textIdPayloads.lookup(id);
408 if (!p) {
409 return nullptr;
410 }
411
412 uint32_t dictId = p->value()->dictionaryId();
413 MOZ_ASSERT(dictId < nextDictionaryId);
414 return dictionaryData[dictId].get();
415 }
416
maybeEventText(TraceLoggerEventPayload * p)417 const char* TraceLoggerThreadState::maybeEventText(TraceLoggerEventPayload* p) {
418 LockGuard<Mutex> guard(lock);
419 if (!p) {
420 return nullptr;
421 }
422
423 uint32_t dictId = p->dictionaryId();
424 MOZ_ASSERT(dictId < nextDictionaryId);
425 return dictionaryData[dictId].get();
426 }
427
sizeOfExcludingThis(mozilla::MallocSizeOf mallocSizeOf)428 size_t TraceLoggerThreadState::sizeOfExcludingThis(
429 mozilla::MallocSizeOf mallocSizeOf) {
430 LockGuard<Mutex> guard(lock);
431
432 // Do not count threadLoggers since they are counted by
433 // JSContext::traceLogger.
434
435 size_t size = 0;
436 size += dictionaryData.sizeOfExcludingThis(mallocSizeOf);
437 size += payloadDictionary.shallowSizeOfExcludingThis(mallocSizeOf);
438 size += textIdPayloads.shallowSizeOfExcludingThis(mallocSizeOf);
439 for (TextIdToPayloadMap::Range r = textIdPayloads.all(); !r.empty();
440 r.popFront()) {
441 r.front().value()->sizeOfIncludingThis(mallocSizeOf);
442 }
443
444 return size;
445 }
446
getOrCreateEventPayload(const char * text)447 TraceLoggerEventPayload* TraceLoggerThreadState::getOrCreateEventPayload(
448 const char* text) {
449 LockGuard<Mutex> guard(lock);
450
451 uint32_t dictId = nextDictionaryId;
452
453 StringHashToDictionaryMap::AddPtr dictp =
454 payloadDictionary.lookupForAdd(text);
455 if (dictp) {
456 dictId = dictp->value();
457 MOZ_ASSERT(dictId < nextDictionaryId); // Sanity check.
458 } else {
459 UniqueChars str = DuplicateString(text);
460 if (!str) {
461 return nullptr;
462 }
463 if (!payloadDictionary.add(dictp, str.get(), nextDictionaryId)) {
464 return nullptr;
465 }
466 if (!dictionaryData.append(std::move(str))) {
467 return nullptr;
468 }
469
470 nextDictionaryId++;
471 }
472
473 // Look for a free entry, as some textId's may
474 // already be taken from previous profiling sessions.
475 while (textIdPayloads.has(nextTextId)) {
476 nextTextId++;
477 }
478
479 auto* payload = js_new<TraceLoggerEventPayload>(nextTextId, dictId);
480 if (!payload) {
481 return nullptr;
482 }
483
484 if (!textIdPayloads.putNew(nextTextId, payload)) {
485 js_delete(payload);
486 return nullptr;
487 }
488
489 payload->use();
490
491 nextTextId++;
492
493 return payload;
494 }
495
getOrCreateEventPayload(const char * filename,uint32_t lineno,uint32_t colno)496 TraceLoggerEventPayload* TraceLoggerThreadState::getOrCreateEventPayload(
497 const char* filename, uint32_t lineno, uint32_t colno) {
498 if (!filename) {
499 filename = "<unknown>";
500 }
501
502 TraceLoggerEventPayload* payload = getOrCreateEventPayload(filename);
503 if (!payload) {
504 return nullptr;
505 }
506
507 payload->setLine(lineno);
508 payload->setColumn(colno);
509
510 return payload;
511 }
512
getOrCreateEventPayload(JSScript * script)513 TraceLoggerEventPayload* TraceLoggerThreadState::getOrCreateEventPayload(
514 JSScript* script) {
515 return getOrCreateEventPayload(script->filename(), script->lineno(),
516 script->column());
517 }
518
purgeUnusedPayloads()519 void TraceLoggerThreadState::purgeUnusedPayloads() {
520 // Care needs to be taken to maintain a coherent state in this function,
521 // as payloads can have their use count change at any time from non-zero to
522 // zero (but not the other way around; see TraceLoggerEventPayload::use()).
523 LockGuard<Mutex> guard(lock);
524
525 // Free all other payloads that have no uses anymore.
526 for (TextIdToPayloadMap::Enum e(textIdPayloads); !e.empty(); e.popFront()) {
527 if (e.front().value()->uses() == 0) {
528 uint32_t dictId = e.front().value()->dictionaryId();
529 dictionaryData.erase(dictionaryData.begin() + dictId);
530 js_delete(e.front().value());
531 e.removeFront();
532 }
533 }
534 }
535
startEvent(TraceLoggerTextId id)536 void TraceLoggerThread::startEvent(TraceLoggerTextId id) {
537 startEvent(uint32_t(id));
538 }
539
startEvent(const TraceLoggerEvent & event)540 void TraceLoggerThread::startEvent(const TraceLoggerEvent& event) {
541 if (!event.hasTextId()) {
542 if (!enabled()) {
543 return;
544 }
545 startEvent(TraceLogger_Error);
546 disable(/* force = */ true,
547 "TraceLogger encountered an empty event. "
548 "Potentially due to OOM during creation of "
549 "this event. Disabling TraceLogger.");
550 return;
551 }
552 startEvent(event.textId());
553 }
554
startEvent(uint32_t id)555 void TraceLoggerThread::startEvent(uint32_t id) {
556 if (!jit::JitOptions.enableTraceLogger) {
557 return;
558 }
559
560 MOZ_ASSERT(TLTextIdIsTreeEvent(id) || id == TraceLogger_Error);
561 MOZ_ASSERT(traceLoggerState);
562 if (!traceLoggerState->isTextIdEnabled(id)) {
563 return;
564 }
565
566 #ifdef DEBUG
567 if (enabled_ > 0) {
568 AutoEnterOOMUnsafeRegion oomUnsafe;
569 if (!graphStack_.append(id)) {
570 oomUnsafe.crash("Could not add item to debug stack.");
571 }
572 }
573 #endif
574
575 if (graph_.get() && traceLoggerState->isGraphFileEnabled()) {
576 // Flush each textId to disk. textId values up to TraceLogger_Last are
577 // statically defined and each one has an associated constant event string
578 // defined by TLTextIdString(). For any events with textId >=
579 // TraceLogger_Last the payload associated with that textId must first be
580 // found and then maybeEventText() will find the event string form the
581 // dictionary.
582 for (uint32_t otherId = graph_->nextTextId(); otherId <= id; otherId++) {
583 if (TLTextIdIsEnumEvent(id)) {
584 const char* text = TLTextIdString(static_cast<TraceLoggerTextId>(id));
585 graph_->addTextId(otherId, text);
586 } else {
587 TraceLoggerEventPayload* p = traceLoggerState->getPayload(id);
588 if (p) {
589 const char* filename = traceLoggerState->maybeEventText(p);
590 mozilla::Maybe<uint32_t> line = p->line();
591 mozilla::Maybe<uint32_t> column = p->column();
592 graph_->addTextId(otherId, filename, line, column);
593 p->release();
594 }
595 }
596 }
597 }
598
599 log(id);
600 }
601
stopEvent(TraceLoggerTextId id)602 void TraceLoggerThread::stopEvent(TraceLoggerTextId id) {
603 stopEvent(uint32_t(id));
604 }
605
stopEvent(const TraceLoggerEvent & event)606 void TraceLoggerThread::stopEvent(const TraceLoggerEvent& event) {
607 if (!event.hasTextId()) {
608 stopEvent(TraceLogger_Error);
609 return;
610 }
611 stopEvent(event.textId());
612 }
613
stopEvent(uint32_t id)614 void TraceLoggerThread::stopEvent(uint32_t id) {
615 if (!jit::JitOptions.enableTraceLogger) {
616 return;
617 }
618
619 MOZ_ASSERT(TLTextIdIsTreeEvent(id) || id == TraceLogger_Error);
620 MOZ_ASSERT(traceLoggerState);
621 if (!traceLoggerState->isTextIdEnabled(id)) {
622 return;
623 }
624
625 #ifdef DEBUG
626 if (!graphStack_.empty()) {
627 uint32_t prev = graphStack_.popCopy();
628 if (id == TraceLogger_Error || prev == TraceLogger_Error) {
629 // When encountering an Error id the stack will most likely not be correct
630 // anymore. Ignore this.
631 } else if (id == TraceLogger_Engine) {
632 MOZ_ASSERT(prev == TraceLogger_IonMonkey ||
633 prev == TraceLogger_Baseline ||
634 prev == TraceLogger_Interpreter);
635 } else if (id == TraceLogger_Scripts) {
636 MOZ_ASSERT(TLTextIdIsScriptEvent(prev));
637 } else if (TLTextIdIsScriptEvent(id)) {
638 MOZ_ASSERT(TLTextIdIsScriptEvent(prev));
639 if (prev != id) {
640 // Ignore if the text has been flushed already.
641 MOZ_ASSERT_IF(maybeEventText(prev),
642 strcmp(maybeEventText(id), maybeEventText(prev)) == 0);
643 }
644 } else {
645 MOZ_ASSERT(id == prev);
646 }
647 }
648 #endif
649
650 log(TraceLogger_Stop);
651 }
652
AutoTraceLoggerLockGuard()653 JS::AutoTraceLoggerLockGuard::AutoTraceLoggerLockGuard() {
654 traceLoggerState->lock.lock();
655 }
656
~AutoTraceLoggerLockGuard()657 JS::AutoTraceLoggerLockGuard::~AutoTraceLoggerLockGuard() {
658 traceLoggerState->lock.unlock();
659 }
660
NextChunk(JSContext * cx,size_t * dataIndex,char buffer[],size_t bufferSize)661 size_t JS::TraceLoggerDictionaryImpl::NextChunk(JSContext* cx,
662 size_t* dataIndex,
663 char buffer[],
664 size_t bufferSize) {
665 MOZ_ASSERT(dataIndex != nullptr);
666 if (!traceLoggerState || bufferSize == 0 || !buffer ||
667 !jit::JitOptions.enableTraceLogger) {
668 return 0;
669 }
670
671 size_t bufferIndex = 0;
672
673 const char* eventString = nullptr;
674 if (TLTextIdIsEnumEvent(*dataIndex)) {
675 eventString = TLTextIdString(static_cast<TraceLoggerTextId>(*dataIndex));
676 } else {
677 uint32_t dictId = *dataIndex - TraceLogger_Last;
678 if (dictId < traceLoggerState->dictionaryData.length()) {
679 eventString = traceLoggerState->dictionaryData[dictId].get();
680 MOZ_ASSERT(eventString);
681 }
682 }
683
684 if (eventString) {
685 size_t length = strlen(eventString);
686 if (length < bufferSize - 1) {
687 memcpy(buffer, eventString, length);
688 buffer[length] = '\0';
689 bufferIndex = length;
690 } else {
691 memcpy(buffer, eventString, bufferSize);
692 buffer[bufferSize - 1] = '\0';
693 bufferIndex = bufferSize - 1;
694 }
695 }
696
697 (*dataIndex)++;
698 return bufferIndex;
699 }
700
NextChunk(JSContext * cx,size_t * dataIndex,uint32_t buffer[],size_t bufferSize)701 size_t JS::TraceLoggerIdImpl::NextChunk(JSContext* cx, size_t* dataIndex,
702 uint32_t buffer[], size_t bufferSize) {
703 MOZ_ASSERT(dataIndex != nullptr);
704 if (!cx || !cx->traceLogger) {
705 return 0;
706 }
707
708 if (bufferSize == 0 || !buffer || !jit::JitOptions.enableTraceLogger) {
709 return 0;
710 }
711
712 size_t bufferIndex = 0;
713 ContinuousSpace<EventEntry>& events = cx->traceLogger->events_;
714
715 for (; *dataIndex < events.size(); (*dataIndex)++) {
716 if (TLTextIdIsInternalEvent(events[*dataIndex].textId)) {
717 continue;
718 }
719
720 if (TLTextIdIsScriptEvent(events[*dataIndex].textId)) {
721 TraceLoggerEventPayload* payload =
722 traceLoggerState->getPayload(events[*dataIndex].textId);
723 MOZ_ASSERT(payload);
724 if (!payload) {
725 return 0;
726 }
727 // Write the index of this event into the jsTracerDictionary array
728 // property
729 uint32_t dictId = TraceLogger_Last + payload->dictionaryId();
730 buffer[bufferIndex++] = dictId;
731 payload->release();
732 } else {
733 buffer[bufferIndex++] = events[*dataIndex].textId;
734 }
735
736 if (bufferIndex == bufferSize) {
737 break;
738 }
739 }
740
741 return bufferIndex;
742 }
743
NextChunk(JSContext * cx,size_t * dataIndex,int32_t buffer[],size_t bufferSize)744 size_t JS::TraceLoggerLineNoImpl::NextChunk(JSContext* cx, size_t* dataIndex,
745 int32_t buffer[],
746 size_t bufferSize) {
747 MOZ_ASSERT(dataIndex != nullptr);
748 if (!cx || !cx->traceLogger) {
749 return 0;
750 }
751
752 if (bufferSize == 0 || !buffer || !jit::JitOptions.enableTraceLogger) {
753 return 0;
754 }
755
756 size_t bufferIndex = 0;
757 ContinuousSpace<EventEntry>& events = cx->traceLogger->events_;
758
759 for (; *dataIndex < events.size(); (*dataIndex)++) {
760 if (TLTextIdIsInternalEvent(events[*dataIndex].textId)) {
761 continue;
762 }
763
764 if (TLTextIdIsScriptEvent(events[*dataIndex].textId)) {
765 TraceLoggerEventPayload* payload =
766 traceLoggerState->getPayload(events[*dataIndex].textId);
767 MOZ_ASSERT(payload);
768 if (!payload) {
769 return 0;
770 }
771 mozilla::Maybe<uint32_t> line = payload->line();
772 payload->release();
773 if (line) {
774 buffer[bufferIndex++] = *line;
775 } else {
776 buffer[bufferIndex++] = -1;
777 }
778 } else {
779 buffer[bufferIndex++] = -1;
780 }
781 if (bufferIndex == bufferSize) {
782 break;
783 }
784 }
785
786 return bufferIndex;
787 }
788
NextChunk(JSContext * cx,size_t * dataIndex,int32_t buffer[],size_t bufferSize)789 size_t JS::TraceLoggerColNoImpl::NextChunk(JSContext* cx, size_t* dataIndex,
790 int32_t buffer[],
791 size_t bufferSize) {
792 MOZ_ASSERT(dataIndex != nullptr);
793 if (!cx || !cx->traceLogger) {
794 return 0;
795 }
796
797 if (bufferSize == 0 || !buffer || !jit::JitOptions.enableTraceLogger) {
798 return 0;
799 }
800
801 size_t bufferIndex = 0;
802 ContinuousSpace<EventEntry>& events = cx->traceLogger->events_;
803
804 for (; *dataIndex < events.size(); (*dataIndex)++) {
805 if (TLTextIdIsInternalEvent(events[*dataIndex].textId)) {
806 continue;
807 }
808
809 if (TLTextIdIsScriptEvent(events[*dataIndex].textId)) {
810 TraceLoggerEventPayload* payload =
811 traceLoggerState->getPayload(events[*dataIndex].textId);
812 MOZ_ASSERT(payload);
813 if (!payload) {
814 return 0;
815 }
816 mozilla::Maybe<uint32_t> column = payload->column();
817 payload->release();
818 if (column) {
819 buffer[bufferIndex++] = *column;
820 } else {
821 buffer[bufferIndex++] = -1;
822 }
823 } else {
824 buffer[bufferIndex++] = -1;
825 }
826 if (bufferIndex == bufferSize) {
827 break;
828 }
829 }
830
831 return bufferIndex;
832 }
833
NextChunk(JSContext * cx,size_t * dataIndex,mozilla::TimeStamp buffer[],size_t bufferSize)834 size_t JS::TraceLoggerTimeStampImpl::NextChunk(JSContext* cx, size_t* dataIndex,
835 mozilla::TimeStamp buffer[],
836 size_t bufferSize) {
837 MOZ_ASSERT(dataIndex != nullptr);
838 if (!cx || !cx->traceLogger) {
839 return 0;
840 }
841
842 if (bufferSize == 0 || !buffer || !jit::JitOptions.enableTraceLogger) {
843 return 0;
844 }
845
846 size_t bufferIndex = 0;
847 ContinuousSpace<EventEntry>& events = cx->traceLogger->events_;
848
849 for (; *dataIndex < events.size(); (*dataIndex)++) {
850 if (TLTextIdIsInternalEvent(events[*dataIndex].textId)) {
851 continue;
852 }
853 buffer[bufferIndex++] = events[*dataIndex].time;
854 if (bufferIndex == bufferSize) {
855 break;
856 }
857 }
858
859 return bufferIndex;
860 }
861
NextChunk(JSContext * cx,size_t * dataIndex,double buffer[],size_t bufferSize)862 size_t JS::TraceLoggerDurationImpl::NextChunk(JSContext* cx, size_t* dataIndex,
863 double buffer[],
864 size_t bufferSize) {
865 MOZ_ASSERT(dataIndex != nullptr);
866 if (!cx || !cx->traceLogger) {
867 return 0;
868 }
869
870 if (bufferSize == 0 || !buffer || !jit::JitOptions.enableTraceLogger) {
871 return 0;
872 }
873
874 ContinuousSpace<EventEntry>& events = cx->traceLogger->events_;
875 Vector<size_t, 0, js::SystemAllocPolicy> eventStack;
876 using EventDurationMap =
877 HashMap<size_t, double, DefaultHasher<size_t>, SystemAllocPolicy>;
878 EventDurationMap eventMap;
879
880 size_t bufferIndex = 0;
881 for (; *dataIndex < events.size(); (*dataIndex)++) {
882 if (TLTextIdIsInternalEvent(events[*dataIndex].textId)) {
883 continue;
884 }
885 double duration = 0;
886 if (TLTextIdIsLogEvent(events[*dataIndex].textId)) {
887 // log events are snapshot events with no start & stop
888 duration = -1;
889 } else if (EventDurationMap::Ptr p = eventMap.lookup(*dataIndex)) {
890 // value has already been cached
891 duration = p->value();
892 } else {
893 MOZ_ASSERT(eventStack.empty());
894 if (!eventStack.append(*dataIndex)) {
895 return 0;
896 }
897
898 // Search through the events array to find the matching stop event in
899 // order to calculate the duration time. Cache all other durations we
900 // calculate in the meantime.
901 for (size_t j = *dataIndex + 1; j < events.size(); j++) {
902 uint32_t id = events[j].textId;
903 if (id == TraceLogger_Stop) {
904 uint32_t prev = eventStack.popCopy();
905 double delta = (events[j].time - events[prev].time).ToMicroseconds();
906 if (prev == *dataIndex) {
907 MOZ_ASSERT(eventStack.empty());
908 duration = delta;
909 break;
910 }
911
912 if (!eventMap.putNew(prev, delta)) {
913 return 0;
914 }
915
916 } else if (TLTextIdIsTreeEvent(id)) {
917 if (!eventStack.append(j)) {
918 return 0;
919 }
920 }
921
922 // If we reach the end of the list, use the last event as the end
923 // event for all events remaining on the stack.
924 if (j == events.size() - 1) {
925 while (!eventStack.empty()) {
926 uint32_t prev = eventStack.popCopy();
927 double delta =
928 (events[j].time - events[prev].time).ToMicroseconds();
929 if (prev == *dataIndex) {
930 MOZ_ASSERT(eventStack.empty());
931 duration = delta;
932 } else {
933 if (!eventMap.putNew(prev, delta)) {
934 return 0;
935 }
936 }
937 }
938 }
939 }
940 }
941
942 buffer[bufferIndex++] = duration;
943 if (bufferIndex == bufferSize) {
944 break;
945 }
946 }
947
948 return bufferIndex;
949 }
950
logTimestamp(TraceLoggerTextId id)951 void TraceLoggerThread::logTimestamp(TraceLoggerTextId id) {
952 logTimestamp(uint32_t(id));
953 }
954
logTimestamp(uint32_t id)955 void TraceLoggerThread::logTimestamp(uint32_t id) {
956 MOZ_ASSERT(id > TraceLogger_TreeItemEnd && id < TraceLogger_Last);
957 log(id);
958 }
959
log(uint32_t id)960 void TraceLoggerThread::log(uint32_t id) {
961 if (enabled_ == 0) {
962 return;
963 }
964
965 #ifdef DEBUG
966 if (id == TraceLogger_Disable) {
967 graphStack_.clear();
968 }
969 #endif
970
971 MOZ_ASSERT(traceLoggerState);
972
973 // We request for 3 items to add, since if we don't have enough room
974 // we record the time it took to make more space. To log this information
975 // we need 2 extra free entries.
976 if (!events_.hasSpaceForAdd(3)) {
977 mozilla::TimeStamp start = mozilla::TimeStamp::NowUnfuzzed();
978
979 if (!events_.ensureSpaceBeforeAdd(3)) {
980 if (graph_.get()) {
981 graph_->log(events_, traceLoggerState->startTime);
982 }
983
984 // The data structures are full, and the graph file is not enabled
985 // so we cannot flush to disk. Trace logging should stop here.
986 if (!traceLoggerState->isGraphFileEnabled()) {
987 enabled_ = 0;
988 return;
989 }
990
991 iteration_++;
992 events_.clear();
993
994 // Periodically remove unused payloads from the global logger state.
995 traceLoggerState->purgeUnusedPayloads();
996 }
997
998 // Log the time it took to flush the events_ as being from the
999 // Tracelogger.
1000 if (graph_.get()) {
1001 MOZ_ASSERT(events_.hasSpaceForAdd(2));
1002 EventEntry& entryStart = events_.pushUninitialized();
1003 entryStart.time = start;
1004 entryStart.textId = TraceLogger_Internal;
1005
1006 EventEntry& entryStop = events_.pushUninitialized();
1007 entryStop.time = mozilla::TimeStamp::NowUnfuzzed();
1008 entryStop.textId = TraceLogger_Stop;
1009 }
1010 }
1011
1012 mozilla::TimeStamp time = mozilla::TimeStamp::NowUnfuzzed();
1013
1014 EventEntry& entry = events_.pushUninitialized();
1015 entry.time = time;
1016 entry.textId = id;
1017 }
1018
remapDictionaryEntries(mozilla::Vector<UniqueChars,0,SystemAllocPolicy> * newDictionary,uint32_t * newNextDictionaryId)1019 bool TraceLoggerThreadState::remapDictionaryEntries(
1020 mozilla::Vector<UniqueChars, 0, SystemAllocPolicy>* newDictionary,
1021 uint32_t* newNextDictionaryId) {
1022 MOZ_ASSERT(newNextDictionaryId != nullptr && newDictionary != nullptr);
1023
1024 typedef HashMap<uint32_t, uint32_t, DefaultHasher<uint32_t>,
1025 SystemAllocPolicy>
1026 DictionaryMap;
1027 DictionaryMap dictionaryMap;
1028
1029 // Clear all payloads that are not currently used. There may be some events
1030 // that still hold a pointer to a payload. Restarting the profiler may reuse
1031 // the exact same event as a previous session if it's still alive so we need
1032 // to maintain it's existence.
1033 for (TextIdToPayloadMap::Enum e(textIdPayloads); !e.empty(); e.popFront()) {
1034 if (e.front().value()->uses() == 0) {
1035 js_delete(e.front().value());
1036 e.removeFront();
1037 } else {
1038 TraceLoggerEventPayload* payload = e.front().value();
1039 uint32_t dictId = payload->dictionaryId();
1040
1041 if (dictionaryMap.has(dictId)) {
1042 DictionaryMap::Ptr mapPointer = dictionaryMap.lookup(dictId);
1043 MOZ_ASSERT(mapPointer);
1044 payload->setDictionaryId(mapPointer->value());
1045 } else {
1046 if (!newDictionary->append(std::move(dictionaryData[dictId]))) {
1047 return false;
1048 }
1049 payload->setDictionaryId(*newNextDictionaryId);
1050
1051 if (!dictionaryMap.putNew(dictId, *newNextDictionaryId)) {
1052 return false;
1053 }
1054
1055 (*newNextDictionaryId)++;
1056 }
1057 }
1058 }
1059
1060 return true;
1061 }
1062
clear()1063 void TraceLoggerThreadState::clear() {
1064 LockGuard<Mutex> guard(lock);
1065
1066 uint32_t newNextDictionaryId = 0;
1067 mozilla::Vector<UniqueChars, 0, SystemAllocPolicy> newDictionary;
1068 if (remapDictionaryEntries(&newDictionary, &newNextDictionaryId)) {
1069 // Clear and free any data used for the string dictionary.
1070 for (auto range = dictionaryData.all(); !range.empty(); range.popFront()) {
1071 range.front().reset();
1072 }
1073 dictionaryData.clearAndFree();
1074 dictionaryData = std::move(newDictionary);
1075
1076 payloadDictionary.clearAndCompact();
1077
1078 nextTextId = TraceLogger_Last;
1079 nextDictionaryId = newNextDictionaryId;
1080 }
1081
1082 for (TraceLoggerThread* logger : threadLoggers) {
1083 logger->clear();
1084 }
1085 }
1086
clear()1087 void TraceLoggerThread::clear() {
1088 if (graph_.get()) {
1089 graph_.reset();
1090 }
1091
1092 graph_ = nullptr;
1093
1094 #ifdef DEBUG
1095 graphStack_.clear();
1096 #endif
1097
1098 if (!events_.reset()) {
1099 silentFail("Cannot reset event buffer.");
1100 }
1101 }
1102
~TraceLoggerThreadState()1103 TraceLoggerThreadState::~TraceLoggerThreadState() {
1104 while (TraceLoggerThread* logger = threadLoggers.popFirst()) {
1105 js_delete(logger);
1106 }
1107
1108 threadLoggers.clear();
1109
1110 for (TextIdToPayloadMap::Range r = textIdPayloads.all(); !r.empty();
1111 r.popFront()) {
1112 js_delete(r.front().value());
1113 }
1114
1115 #ifdef DEBUG
1116 initialized = false;
1117 #endif
1118 }
1119
init()1120 bool TraceLoggerThreadState::init() {
1121 const char* env = getenv("TLLOG");
1122 if (env) {
1123 if (strstr(env, "help")) {
1124 fflush(nullptr);
1125 printf(
1126 "\n"
1127 "usage: TLLOG=option,option,option,... where options can be:\n"
1128 "\n"
1129 "Collections:\n"
1130 " Default Output all default. It includes:\n"
1131 " AnnotateScripts, Bailout, Baseline, "
1132 "BaselineCompilation, GC,\n"
1133 " GCAllocation, GCSweeping, Interpreter, "
1134 "IonAnalysis, IonCompilation,\n"
1135 " IonLinking, IonMonkey, MinorGC, Frontend, "
1136 "ParsingFull,\n"
1137 " ParsingSyntax, BytecodeEmission, IrregexpCompile, "
1138 "IrregexpExecute,\n"
1139 " Scripts, Engine, WasmCompilation\n"
1140 "\n"
1141 " IonCompiler Output all information about compilation. It "
1142 "includes:\n"
1143 " IonCompilation, IonLinking, PruneUnusedBranches, "
1144 "FoldTests,\n"
1145 " SplitCriticalEdges, RenumberBlocks, "
1146 "ScalarReplacement,\n"
1147 " DominatorTree, PhiAnalysis, MakeLoopsContiguous, "
1148 "ApplyTypes,\n"
1149 " EagerSimdUnbox, AliasAnalysis, GVN, LICM, "
1150 "RangeAnalysis,\n"
1151 " LoopUnrolling, FoldLinearArithConstants, "
1152 "EffectiveAddressAnalysis,\n"
1153 " AlignmentMaskAnalysis, EliminateDeadCode, "
1154 "ReorderInstructions,\n"
1155 " EdgeCaseAnalysis, EliminateRedundantChecks,\n"
1156 " AddKeepAliveInstructions, GenerateLIR, "
1157 "RegisterAllocation,\n"
1158 " GenerateCode, Scripts\n"
1159 "\n"
1160 " VMSpecific Output the specific name of the VM call\n"
1161 "\n"
1162 " Frontend Output all information about frontend compilation. "
1163 "It includes:\n"
1164 " Frontend, ParsingFull, ParsingSyntax, Tokenizing,\n"
1165 " BytecodeEmission, BytecodeFoldConstants, "
1166 "BytecodeNameFunctions\n"
1167 "Specific log items:\n");
1168 for (uint32_t i = 1; i < TraceLogger_Last; i++) {
1169 TraceLoggerTextId id = TraceLoggerTextId(i);
1170 if (!TLTextIdIsTogglable(id)) {
1171 continue;
1172 }
1173 printf(" %s\n", TLTextIdString(id));
1174 }
1175 printf("\n");
1176 exit(0);
1177 /*NOTREACHED*/
1178 }
1179
1180 for (uint32_t i = 1; i < TraceLogger_Last; i++) {
1181 TraceLoggerTextId id = TraceLoggerTextId(i);
1182 if (TLTextIdIsTogglable(id)) {
1183 enabledTextIds[i] = ContainsFlag(env, TLTextIdString(id));
1184 } else {
1185 enabledTextIds[i] = true;
1186 }
1187 }
1188
1189 if (ContainsFlag(env, "Default")) {
1190 enableDefaultLogging();
1191 }
1192
1193 if (ContainsFlag(env, "IonCompiler")) {
1194 enableIonLogging();
1195 }
1196
1197 if (ContainsFlag(env, "Frontend")) {
1198 enableFrontendLogging();
1199 }
1200
1201 #ifdef DEBUG
1202 enabledTextIds[TraceLogger_Error] = true;
1203 #endif
1204
1205 } else {
1206 // Most of the textId's will be enabled through JS::StartTraceLogger when
1207 // the gecko profiler is started.
1208 disableTextIdsForProfiler();
1209 }
1210
1211 enabledTextIds[TraceLogger_Interpreter] = enabledTextIds[TraceLogger_Engine];
1212 enabledTextIds[TraceLogger_Baseline] = enabledTextIds[TraceLogger_Engine];
1213 enabledTextIds[TraceLogger_IonMonkey] = enabledTextIds[TraceLogger_Engine];
1214
1215 enabledTextIds[TraceLogger_Error] = true;
1216
1217 const char* options = getenv("TLOPTIONS");
1218 if (options) {
1219 if (strstr(options, "help")) {
1220 fflush(nullptr);
1221 printf(
1222 "\n"
1223 "usage: TLOPTIONS=option,option,option,... where options can be:\n"
1224 "\n"
1225 " EnableMainThread Start logging main threads immediately.\n"
1226 " EnableOffThread Start logging helper threads "
1227 "immediately.\n"
1228 " EnableGraph Enable the tracelogging graph.\n"
1229 " EnableGraphFile Enable flushing tracelogger data to a "
1230 "file.\n"
1231 " Errors Report errors during tracing to "
1232 "stderr.\n");
1233 printf("\n");
1234 exit(0);
1235 /*NOTREACHED*/
1236 }
1237
1238 if (strstr(options, "EnableMainThread")) {
1239 mainThreadEnabled = true;
1240 }
1241 if (strstr(options, "EnableOffThread")) {
1242 helperThreadEnabled = true;
1243 }
1244 if (strstr(options, "EnableGraph")) {
1245 graphEnabled = true;
1246 }
1247 if (strstr(options, "EnableGraphFile")) {
1248 graphFileEnabled = true;
1249 jit::JitOptions.enableTraceLogger = true;
1250 }
1251 if (strstr(options, "Errors")) {
1252 spewErrors = true;
1253 }
1254 } else {
1255 mainThreadEnabled = true;
1256 helperThreadEnabled = true;
1257 graphEnabled = false;
1258 graphFileEnabled = false;
1259 spewErrors = false;
1260 }
1261
1262 startTime = mozilla::TimeStamp::NowUnfuzzed();
1263
1264 #ifdef DEBUG
1265 initialized = true;
1266 #endif
1267
1268 return true;
1269 }
1270
enableTextId(JSContext * cx,uint32_t textId)1271 void TraceLoggerThreadState::enableTextId(JSContext* cx, uint32_t textId) {
1272 MOZ_ASSERT(TLTextIdIsTogglable(textId));
1273
1274 if (enabledTextIds[textId]) {
1275 return;
1276 }
1277
1278 ReleaseAllJITCode(cx->runtime()->defaultFreeOp());
1279
1280 enabledTextIds[textId] = true;
1281 if (textId == TraceLogger_Engine) {
1282 enabledTextIds[TraceLogger_IonMonkey] = true;
1283 enabledTextIds[TraceLogger_Baseline] = true;
1284 enabledTextIds[TraceLogger_Interpreter] = true;
1285 }
1286
1287 if (textId == TraceLogger_Scripts) {
1288 jit::ToggleBaselineTraceLoggerScripts(cx->runtime(), true);
1289 }
1290 if (textId == TraceLogger_Engine) {
1291 jit::ToggleBaselineTraceLoggerEngine(cx->runtime(), true);
1292 }
1293 }
disableTextId(JSContext * cx,uint32_t textId)1294 void TraceLoggerThreadState::disableTextId(JSContext* cx, uint32_t textId) {
1295 MOZ_ASSERT(TLTextIdIsTogglable(textId));
1296
1297 if (!enabledTextIds[textId]) {
1298 return;
1299 }
1300
1301 ReleaseAllJITCode(cx->runtime()->defaultFreeOp());
1302
1303 enabledTextIds[textId] = false;
1304 if (textId == TraceLogger_Engine) {
1305 enabledTextIds[TraceLogger_IonMonkey] = false;
1306 enabledTextIds[TraceLogger_Baseline] = false;
1307 enabledTextIds[TraceLogger_Interpreter] = false;
1308 }
1309
1310 if (textId == TraceLogger_Scripts) {
1311 jit::ToggleBaselineTraceLoggerScripts(cx->runtime(), false);
1312 }
1313 if (textId == TraceLogger_Engine) {
1314 jit::ToggleBaselineTraceLoggerEngine(cx->runtime(), false);
1315 }
1316 }
1317
TraceLoggerForCurrentThread(JSContext * maybecx)1318 TraceLoggerThread* js::TraceLoggerForCurrentThread(JSContext* maybecx) {
1319 if (!traceLoggerState) {
1320 return nullptr;
1321 }
1322 return traceLoggerState->forCurrentThread(maybecx);
1323 }
1324
forCurrentThread(JSContext * maybecx)1325 TraceLoggerThread* TraceLoggerThreadState::forCurrentThread(
1326 JSContext* maybecx) {
1327 if (!jit::JitOptions.enableTraceLogger) {
1328 return nullptr;
1329 }
1330
1331 MOZ_ASSERT(initialized);
1332 MOZ_ASSERT_IF(maybecx, maybecx == TlsContext.get());
1333
1334 JSContext* cx = maybecx ? maybecx : TlsContext.get();
1335 if (!cx) {
1336 return nullptr;
1337 }
1338
1339 if (!cx->traceLogger) {
1340 LockGuard<Mutex> guard(lock);
1341
1342 TraceLoggerThread* logger = js_new<TraceLoggerThread>(cx);
1343 if (!logger) {
1344 return nullptr;
1345 }
1346
1347 if (!logger->init()) {
1348 return nullptr;
1349 }
1350
1351 threadLoggers.insertFront(logger);
1352 cx->traceLogger = logger;
1353
1354 if (graphEnabled) {
1355 logger->initGraph();
1356 }
1357
1358 if (cx->isHelperThreadContext() ? helperThreadEnabled : mainThreadEnabled) {
1359 logger->enable();
1360 }
1361 }
1362
1363 return cx->traceLogger;
1364 }
1365
destroyLogger(TraceLoggerThread * logger)1366 void TraceLoggerThreadState::destroyLogger(TraceLoggerThread* logger) {
1367 MOZ_ASSERT(initialized);
1368 MOZ_ASSERT(logger);
1369 LockGuard<Mutex> guard(lock);
1370
1371 logger->remove();
1372 js_delete(logger);
1373 }
1374
TraceLogTextIdEnabled(uint32_t textId)1375 bool js::TraceLogTextIdEnabled(uint32_t textId) {
1376 if (!traceLoggerState) {
1377 return false;
1378 }
1379 return traceLoggerState->isTextIdEnabled(textId);
1380 }
1381
TraceLogEnableTextId(JSContext * cx,uint32_t textId)1382 void js::TraceLogEnableTextId(JSContext* cx, uint32_t textId) {
1383 if (!traceLoggerState) {
1384 return;
1385 }
1386 traceLoggerState->enableTextId(cx, textId);
1387 }
TraceLogDisableTextId(JSContext * cx,uint32_t textId)1388 void js::TraceLogDisableTextId(JSContext* cx, uint32_t textId) {
1389 if (!traceLoggerState) {
1390 return;
1391 }
1392 traceLoggerState->disableTextId(cx, textId);
1393 }
1394
TraceLoggerEvent(TraceLoggerTextId type,JSScript * script)1395 TraceLoggerEvent::TraceLoggerEvent(TraceLoggerTextId type, JSScript* script)
1396 : TraceLoggerEvent(type, script->filename(), script->lineno(),
1397 script->column()) {}
1398
TraceLoggerEvent(TraceLoggerTextId type,const char * filename,uint32_t line,uint32_t column)1399 TraceLoggerEvent::TraceLoggerEvent(TraceLoggerTextId type, const char* filename,
1400 uint32_t line, uint32_t column)
1401 : payload_() {
1402 MOZ_ASSERT(
1403 type == TraceLogger_Scripts || type == TraceLogger_AnnotateScripts ||
1404 type == TraceLogger_InlinedScripts || type == TraceLogger_Frontend);
1405
1406 if (!traceLoggerState || !jit::JitOptions.enableTraceLogger) {
1407 return;
1408 }
1409
1410 // Only log scripts when enabled, otherwise use the more generic type
1411 // (which will get filtered out).
1412 if (!traceLoggerState->isTextIdEnabled(type)) {
1413 payload_.setTextId(type);
1414 return;
1415 }
1416
1417 payload_.setEventPayload(
1418 traceLoggerState->getOrCreateEventPayload(filename, line, column));
1419 }
1420
TraceLoggerEvent(const char * text)1421 TraceLoggerEvent::TraceLoggerEvent(const char* text) : payload_() {
1422 if (jit::JitOptions.enableTraceLogger && traceLoggerState) {
1423 payload_.setEventPayload(traceLoggerState->getOrCreateEventPayload(text));
1424 }
1425 }
1426
~TraceLoggerEvent()1427 TraceLoggerEvent::~TraceLoggerEvent() {
1428 if (hasExtPayload()) {
1429 extPayload()->release();
1430 }
1431 }
1432
textId() const1433 uint32_t TraceLoggerEvent::textId() const {
1434 MOZ_ASSERT(hasTextId());
1435 if (hasExtPayload()) {
1436 return extPayload()->textId();
1437 }
1438 return payload_.textId();
1439 }
1440
operator =(const TraceLoggerEvent & other)1441 TraceLoggerEvent& TraceLoggerEvent::operator=(const TraceLoggerEvent& other) {
1442 if (other.hasExtPayload()) {
1443 other.extPayload()->use();
1444 }
1445 if (hasExtPayload()) {
1446 extPayload()->release();
1447 }
1448
1449 payload_ = other.payload_;
1450
1451 return *this;
1452 }
1453
TraceLoggerEvent(const TraceLoggerEvent & other)1454 TraceLoggerEvent::TraceLoggerEvent(const TraceLoggerEvent& other)
1455 : payload_(other.payload_) {
1456 if (hasExtPayload()) {
1457 extPayload()->use();
1458 }
1459 }
1460
InitTraceLogger()1461 JS_PUBLIC_API bool JS::InitTraceLogger() {
1462 MOZ_RELEASE_ASSERT(!traceLoggerState);
1463
1464 if (!getTraceLoggerSupported()) {
1465 return true;
1466 }
1467
1468 traceLoggerState = js_new<TraceLoggerThreadState>();
1469 if (!traceLoggerState) {
1470 return false;
1471 }
1472
1473 if (!traceLoggerState->init()) {
1474 DestroyTraceLoggerThreadState();
1475 return false;
1476 }
1477
1478 return true;
1479 }
1480
TraceLoggerSupported()1481 JS_PUBLIC_API bool JS::TraceLoggerSupported() { return traceLoggerState; }
1482
1483 // Perform a process wide synchronous spew of every thread that tracelogger has
1484 // captured.
spewTraceLoggerStats()1485 void TraceLoggerThreadState::spewTraceLoggerStats() {
1486 for (TraceLoggerThread* logger : threadLoggers) {
1487 logger->spewTraceLoggerStats();
1488 }
1489 }
1490
1491 // Usage here is JS_TRACELOGGER_SPEW=<event1>,<event2>,etc for custom spewing.
1492 // If the environment variable is not found, we use a default set of events.
getSpewIds(EventVector & spewIds)1493 static bool getSpewIds(EventVector& spewIds) {
1494 const char* env = getenv("JS_TRACELOGGER_SPEW");
1495 if (env) {
1496 for (uint32_t i = 1; i < TraceLogger_Last; i++) {
1497 TraceLoggerTextId id = TraceLoggerTextId(i);
1498 if (ContainsFlag(env, TLTextIdString(id))) {
1499 if (!spewIds.append(id)) {
1500 return false;
1501 }
1502 }
1503 }
1504 } else {
1505 const uint32_t defaultSpewEvents[] = {
1506 TraceLogger_ParsingFull, TraceLogger_Interpreter,
1507 TraceLogger_Baseline, TraceLogger_BaselineCompilation,
1508 TraceLogger_IonMonkey, TraceLogger_IonCompilation,
1509 TraceLogger_Bailout};
1510
1511 for (uint32_t id : defaultSpewEvents) {
1512 if (!spewIds.append(id)) {
1513 return false;
1514 }
1515 }
1516 }
1517
1518 return true;
1519 }
1520
spewHeaderRow(UniqueChars & threadName,EventVector & spewIds)1521 static void spewHeaderRow(UniqueChars& threadName, EventVector& spewIds) {
1522 if (threadName) {
1523 JitSpew(jit::JitSpew_ScriptStats, "Thread: %s (pid=%d)", threadName.get(),
1524 getpid());
1525 } else {
1526 JitSpew(jit::JitSpew_ScriptStats, "Unknown Thread (pid=%d)", getpid());
1527 }
1528
1529 UniqueChars header = JS_smprintf("%10s ", "totalTime");
1530 for (uint32_t i : spewIds) {
1531 TraceLoggerTextId id = TraceLoggerTextId(i);
1532 if (TLTextIdIsLogEvent(id)) {
1533 header =
1534 JS_sprintf_append(std::move(header), "%12s ", TLTextIdString(id));
1535 } else {
1536 header =
1537 JS_sprintf_append(std::move(header), "%25s ", TLTextIdString(id));
1538 }
1539 }
1540
1541 JitSpew(jit::JitSpew_ScriptStats, "%s Script", header.get());
1542 }
1543
spewTraceLoggerStats()1544 void TraceLoggerThread::spewTraceLoggerStats() {
1545 if (!jit::JitOptions.enableTraceLogger) {
1546 return;
1547 }
1548
1549 ScriptMap map;
1550 if (!collectTraceLoggerStats(map)) {
1551 return;
1552 }
1553 if (map.empty()) {
1554 return;
1555 }
1556
1557 SortedStatsVector sorted_map;
1558 if (!sortTraceLoggerStats(map, sorted_map)) {
1559 return;
1560 }
1561 map.clearAndCompact();
1562
1563 EventVector spewIds;
1564 if (!getSpewIds(spewIds)) {
1565 return;
1566 }
1567
1568 // Dynamically generate the header row in JitSpew.
1569 spewHeaderRow(threadName_, spewIds);
1570
1571 for (UniquePtr<ScriptStats>& datap : sorted_map) {
1572 auto& tlevents = datap->events_;
1573 uint32_t selfTime = datap->selfTime;
1574
1575 if (selfTime == 0) {
1576 continue;
1577 }
1578
1579 UniqueChars row = JS_smprintf("%10u ", selfTime);
1580 for (uint32_t i : spewIds) {
1581 TraceLoggerTextId id = TraceLoggerTextId(i);
1582 uint32_t time = tlevents[id].time;
1583 uint32_t freq = tlevents[id].count;
1584 uint32_t percent = (time * 100) / selfTime;
1585 if (TLTextIdIsLogEvent(id)) {
1586 row = JS_sprintf_append(std::move(row), "%12u ", freq);
1587 } else {
1588 row = JS_sprintf_append(std::move(row), "%8u (%3u%%,f=%-7u) ", time,
1589 percent, freq);
1590 }
1591 }
1592 JitSpew(jit::JitSpew_ScriptStats, "%s %s", row.get(), datap->scriptName);
1593
1594 // If structured spewer is enabled, we might as well spew everything.
1595 AutoStructuredSpewer spew(cx_, SpewChannel::ScriptStats, nullptr);
1596 if (spew) {
1597 spew->property("script", datap->scriptName);
1598 spew->property("totalTime", selfTime);
1599 spew->beginListProperty("events");
1600 for (uint32_t i = 1; i < TraceLogger_Last; i++) {
1601 TraceLoggerTextId id = TraceLoggerTextId(i);
1602 if (TLTextIdIsInternalEvent(id) || tlevents[id].count == 0) {
1603 continue;
1604 }
1605
1606 spew->beginObject();
1607 spew->property("id", TLTextIdString(id));
1608 if (TLTextIdIsTreeEvent(id)) {
1609 spew->property("time", tlevents[id].time);
1610 spew->property("frequency", tlevents[id].count);
1611 } else if (TLTextIdIsLogEvent(id)) {
1612 spew->property("frequency", tlevents[id].count);
1613 }
1614 spew->endObject();
1615 }
1616 spew->endList();
1617 }
1618 }
1619 }
1620
updateScriptMap(ScriptMap & map,char * key,uint32_t eventId,uint32_t value)1621 static bool updateScriptMap(ScriptMap& map, char* key, uint32_t eventId,
1622 uint32_t value) {
1623 if (!key) {
1624 return false;
1625 }
1626
1627 if (!map.has(key)) {
1628 UniquePtr<ScriptStats> datap;
1629 datap.reset(js_new<ScriptStats>(key));
1630 if (!map.putNew(key, std::move(datap))) {
1631 return false;
1632 }
1633 }
1634 ScriptMap::Ptr p = map.lookup(key);
1635 p->value()->events_[eventId].time += value;
1636 p->value()->events_[eventId].count++;
1637
1638 if (TLTextIdIsTreeEvent(eventId)) {
1639 p->value()->selfTime += value;
1640 }
1641 return true;
1642 }
1643
getFullScriptName(uint32_t textId)1644 UniqueChars TraceLoggerThreadState::getFullScriptName(uint32_t textId) {
1645 TraceLoggerEventPayload* payload = getPayload(textId);
1646 MOZ_ASSERT(payload);
1647 if (!payload) {
1648 return nullptr;
1649 }
1650 char* filename = dictionaryData[payload->dictionaryId()].get();
1651 uint32_t lineno = payload->line() ? *(payload->line()) : 0;
1652 uint32_t colno = payload->column() ? *(payload->column()) : 0;
1653 UniqueChars scriptName = JS_smprintf("%s:%u:%u", filename, lineno, colno);
1654 payload->release();
1655 return scriptName;
1656 }
1657
sortBySelfTime(const UniquePtr<ScriptStats> & lhs,const UniquePtr<ScriptStats> & rhs)1658 static bool sortBySelfTime(const UniquePtr<ScriptStats>& lhs,
1659 const UniquePtr<ScriptStats>& rhs) {
1660 return lhs.get()->selfTime > rhs.get()->selfTime;
1661 }
1662
sortTraceLoggerStats(ScriptMap & map,SortedStatsVector & sorted_map)1663 bool TraceLoggerThread::sortTraceLoggerStats(ScriptMap& map,
1664 SortedStatsVector& sorted_map) {
1665 for (auto range = map.all(); !range.empty(); range.popFront()) {
1666 if (!sorted_map.append(std::move(range.front().value()))) {
1667 return false;
1668 }
1669 }
1670
1671 std::sort(sorted_map.begin(), sorted_map.end(), sortBySelfTime);
1672
1673 return true;
1674 }
1675
1676 // Traverse each event and calculate the self-time, along with the script that
1677 // each event belongs to. We do this quickly by maintaining two stacks:
1678 // (i) eventStack - Each new event encountered is pushed onto the stack. Events
1679 // are popped off whenever a TraceLogger_Stop is encountered
1680 // and sent to updateScriptMap.
1681 // (ii) funcStack - Each new script encountered is pushed onto this stack.
1682 // Elements are popped off whenever a TraceLogger_Stop is
1683 // encountered that matches a script event on the top of
1684 // eventStack.
collectTraceLoggerStats(ScriptMap & map)1685 bool TraceLoggerThread::collectTraceLoggerStats(ScriptMap& map) {
1686 uint32_t totalJSTime = 0;
1687
1688 struct eventInfo {
1689 uint32_t textId;
1690 uint32_t time;
1691 mozilla::TimeStamp start;
1692
1693 explicit eventInfo(uint32_t textId_) : textId(textId_), time(0) {}
1694 };
1695
1696 Vector<eventInfo*, 0, js::SystemAllocPolicy> eventStack;
1697 Vector<uint32_t, 0, js::SystemAllocPolicy> funcStack;
1698
1699 mozilla::TimeStamp startTime, stopTime;
1700 uint32_t size = events_.size();
1701 for (size_t i = 0; i < size; i++) {
1702 uint32_t textId = events_[i].textId;
1703
1704 // Record any log events that have no durations such as Bailouts with a
1705 // value of 1. Make sure the funcStack actually has something in it or
1706 // else the Bailout event will not be associated with any script. This
1707 // can commonly occur when profiling & tracing starts since we may have
1708 // already past the point where the script event is created.
1709 if (TLTextIdIsLogEvent(textId) && !funcStack.empty()) {
1710 UniqueChars script =
1711 traceLoggerState->getFullScriptName(funcStack.back());
1712 if (!updateScriptMap(map, script.release(), textId, 1)) {
1713 return false;
1714 }
1715 }
1716
1717 // Hit a new tree event or a stop event, so add (new event timestamp - old
1718 // event timestamp) to the old event's self-time.
1719 if (TLTextIdIsTreeEvent(textId)) {
1720 if (!eventStack.empty()) {
1721 stopTime = events_[i].time;
1722
1723 uint32_t deltaTime =
1724 static_cast<uint32_t>((stopTime - startTime).ToMicroseconds());
1725 eventStack.back()->time += deltaTime;
1726
1727 if (TLTextIdIsEnumEvent(eventStack.back()->textId)) {
1728 if (!funcStack.empty() && !eventStack.empty()) {
1729 UniqueChars script =
1730 traceLoggerState->getFullScriptName(funcStack.back());
1731 if (!updateScriptMap(map, script.release(),
1732 eventStack.back()->textId, deltaTime)) {
1733 return false;
1734 }
1735 }
1736 }
1737 totalJSTime += deltaTime;
1738 }
1739
1740 if (TLTextIdIsScriptEvent(textId)) {
1741 if (!funcStack.append(textId)) {
1742 return false;
1743 }
1744 }
1745
1746 eventInfo* entry = js_new<eventInfo>(textId);
1747 entry->start = events_[i].time;
1748 if (!eventStack.append(entry)) {
1749 return false;
1750 }
1751
1752 startTime = events_[i].time;
1753
1754 } else if (textId == TraceLogger_Stop) {
1755 if (!eventStack.empty()) {
1756 stopTime = events_[i].time;
1757
1758 uint32_t deltaTime =
1759 static_cast<uint32_t>((stopTime - startTime).ToMicroseconds());
1760 eventInfo* entry = eventStack.popCopy();
1761
1762 uint32_t topId = entry->textId;
1763 entry->time += deltaTime;
1764
1765 if (TLTextIdIsEnumEvent(topId)) {
1766 // funcStack will usually be empty near the beginning of a profiling
1767 // session since we may have skipped the point where the script event
1768 // is created. If that's the case, then skip this event since we
1769 // cannot associate it with any script.
1770 if (!funcStack.empty()) {
1771 UniqueChars script =
1772 traceLoggerState->getFullScriptName(funcStack.back());
1773 if (!updateScriptMap(map, script.release(), topId, deltaTime)) {
1774 return false;
1775 }
1776 }
1777 }
1778 js_delete(entry);
1779
1780 if (TLTextIdIsScriptEvent(topId) && !funcStack.empty()) {
1781 funcStack.popBack();
1782 }
1783
1784 totalJSTime += deltaTime;
1785 startTime = events_[i].time;
1786 }
1787 }
1788 }
1789
1790 return true;
1791 }
1792
ResetTraceLogger(void)1793 JS_PUBLIC_API void JS::ResetTraceLogger(void) { js::ResetTraceLogger(); }
1794
SpewTraceLoggerThread(JSContext * cx)1795 JS_PUBLIC_API void JS::SpewTraceLoggerThread(JSContext* cx) {
1796 if (!traceLoggerState) {
1797 return;
1798 }
1799
1800 if (cx && cx->traceLogger) {
1801 cx->traceLogger->spewTraceLoggerStats();
1802 }
1803 }
1804
SpewTraceLoggerForCurrentProcess()1805 JS_PUBLIC_API void JS::SpewTraceLoggerForCurrentProcess() {
1806 if (!traceLoggerState) {
1807 return;
1808 }
1809 traceLoggerState->spewTraceLoggerStats();
1810 }
1811
StartTraceLogger(JSContext * cx)1812 JS_PUBLIC_API void JS::StartTraceLogger(JSContext* cx) {
1813 if (!traceLoggerState) {
1814 return;
1815 }
1816
1817 if (!jit::JitOptions.enableTraceLogger) {
1818 LockGuard<Mutex> guard(traceLoggerState->lock);
1819 traceLoggerState->enableTextIdsForProfiler();
1820 jit::JitOptions.enableTraceLogger = true;
1821 traceLoggerState->startTime = mozilla::TimeStamp::Now();
1822 }
1823
1824 TraceLoggerThread* logger = traceLoggerState->forCurrentThread(cx);
1825 if (logger) {
1826 logger->enable();
1827 }
1828 }
1829
StopTraceLogger(JSContext * cx)1830 JS_PUBLIC_API void JS::StopTraceLogger(JSContext* cx) {
1831 if (!traceLoggerState) {
1832 return;
1833 }
1834
1835 if (jit::JitOptions.enableTraceLogger) {
1836 LockGuard<Mutex> guard(traceLoggerState->lock);
1837 traceLoggerState->disableTextIdsForProfiler();
1838 jit::JitOptions.enableTraceLogger = false;
1839 }
1840
1841 TraceLoggerThread* logger = traceLoggerState->forCurrentThread(cx);
1842 if (logger) {
1843 logger->disable();
1844 }
1845 }
1846