aboutsummaryrefslogtreecommitdiffhomepage
diff options
context:
space:
mode:
Diffstat
-rw-r--r--gn/tests.gni1
-rw-r--r--src/core/SkTraceEvent.h51
-rw-r--r--src/core/SkTraceEventCommon.h20
-rw-r--r--tests/TracingTest.cpp189
-rw-r--r--tools/trace/SkChromeTracingTracer.cpp106
-rw-r--r--tools/trace/SkChromeTracingTracer.h8
6 files changed, 344 insertions, 31 deletions
diff --git a/gn/tests.gni b/gn/tests.gni
index 03138d5728..3edb3e3f49 100644
--- a/gn/tests.gni
+++ b/gn/tests.gni
@@ -252,6 +252,7 @@ tests_sources = [
"$_tests/TLSTest.cpp",
"$_tests/TopoSortTest.cpp",
"$_tests/TraceMemoryDumpTest.cpp",
+ "$_tests/TracingTest.cpp",
"$_tests/TransferPixelsTest.cpp",
"$_tests/TypefaceTest.cpp",
"$_tests/UnicodeTest.cpp",
diff --git a/src/core/SkTraceEvent.h b/src/core/SkTraceEvent.h
index d4d0883a23..5f9ae3ca55 100644
--- a/src/core/SkTraceEvent.h
+++ b/src/core/SkTraceEvent.h
@@ -128,6 +128,23 @@
} \
} while (0)
+// Implementation detail: internal macro to create static category and add
+// event if the category is enabled.
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID(phase, category_group, name, id, \
+ flags, ...) \
+ do { \
+ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
+ if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE()) { \
+ unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
+ skia::tracing_internals::TraceID trace_event_trace_id( \
+ id, &trace_event_flags); \
+ skia::tracing_internals::AddTraceEvent( \
+ phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), \
+ name, trace_event_trace_id.data(), trace_event_flags, \
+ ##__VA_ARGS__); \
+ } \
+ } while (0)
+
// Implementation detail: internal macro to create static category and add begin
// event if the category is enabled. Also adds the end event when the scope
// ends.
@@ -152,6 +169,40 @@ namespace tracing_internals {
const int kZeroNumArgs = 0;
const uint64_t kNoEventId = 0;
+// TraceID encapsulates an ID that can either be an integer or pointer. Pointers
+// are by default mangled with the Process ID so that they are unlikely to
+// collide when the same pointer is used on different processes.
+class TraceID {
+public:
+ TraceID(const void* id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(reinterpret_cast<uintptr_t>(id))) {
+ *flags |= TRACE_EVENT_FLAG_MANGLE_ID;
+ }
+ TraceID(uint64_t id, unsigned char* flags)
+ : data_(id) { (void)flags; }
+ TraceID(unsigned int id, unsigned char* flags)
+ : data_(id) { (void)flags; }
+ TraceID(unsigned short id, unsigned char* flags)
+ : data_(id) { (void)flags; }
+ TraceID(unsigned char id, unsigned char* flags)
+ : data_(id) { (void)flags; }
+ TraceID(long long id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(id)) { (void)flags; }
+ TraceID(long id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(id)) { (void)flags; }
+ TraceID(int id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(id)) { (void)flags; }
+ TraceID(short id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(id)) { (void)flags; }
+ TraceID(signed char id, unsigned char* flags)
+ : data_(static_cast<uint64_t>(id)) { (void)flags; }
+
+ uint64_t data() const { return data_; }
+
+private:
+ uint64_t data_;
+};
+
// Simple union to store various types as uint64_t.
union TraceValueUnion {
bool as_bool;
diff --git a/src/core/SkTraceEventCommon.h b/src/core/SkTraceEventCommon.h
index dbce48f56d..8cfaa4b1e6 100644
--- a/src/core/SkTraceEventCommon.h
+++ b/src/core/SkTraceEventCommon.h
@@ -98,6 +98,23 @@
static_cast<int>(value1_val), value2_name, \
static_cast<int>(value2_val))
+// Macros to track the life time and value of arbitrary client objects.
+#define TRACE_EVENT_OBJECT_CREATED_WITH_ID(category_group, name, id) \
+ INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
+ TRACE_EVENT_PHASE_CREATE_OBJECT, category_group, name, id, \
+ TRACE_EVENT_FLAG_NONE)
+
+#define TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(category_group, name, id, \
+ snapshot) \
+ INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
+ TRACE_EVENT_PHASE_SNAPSHOT_OBJECT, category_group, name, \
+ id, TRACE_EVENT_FLAG_NONE, "snapshot", snapshot)
+
+#define TRACE_EVENT_OBJECT_DELETED_WITH_ID(category_group, name, id) \
+ INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
+ TRACE_EVENT_PHASE_DELETE_OBJECT, category_group, name, id, \
+ TRACE_EVENT_FLAG_NONE)
+
// Macro to efficiently determine if a given category group is enabled.
#define TRACE_EVENT_CATEGORY_GROUP_ENABLED(category_group, ret) \
do { \
@@ -118,6 +135,9 @@
#define TRACE_EVENT_PHASE_ASYNC_BEGIN ('S')
#define TRACE_EVENT_PHASE_ASYNC_END ('F')
#define TRACE_EVENT_PHASE_COUNTER ('C')
+#define TRACE_EVENT_PHASE_CREATE_OBJECT ('N')
+#define TRACE_EVENT_PHASE_SNAPSHOT_OBJECT ('O')
+#define TRACE_EVENT_PHASE_DELETE_OBJECT ('D')
// Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT.
#define TRACE_EVENT_FLAG_NONE (static_cast<unsigned int>(0))
diff --git a/tests/TracingTest.cpp b/tests/TracingTest.cpp
new file mode 100644
index 0000000000..e157cd70eb
--- /dev/null
+++ b/tests/TracingTest.cpp
@@ -0,0 +1,189 @@
+/*
+ * Copyright 2017 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "SkCommandLineFlags.h"
+#include "SkImageInfo.h"
+#include "SkLeanWindows.h"
+#include "SkPoint.h"
+#include "SkRect.h"
+#include "SkTraceEvent.h"
+#include "Test.h"
+
+DEFINE_bool(slowTracingTest, false, "Artificially slow down tracing test to produce nicer JSON");
+
+namespace {
+
+/**
+ * Helper types for demonstrating usage of TRACE_EVENT_OBJECT_XXX macros.
+ */
+struct TracingShape {
+ TracingShape() {
+ TRACE_EVENT_OBJECT_CREATED_WITH_ID("skia.objects", this->typeName(), this);
+ }
+ virtual ~TracingShape() {
+ TRACE_EVENT_OBJECT_DELETED_WITH_ID("skia.objects", this->typeName(), this);
+ }
+ void traceSnapshot() {
+ // The state of an object can be specified at any point with the OBJECT_SNAPSHOT macro.
+ // This takes the "name" (actually the type name), the ID of the object (typically a
+ // pointer), and a single (unnnamed) argument, which is the "snapshot" of that object.
+ //
+ // Tracing viewer requires that all object macros use the same name and id for creation,
+ // deletion, and snapshots. However: It's convenient to put creation and deletion in the
+ // base-class constructor/destructor where the actual type name isn't known yet. That's
+ // what we're doing here. The JSON for snapshots can therefore include the actual type
+ // name, and a special tag that refers to the type name originally used at creation time.
+ // Skia's JSON tracer handles this automatically, so SNAPSHOT macros can simply use the
+ // derived type name, and the JSON will be formatted correctly to link the events.
+ TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID("skia.objects", this->typeName(), this,
+ TRACE_STR_COPY(this->toString().c_str()));
+ }
+
+ virtual const char* typeName() { return "TracingShape"; }
+ virtual SkString toString() { return SkString("Shape()"); }
+};
+
+struct TracingCircle : public TracingShape {
+ TracingCircle(SkPoint center, SkScalar radius) : fCenter(center), fRadius(radius) {}
+ const char* typeName() override { return "TracingCircle"; }
+ SkString toString() override {
+ return SkStringPrintf("Circle(%f, %f, %f)", fCenter.fX, fCenter.fY, fRadius);
+ }
+
+ SkPoint fCenter;
+ SkScalar fRadius;
+};
+
+struct TracingRect : public TracingShape {
+ TracingRect(SkRect rect) : fRect(rect) {}
+ const char* typeName() override { return "TracingRect"; }
+ SkString toString() override {
+ return SkStringPrintf("Rect(%f, %f, %f, %f)",
+ fRect.fLeft, fRect.fTop, fRect.fRight, fRect.fBottom);
+ }
+
+ SkRect fRect;
+};
+
+}
+
+static SkScalar gTracingTestWorkSink = 1.0f;
+
+static void do_work(int howMuchWork) {
+ // Do busy work so the trace marker durations are large enough to be readable in trace viewer
+ if (FLAGS_slowTracingTest) {
+ for (int i = 0; i < howMuchWork * 100; ++i) {
+ gTracingTestWorkSink += SkScalarSin(i);
+ }
+ }
+}
+
+static void test_trace_simple() {
+ // Simple event that lasts until the end of the current scope. TRACE_FUNC is an easy way
+ // to insert the current function name.
+ TRACE_EVENT0("skia", TRACE_FUNC);
+
+ {
+ // There are versions of the macro that take 1 or 2 named arguments. The arguments
+ // can be any simple type. Strings need to be static/literal - we just copy pointers.
+ // Argument names & values are shown when the event is selected in the viewer.
+ TRACE_EVENT1("skia", "Nested work",
+ "isBGRA", kN32_SkColorType == kBGRA_8888_SkColorType);
+ do_work(500);
+ }
+
+ {
+ // If you must copy a string as an argument value, use the TRACE_STR_COPY macro.
+ // This will instruct the tracing system (if one is active) to make a copy.
+ SkString message = SkStringPrintf("%s %s", "Hello", "World");
+ TRACE_EVENT1("skia", "Dynamic String", "message", TRACE_STR_COPY(message.c_str()));
+ do_work(500);
+ }
+}
+
+static void test_trace_counters() {
+ TRACE_EVENT0("skia", TRACE_FUNC);
+
+ {
+ TRACE_EVENT0("skia", "Single Counter");
+
+ // Counter macros allow recording a named value (which must be a 32-bit integer).
+ // The value will be graphed in the viewer.
+ for (int i = 0; i < 180; ++i) {
+ SkScalar rad = SkDegreesToRadians(SkIntToScalar(i));
+ TRACE_COUNTER1("skia", "sin", SkScalarSin(rad) * 1000.0f + 1000.0f);
+ do_work(10);
+ }
+ }
+
+ {
+ TRACE_EVENT0("skia", "Independent Counters");
+
+ // Recording multiple counters with separate COUNTER1 macros will make separate graphs.
+ for (int i = 0; i < 180; ++i) {
+ SkScalar rad = SkDegreesToRadians(SkIntToScalar(i));
+ SkScalar cos;
+ SkScalar sin = SkScalarSinCos(rad, &cos);
+ TRACE_COUNTER1("skia", "sin", sin * 1000.0f + 1000.0f);
+ TRACE_COUNTER1("skia", "cos", cos * 1000.0f + 1000.0f);
+ do_work(10);
+ }
+ }
+
+ {
+ TRACE_EVENT0("skia", "Stacked Counters");
+
+ // Two counters can be recorded together with COUNTER2. They will be graphed together,
+ // as a stacked bar graph. The combined graph needs a name, as does each data series.
+ for (int i = 0; i < 180; ++i) {
+ SkScalar rad = SkDegreesToRadians(SkIntToScalar(i));
+ SkScalar cos;
+ SkScalar sin = SkScalarSinCos(rad, &cos);
+ TRACE_COUNTER2("skia", "trig",
+ "sin", sin * 1000.0f + 1000.0f,
+ "cos", cos * 1000.0f + 1000.0f);
+ do_work(10);
+ }
+ }
+}
+
+static void test_trace_objects() {
+ TRACE_EVENT0("skia", TRACE_FUNC);
+
+ // Objects can be tracked through time with the TRACE_EVENT_OBJECT_ macros.
+ // The macros in use (and their idiosyncracies) are commented in the TracingShape class above.
+
+ TracingCircle* circle = new TracingCircle(SkPoint::Make(20, 20), 15);
+ circle->traceSnapshot();
+ do_work(100);
+
+ // Make another object. Objects with the same base type are shown in the same row in the viewer.
+ TracingRect* rect = new TracingRect(SkRect::MakeWH(100, 50));
+ rect->traceSnapshot();
+ do_work(100);
+
+ // We can create multiple snapshots of objects to reflect their state over time.
+ circle->fCenter.offset(10, 10);
+ circle->traceSnapshot();
+
+ {
+ // Other events (duration or instant) can refer directly to objects. For Skia's JSON
+ // tracer, having an argument whose name starts with '#' will trigger the creation of JSON
+ // that links the event to the object (with a direct link to the most recent snapshot).
+ TRACE_EVENT1("skia", "Processing Shape", "#shape", circle);
+ do_work(100);
+ }
+
+ delete circle;
+ delete rect;
+}
+
+DEF_TEST(Tracing, reporter) {
+ test_trace_simple();
+ test_trace_counters();
+ test_trace_objects();
+}
diff --git a/tools/trace/SkChromeTracingTracer.cpp b/tools/trace/SkChromeTracingTracer.cpp
index 4f424f8801..fd9e8d1c3d 100644
--- a/tools/trace/SkChromeTracingTracer.cpp
+++ b/tools/trace/SkChromeTracingTracer.cpp
@@ -56,6 +56,7 @@ SkEventTracer::Handle SkChromeTracingTracer::addTraceEvent(char phase,
traceEvent.fNumArgs = numArgs;
traceEvent.fName = name;
traceEvent.fCategory = fCategories.getCategoryGroupName(categoryEnabledFlag);
+ traceEvent.fID = id;
traceEvent.fClockBegin = std::chrono::high_resolution_clock::now().time_since_epoch().count();
traceEvent.fClockEnd = 0;
traceEvent.fThreadID = SkGetThreadID();
@@ -85,12 +86,51 @@ void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnab
traceEvent->fClockEnd = std::chrono::high_resolution_clock::now().time_since_epoch().count();
}
-Json::Value SkChromeTracingTracer::traceEventToJson(const TraceEvent& traceEvent) {
+static Json::Value trace_value_to_json(uint64_t argValue, uint8_t argType) {
+ skia::tracing_internals::TraceValueUnion value;
+ value.as_uint = argValue;
+
+ switch (argType) {
+ case TRACE_VALUE_TYPE_BOOL:
+ return Json::Value(value.as_bool);
+ case TRACE_VALUE_TYPE_UINT:
+ return Json::Value(static_cast<Json::UInt64>(value.as_uint));
+ case TRACE_VALUE_TYPE_INT:
+ return Json::Value(static_cast<Json::Int64>(value.as_uint));
+ case TRACE_VALUE_TYPE_DOUBLE:
+ return Json::Value(value.as_double);
+ case TRACE_VALUE_TYPE_POINTER:
+ return Json::Value(SkStringPrintf("%p", value.as_pointer).c_str());
+ case TRACE_VALUE_TYPE_STRING:
+ case TRACE_VALUE_TYPE_COPY_STRING:
+ return Json::Value(value.as_string);
+ default:
+ return Json::Value("<unknown type>");
+ }
+}
+
+Json::Value SkChromeTracingTracer::traceEventToJson(const TraceEvent& traceEvent,
+ BaseTypeResolver* baseTypeResolver) {
+ // We track the original (creation time) "name" of each currently live object, so we can
+ // automatically insert "base_name" fields in object snapshot events.
+ if (TRACE_EVENT_PHASE_CREATE_OBJECT == traceEvent.fPhase) {
+ SkASSERT(nullptr == baseTypeResolver->find(traceEvent.fID));
+ baseTypeResolver->set(traceEvent.fID, traceEvent.fName);
+ } else if (TRACE_EVENT_PHASE_DELETE_OBJECT == traceEvent.fPhase) {
+ SkASSERT(nullptr != baseTypeResolver->find(traceEvent.fID));
+ baseTypeResolver->remove(traceEvent.fID);
+ }
+
Json::Value json;
char phaseString[2] = { traceEvent.fPhase, 0 };
json["ph"] = phaseString;
json["name"] = traceEvent.fName;
json["cat"] = traceEvent.fCategory;
+ if (0 != traceEvent.fID) {
+ // IDs are (almost) always pointers
+ json["id"] = SkStringPrintf("%p", traceEvent.fID).c_str();
+ }
+ // Convert nanoseconds to microseconds (standard time unit for tracing JSON files)
json["ts"] = static_cast<double>(traceEvent.fClockBegin) * 1E-3;
if (0 != traceEvent.fClockEnd) {
json["dur"] = static_cast<double>(traceEvent.fClockEnd - traceEvent.fClockBegin) * 1E-3;
@@ -99,37 +139,44 @@ Json::Value SkChromeTracingTracer::traceEventToJson(const TraceEvent& traceEvent
// Trace events *must* include a process ID, but for internal tools this isn't particularly
// important (and certainly not worth adding a cross-platform API to get it).
json["pid"] = 0;
+
if (traceEvent.fNumArgs) {
Json::Value args;
- skia::tracing_internals::TraceValueUnion value;
for (int i = 0; i < traceEvent.fNumArgs; ++i) {
- value.as_uint = traceEvent.fArgValues[i];
- switch (traceEvent.fArgTypes[i]) {
- case TRACE_VALUE_TYPE_BOOL:
- args[traceEvent.fArgNames[i]] = value.as_bool;
- break;
- case TRACE_VALUE_TYPE_UINT:
- args[traceEvent.fArgNames[i]] = static_cast<Json::UInt64>(value.as_uint);
- break;
- case TRACE_VALUE_TYPE_INT:
- args[traceEvent.fArgNames[i]] = static_cast<Json::Int64>(value.as_uint);
- break;
- case TRACE_VALUE_TYPE_DOUBLE:
- args[traceEvent.fArgNames[i]] = value.as_double;
- break;
- case TRACE_VALUE_TYPE_POINTER:
- args[traceEvent.fArgNames[i]] = value.as_pointer;
- break;
- case TRACE_VALUE_TYPE_STRING:
- case TRACE_VALUE_TYPE_COPY_STRING:
- args[traceEvent.fArgNames[i]] = value.as_string;
- break;
- default:
- args[traceEvent.fArgNames[i]] = "<unknown type>";
- break;
+ Json::Value argValue = trace_value_to_json(traceEvent.fArgValues[i],
+ traceEvent.fArgTypes[i]);
+ if (traceEvent.fArgNames[i] && '#' == traceEvent.fArgNames[i][0]) {
+ // Interpret #foo as an ID reference
+ Json::Value idRef;
+ idRef["id_ref"] = argValue;
+ args[traceEvent.fArgNames[i] + 1] = idRef;
+ } else {
+ args[traceEvent.fArgNames[i]] = argValue;
}
}
- json["args"] = args;
+ if (TRACE_EVENT_PHASE_SNAPSHOT_OBJECT == traceEvent.fPhase &&
+ baseTypeResolver->find(traceEvent.fID) &&
+ 0 != strcmp(*baseTypeResolver->find(traceEvent.fID), traceEvent.fName)) {
+ // Special handling for snapshots where the name differs from creation.
+ // We start with args = { "snapshot": "Object info" }
+
+ // Inject base_type. args = { "snapshot": "Object Info", "base_type": "BaseFoo" }
+ args["base_type"] = *baseTypeResolver->find(traceEvent.fID);
+
+ // Wrap this up in a new dict, again keyed by "snapshot". The inner "snapshot" is now
+ // arbitrary, but we don't have a better name (and the outer key *must* be snapshot).
+ // snapshot = { "snapshot": { "snapshot": "Object Info", "base_type": "BaseFoo" } }
+ Json::Value snapshot;
+ snapshot["snapshot"] = args;
+
+ // Now insert that whole thing as the event's args.
+ // { "name": "DerivedFoo", "id": "0x12345678, ...
+ // "args": { "snapshot": { "snapshot": "Object Info", "base_type": "BaseFoo" } }
+ // }, ...
+ json["args"] = snapshot;
+ } else {
+ json["args"] = args;
+ }
}
return json;
}
@@ -138,15 +185,16 @@ void SkChromeTracingTracer::flush() {
SkAutoMutexAcquire lock(fMutex);
Json::Value root(Json::arrayValue);
+ BaseTypeResolver baseTypeResolver;
for (int i = 0; i < fBlocks.count(); ++i) {
for (int j = 0; j < kEventsPerBlock; ++j) {
- root.append(this->traceEventToJson(fBlocks[i][j]));
+ root.append(this->traceEventToJson(fBlocks[i][j], &baseTypeResolver));
}
}
for (int i = 0; i < fEventsInCurBlock; ++i) {
- root.append(this->traceEventToJson(fCurBlock[i]));
+ root.append(this->traceEventToJson(fCurBlock[i], &baseTypeResolver));
}
SkString dirname = SkOSPath::Dirname(fFilename.c_str());
diff --git a/tools/trace/SkChromeTracingTracer.h b/tools/trace/SkChromeTracingTracer.h
index 4a749081b9..987031641b 100644
--- a/tools/trace/SkChromeTracingTracer.h
+++ b/tools/trace/SkChromeTracingTracer.h
@@ -13,6 +13,7 @@
#include "SkJSONCPP.h"
#include "SkSpinlock.h"
#include "SkString.h"
+#include "SkTHash.h"
/**
* A SkEventTracer implementation that logs events to JSON for viewing with chrome://tracing.
@@ -48,7 +49,7 @@ private:
void flush();
enum {
- // Events are currently 80 bytes, assuming 64-bit pointers and reasonable packing.
+ // Events are currently 88 bytes, assuming 64-bit pointers and reasonable packing.
// This is a first guess at a number that balances memory usage vs. time overhead of
// allocating blocks.
kEventsPerBlock = 10000,
@@ -65,6 +66,7 @@ private:
const char* fName;
const char* fCategory;
+ uint64_t fID;
uint64_t fClockBegin;
uint64_t fClockEnd;
SkThreadID fThreadID;
@@ -75,8 +77,10 @@ private:
typedef std::unique_ptr<TraceEvent[]> BlockPtr;
BlockPtr createBlock();
+
+ typedef SkTHashMap<uint64_t, const char*> BaseTypeResolver;
TraceEvent* appendEvent(const TraceEvent&);
- Json::Value traceEventToJson(const TraceEvent&);
+ Json::Value traceEventToJson(const TraceEvent&, BaseTypeResolver* baseTypeResolver);
SkString fFilename;
SkSpinlock fMutex;
generated by cgit v1.2.3 (git 2.39.1) at 2024-06-07 13:15:44 +0000