/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- * 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/. */ #include "vm/TraceLoggingGraph.h" #ifdef XP_WIN #include #define getpid _getpid #else #include #endif #include "mozilla/EndianUtils.h" #include "mozilla/ScopeExit.h" #include "jsstr.h" #include "js/UniquePtr.h" #include "threading/LockGuard.h" #include "threading/Thread.h" #include "vm/TraceLogging.h" #ifndef DEFAULT_TRACE_LOG_DIR # if defined(_WIN32) # define DEFAULT_TRACE_LOG_DIR "." # else # define DEFAULT_TRACE_LOG_DIR "/tmp/" # endif #endif using mozilla::MakeScopeExit; using mozilla::NativeEndian; TraceLoggerGraphState* traceLoggerGraphState = nullptr; // gcc and clang have these in symcat.h, but MSVC does not. #ifndef STRINGX # define STRINGX(x) #x #endif #ifndef XSTRING # define XSTRING(macro) STRINGX(macro) #endif #define MAX_LOGGERS 999 // Return a filename relative to the output directory. %u and %d substitutions // are allowed, with %u standing for a full 32-bit number and %d standing for // an up to 3-digit number. static js::UniqueChars MOZ_FORMAT_PRINTF(1, 2) AllocTraceLogFilename(const char* pattern, ...) { js::UniqueChars filename; va_list ap; static const char* outdir = getenv("TLDIR") ? getenv("TLDIR") : DEFAULT_TRACE_LOG_DIR; size_t len = strlen(outdir) + 1; // "+ 1" is for the '/' for (const char* p = pattern; *p; p++) { if (*p == '%') { p++; if (*p == 'u') len += sizeof("4294967295") - 1; else if (*p == 'd') len += sizeof(XSTRING(MAX_LOGGERS)) - 1; else MOZ_CRASH("Invalid format"); } else { len++; } } len++; // For the terminating NUL. filename.reset((char*) js_malloc(len)); if (!filename) return nullptr; char* rest = filename.get() + sprintf(filename.get(), "%s/", outdir); va_start(ap, pattern); int ret = vsnprintf(rest, len, pattern, ap); va_end(ap); if (ret < 0) return nullptr; MOZ_ASSERT(size_t(ret) <= len - (strlen(outdir) + 1), "overran TL filename buffer; %d given too large a value?"); return filename; } bool TraceLoggerGraphState::init() { pid_ = (uint32_t) getpid(); js::UniqueChars filename = AllocTraceLogFilename("tl-data.%u.json", pid_); out = fopen(filename.get(), "w"); if (!out) { fprintf(stderr, "warning: failed to create TraceLogger output file %s\n", filename.get()); return false; } fprintf(out, "["); // Write the latest tl-data.*.json file to tl-data.json. // In most cases that is the wanted file. js::UniqueChars masterFilename = AllocTraceLogFilename("tl-data.json"); if (FILE* last = fopen(masterFilename.get(), "w")) { char *basename = strrchr(filename.get(), '/'); basename = basename ? basename + 1 : filename.get(); fprintf(last, "\"%s\"", basename); fclose(last); } #ifdef DEBUG initialized = true; #endif return true; } TraceLoggerGraphState::~TraceLoggerGraphState() { if (out) { fprintf(out, "]"); fclose(out); out = nullptr; } #ifdef DEBUG initialized = false; #endif } uint32_t TraceLoggerGraphState::nextLoggerId() { js::LockGuard guard(lock); MOZ_ASSERT(initialized); if (numLoggers > MAX_LOGGERS) { fputs("TraceLogging: Can't create more than " XSTRING(MAX_LOGGERS) " different loggers.", stderr); return uint32_t(-1); } if (numLoggers > 0) { int written = fprintf(out, ",\n"); if (written < 0) { fprintf(stderr, "TraceLogging: Error while writing.\n"); return uint32_t(-1); } } int written = fprintf(out, "{\"tree\":\"tl-tree.%u.%d.tl\", \"events\":\"tl-event.%u.%d.tl\", " "\"dict\":\"tl-dict.%u.%d.json\", \"treeFormat\":\"64,64,31,1,32\"", pid_, numLoggers, pid_, numLoggers, pid_, numLoggers); if (written > 0) { char threadName[16]; js::ThisThread::GetName(threadName, sizeof(threadName)); if (threadName[0]) written = fprintf(out, ", \"threadName\":\"%s\"", threadName); } if (written > 0) written = fprintf(out, "}"); if (written < 0) { fprintf(stderr, "TraceLogging: Error while writing.\n"); return uint32_t(-1); } return numLoggers++; } static bool EnsureTraceLoggerGraphState() { if (MOZ_LIKELY(traceLoggerGraphState)) return true; traceLoggerGraphState = js_new(); if (!traceLoggerGraphState) return false; if (!traceLoggerGraphState->init()) { js::DestroyTraceLoggerGraphState(); return false; } return true; } void js::DestroyTraceLoggerGraphState() { if (traceLoggerGraphState) { js_delete(traceLoggerGraphState); traceLoggerGraphState = nullptr; } } bool TraceLoggerGraph::init(uint64_t startTimestamp) { auto fail = MakeScopeExit([&] { failed = true; }); if (!tree.init()) return false; if (!stack.init()) return false; if (!EnsureTraceLoggerGraphState()) return false; uint32_t loggerId = traceLoggerGraphState->nextLoggerId(); if (loggerId == uint32_t(-1)) return false; uint32_t pid = traceLoggerGraphState->pid(); js::UniqueChars dictFilename = AllocTraceLogFilename("tl-dict.%u.%d.json", pid, loggerId); dictFile = fopen(dictFilename.get(), "w"); if (!dictFile) return false; auto cleanupDict = MakeScopeExit([&] { fclose(dictFile); dictFile = nullptr; }); js::UniqueChars treeFilename = AllocTraceLogFilename("tl-tree.%u.%d.tl", pid, loggerId); treeFile = fopen(treeFilename.get(), "w+b"); if (!treeFile) return false; auto cleanupTree = MakeScopeExit([&] { fclose(treeFile); treeFile = nullptr; }); js::UniqueChars eventFilename = AllocTraceLogFilename("tl-event.%u.%d.tl", pid, loggerId); eventFile = fopen(eventFilename.get(), "wb"); if (!eventFile) return false; auto cleanupEvent = MakeScopeExit([&] { fclose(eventFile); eventFile = nullptr; }); // Create the top tree node and corresponding first stack item. TreeEntry& treeEntry = tree.pushUninitialized(); treeEntry.setStart(startTimestamp); treeEntry.setStop(0); treeEntry.setTextId(0); treeEntry.setHasChildren(false); treeEntry.setNextId(0); StackEntry& stackEntry = stack.pushUninitialized(); stackEntry.setTreeId(0); stackEntry.setLastChildId(0); stackEntry.setActive(true); if (fprintf(dictFile, "[") < 0) { fprintf(stderr, "TraceLogging: Error while writing.\n"); return false; } fail.release(); cleanupDict.release(); cleanupTree.release(); cleanupEvent.release(); return true; } TraceLoggerGraph::~TraceLoggerGraph() { // Write dictionary to disk if (dictFile) { int written = fprintf(dictFile, "]"); if (written < 0) fprintf(stderr, "TraceLogging: Error while writing.\n"); fclose(dictFile); dictFile = nullptr; } if (!failed && treeFile) { // Make sure every start entry has a corresponding stop value. // We temporarily enable logging for this. Stop doesn't need any extra data, // so is safe to do even when we have encountered OOM. enabled = true; while (stack.size() > 1) stopEvent(0); enabled = false; } if (!failed && !flush()) { fprintf(stderr, "TraceLogging: Couldn't write the data to disk.\n"); enabled = false; failed = true; } if (treeFile) { fclose(treeFile); treeFile = nullptr; } if (eventFile) { fclose(eventFile); eventFile = nullptr; } } bool TraceLoggerGraph::flush() { MOZ_ASSERT(!failed); if (treeFile) { // Format data in big endian. for (size_t i = 0; i < tree.size(); i++) entryToBigEndian(&tree[i]); int success = fseek(treeFile, 0, SEEK_END); if (success != 0) return false; size_t bytesWritten = fwrite(tree.data(), sizeof(TreeEntry), tree.size(), treeFile); if (bytesWritten < tree.size()) return false; treeOffset += tree.size(); tree.clear(); } return true; } void TraceLoggerGraph::entryToBigEndian(TreeEntry* entry) { entry->start_ = NativeEndian::swapToBigEndian(entry->start_); entry->stop_ = NativeEndian::swapToBigEndian(entry->stop_); uint32_t data = (entry->u.s.textId_ << 1) + entry->u.s.hasChildren_; entry->u.value_ = NativeEndian::swapToBigEndian(data); entry->nextId_ = NativeEndian::swapToBigEndian(entry->nextId_); } void TraceLoggerGraph::entryToSystemEndian(TreeEntry* entry) { entry->start_ = NativeEndian::swapFromBigEndian(entry->start_); entry->stop_ = NativeEndian::swapFromBigEndian(entry->stop_); uint32_t data = NativeEndian::swapFromBigEndian(entry->u.value_); entry->u.s.textId_ = data >> 1; entry->u.s.hasChildren_ = data & 0x1; entry->nextId_ = NativeEndian::swapFromBigEndian(entry->nextId_); } void TraceLoggerGraph::startEvent(uint32_t id, uint64_t timestamp) { if (failed || enabled == 0) return; if (!tree.hasSpaceForAdd()) { if (tree.size() >= treeSizeFlushLimit() || !tree.ensureSpaceBeforeAdd()) { if (!flush()) { fprintf(stderr, "TraceLogging: Couldn't write the data to disk.\n"); enabled = false; failed = true; return; } } } if (!startEventInternal(id, timestamp)) { fprintf(stderr, "TraceLogging: Failed to start an event.\n"); enabled = false; failed = true; return; } } TraceLoggerGraph::StackEntry& TraceLoggerGraph::getActiveAncestor() { uint32_t parentId = stack.lastEntryId(); while (!stack[parentId].active()) parentId--; return stack[parentId]; } bool TraceLoggerGraph::startEventInternal(uint32_t id, uint64_t timestamp) { if (!stack.ensureSpaceBeforeAdd()) return false; // Patch up the tree to be correct. There are two scenarios: // 1) Parent has no children yet. So update parent to include children. // 2) Parent has already children. Update last child to link to the new // child. StackEntry& parent = getActiveAncestor(); #ifdef DEBUG TreeEntry entry; if (!getTreeEntry(parent.treeId(), &entry)) return false; #endif if (parent.lastChildId() == 0) { MOZ_ASSERT(!entry.hasChildren()); MOZ_ASSERT(parent.treeId() == treeOffset + tree.size() - 1); if (!updateHasChildren(parent.treeId())) return false; } else { MOZ_ASSERT(entry.hasChildren()); if (!updateNextId(parent.lastChildId(), tree.size() + treeOffset)) return false; } // Add a new tree entry. TreeEntry& treeEntry = tree.pushUninitialized(); treeEntry.setStart(timestamp); treeEntry.setStop(0); treeEntry.setTextId(id); treeEntry.setHasChildren(false); treeEntry.setNextId(0); // Add a new stack entry. StackEntry& stackEntry = stack.pushUninitialized(); stackEntry.setTreeId(tree.lastEntryId() + treeOffset); stackEntry.setLastChildId(0); stackEntry.setActive(true); // Set the last child of the parent to this newly added entry. parent.setLastChildId(tree.lastEntryId() + treeOffset); return true; } void TraceLoggerGraph::stopEvent(uint32_t id, uint64_t timestamp) { #ifdef DEBUG if (id != TraceLogger_Scripts && id != TraceLogger_Engine && stack.size() > 1 && stack.lastEntry().active()) { TreeEntry entry; MOZ_ASSERT(getTreeEntry(stack.lastEntry().treeId(), &entry)); MOZ_ASSERT(entry.textId() == id); } #endif stopEvent(timestamp); } void TraceLoggerGraph::stopEvent(uint64_t timestamp) { if (enabled && stack.lastEntry().active()) { if (!updateStop(stack.lastEntry().treeId(), timestamp)) { fprintf(stderr, "TraceLogging: Failed to stop an event.\n"); enabled = false; failed = true; return; } } if (stack.size() == 1) { if (!enabled) return; // Forcefully disable logging. We have no stack information anymore. logTimestamp(TraceLogger_Disable, timestamp); return; } stack.pop(); } void TraceLoggerGraph::logTimestamp(uint32_t id, uint64_t timestamp) { if (failed) return; if (id == TraceLogger_Enable) enabled = true; if (!enabled) return; if (id == TraceLogger_Disable) disable(timestamp); MOZ_ASSERT(eventFile); // Format data in big endian timestamp = NativeEndian::swapToBigEndian(timestamp); id = NativeEndian::swapToBigEndian(id); // The layout of the event log in the log file is: // [timestamp, textId] size_t itemsWritten = 0; itemsWritten += fwrite(×tamp, sizeof(uint64_t), 1, eventFile); itemsWritten += fwrite(&id, sizeof(uint32_t), 1, eventFile); if (itemsWritten < 2) { failed = true; enabled = false; } } bool TraceLoggerGraph::getTreeEntry(uint32_t treeId, TreeEntry* entry) { // Entry is still in memory if (treeId >= treeOffset) { *entry = tree[treeId - treeOffset]; return true; } int success = fseek(treeFile, treeId * sizeof(TreeEntry), SEEK_SET); if (success != 0) return false; size_t itemsRead = fread((void*)entry, sizeof(TreeEntry), 1, treeFile); if (itemsRead < 1) return false; entryToSystemEndian(entry); return true; } bool TraceLoggerGraph::saveTreeEntry(uint32_t treeId, TreeEntry* entry) { int success = fseek(treeFile, treeId * sizeof(TreeEntry), SEEK_SET); if (success != 0) return false; entryToBigEndian(entry); size_t itemsWritten = fwrite(entry, sizeof(TreeEntry), 1, treeFile); if (itemsWritten < 1) return false; return true; } bool TraceLoggerGraph::updateHasChildren(uint32_t treeId, bool hasChildren) { if (treeId < treeOffset) { TreeEntry entry; if (!getTreeEntry(treeId, &entry)) return false; entry.setHasChildren(hasChildren); if (!saveTreeEntry(treeId, &entry)) return false; return true; } tree[treeId - treeOffset].setHasChildren(hasChildren); return true; } bool TraceLoggerGraph::updateNextId(uint32_t treeId, uint32_t nextId) { if (treeId < treeOffset) { TreeEntry entry; if (!getTreeEntry(treeId, &entry)) return false; entry.setNextId(nextId); if (!saveTreeEntry(treeId, &entry)) return false; return true; } tree[treeId - treeOffset].setNextId(nextId); return true; } bool TraceLoggerGraph::updateStop(uint32_t treeId, uint64_t timestamp) { if (treeId < treeOffset) { TreeEntry entry; if (!getTreeEntry(treeId, &entry)) return false; entry.setStop(timestamp); if (!saveTreeEntry(treeId, &entry)) return false; return true; } tree[treeId - treeOffset].setStop(timestamp); return true; } void TraceLoggerGraph::disable(uint64_t timestamp) { MOZ_ASSERT(enabled); while (stack.size() > 1) stopEvent(timestamp); enabled = false; } void TraceLoggerGraph::log(ContinuousSpace& events) { for (uint32_t i = 0; i < events.size(); i++) { if (events[i].textId == TraceLogger_Stop) stopEvent(events[i].time); else if (TLTextIdIsTreeEvent(events[i].textId)) startEvent(events[i].textId, events[i].time); else logTimestamp(events[i].textId, events[i].time); } } void TraceLoggerGraph::addTextId(uint32_t id, const char* text) { if (failed) return; // Assume ids are given in order. Which is currently true. #ifdef DEBUG MOZ_ASSERT(id == nextTextId); nextTextId++; #endif if (id > 0) { int written = fprintf(dictFile, ",\n"); if (written < 0) { failed = true; return; } } if (!js::FileEscapedString(dictFile, text, strlen(text), '"')) failed = true; } #undef getpid