Source code

Revision control

Other Tools

/* -*- 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/. */
#include "vm/TraceLoggingGraph.h"
#ifdef XP_WIN
# include <process.h>
# define getpid _getpid
#else
# include <unistd.h>
#endif
#include "mozilla/EndianUtils.h"
#include "mozilla/MemoryReporting.h"
#include "mozilla/ScopeExit.h"
#include "js/Printf.h"
#include "js/UniquePtr.h"
#include "threading/LockGuard.h"
#include "threading/Thread.h"
#include "util/Text.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, ...) {
va_list ap;
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.
js::UniqueChars filename(js_pod_malloc<char>(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<js::Mutex> 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.%u.tl\", \"events\":\"tl-event.%u.%u.tl\", "
"\"dict\":\"tl-dict.%u.%u.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, R"(, "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++;
}
size_t TraceLoggerGraphState::sizeOfExcludingThis(
mozilla::MallocSizeOf mallocSizeOf) const {
return 0;
}
static bool EnsureTraceLoggerGraphState() {
if (MOZ_LIKELY(traceLoggerGraphState)) {
return true;
}
traceLoggerGraphState = js_new<TraceLoggerGraphState>();
if (!traceLoggerGraphState) {
return false;
}
if (!traceLoggerGraphState->init()) {
js::DestroyTraceLoggerGraphState();
return false;
}
return true;
}
size_t js::SizeOfTraceLogGraphState(mozilla::MallocSizeOf mallocSizeOf) {
return traceLoggerGraphState
? traceLoggerGraphState->sizeOfIncludingThis(mallocSizeOf)
: 0;
}
void js::DestroyTraceLoggerGraphState() {
if (traceLoggerGraphState) {
js_delete(traceLoggerGraphState);
traceLoggerGraphState = nullptr;
}
}
bool TraceLoggerGraph::init(uint64_t startTimestamp, bool graphFileEnabled) {
auto fail = MakeScopeExit([&] { failed = true; });
if (graphFileEnabled) {
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.%u.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.%u.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.%u.tl", pid, loggerId);
eventFile = fopen(eventFilename.get(), "wb");
if (!eventFile) {
return false;
}
auto cleanupEvent = MakeScopeExit([&] {
fclose(eventFile);
eventFile = nullptr;
});
if (fprintf(dictFile, "[") < 0) {
fprintf(stderr, "TraceLogging: Error while writing.\n");
return false;
}
cleanupDict.release();
cleanupTree.release();
cleanupEvent.release();
}
if (!tree.init()) {
return false;
}
if (!stack.init()) {
return false;
}
// 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);
fail.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 (!treeFile) {
disable(timestamp);
return;
}
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);
}
if (!eventFile) {
return;
}
// 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(&timestamp, 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;
}
// If treeFile is null and treeOffset is non-zero then something is wrong
if (!treeFile) {
return false;
}
// Entry has been flushed to disk. Look it up.
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) {
MOZ_ASSERT(treeFile != nullptr);
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 (treeFile && !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 (treeFile && !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 (treeFile && !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<EventEntry>& events,
mozilla::TimeStamp startTime) {
for (uint32_t i = 0; i < events.size(); i++) {
mozilla::TimeDuration delta = events[i].time - startTime;
uint64_t timeOffset = static_cast<uint64_t>(delta.ToMicroseconds());
if (events[i].textId == TraceLogger_Stop) {
stopEvent(timeOffset);
} else if (TLTextIdIsTreeEvent(events[i].textId)) {
startEvent(events[i].textId, timeOffset);
} else {
logTimestamp(events[i].textId, timeOffset);
}
}
}
void TraceLoggerGraph::addTextId(uint32_t id, const char* text) {
mozilla::Maybe<uint32_t> line = mozilla::Nothing();
mozilla::Maybe<uint32_t> column = mozilla::Nothing();
addTextId(id, text, line, column);
}
void TraceLoggerGraph::addTextId(uint32_t id, const char* text,
mozilla::Maybe<uint32_t>& line,
mozilla::Maybe<uint32_t>& column) {
if (failed) {
return;
}
// Assume ids are given in order. Which is currently true.
MOZ_ASSERT(id == nextTextId_);
nextTextId_++;
if (id > 0) {
int written = fprintf(dictFile, ",\n");
if (written < 0) {
failed = true;
return;
}
}
js::UniqueChars str;
if (line && column) {
str = JS_smprintf("script %s:%u:%u", text, *line, *column);
} else if (line) {
str = JS_smprintf("script %s:%u", text, *line);
} else {
str = JS_smprintf("%s", text);
}
if (!js::FileEscapedString(dictFile, str.get(), strlen(str.get()), '"')) {
failed = true;
}
str.reset();
}
size_t TraceLoggerGraph::sizeOfExcludingThis(
mozilla::MallocSizeOf mallocSizeOf) const {
size_t size = 0;
size += tree.sizeOfExcludingThis(mallocSizeOf);
size += stack.sizeOfExcludingThis(mallocSizeOf);
return size;
}
size_t TraceLoggerGraph::sizeOfIncludingThis(
mozilla::MallocSizeOf mallocSizeOf) const {
return mallocSizeOf(this) + sizeOfExcludingThis(mallocSizeOf);
}
#undef getpid