Yarn: Add Trace class

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::schedule()
 
 void Scheduler::Fiber::yield()
 {
+    YARN_SCOPED_EVENT("YIELD");
     worker->yield(this);
 }
 
@@ -398,6 +409,7 @@ void Scheduler::Worker::run()
     {
     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::waitForWork(std::unique_lock<std::mutex> &lock)
 
 void Scheduler::Worker::spinForWork()
 {
+    TRACE("SPIN");
     Task stolen;
 
     constexpr auto duration = std::chrono::milliseconds(1);

src/Yarn/Thread.cpp

@@ -14,6 +14,8 @@
 
 #include "Thread.hpp"
 
+#include "Trace.hpp"
+
 #include <cstdarg>
 
 #if defined(_WIN32)
@@ -51,6 +53,7 @@ void Thread::setName(const char* fmt, ...)
     wchar_t wname[1024];
     mbstowcs(wname, name, 1024);
     setThreadDescription(GetCurrentThread(), wname);
+    YARN_NAME_THREAD("%s", name);
 }
 
 unsigned int Thread::numLogicalCPUs()
@@ -88,6 +91,8 @@ void Thread::setName(const char* fmt, ...)
 #else
     pthread_setname_np(pthread_self(), name);
 #endif
+
+    YARN_NAME_THREAD("%s", name);
 }
 
 unsigned int Thread::numLogicalCPUs()

src/Yarn/Trace.cpp

+// 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

src/Yarn/Trace.hpp

+// 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