diff options
author | Brian Osman <brianosman@google.com> | 2017-08-01 10:23:38 -0400 |
---|---|---|
committer | Skia Commit-Bot <skia-commit-bot@chromium.org> | 2017-08-03 17:10:08 +0000 |
commit | b6705c25362fff0298f098631cbd939b0d2898b5 (patch) | |
tree | 3e3bcf33d084c2233a46a6a06d9a7fd043f73994 | |
parent | 29dbae9acf00bc6ffb9f7baa3438306029aa68cb (diff) |
Add support for object creation/snapshot/deletion events
- Bring back some previously deleted macros and helper types.
- Automatically inject base_type information into snapshot events,
to allow simpler tracking of polymorphic object types.
- Fix JSON formatting of pointer values (they were serializing as bool).
Bug: skia:
Change-Id: Iac7803f72ce5396ffd2fbcb5a36d76745c5e3f3e
Reviewed-on: https://skia-review.googlesource.com/28220
Reviewed-by: Mike Klein <mtklein@chromium.org>
Commit-Queue: Brian Osman <brianosman@google.com>
-rw-r--r-- | gn/tests.gni | 1 | ||||
-rw-r--r-- | src/core/SkTraceEvent.h | 51 | ||||
-rw-r--r-- | src/core/SkTraceEventCommon.h | 20 | ||||
-rw-r--r-- | tests/TracingTest.cpp | 189 | ||||
-rw-r--r-- | tools/trace/SkChromeTracingTracer.cpp | 106 | ||||
-rw-r--r-- | tools/trace/SkChromeTracingTracer.h | 8 |
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; |