Yarn: Add Trace class
When enabled, it writes out a chrome trace file populated with events from the YARN_* event macros.
Bug: b/139010488
Change-Id: Ifae27b2bcf08f767e9886664b1a998162a617108
Reviewed-on: https://swiftshader-review.googlesource.com/c/SwiftShader/+/34813
Tested-by: Ben Clayton <bclayton@google.com>
Reviewed-by: Nicolas Capens <nicolascapens@google.com>
Kokoro-Presubmit: kokoro <noreply+kokoro@google.com>
diff --git a/src/Yarn/Scheduler.cpp b/src/Yarn/Scheduler.cpp
index dab3628..25b432e 100644
--- a/src/Yarn/Scheduler.cpp
+++ b/src/Yarn/Scheduler.cpp
@@ -19,11 +19,21 @@
#include "Debug.hpp"
#include "Defer.hpp"
#include "Thread.hpp"
+#include "Trace.hpp"
#if defined(_WIN32)
#include <intrin.h> // __nop()
#endif
+// Enable to trace scheduler events.
+#define ENABLE_TRACE_EVENTS 0
+
+#if ENABLE_TRACE_EVENTS
+#define TRACE(...) YARN_SCOPED_EVENT(__VA_ARGS__)
+#else
+#define TRACE(...)
+#endif
+
namespace
{
@@ -228,6 +238,7 @@
void Scheduler::Fiber::yield()
{
+ YARN_SCOPED_EVENT("YIELD");
worker->yield(this);
}
@@ -398,6 +409,7 @@
{
case Mode::MultiThreaded:
{
+ YARN_NAME_THREAD("Thread<%.2d> Fiber<%.2d>", int(id), Fiber::current()->id);
{
std::unique_lock<std::mutex> lock(work.mutex);
work.added.wait(lock, [this] { return work.num > 0 || shutdown; });
@@ -441,6 +453,7 @@
void Scheduler::Worker::spinForWork()
{
+ TRACE("SPIN");
Task stolen;
constexpr auto duration = std::chrono::milliseconds(1);
diff --git a/src/Yarn/Thread.cpp b/src/Yarn/Thread.cpp
index 83c56b2..e415453 100644
--- a/src/Yarn/Thread.cpp
+++ b/src/Yarn/Thread.cpp
@@ -14,6 +14,8 @@
#include "Thread.hpp"
+#include "Trace.hpp"
+
#include <cstdarg>
#if defined(_WIN32)
@@ -51,6 +53,7 @@
wchar_t wname[1024];
mbstowcs(wname, name, 1024);
setThreadDescription(GetCurrentThread(), wname);
+ YARN_NAME_THREAD("%s", name);
}
unsigned int Thread::numLogicalCPUs()
@@ -88,6 +91,8 @@
#else
pthread_setname_np(pthread_self(), name);
#endif
+
+ YARN_NAME_THREAD("%s", name);
}
unsigned int Thread::numLogicalCPUs()
diff --git a/src/Yarn/Trace.cpp b/src/Yarn/Trace.cpp
new file mode 100644
index 0000000..0b00e14
--- /dev/null
+++ b/src/Yarn/Trace.cpp
@@ -0,0 +1,248 @@
+// Copyright 2019 The SwiftShader Authors. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// The Trace API produces a trace event file that can be consumed with Chrome's
+// about:tracing viewer.
+// Documentation can be found at:
+// https://www.chromium.org/developers/how-tos/trace-event-profiling-tool
+// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
+
+#include "Trace.hpp"
+
+#include "Defer.hpp"
+#include "Scheduler.hpp"
+#include "Thread.hpp"
+
+#if YARN_TRACE_ENABLED
+
+#include <atomic>
+#include <unordered_set>
+#include <fstream>
+
+namespace
+{
+
+// Chrome traces can choke or error on very large trace files.
+// Limit the number of events created to this number.
+static constexpr int MaxEvents = 100000;
+
+uint64_t threadFiberID(uint32_t threadID, uint32_t fiberID)
+{
+ return static_cast<uint64_t>(threadID) * 31 + static_cast<uint64_t>(fiberID);
+}
+
+} // anonymous namespace
+
+namespace yarn
+{
+
+Trace* Trace::get()
+{
+ static Trace trace;
+ return &trace;
+}
+
+Trace::Trace()
+{
+ nameThread("main");
+ thread = std::thread([&] {
+ Thread::setName("Trace worker");
+
+ auto out = std::fstream("chrome.trace", std::ios_base::out);
+
+ out << "[" << std::endl;
+ defer(out << std::endl << "]" << std::endl);
+
+ auto first = true;
+ for (int i = 0; i < MaxEvents; i++)
+ {
+ auto event = take();
+ if (event->type() == Event::Type::Shutdown)
+ {
+ return;
+ }
+ if (!first) { out << "," << std::endl; };
+ first = false;
+ out << "{" << std::endl;
+ event->write(out);
+ out << "}";
+ }
+
+ stopped = true;
+
+ while(take()->type() != Event::Type::Shutdown) {}
+ });
+}
+
+Trace::~Trace()
+{
+ put(new Shutdown());
+ thread.join();
+}
+
+void Trace::nameThread(const char* fmt, ...)
+{
+ if (stopped) { return; }
+ auto event = new NameThreadEvent();
+
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+
+ put(event);
+}
+
+void Trace::beginEvent(const char* fmt, ...)
+{
+ if (stopped) { return; }
+ auto event = new BeginEvent();
+
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+
+ event->timestamp = timestamp();
+ put(event);
+}
+
+void Trace::endEvent()
+{
+ if (stopped) { return; }
+ auto event = new EndEvent();
+ event->timestamp = timestamp();
+ put(event);
+}
+
+void Trace::beginAsyncEvent(uint32_t id, const char* fmt, ...)
+{
+ if (stopped) { return; }
+ auto event = new AsyncStartEvent();
+
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+
+ event->timestamp = timestamp();
+ event->id = id;
+ put(event);
+}
+
+void Trace::endAsyncEvent(uint32_t id, const char* fmt, ...)
+{
+ if (stopped) { return; }
+ auto event = new AsyncEndEvent();
+
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+
+ event->timestamp = timestamp();
+ event->id = id;
+ put(event);
+}
+
+uint64_t Trace::timestamp()
+{
+ auto now = std::chrono::high_resolution_clock::now();
+ auto diff = std::chrono::duration_cast<std::chrono::microseconds>(now - createdAt);
+ return static_cast<uint64_t>(diff.count());
+}
+
+void Trace::put(Event* event)
+{
+ auto idx = eventQueueWriteIdx++ % eventQueues.size();
+ auto &queue = eventQueues[idx];
+ std::unique_lock<std::mutex> lock(queue.mutex);
+ auto notify = queue.data.size() == 0;
+ queue.data.push(std::unique_ptr<Event>(event));
+ lock.unlock();
+ if (notify) { queue.condition.notify_one(); }
+}
+
+std::unique_ptr<Trace::Event> Trace::take()
+{
+ auto idx = eventQueueReadIdx++ % eventQueues.size();
+ auto &queue = eventQueues[idx];
+ std::unique_lock<std::mutex> lock(queue.mutex);
+ queue.condition.wait(lock, [&queue] { return queue.data.size() > 0; });
+ auto event = std::move(queue.data.front());
+ queue.data.pop();
+ return event;
+}
+
+#define QUOTE(x) "\"" << x << "\""
+#define INDENT " "
+
+Trace::Event::Event() :
+ threadID(std::hash<std::thread::id>()(std::this_thread::get_id()))
+{
+ if (auto fiber = Scheduler::Fiber::current())
+ {
+ fiberID = fiber->id;
+ }
+}
+
+void Trace::Event::write(std::ostream &out) const
+{
+ out << INDENT << QUOTE("name") << ": " << QUOTE(name) << "," << std::endl;
+ if (categories != nullptr)
+ {
+ out << INDENT << QUOTE("cat") << ": " << "\"";
+ auto first = true;
+ for (auto category = *categories; category != nullptr; category++)
+ {
+ if (!first) { out << ","; }
+ out << category;
+ }
+ out << "\"," << std::endl;
+ }
+ if (fiberID != 0)
+ {
+ out << INDENT << QUOTE("args") << ": " << "{" << std::endl
+ << INDENT << INDENT << QUOTE("fiber") << ": " << fiberID << std::endl
+ << INDENT << "}," << std::endl;
+ }
+ if (threadID != 0)
+ {
+ out << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID) << "," << std::endl;
+ }
+ out << INDENT << QUOTE("ph") << ": " << QUOTE(static_cast<char>(type())) << "," << std::endl
+ << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
+ << INDENT << QUOTE("ts") << ": " << timestamp << std::endl;
+}
+
+void Trace::NameThreadEvent::write(std::ostream &out) const
+{
+ out << INDENT << QUOTE("name") << ": " << QUOTE("thread_name") << "," << std::endl
+ << INDENT << QUOTE("ph") << ": " << QUOTE("M") << "," << std::endl
+ << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
+ << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID) << "," << std::endl
+ << INDENT << QUOTE("args") << ": {" << QUOTE("name") << ": " << QUOTE(name) << "}" << std::endl;
+}
+
+void Trace::AsyncEvent::write(std::ostream &out) const
+{
+ out << INDENT << QUOTE("id") << ": " << QUOTE(id) << "," << std::endl
+ << INDENT << QUOTE("cat") << ": " << QUOTE("async") << "," << std::endl;
+ Event::write(out);
+}
+
+
+} // namespace yarn
+
+#endif // YARN_TRACE_ENABLED
\ No newline at end of file
diff --git a/src/Yarn/Trace.hpp b/src/Yarn/Trace.hpp
new file mode 100644
index 0000000..3034ccf
--- /dev/null
+++ b/src/Yarn/Trace.hpp
@@ -0,0 +1,226 @@
+// Copyright 2019 The SwiftShader Authors. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// The Trace API produces a trace event file that can be consumed with Chrome's
+// chrome://tracing viewer.
+// Documentation can be found at:
+// https://www.chromium.org/developers/how-tos/trace-event-profiling-tool
+// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
+
+#define YARN_TRACE_ENABLED 0
+
+#if YARN_TRACE_ENABLED
+
+#include <array>
+#include <atomic>
+#include <chrono>
+#include <condition_variable>
+#include <cstdarg>
+#include <cstring>
+#include <mutex>
+#include <ostream>
+#include <queue>
+#include <thread>
+
+namespace yarn
+{
+
+// Trace writes a trace event file into the current working directory that can
+// be consumed with Chrome's chrome://tracing viewer.
+// Use the YARN_* macros below instead of using this class directly.
+class Trace
+{
+public:
+ static constexpr size_t MaxEventNameLength = 64;
+
+ static Trace* get();
+
+ void nameThread(const char* fmt, ...);
+ void beginEvent(const char* fmt, ...);
+ void endEvent();
+ void beginAsyncEvent(uint32_t id, const char* fmt, ...);
+ void endAsyncEvent(uint32_t id, const char* fmt, ...);
+
+ class ScopedEvent
+ {
+ public:
+ inline ScopedEvent(const char* fmt, ...);
+ inline ~ScopedEvent();
+ private:
+ Trace * const trace;
+ };
+
+ class ScopedAsyncEvent
+ {
+ public:
+ inline ScopedAsyncEvent(uint32_t id, const char* fmt, ...);
+ inline ~ScopedAsyncEvent();
+ private:
+ Trace * const trace;
+ const uint32_t id;
+ std::string name;
+ };
+
+private:
+ Trace();
+ ~Trace();
+ Trace(const Trace&) = delete;
+ Trace& operator = (const Trace&) = delete;
+
+ struct Event
+ {
+ enum class Type : uint8_t
+ {
+ Begin = 'B',
+ End = 'E',
+ Complete = 'X',
+ Instant = 'i',
+ Counter = 'C',
+ AsyncStart = 'b',
+ AsyncInstant = 'n',
+ AsyncEnd = 'e',
+ FlowStart = 's',
+ FlowStep = 't',
+ FlowEnd = 'f',
+ Sample = 'P',
+ ObjectCreated = 'N',
+ ObjectSnapshot = 'O',
+ ObjectDestroyed = 'D',
+ Metadata = 'M',
+ GlobalMemoryDump = 'V',
+ ProcessMemoryDump = 'v',
+ Mark = 'R',
+ ClockSync = 'c',
+ ContextEnter = '(',
+ ContextLeave = ')',
+
+ // Internal types
+ Shutdown = 'S',
+ };
+
+ Event();
+ virtual ~Event() = default;
+ virtual Type type() const = 0;
+ virtual void write(std::ostream &out) const;
+
+ char name[MaxEventNameLength] = {};
+ const char **categories = nullptr;
+ uint64_t timestamp = 0; // in microseconds
+ uint32_t processID = 0;
+ uint32_t threadID;
+ uint32_t fiberID;
+ };
+
+ struct BeginEvent : public Event { Type type() const override { return Type::Begin; } };
+ struct EndEvent : public Event { Type type() const override { return Type::End; } };
+ struct MetadataEvent : public Event { Type type() const override { return Type::Metadata; } };
+ struct Shutdown : public Event { Type type() const override { return Type::Shutdown; } };
+
+ struct AsyncEvent : public Event
+ {
+ void write(std::ostream &out) const override;
+ uint32_t id;
+ };
+
+ struct AsyncStartEvent : public AsyncEvent { Type type() const override { return Type::AsyncStart; } };
+ struct AsyncEndEvent : public AsyncEvent { Type type() const override { return Type::AsyncEnd; } };
+
+ struct NameThreadEvent : public MetadataEvent
+ {
+ void write(std::ostream &out) const override;
+ };
+
+ uint64_t timestamp(); // in microseconds
+
+ void put(Event*);
+ std::unique_ptr<Event> take();
+
+ struct EventQueue
+ {
+ std::queue< std::unique_ptr<Event> > data; // guarded by mutes
+ std::condition_variable condition;
+ std::mutex mutex;
+ };
+ std::array<EventQueue, 1> eventQueues; // TODO: Increasing this from 1 can cause events to go out of order. Investigate, fix.
+ std::atomic<unsigned int> eventQueueWriteIdx = { 0 };
+ unsigned int eventQueueReadIdx = 0;
+ std::chrono::time_point<std::chrono::high_resolution_clock> createdAt = std::chrono::high_resolution_clock::now();
+ std::thread thread;
+ std::atomic<bool> stopped = { false };
+};
+
+Trace::ScopedEvent::ScopedEvent(const char* fmt, ...) : trace(Trace::get())
+{
+ if (trace != nullptr)
+ {
+ char name[Trace::MaxEventNameLength];
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(name, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+
+ trace->beginEvent(name);
+ }
+}
+
+Trace::ScopedEvent::~ScopedEvent()
+{
+ if (trace != nullptr)
+ {
+ trace->endEvent();
+ }
+}
+
+Trace::ScopedAsyncEvent::ScopedAsyncEvent(uint32_t id, const char* fmt, ...) : trace(Trace::get()), id(id)
+{
+ if (trace != nullptr)
+ {
+ char buf[Trace::MaxEventNameLength];
+ va_list vararg;
+ va_start(vararg, fmt);
+ vsnprintf(buf, Trace::MaxEventNameLength, fmt, vararg);
+ va_end(vararg);
+ name = buf;
+
+ trace->beginAsyncEvent(id, "%s", buf);
+ }
+}
+
+Trace::ScopedAsyncEvent::~ScopedAsyncEvent()
+{
+ if (trace != nullptr)
+ {
+ trace->endAsyncEvent(id, "%s", name.c_str());
+ }
+}
+
+} // namespace yarn
+
+#define YARN_CONCAT_(a, b) a ## b
+#define YARN_CONCAT(a, b) YARN_CONCAT_(a,b)
+#define YARN_SCOPED_EVENT(...) yarn::Trace::ScopedEvent YARN_CONCAT(scoped_event, __LINE__)(__VA_ARGS__);
+#define YARN_BEGIN_ASYNC_EVENT(id, ...) do { if (auto t = yarn::Trace::get()) { t->beginAsyncEvent(id, __VA_ARGS__); } } while(false);
+#define YARN_END_ASYNC_EVENT(id, ...) do { if (auto t = yarn::Trace::get()) { t->endAsyncEvent(id, __VA_ARGS__); } } while(false);
+#define YARN_SCOPED_ASYNC_EVENT(id, ...) yarn::Trace::ScopedAsyncEvent YARN_CONCAT(defer_, __LINE__)(id, __VA_ARGS__);
+#define YARN_NAME_THREAD(...) do { if (auto t = yarn::Trace::get()) { t->nameThread(__VA_ARGS__); } } while(false);
+
+#else // YARN_TRACE_ENABLED
+
+#define YARN_SCOPED_EVENT(...)
+#define YARN_BEGIN_ASYNC_EVENT(id, ...)
+#define YARN_END_ASYNC_EVENT(id, ...)
+#define YARN_SCOPED_ASYNC_EVENT(id, ...)
+#define YARN_NAME_THREAD(...)
+
+#endif // YARN_TRACE_ENABLED
