blob: 88cd78e1382d58ef92b955e09e2277222ebc2721 [file] [log] [blame]
// Copyright 2019 The Fuchsia 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 "src/ui/scenic/lib/scheduling/frame_stats.h"
#include <lib/async-loop/cpp/loop.h>
#include <lib/async-loop/default.h>
#include <lib/async/cpp/executor.h>
#include <lib/fit/bridge.h>
#include <lib/fit/defer.h>
#include <lib/gtest/real_loop_fixture.h>
#include <lib/gtest/test_loop_fixture.h>
#include <thread>
#include <gmock/gmock.h>
#include <gtest/gtest.h>
#include "lib/inspect/cpp/inspect.h"
#include "lib/inspect/cpp/reader.h"
#include "lib/inspect/service/cpp/reader.h"
#include "lib/inspect/service/cpp/service.h"
#include "lib/inspect/testing/cpp/inspect.h"
#include "src/lib/cobalt/cpp/testing/mock_cobalt_logger.h"
#include "src/ui/scenic/lib/gfx/tests/mocks/mocks.h"
#include "src/ui/scenic/lib/scheduling/frame_timings.h"
namespace scheduling {
namespace test {
using inspect::Hierarchy;
using inspect::Node;
using testing::AllOf;
using testing::IsEmpty;
using testing::SizeIs;
using testing::UnorderedElementsAre;
using namespace inspect::testing;
using cobalt::LogMethod::kLogIntHistogram;
constexpr char kFrameStatsNodeName[] = "FrameStatsTest";
// Note: this is following |garnet/public/lib/inspect/tests/reader_unittest.cc|
// to trigger execution of a LazyStringProperty.
class FrameStatsTest : public gtest::RealLoopFixture {
public:
static constexpr char kObjectsName[] = "diagnostics";
FrameStatsTest() : inspector_(), executor_(dispatcher()) {
handler_ = inspect::MakeTreeHandler(&inspector_, dispatcher());
}
void SchedulePromise(fit::pending_task promise) { executor_.schedule_task(std::move(promise)); }
// Helper function for test boiler plate.
fit::result<Hierarchy> ReadInspectVmo() {
fuchsia::inspect::TreePtr ptr;
handler_(ptr.NewRequest());
fit::result<Hierarchy> ret;
SchedulePromise(inspect::ReadFromTree(std::move(ptr)).then([&](fit::result<Hierarchy>& val) {
ret = std::move(val);
}));
RunLoopUntil([&] { return ret.is_ok() || ret.is_error(); });
return ret;
}
protected:
inspect::Inspector inspector_;
private:
async::Executor executor_;
fidl::InterfaceRequestHandler<fuchsia::inspect::Tree> handler_;
};
namespace {
// Struct which contains pointers to nodes/properties read from the inspect::Hierarchy
// reported by FrameStats.
struct FrameStatsHierarchyPointers {
bool AllPointersPopulated() {
return entire_history && recent_frames && recent_delayed_frames &&
entire_history_props.total_frame_count && entire_history_props.delayed_frame_count &&
entire_history_props.dropped_frame_count;
}
const inspect::Hierarchy* entire_history = nullptr;
const inspect::Hierarchy* recent_frames = nullptr;
const inspect::Hierarchy* recent_delayed_frames = nullptr;
struct {
const inspect::UintPropertyValue* total_frame_count = nullptr;
const inspect::UintPropertyValue* delayed_frame_count = nullptr;
const inspect::UintPropertyValue* dropped_frame_count = nullptr;
} entire_history_props;
};
// Returns a newly-populated FrameStatsHierarchyPointers struct.
FrameStatsHierarchyPointers GetFrameStatsHierarchyPointers(inspect::Hierarchy* root) {
const std::string kEntireHistoryName = "0 - Entire History";
const std::string kRecentFramesName = "1 - Recent Frame Stats (times in ms)";
const std::string kRecentDelayedFramesName = "2 - Recent Delayed Frame Stats (times in ms)";
const std::string kTotalFrameCount = "Total Frame Count";
const std::string kDelayedFrameCount = "Delayed Frame Count (missed VSYNC)";
const std::string kDroppedFrameCount = "Dropped Frame Count";
FrameStatsHierarchyPointers ret;
ret.entire_history = root->GetByPath({kFrameStatsNodeName, kEntireHistoryName});
ret.recent_frames = root->GetByPath({kFrameStatsNodeName, kRecentFramesName});
ret.recent_delayed_frames = root->GetByPath({kFrameStatsNodeName, kRecentDelayedFramesName});
if (ret.entire_history) {
ret.entire_history_props.total_frame_count =
ret.entire_history->node().get_property<inspect::UintPropertyValue>(kTotalFrameCount);
ret.entire_history_props.delayed_frame_count =
ret.entire_history->node().get_property<inspect::UintPropertyValue>(kDelayedFrameCount);
ret.entire_history_props.dropped_frame_count =
ret.entire_history->node().get_property<inspect::UintPropertyValue>(kDroppedFrameCount);
}
return ret;
}
} // anonymous namespace
TEST_F(FrameStatsTest, SmokeTest_TriggerLazyStringProperties) {
FrameStats stats(inspector_.GetRoot().CreateChild(kFrameStatsNodeName), nullptr);
auto root = ReadInspectVmo().take_value();
auto pointers = GetFrameStatsHierarchyPointers(&root);
ASSERT_TRUE(pointers.AllPointersPopulated());
EXPECT_EQ(pointers.entire_history->node().properties().size(), 5U);
EXPECT_EQ(pointers.recent_frames->node().properties().size(), 4U);
EXPECT_EQ(pointers.recent_delayed_frames->node().properties().size(), 4U);
}
TEST_F(FrameStatsTest, SmokeTest_DummyFrameTimings) {
FrameStats stats(inspector_.GetRoot().CreateChild(kFrameStatsNodeName), nullptr);
const zx::duration vsync_interval = zx::msec(16);
FrameTimings::Timestamps frame_times = {
.latch_point_time = zx::time(0) + zx::msec(4),
.update_done_time = zx::time(0) + zx::msec(6),
.render_start_time = zx::time(0) + zx::msec(6),
.render_done_time = zx::time(0) + zx::msec(12),
.target_presentation_time = zx::time(0) + zx::msec(16),
.actual_presentation_time = zx::time(0) + zx::msec(16),
};
for (int i = 0; i < 200; i++) {
stats.RecordFrame(frame_times, vsync_interval);
frame_times.latch_point_time += zx::msec(16);
frame_times.update_done_time += zx::msec(16);
frame_times.render_start_time += zx::msec(16);
frame_times.render_done_time += zx::msec(16);
frame_times.target_presentation_time += zx::msec(16);
frame_times.actual_presentation_time += zx::msec(16);
}
FrameTimings::Timestamps dropped_times = {.latch_point_time = zx::time(0) + zx::msec(4),
.update_done_time = zx::time(0) + zx::msec(6),
.render_start_time = zx::time(0) + zx::msec(6),
.render_done_time = zx::time(0) + zx::msec(12),
.target_presentation_time = zx::time(0) + zx::msec(16),
.actual_presentation_time = FrameTimings::kTimeDropped};
for (int i = 0; i < 30; i++) {
stats.RecordFrame(dropped_times, vsync_interval);
dropped_times.latch_point_time += zx::msec(16);
dropped_times.update_done_time += zx::msec(16);
dropped_times.render_start_time += zx::msec(16);
dropped_times.render_done_time += zx::msec(16);
dropped_times.target_presentation_time += zx::msec(16);
}
FrameTimings::Timestamps delayed_times = {.latch_point_time = zx::time(0) + zx::msec(4),
.update_done_time = zx::time(0) + zx::msec(6),
.render_start_time = zx::time(0) + zx::msec(6),
.render_done_time = zx::time(0) + zx::msec(22),
.target_presentation_time = zx::time(0) + zx::msec(16),
.actual_presentation_time = zx::time(0) + zx::msec(32)};
for (int i = 0; i < 20; i++) {
stats.RecordFrame(delayed_times, vsync_interval);
delayed_times.latch_point_time = delayed_times.actual_presentation_time + zx::msec(1);
delayed_times.update_done_time = delayed_times.actual_presentation_time + zx::msec(4);
delayed_times.render_start_time = delayed_times.actual_presentation_time + zx::msec(4);
delayed_times.render_done_time = delayed_times.actual_presentation_time + zx::msec(20);
delayed_times.target_presentation_time = delayed_times.actual_presentation_time + zx::msec(16);
delayed_times.actual_presentation_time += zx::msec(32);
}
auto root = ReadInspectVmo().take_value();
auto pointers = GetFrameStatsHierarchyPointers(&root);
ASSERT_TRUE(pointers.AllPointersPopulated());
EXPECT_EQ(250U, pointers.entire_history_props.total_frame_count->value());
EXPECT_EQ(30U, pointers.entire_history_props.dropped_frame_count->value());
EXPECT_EQ(20U, pointers.entire_history_props.delayed_frame_count->value());
}
class FrameStatsCobaltTest : public gtest::TestLoopFixture {};
TEST_F(FrameStatsCobaltTest, LogFrameTimes) {
cobalt::CallCountMap cobalt_call_counts;
FrameStats stats(Node(), std::make_unique<cobalt::MockCobaltLogger>(&cobalt_call_counts));
const zx::duration vsync_interval = zx::msec(16);
FrameTimings::Timestamps ontime_frame_times = {
.latch_point_time = zx::time(0) + zx::msec(4),
.update_done_time = zx::time(0) + zx::msec(6),
.render_start_time = zx::time(0) + zx::msec(6),
.render_done_time = zx::time(0) + zx::msec(12),
.target_presentation_time = zx::time(0) + zx::msec(16),
.actual_presentation_time = zx::time(0) + zx::msec(16),
};
FrameTimings::Timestamps dropped_frame_times = {
.latch_point_time = zx::time(10) + zx::msec(4),
.update_done_time = zx::time(10) + zx::msec(6),
.render_start_time = zx::time(10) + zx::msec(6),
.render_done_time = zx::time(10) + zx::msec(12),
.target_presentation_time = zx::time(10) + zx::msec(16),
.actual_presentation_time = FrameTimings::kTimeDropped};
FrameTimings::Timestamps delayed_frame_times = {
.latch_point_time = zx::time(20) + zx::msec(4),
.update_done_time = zx::time(20) + zx::msec(6),
.render_start_time = zx::time(20) + zx::msec(6),
.render_done_time = zx::time(20) + zx::msec(22),
.target_presentation_time = zx::time(20) + zx::msec(16),
.actual_presentation_time = zx::time(20) + zx::msec(32)};
// No frame recorded. No logging needed.
EXPECT_TRUE(RunLoopFor(FrameStats::kCobaltDataCollectionInterval));
EXPECT_TRUE(cobalt_call_counts.empty());
stats.RecordFrame(ontime_frame_times, vsync_interval);
// Histograms will be flushed into Cobalt. One for on time latch to actual presentation time,
// one for rendering times
EXPECT_TRUE(RunLoopFor(FrameStats::kCobaltDataCollectionInterval));
EXPECT_EQ(cobalt_call_counts[kLogIntHistogram], (uint32_t)2);
// Since histograms were emptied, there should be no additional cobalt call count.
EXPECT_TRUE(RunLoopFor(FrameStats::kCobaltDataCollectionInterval));
EXPECT_EQ(cobalt_call_counts[kLogIntHistogram], (uint32_t)2);
stats.RecordFrame(ontime_frame_times, vsync_interval);
stats.RecordFrame(ontime_frame_times, vsync_interval);
stats.RecordFrame(dropped_frame_times, vsync_interval);
stats.RecordFrame(delayed_frame_times, vsync_interval);
stats.RecordFrame(ontime_frame_times, vsync_interval);
// Expect 4 histograms to be flushed into cobalt. One for rendering times,
// three for latch to actual presentation times (for ontime, dropped and delayed).
EXPECT_TRUE(RunLoopFor(FrameStats::kCobaltDataCollectionInterval));
EXPECT_EQ(cobalt_call_counts[kLogIntHistogram], (uint32_t)(2 + 4));
}
} // namespace test
} // namespace scheduling