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