/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- * vim: set ts=8 sts=2 et sw=2 tw=80: * This Source Code Form is subject to the terms of the Mozilla Public * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ #ifndef TraceLogging_h #define TraceLogging_h #include "mozilla/LinkedList.h" #include "mozilla/Maybe.h" #include "mozilla/MemoryReporting.h" #include "mozilla/Vector.h" #include #include "jsapi.h" #include "jsfriendapi.h" #include "js/AllocPolicy.h" #include "js/friend/ErrorMessages.h" // js::GetErrorMessage, JSMSG_* #include "js/HashTable.h" #include "js/TraceLoggerAPI.h" #include "js/TypeDecls.h" #include "js/Utility.h" #include "js/Vector.h" #include "threading/LockGuard.h" #include "vm/MutexIDs.h" #include "vm/TraceLoggingGraph.h" #include "vm/TraceLoggingTypes.h" namespace js { namespace jit { class CompileRuntime; } // namespace jit /* * [SMDOC] Tracelogging overview. * * Tracelogging makes it possible to trace the occurrence of a single event * and/or the start and stop of an event. This is implemented with as low * overhead as possible to not interfere with running. * * Logging something is done in 3 stages. * 1) Get the tracelogger of the current thread. cx may be omitted, in which * case it will be fetched from TLS. * - TraceLoggerForCurrentThread(cx); * * 2) Optionally create a TraceLoggerEvent for the text that needs to get * logged. This step takes some time, so try to do this beforehand, outside * the hot path and don't do unnecessary repetitions, since it will cripple * performance. * - TraceLoggerEvent event(logger, "foo"); * * There are also some predefined events. They are located in * TraceLoggerTextId. They don't require to create an TraceLoggerEvent and * can also be used as an argument to these functions. * * 3) Log the occurrence of a single event: * - TraceLogTimestamp(logger, TraceLoggerTextId); * Note: it is temporarily not supported to provide an TraceLoggerEvent as * argument to log the occurrence of a single event. * * or log the start and stop of an event: * - TraceLogStartEvent(logger, TraceLoggerTextId); * - TraceLogStartEvent(logger, TraceLoggerEvent); * - TraceLogStopEvent(logger, TraceLoggerTextId); * - TraceLogStopEvent(logger, TraceLoggerEvent); * * or the start/stop of an event with a RAII class: * - AutoTraceLog atl(logger, TraceLoggerTextId); * - AutoTraceLog atl(logger, TraceLoggerEvent); */ class AutoTraceLog; class TraceLoggerEventPayload; class TraceLoggerThread; /** * An event that can be used to report start/stop events to TraceLogger. It * prepares the given info by requesting a TraceLoggerEventPayload containing * the string to report and an unique id. It also increases the useCount of * this payload, so it cannot get removed. */ class TraceLoggerEvent { #ifdef JS_TRACE_LOGGING private: class EventPayloadOrTextId { /** * Payload can be a pointer to a TraceLoggerEventPayload* or a * TraceLoggerTextId. The last bit decides how to read the payload. * * payload_ = [ | 0 ] * ----------------------- * TraceLoggerEventPayload* (incl. last bit) * * payload_ = [ | 1 ] * ------------------- * TraceLoggerTextId (excl. last bit) */ uintptr_t payload_; public: EventPayloadOrTextId() : payload_(0) {} bool isEventPayload() const { return (payload_ & 1) == 0; } TraceLoggerEventPayload* eventPayload() const { MOZ_ASSERT(isEventPayload()); return (TraceLoggerEventPayload*)payload_; } void setEventPayload(TraceLoggerEventPayload* payload) { MOZ_ASSERT(payload); payload_ = (uintptr_t)payload; MOZ_ASSERT((payload_ & 1) == 0); } bool isTextId() const { return (payload_ & 1) == 1; } uint32_t textId() const { MOZ_ASSERT(isTextId()); return payload_ >> 1; } void setTextId(TraceLoggerTextId textId) { static_assert(TraceLogger_Last < (UINT32_MAX >> 1), "Too many predefined text ids."); payload_ = (((uint32_t)textId) << 1) | 1; } }; EventPayloadOrTextId payload_; public: TraceLoggerEvent() : payload_() {} explicit TraceLoggerEvent(TraceLoggerTextId textId); TraceLoggerEvent(TraceLoggerTextId type, JSScript* script); TraceLoggerEvent(TraceLoggerTextId type, const char* filename, uint32_t line, uint32_t column); explicit TraceLoggerEvent(const char* text); TraceLoggerEvent(const TraceLoggerEvent& event); TraceLoggerEvent& operator=(const TraceLoggerEvent& other); ~TraceLoggerEvent(); uint32_t textId() const; bool hasTextId() const { return hasExtPayload() || payload_.isTextId(); } private: TraceLoggerEventPayload* extPayload() const { MOZ_ASSERT(hasExtPayload()); return payload_.eventPayload(); } bool hasExtPayload() const { return payload_.isEventPayload() && !!payload_.eventPayload(); } #else public: TraceLoggerEvent() {} explicit TraceLoggerEvent(TraceLoggerTextId textId) {} TraceLoggerEvent(TraceLoggerTextId type, JSScript* script) {} TraceLoggerEvent(TraceLoggerTextId type, const char* filename, uint32_t line, uint32_t column) {} explicit TraceLoggerEvent(const char* text) {} TraceLoggerEvent(const TraceLoggerEvent& event) {} TraceLoggerEvent& operator=(const TraceLoggerEvent& other) { return *this; }; ~TraceLoggerEvent() {} uint32_t textId() const { return 0; } bool hasTextId() const { return false; } #endif }; #ifdef DEBUG void AssertCurrentThreadOwnsTraceLoggerThreadStateLock(); #endif /** * An internal class holding the string information to report, together with an * unique id, and an useCount. Whenever this useCount reaches 0, this event * cannot get started/stopped anymore. Consumers may still request the * string information through maybeEventText below, but this may not succeed: * when the use count becomes zero, a payload may be deleted by any thread * holding the TraceLoggerThreadState lock, after that the pointers have been * cleared out of the dictionaryVector. */ class TraceLoggerEventPayload { uint32_t textId_; uint32_t dictionaryId_; mozilla::Maybe line_; mozilla::Maybe col_; mozilla::Atomic uses_; public: TraceLoggerEventPayload(uint32_t textId, uint32_t dictionaryId) : textId_(textId), dictionaryId_(dictionaryId), line_(mozilla::Nothing()), col_(mozilla::Nothing()), uses_(0) {} ~TraceLoggerEventPayload() { MOZ_ASSERT(uses_ == 0); } void setLine(uint32_t line) { line_ = mozilla::Some(line); } void setColumn(uint32_t col) { col_ = mozilla::Some(col); } mozilla::Maybe line() { return line_; } mozilla::Maybe column() { return col_; } uint32_t textId() { return textId_; } uint32_t dictionaryId() { return dictionaryId_; } void setDictionaryId(uint32_t dictId) { dictionaryId_ = dictId; } uint32_t uses() { return uses_; } // Payloads may have their use count change at any time, *except* the count // can only go from zero to non-zero while the thread state lock is held. // This should only happen under getOrCreateEventPayload below, and avoids // races with purgeUnusedPayloads. void use() { #ifdef DEBUG if (!uses_) { AssertCurrentThreadOwnsTraceLoggerThreadStateLock(); } #endif uses_++; } void release() { uses_--; } size_t sizeOfIncludingThis(mozilla::MallocSizeOf mallocSizeOf) const { return mallocSizeOf(this); } }; // Data structures used to collect per function statistics for spewing struct ScriptStats { struct EventData { uint32_t time; uint32_t count; }; EventData events_[TraceLogger_Last]; char* scriptName; uint32_t selfTime; explicit ScriptStats(char* scriptName_) : scriptName(scriptName_), selfTime(0) { for (EventData& entry : events_) { entry.time = 0; entry.count = 0; } } ~ScriptStats() { JS::FreePolicy freePolicy; freePolicy(scriptName); } }; typedef HashMap, mozilla::CStringHasher, SystemAllocPolicy> ScriptMap; typedef Vector, 0, SystemAllocPolicy> SortedStatsVector; typedef Vector EventVector; // Per thread trace logger state. class TraceLoggerThread : public mozilla::LinkedListElement { #ifdef JS_TRACE_LOGGING friend JS::TraceLoggerIdImpl; friend JS::TraceLoggerTimeStampImpl; friend JS::TraceLoggerDurationImpl; friend JS::TraceLoggerLineNoImpl; friend JS::TraceLoggerColNoImpl; private: JSContext* cx_; uint32_t enabled_ = 0; bool failed_ = false; UniquePtr graph_; ContinuousSpace events_; // Every time the events get flushed, this count is increased by one. // Together with events.lastEntryId(), this gives an unique id for every // event. uint32_t iteration_ = 0; # ifdef DEBUG EventVector graphStack_; # endif JS::UniqueChars threadName_ = nullptr; public: AutoTraceLog* top_ = nullptr; explicit TraceLoggerThread(JSContext* cx) : cx_(cx) {} bool init(); ~TraceLoggerThread(); bool init(uint32_t loggerId); void initGraph(); void clear(); bool enable(); bool enable(JSContext* cx); bool disable(bool force = false, const char* = ""); bool enabled() { return enabled_ > 0; } void silentFail(const char* error); size_t sizeOfExcludingThis(mozilla::MallocSizeOf mallocSizeOf) const; size_t sizeOfIncludingThis(mozilla::MallocSizeOf mallocSizeOf) const; private: bool fail(JSContext* cx, const char* error); public: // Given the previous iteration and size, return an array of events // (there could be lost events). At the same time update the iteration and // size and gives back how many events there are. EventEntry* getEventsStartingAt(uint32_t* lastIteration, uint32_t* lastSize, size_t* num) { EventEntry* start; if (iteration_ == *lastIteration) { MOZ_ASSERT(*lastSize <= events_.size()); *num = events_.size() - *lastSize; start = events_.data() + *lastSize; } else { *num = events_.size(); start = events_.data(); } getIterationAndSize(lastIteration, lastSize); return start; } void getIterationAndSize(uint32_t* iteration, uint32_t* size) const { *iteration = iteration_; *size = events_.size(); } bool lostEvents(uint32_t lastIteration, uint32_t lastSize) { // If still logging in the same iteration, there are no lost events. if (lastIteration == iteration_) { MOZ_ASSERT(lastSize <= events_.size()); return false; } // If we are in the next consecutive iteration we are only sure we // didn't lose any events when the lastSize equals the maximum size // 'events' can get. if (lastIteration == iteration_ - 1 && lastSize == events_.maxSize()) { return false; } return true; } bool collectTraceLoggerStats(ScriptMap& map); bool sortTraceLoggerStats(ScriptMap& map, SortedStatsVector& sorted_map); void spewTraceLoggerStats(); private: const char* maybeEventText(uint32_t id); public: const char* eventText(uint32_t id) { const char* text = maybeEventText(id); MOZ_ASSERT(text); return text; }; public: // Log an event (no start/stop, only the timestamp is recorded). void logTimestamp(TraceLoggerTextId id); // Record timestamps for start and stop of an event. void startEvent(TraceLoggerTextId id); void startEvent(const TraceLoggerEvent& event); void stopEvent(TraceLoggerTextId id); void stopEvent(const TraceLoggerEvent& event); // These functions are actually private and shouldn't be used in normal // code. They are made public so they can be used in assembly. void logTimestamp(uint32_t id); void startEvent(uint32_t id); void stopEvent(uint32_t id); private: void stopEvent(); void log(uint32_t id); public: static unsigned offsetOfEnabled() { return offsetof(TraceLoggerThread, enabled_); } #endif }; // Process wide trace logger state. class TraceLoggerThreadState { #ifdef JS_TRACE_LOGGING friend JS::TraceLoggerDictionaryImpl; # ifdef DEBUG bool initialized = false; # endif bool enabledTextIds[TraceLogger_Last]; bool mainThreadEnabled = false; bool helperThreadEnabled = false; bool graphEnabled = false; bool graphFileEnabled = false; bool spewErrors = false; mozilla::LinkedList threadLoggers; // Any events that carry a payload are saved in this hash map. // The key is the event textId, and the value is a pointer to // the payload object. typedef HashMap, SystemAllocPolicy> TextIdToPayloadMap; // The dictionary vector is used to store all of the custom event strings // that are referenced by the payload objects. typedef mozilla::Vector DictionaryVector; // All payload strings are hashed and saved as a key in the payloadDictionary // hash table. The values are indices to the dictionaryData vector where the // actual string is stored. The major benefit of having this hash map is for // de-duplication of JS script filenames. typedef HashMap StringHashToDictionaryMap; TextIdToPayloadMap textIdPayloads; StringHashToDictionaryMap payloadDictionary; DictionaryVector dictionaryData; uint32_t nextTextId = TraceLogger_Last; uint32_t nextDictionaryId = 0; public: mozilla::TimeStamp startTime; double getTimeStampOffset(mozilla::TimeStamp time) { mozilla::TimeDuration delta = time - startTime; return delta.ToMicroseconds(); } JS::UniqueChars getFullScriptName(uint32_t textId); // Mutex to guard the data structures used to hold the payload data: // textIdPayloads, payloadDictionary & dictionaryData. Mutex lock; TraceLoggerThreadState() : lock(js::mutexid::TraceLoggerThreadState) {} bool init(); ~TraceLoggerThreadState(); void enableDefaultLogging(); void enableIonLogging(); void enableFrontendLogging(); void spewTraceLoggerStats(); void clear(); bool remapDictionaryEntries( mozilla::Vector* newDictionary, uint32_t* newNextDictionaryId); TraceLoggerThread* forCurrentThread(JSContext* cx); void destroyLogger(TraceLoggerThread* logger); bool isTextIdEnabled(uint32_t textId) { if (textId < TraceLogger_Last) { return enabledTextIds[textId]; } return true; } void enableTextId(JSContext* cx, uint32_t textId); void disableTextId(JSContext* cx, uint32_t textId); void maybeSpewError(const char* text) { if (spewErrors) { fprintf(stderr, "%s\n", text); } } const char* maybeEventText(uint32_t id); const char* maybeEventText(TraceLoggerEventPayload* p); void purgeUnusedPayloads(); // These functions map a unique input to a logger ID. // This can be used to give start and stop events. Calls to these functions // should be limited if possible, because of the overhead. Note: it is not // allowed to use them in logTimestamp. TraceLoggerEventPayload* getOrCreateEventPayload(const char* text); TraceLoggerEventPayload* getOrCreateEventPayload(JSScript* script); TraceLoggerEventPayload* getOrCreateEventPayload(const char* filename, uint32_t lineno, uint32_t colno); TraceLoggerEventPayload* getPayload(uint32_t id); size_t sizeOfExcludingThis(mozilla::MallocSizeOf mallocSizeOf); size_t sizeOfIncludingThis(mozilla::MallocSizeOf mallocSizeOf) { return mallocSizeOf(this) + sizeOfExcludingThis(mallocSizeOf); } bool isGraphFileEnabled() { return graphFileEnabled; } bool isGraphEnabled() { return graphEnabled; } void enableTextIdsForProfiler(); void disableTextIdsForProfiler(); void disableAllTextIds(); #endif }; #ifdef JS_TRACE_LOGGING void ResetTraceLogger(); void DestroyTraceLoggerThreadState(); void DestroyTraceLogger(TraceLoggerThread* logger); TraceLoggerThread* TraceLoggerForCurrentThread(JSContext* cx = nullptr); #else inline TraceLoggerThread* TraceLoggerForCurrentThread(JSContext* cx = nullptr) { return nullptr; }; #endif inline bool TraceLoggerEnable(TraceLoggerThread* logger) { #ifdef JS_TRACE_LOGGING if (logger) { return logger->enable(); } #endif return false; } inline bool TraceLoggerEnable(TraceLoggerThread* logger, JSContext* cx) { #ifdef JS_TRACE_LOGGING if (logger) { return logger->enable(cx); } JS_ReportErrorNumberASCII(cx, GetErrorMessage, nullptr, JSMSG_TRACELOGGER_ENABLE_FAIL, "internal error"); #endif return false; } inline bool TraceLoggerDisable(TraceLoggerThread* logger) { #ifdef JS_TRACE_LOGGING if (logger) { return logger->disable(); } #endif return false; } inline void TraceLoggerSilentFail(TraceLoggerThread* logger, const char* error) { #ifdef JS_TRACE_LOGGING if (logger) { logger->silentFail(error); } #endif } #ifdef JS_TRACE_LOGGING bool TraceLogTextIdEnabled(uint32_t textId); void TraceLogEnableTextId(JSContext* cx, uint32_t textId); void TraceLogDisableTextId(JSContext* cx, uint32_t textId); #else inline bool TraceLogTextIdEnabled(uint32_t textId) { return false; } inline void TraceLogEnableTextId(JSContext* cx, uint32_t textId) {} inline void TraceLogDisableTextId(JSContext* cx, uint32_t textId) {} #endif inline void TraceLogTimestamp(TraceLoggerThread* logger, TraceLoggerTextId textId) { #ifdef JS_TRACE_LOGGING if (logger) { logger->logTimestamp(textId); } #endif } inline void TraceLogStartEvent(TraceLoggerThread* logger, TraceLoggerTextId textId) { #ifdef JS_TRACE_LOGGING if (logger) { logger->startEvent(textId); } #endif } inline void TraceLogStartEvent(TraceLoggerThread* logger, const TraceLoggerEvent& event) { #ifdef JS_TRACE_LOGGING if (logger) { logger->startEvent(event); } #endif } inline void TraceLogStopEvent(TraceLoggerThread* logger, TraceLoggerTextId textId) { #ifdef JS_TRACE_LOGGING if (logger) { logger->stopEvent(textId); } #endif } inline void TraceLogStopEvent(TraceLoggerThread* logger, const TraceLoggerEvent& event) { #ifdef JS_TRACE_LOGGING if (logger) { logger->stopEvent(event); } #endif } // Helper functions for assembly. May not be used otherwise. inline void TraceLogTimestampPrivate(TraceLoggerThread* logger, uint32_t id) { #ifdef JS_TRACE_LOGGING if (logger) { logger->logTimestamp(id); } #endif } inline void TraceLogStartEventPrivate(TraceLoggerThread* logger, uint32_t id) { #ifdef JS_TRACE_LOGGING if (logger) { logger->startEvent(id); } #endif } inline void TraceLogStopEventPrivate(TraceLoggerThread* logger, uint32_t id) { #ifdef JS_TRACE_LOGGING if (logger) { logger->stopEvent(id); } #endif } size_t SizeOfTraceLogState(mozilla::MallocSizeOf mallocSizeOf); // Automatic logging at the start and end of function call. class MOZ_RAII AutoTraceLog { #ifdef JS_TRACE_LOGGING TraceLoggerThread* logger; union { const TraceLoggerEvent* event; TraceLoggerTextId id; } payload; bool isEvent; bool executed; AutoTraceLog* prev; public: AutoTraceLog(TraceLoggerThread* logger, const TraceLoggerEvent& event) : logger(logger), isEvent(true), executed(false), prev(nullptr) { payload.event = &event; if (logger) { logger->startEvent(event); prev = logger->top_; logger->top_ = this; } } AutoTraceLog(TraceLoggerThread* logger, TraceLoggerTextId id) : logger(logger), isEvent(false), executed(false), prev(nullptr) { payload.id = id; if (logger) { logger->startEvent(id); prev = logger->top_; logger->top_ = this; } } ~AutoTraceLog() { if (logger) { while (this != logger->top_) { logger->top_->stop(); } stop(); } } private: void stop() { if (!executed) { executed = true; if (isEvent) { logger->stopEvent(*payload.event); } else { logger->stopEvent(payload.id); } } if (logger->top_ == this) { logger->top_ = prev; } } #else public: AutoTraceLog(TraceLoggerThread* logger, uint32_t textId) {} AutoTraceLog(TraceLoggerThread* logger, const TraceLoggerEvent& event) {} #endif private: }; } // namespace js #endif /* TraceLogging_h */