diff options
Diffstat (limited to 'tools/profiler/tasktracer/GeckoTaskTracer.cpp')
-rw-r--r-- | tools/profiler/tasktracer/GeckoTaskTracer.cpp | 464 |
1 files changed, 464 insertions, 0 deletions
diff --git a/tools/profiler/tasktracer/GeckoTaskTracer.cpp b/tools/profiler/tasktracer/GeckoTaskTracer.cpp new file mode 100644 index 0000000000..5a8ca8625c --- /dev/null +++ b/tools/profiler/tasktracer/GeckoTaskTracer.cpp @@ -0,0 +1,464 @@ +/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */ +/* vim:set ts=2 sw=2 sts=2 et cindent: */ +/* 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 "GeckoTaskTracer.h" +#include "GeckoTaskTracerImpl.h" + +#include "platform.h" + +#include "mozilla/DebugOnly.h" +#include "mozilla/MathAlgorithms.h" +#include "mozilla/StaticMutex.h" +#include "mozilla/ThreadLocal.h" +#include "mozilla/TimeStamp.h" +#include "mozilla/UniquePtr.h" +#include "mozilla/Unused.h" +#include "nsString.h" +#include "nsThreadUtils.h" +#include "prtime.h" + +#include <stdarg.h> + +#define MAX_SIZE_LOG (1024 * 128) + +// NS_ENSURE_TRUE_VOID() without the warning on the debug build. +#define ENSURE_TRUE_VOID(x) \ + do { \ + if (MOZ_UNLIKELY(!(x))) { \ + return; \ + } \ + } while (0) + +// NS_ENSURE_TRUE() without the warning on the debug build. +#define ENSURE_TRUE(x, ret) \ + do { \ + if (MOZ_UNLIKELY(!(x))) { \ + return ret; \ + } \ + } while (0) + +namespace mozilla { +namespace tasktracer { + +#define SOURCE_EVENT_NAME(type) \ + const char* CreateSourceEvent##type() { return "SourceEvent" #type; } +#include "SourceEventTypeMap.h" +#undef SOURCE_EVENT_NAME + +static MOZ_THREAD_LOCAL(TraceInfo*) sTraceInfoTLS; +static mozilla::StaticMutex sMutex; + +// The generation of TraceInfo. It will be > 0 if the Task Tracer is started and +// <= 0 if stopped. +bool gStarted(false); +static nsTArray<UniquePtr<TraceInfo>>* sTraceInfos = nullptr; +static PRTime sStartTime; + +static const char sJSLabelPrefix[] = "#tt#"; + +namespace { + +static PRTime GetTimestamp() { return PR_Now() / 1000; } + +static TraceInfo* AllocTraceInfo(int aTid) { + sMutex.AssertCurrentThreadOwns(); + MOZ_ASSERT(sTraceInfos); + auto* info = sTraceInfos->AppendElement(MakeUnique<TraceInfo>(aTid)); + + return info->get(); +} + +static void CreateSourceEvent(SourceEventType aType) { + // Create a new unique task id. + uint64_t newId = GenNewUniqueTaskId(); + { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + info->mCurTraceSourceId = newId; + info->mCurTraceSourceType = aType; + info->mCurTaskId = newId; + } + + uintptr_t* namePtr; +#define SOURCE_EVENT_NAME(type) \ + case SourceEventType::type: { \ + namePtr = (uintptr_t*)&CreateSourceEvent##type; \ + break; \ + } + + switch (aType) { +#include "SourceEventTypeMap.h" + default: + MOZ_CRASH("Unknown SourceEvent."); + } +#undef SOURCE_EVENT_NAME + + // Log a fake dispatch and start for this source event. + LogDispatch(newId, newId, newId, aType); + LogVirtualTablePtr(newId, newId, namePtr); + LogBegin(newId, newId); +} + +static void DestroySourceEvent() { + // Log a fake end for this source event. + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + uint64_t curTraceSourceId; + curTraceSourceId = info->mCurTraceSourceId; + info.Reset(); + + LogEnd(curTraceSourceId, curTraceSourceId); +} + +inline static void ObsoleteCurrentTraceInfos() { + MOZ_ASSERT(sTraceInfos); + for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) { + (*sTraceInfos)[i]->mObsolete = true; + } +} + +static void SetLogStarted(bool aIsStartLogging) { + MOZ_ASSERT(aIsStartLogging != gStarted); + StaticMutexAutoLock lock(sMutex); + + gStarted = aIsStartLogging; + + if (aIsStartLogging && sTraceInfos == nullptr) { + sTraceInfos = new nsTArray<UniquePtr<TraceInfo>>(); + } + + if (!aIsStartLogging && sTraceInfos) { + ObsoleteCurrentTraceInfos(); + } +} + +} // namespace + +TraceInfoLogType* TraceInfo::AppendLog() { + if (mLogsSize >= MAX_SIZE_LOG) { + return nullptr; + } + TraceInfoLogNode* node = new TraceInfoLogNode; + node->mNext = nullptr; + if (mLogsTail) { + mLogsTail->mNext = node; + mLogsTail = node; + } else { + mLogsTail = mLogsHead = node; + } + mLogsSize++; + return &node->mLog; +} + +void InitTaskTracer(uint32_t aFlags) { + StaticMutexAutoLock lock(sMutex); + + if (aFlags & FORKED_AFTER_NUWA) { + ObsoleteCurrentTraceInfos(); + return; + } + + MOZ_ASSERT(!sTraceInfos); + + bool success = sTraceInfoTLS.init(); + if (!success) { + MOZ_CRASH(); + } +} + +void ShutdownTaskTracer() { + if (IsStartLogging()) { + SetLogStarted(false); + + StaticMutexAutoLock lock(sMutex); + // Make sure all threads are out of holding mutics. + // See |GetOrCreateTraceInfo()| + for (auto& traceinfo : *sTraceInfos) { + MutexAutoLock lock(traceinfo->mLogsMutex); + } + delete sTraceInfos; + sTraceInfos = nullptr; + } +} + +static void FreeTraceInfo(TraceInfo* aTraceInfo) { + sMutex.AssertCurrentThreadOwns(); + if (aTraceInfo) { + UniquePtr<TraceInfo> traceinfo(aTraceInfo); + mozilla::DebugOnly<bool> removed = sTraceInfos->RemoveElement(traceinfo); + MOZ_ASSERT(removed); + Unused << traceinfo.release(); // A dirty hack to prevent double free. + } +} + +void FreeTraceInfo() { + StaticMutexAutoLock lock(sMutex); + if (sTraceInfos) { + FreeTraceInfo(sTraceInfoTLS.get()); + } +} + +TraceInfoHolder GetOrCreateTraceInfo() { + TraceInfo* info = sTraceInfoTLS.get(); + StaticMutexAutoLock lock(sMutex); + ENSURE_TRUE(IsStartLogging(), TraceInfoHolder{}); + + if (info && info->mObsolete) { + // TraceInfo is obsolete: remove it. + FreeTraceInfo(info); + info = nullptr; + } + + if (!info) { + info = AllocTraceInfo(profiler_current_thread_id()); + sTraceInfoTLS.set(info); + } + + return TraceInfoHolder{info}; // |mLogsMutex| will be held, then + // ||sMutex| will be released for + // efficiency reason. +} + +uint64_t GenNewUniqueTaskId() { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE(info, 0); + + int tid = profiler_current_thread_id(); + uint64_t taskid = ((uint64_t)tid << 32) | ++info->mLastUniqueTaskId; + return taskid; +} + +AutoSaveCurTraceInfoImpl::AutoSaveCurTraceInfoImpl() { + GetCurTraceInfo(&mSavedSourceEventId, &mSavedTaskId, &mSavedSourceEventType); +} + +AutoSaveCurTraceInfoImpl::~AutoSaveCurTraceInfoImpl() { + SetCurTraceInfo(mSavedSourceEventId, mSavedTaskId, mSavedSourceEventType); +} + +void SetCurTraceInfo(uint64_t aSourceEventId, uint64_t aParentTaskId, + SourceEventType aSourceEventType) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + info->mCurTraceSourceId = aSourceEventId; + info->mCurTaskId = aParentTaskId; + info->mCurTraceSourceType = aSourceEventType; +} + +void GetCurTraceInfo(uint64_t* aOutSourceEventId, uint64_t* aOutParentTaskId, + SourceEventType* aOutSourceEventType) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + *aOutSourceEventId = info->mCurTraceSourceId; + *aOutParentTaskId = info->mCurTaskId; + *aOutSourceEventType = info->mCurTraceSourceType; +} + +void LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId, + uint64_t aSourceEventId, SourceEventType aSourceEventType) { + LogDispatch(aTaskId, aParentTaskId, aSourceEventId, aSourceEventType, 0); +} + +void LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId, + uint64_t aSourceEventId, SourceEventType aSourceEventType, + int aDelayTimeMs) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + // aDelayTimeMs is the expected delay time in milliseconds, thus the dispatch + // time calculated of it might be slightly off in the real world. + uint64_t time = + (aDelayTimeMs <= 0) ? GetTimestamp() : GetTimestamp() + aDelayTimeMs; + + // Log format: + // [0 taskId dispatchTime sourceEventId sourceEventType parentTaskId] + TraceInfoLogType* log = info->AppendLog(); + if (log) { + log->mDispatch.mType = ACTION_DISPATCH; + log->mDispatch.mTaskId = aTaskId; + log->mDispatch.mTime = time; + log->mDispatch.mSourceEventId = aSourceEventId; + log->mDispatch.mSourceEventType = aSourceEventType; + log->mDispatch.mParentTaskId = aParentTaskId; + } +} + +void LogBegin(uint64_t aTaskId, uint64_t aSourceEventId) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + // Log format: + // [1 taskId beginTime processId threadId] + TraceInfoLogType* log = info->AppendLog(); + if (log) { + log->mBegin.mType = ACTION_BEGIN; + log->mBegin.mTaskId = aTaskId; + log->mBegin.mTime = GetTimestamp(); + log->mBegin.mPid = profiler_current_process_id(); + log->mBegin.mTid = profiler_current_thread_id(); + + MOZ_ASSERT(log->mBegin.mPid >= 0, + "native process ID is < 0 (signed integer overflow)"); + MOZ_ASSERT(log->mBegin.mTid >= 0, + "native thread ID is < 0 (signed integer overflow)"); + } +} + +void LogEnd(uint64_t aTaskId, uint64_t aSourceEventId) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + // Log format: + // [2 taskId endTime] + TraceInfoLogType* log = info->AppendLog(); + if (log) { + log->mEnd.mType = ACTION_END; + log->mEnd.mTaskId = aTaskId; + log->mEnd.mTime = GetTimestamp(); + } +} + +void LogVirtualTablePtr(uint64_t aTaskId, uint64_t aSourceEventId, + uintptr_t* aVptr) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + // Log format: + // [4 taskId address] + TraceInfoLogType* log = info->AppendLog(); + if (log) { + // Since addr2line used by the Gecko Profiler addon can not solve + // non-function addresses, we use the first entry of vtable as the symbol + // to solve. We should find a better solution later. + log->mVPtr.mType = ACTION_GET_VTABLE; + log->mVPtr.mTaskId = aTaskId; + log->mVPtr.mVPtr = reinterpret_cast<uintptr_t>(aVptr); + } +} + +void AutoSourceEvent::StartScope(SourceEventType aType) { + CreateSourceEvent(aType); +} + +void AutoSourceEvent::StopScope() { DestroySourceEvent(); } + +void AutoScopedLabel::Init(const char* aFormat, va_list& aArgs) { + nsCString label; + va_list& args = aArgs; + label.AppendPrintf(aFormat, args); + mLabel = strdup(label.get()); + AddLabel("Begin %s", mLabel); +} + +void DoAddLabel(const char* aFormat, va_list& aArgs) { + TraceInfoHolder info = GetOrCreateTraceInfo(); + ENSURE_TRUE_VOID(info); + + // Log format: + // [3 taskId "label"] + TraceInfoLogType* log = info->AppendLog(); + if (log) { + va_list& args = aArgs; + nsCString& buffer = *info->mStrs.AppendElement(); + buffer.AppendPrintf(aFormat, args); + + log->mLabel.mType = ACTION_ADD_LABEL; + log->mLabel.mTaskId = info->mCurTaskId; + log->mLabel.mTime = GetTimestamp(); + log->mLabel.mStrIdx = info->mStrs.Length() - 1; + } +} + +// Functions used by GeckoProfiler. + +void StartLogging() { + sStartTime = GetTimestamp(); + SetLogStarted(true); +} + +void StopLogging() { SetLogStarted(false); } + +UniquePtr<Vector<nsCString>> GetLoggedData(TimeStamp aTimeStamp) { + auto result = MakeUnique<Vector<nsCString>>(); + + // TODO: This is called from a signal handler. Use semaphore instead. + StaticMutexAutoLock lock(sMutex); + + if (sTraceInfos == nullptr) { + return result; + } + + for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) { + TraceInfo* info = (*sTraceInfos)[i].get(); + MutexAutoLock lockLogs(info->mLogsMutex); + if (info->mObsolete) { + continue; + } + + nsTArray<nsCString>& strs = info->mStrs; + for (TraceInfoLogNode* node = info->mLogsHead; node; node = node->mNext) { + TraceInfoLogType& log = node->mLog; + MOZ_RELEASE_ASSERT(result->append(nsCString())); + nsCString& buffer = result->back(); + + switch (log.mType) { + case ACTION_DISPATCH: + buffer.AppendPrintf("%d %llu %llu %llu %d %llu", ACTION_DISPATCH, + (unsigned long long)log.mDispatch.mTaskId, + (unsigned long long)log.mDispatch.mTime, + (unsigned long long)log.mDispatch.mSourceEventId, + log.mDispatch.mSourceEventType, + (unsigned long long)log.mDispatch.mParentTaskId); + break; + + case ACTION_BEGIN: + buffer.AppendPrintf("%d %llu %llu %d %d", ACTION_BEGIN, + (unsigned long long)log.mBegin.mTaskId, + (unsigned long long)log.mBegin.mTime, + log.mBegin.mPid, log.mBegin.mTid); + break; + + case ACTION_END: + buffer.AppendPrintf("%d %llu %llu", ACTION_END, + (unsigned long long)log.mEnd.mTaskId, + (unsigned long long)log.mEnd.mTime); + break; + + case ACTION_GET_VTABLE: + buffer.AppendPrintf("%d %llu %p", ACTION_GET_VTABLE, + (unsigned long long)log.mVPtr.mTaskId, + (void*)log.mVPtr.mVPtr); + break; + + case ACTION_ADD_LABEL: + buffer.AppendPrintf("%d %llu %llu2 \"%s\"", ACTION_ADD_LABEL, + (unsigned long long)log.mLabel.mTaskId, + (unsigned long long)log.mLabel.mTime, + strs[log.mLabel.mStrIdx].get()); + break; + + default: + MOZ_CRASH("Unknow TaskTracer log type!"); + } + } + } + + return result; +} + +PRTime GetStartTime() { return sStartTime; } + +const char* GetJSLabelPrefix() { return sJSLabelPrefix; } + +#undef ENSURE_TRUE_VOID +#undef ENSURE_TRUE + +} // namespace tasktracer +} // namespace mozilla |