From b6705c25362fff0298f098631cbd939b0d2898b5 Mon Sep 17 00:00:00 2001 From: Brian Osman Date: Tue, 1 Aug 2017 10:23:38 -0400 Subject: 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 Commit-Queue: Brian Osman --- tools/trace/SkChromeTracingTracer.cpp | 106 ++++++++++++++++++++++++---------- tools/trace/SkChromeTracingTracer.h | 8 ++- 2 files changed, 83 insertions(+), 31 deletions(-) (limited to 'tools/trace') 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(value.as_uint)); + case TRACE_VALUE_TYPE_INT: + return Json::Value(static_cast(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(""); + } +} + +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(traceEvent.fClockBegin) * 1E-3; if (0 != traceEvent.fClockEnd) { json["dur"] = static_cast(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(value.as_uint); - break; - case TRACE_VALUE_TYPE_INT: - args[traceEvent.fArgNames[i]] = static_cast(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]] = ""; - 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 BlockPtr; BlockPtr createBlock(); + + typedef SkTHashMap BaseTypeResolver; TraceEvent* appendEvent(const TraceEvent&); - Json::Value traceEventToJson(const TraceEvent&); + Json::Value traceEventToJson(const TraceEvent&, BaseTypeResolver* baseTypeResolver); SkString fFilename; SkSpinlock fMutex; -- cgit v1.2.3