// Copyright 2013 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "base/debug/trace_event.h" #include "base/json/json_writer.h" #include "base/memory/scoped_ptr.h" #include "base/strings/stringprintf.h" #include "ui/events/latency_info.h" #include <algorithm> namespace { const size_t kMaxLatencyInfoNumber = 100; const char* GetComponentName(ui::LatencyComponentType type) { #define CASE_TYPE(t) case ui::t: return #t switch (type) { CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_SCROLL_UPDATE_MAIN_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_RWH_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_FORWARD_SCROLL_UPDATE_TO_MAIN_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT); CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT); CASE_TYPE(WINDOW_OLD_SNAPSHOT_FRAME_NUMBER_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT); CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT); default: DLOG(WARNING) << "Unhandled LatencyComponentType.\n"; break; } #undef CASE_TYPE return "unknown"; } bool IsTerminalComponent(ui::LatencyComponentType type) { switch (type) { case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT: case ui::INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT: return true; default: return false; } } bool IsBeginComponent(ui::LatencyComponentType type) { return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT || type == ui::INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT || type == ui::INPUT_EVENT_LATENCY_BEGIN_SCROLL_UPDATE_MAIN_COMPONENT); } // This class is for converting latency info to trace buffer friendly format. class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat { public: static scoped_refptr<ConvertableToTraceFormat> FromValue( scoped_ptr<base::Value> value); virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE; private: explicit LatencyInfoTracedValue(base::Value* value); virtual ~LatencyInfoTracedValue(); scoped_ptr<base::Value> value_; DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue); }; scoped_refptr<base::debug::ConvertableToTraceFormat> LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) { return scoped_refptr<base::debug::ConvertableToTraceFormat>( new LatencyInfoTracedValue(value.release())); } LatencyInfoTracedValue::~LatencyInfoTracedValue() { } void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const { std::string tmp; base::JSONWriter::Write(value_.get(), &tmp); *out += tmp; } LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value) : value_(value) { } // Converts latencyinfo into format that can be dumped into trace buffer. scoped_refptr<base::debug::ConvertableToTraceFormat> AsTraceableData( const ui::LatencyInfo& latency) { scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue()); for (ui::LatencyInfo::LatencyMap::const_iterator it = latency.latency_components.begin(); it != latency.latency_components.end(); ++it) { base::DictionaryValue* component_info = new base::DictionaryValue(); component_info->SetDouble("comp_id", it->first.second); component_info->SetDouble("time", it->second.event_time.ToInternalValue()); component_info->SetDouble("count", it->second.event_count); record_data->Set(GetComponentName(it->first.first), component_info); } record_data->SetDouble("trace_id", latency.trace_id); scoped_ptr<base::ListValue> coordinates(new base::ListValue()); for (size_t i = 0; i < latency.input_coordinates_size; i++) { scoped_ptr<base::DictionaryValue> coordinate_pair( new base::DictionaryValue()); coordinate_pair->SetDouble("x", latency.input_coordinates[i].x); coordinate_pair->SetDouble("y", latency.input_coordinates[i].y); coordinates->Append(coordinate_pair.release()); } record_data->Set("coordinates", coordinates.release()); return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>()); } } // namespace namespace ui { LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) { } LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) { } LatencyInfo::LatencyInfo() : input_coordinates_size(0), trace_id(-1), terminated(false) { } LatencyInfo::~LatencyInfo() { } bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info, const char* referring_msg) { if (latency_info.size() > kMaxLatencyInfoNumber) { LOG(ERROR) << referring_msg << ", LatencyInfo vector size " << latency_info.size() << " is too big."; return false; } for (size_t i = 0; i < latency_info.size(); i++) { if (latency_info[i].input_coordinates_size > kMaxInputCoordinates) { LOG(ERROR) << referring_msg << ", coordinate vector size " << latency_info[i].input_coordinates_size << " is too big."; return false; } } return true; } void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other, LatencyComponentType type) { for (LatencyMap::const_iterator it = other.latency_components.begin(); it != other.latency_components.end(); ++it) { if (it->first.first == type) { AddLatencyNumberWithTimestamp(it->first.first, it->first.second, it->second.sequence_number, it->second.event_time, it->second.event_count); } } } void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) { for (LatencyMap::const_iterator it = other.latency_components.begin(); it != other.latency_components.end(); ++it) { if (!FindLatency(it->first.first, it->first.second, NULL)) { AddLatencyNumberWithTimestamp(it->first.first, it->first.second, it->second.sequence_number, it->second.event_time, it->second.event_count); } } } void LatencyInfo::AddLatencyNumber(LatencyComponentType component, int64 id, int64 component_sequence_number) { AddLatencyNumberWithTimestamp(component, id, component_sequence_number, base::TimeTicks::HighResNow(), 1); } void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component, int64 id, int64 component_sequence_number, base::TimeTicks time, uint32 event_count) { static const unsigned char* benchmark_enabled = TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark"); if (IsBeginComponent(component)) { // Should only ever add begin component once. CHECK_EQ(-1, trace_id); trace_id = component_sequence_number; if (*benchmark_enabled) { // The timestamp for ASYNC_BEGIN trace event is used for drawing the // beginning of the trace event in trace viewer. For better visualization, // for an input event, we want to draw the beginning as when the event is // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT, // not when we actually issue the ASYNC_BEGIN trace event. LatencyComponent component; int64 ts = 0; if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0, &component) || FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT, 0, &component)) { // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0 // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we // can't use a static value. int64 diff = base::TimeTicks::HighResNow().ToInternalValue() - base::TimeTicks::NowFromSystemTraceTime().ToInternalValue(); ts = component.event_time.ToInternalValue() - diff; } else { ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue(); } TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0( "benchmark", "InputLatency", TRACE_ID_DONT_MANGLE(trace_id), ts); } TRACE_EVENT_FLOW_BEGIN0( "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); } LatencyMap::key_type key = std::make_pair(component, id); LatencyMap::iterator it = latency_components.find(key); if (it == latency_components.end()) { LatencyComponent info = {component_sequence_number, time, event_count}; latency_components[key] = info; } else { it->second.sequence_number = std::max(component_sequence_number, it->second.sequence_number); uint32 new_count = event_count + it->second.event_count; if (event_count > 0 && new_count != 0) { // Do a weighted average, so that the new event_time is the average of // the times of events currently in this structure with the time passed // into this method. it->second.event_time += (time - it->second.event_time) * event_count / new_count; it->second.event_count = new_count; } } if (IsTerminalComponent(component) && trace_id != -1) { // Should only ever add terminal component once. CHECK(!terminated); terminated = true; if (*benchmark_enabled) { TRACE_EVENT_ASYNC_END1("benchmark", "InputLatency", TRACE_ID_DONT_MANGLE(trace_id), "data", AsTraceableData(*this)); } TRACE_EVENT_FLOW_END0( "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); } } bool LatencyInfo::FindLatency(LatencyComponentType type, int64 id, LatencyComponent* output) const { LatencyMap::const_iterator it = latency_components.find( std::make_pair(type, id)); if (it == latency_components.end()) return false; if (output) *output = it->second; return true; } void LatencyInfo::RemoveLatency(LatencyComponentType type) { LatencyMap::iterator it = latency_components.begin(); while (it != latency_components.end()) { if (it->first.first == type) { LatencyMap::iterator tmp = it; ++it; latency_components.erase(tmp); } else { it++; } } } void LatencyInfo::Clear() { latency_components.clear(); } void LatencyInfo::TraceEventType(const char* event_type) { TRACE_EVENT_ASYNC_STEP_INTO0("benchmark", "InputLatency", TRACE_ID_DONT_MANGLE(trace_id), event_type); } } // namespace ui