chrome/browser/ash/dbus/arc_tracing_service_provider_unittest.cc

// Copyright 2024 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "chrome/browser/ash/dbus/arc_tracing_service_provider.h"

#include <memory>
#include <utility>

#include "base/files/scoped_temp_dir.h"
#include "base/strings/string_util.h"
#include "base/strings/stringprintf.h"
#include "base/test/scoped_feature_list.h"
#include "base/test/test_file_util.h"
#include "base/time/time.h"
#include "chrome/browser/ash/arc/tracing/overview_tracing_handler.h"
#include "chrome/browser/ash/arc/tracing/test/overview_tracing_test_base.h"
#include "chrome/browser/ash/arc/tracing/test/overview_tracing_test_handler.h"
#include "chromeos/ash/components/dbus/services/service_provider_test_helper.h"
#include "chromeos/ash/experiences/arc/test/arc_task_window_builder.h"
#include "chromeos/dbus/missive/missive_client.h"
#include "components/exo/surface.h"
#include "content/public/test/browser_task_environment.h"
#include "dbus/exported_object.h"
#include "dbus/message.h"
#include "testing/gmock/include/gmock/gmock.h"
#include "testing/gtest/include/gtest/gtest.h"
#include "third_party/cros_system_api/dbus/service_constants.h"

using ::testing::_;
using ::testing::ElementsAre;
using ::testing::Eq;

namespace ash {
namespace {

class TestProvider : public ArcTracingServiceProvider {
 public:
  // Supplies the handler used for the next trace, used by tests to prepare the
  // handler before the trace begins.
  arc::OverviewTracingTestHandler* GetOrCreateNextHandler() {
    if (!next_handler_) {
      next_handler_ = std::make_unique<arc::OverviewTracingTestHandler>(
          arc::OverviewTracingHandler::ArcWindowFocusChangeCb());
    }
    return next_handler_.get();
  }

 private:
  std::unique_ptr<arc::OverviewTracingHandler> NewHandler() override {
    // Make sure a handler is ready to go - ignore return.
    GetOrCreateNextHandler();

    return std::move(next_handler_);
  }

  std::unique_ptr<arc::OverviewTracingTestHandler> next_handler_;
};

class ArcTracingServiceProviderTest : public arc::OverviewTracingTestBase {
 protected:
  void SetUp() override {
    arc::OverviewTracingTestBase::SetUp();

    chromeos::MissiveClient::InitializeFake();

    provider_ = std::make_unique<TestProvider>();

    CHECK(trace_outdir_.CreateUniqueTempDir());
    provider_->set_trace_outdir_for_testing(trace_outdir_.GetPath());

    // Set arbitrary times for tests which fail to start a trace or don't
    // attempt to - we don't actually use the times because a model file is not
    // generated, but at least make the times non-zero.
    auto* first_handler = provider_->GetOrCreateNextHandler();
    first_handler->set_now(
        base::Time::FromSecondsSinceUnixEpoch(1'700'009'000));
    first_handler->set_trace_time_base(
        base::Time::FromSecondsSinceUnixEpoch(1'700'000'000));
  }

  void SetupForRequest(std::string_view method_name) {
    test_helper_.SetUp(arc::tracing::kArcTracingServiceName,
                       dbus::ObjectPath(arc::tracing::kArcTracingServicePath),
                       arc::tracing::kArcTracingInterfaceName,
                       std::string(method_name), provider_.get());
  }

  std::string InvokeStartMethod(double max_time_seconds) {
    SetupForRequest(arc::tracing::kArcTracingStartMethod);
    dbus::MethodCall call{arc::tracing::kArcTracingInterfaceName,
                          arc::tracing::kArcTracingStartMethod};
    dbus::MessageWriter writer{&call};
    writer.AppendDouble(max_time_seconds);
    auto response = test_helper_.CallMethod(&call);

    dbus::MessageReader reader{response.get()};
    std::string response_msg;
    CHECK(reader.PopString(&response_msg));
    test_helper_.TearDown();
    return response_msg;
  }

  std::string InvokeGetStatusMethod() {
    SetupForRequest(arc::tracing::kArcTracingGetStatusMethod);
    dbus::MethodCall call{arc::tracing::kArcTracingInterfaceName,
                          arc::tracing::kArcTracingGetStatusMethod};
    dbus::MessageWriter writer{&call};
    auto response = test_helper_.CallMethod(&call);

    dbus::MessageReader reader{response.get()};
    std::vector<std::string> response_msgs;
    std::string msg;
    while (reader.PopString(&msg)) {
      response_msgs.emplace_back(std::move(msg));
    }
    test_helper_.TearDown();
    return base::JoinString(response_msgs, "\n");
  }

  void TearDown() override {
    provider_.reset();
    chromeos::MissiveClient::Shutdown();
    arc::OverviewTracingTestBase::TearDown();
  }

  std::unique_ptr<TestProvider> provider_;
  base::ScopedTempDir trace_outdir_;
  ServiceProviderTestHelper test_helper_;
};

// The times and timezones in each test below were chosen arbitrarily to
// verify we are formatting the times via the correct API and not ignoring
// timezone settings.

TEST_F(ArcTracingServiceProviderTest, StartTraceAndGetStatus) {
  SetTimeZone("Asia/Chongqing");
  auto* handler = provider_->GetOrCreateNextHandler();

  base::Time time_base;
  ASSERT_TRUE(base::Time::FromString("2023-11-15 08:43:20 +0800", &time_base));
  handler->set_now(time_base + base::Seconds(2));
  handler->set_trace_time_base(time_base);

  exo::Surface s;
  auto arc_widget = arc::ArcTaskWindowBuilder()
                        .SetTaskId(22)
                        .SetPackageName("org.funstuff.client")
                        .SetShellRootSurface(&s)
                        .BuildOwnsNativeWidget();

  auto max_time = base::Seconds(5);
  arc_widget->Show();
  ASSERT_EQ("Trace started", InvokeStartMethod(max_time.InSecondsF()));

  EXPECT_EQ("Trace started", InvokeGetStatusMethod());

  handler->StartTracingOnControllerRespond();

  // Present 60 frames per second until end of trace time.
  auto frame_time = base::Microseconds(16'666);
  CommitAndPresentFrames(handler, &s, max_time / frame_time, frame_time);

  // Fast forward past the max tracing interval. This will stop the trace at the
  // end of the fast-forward, which is 400ms after the timeout. There are no
  // events here, so this does not add to the trace duration, so it does not
  // deflate the FPS measurement.
  FastForwardClockAndTaskQueue(handler, base::Milliseconds(400));

  // Pass results from trace controller to handler.
  handler->StopTracingOnControllerRespond(
      std::make_unique<std::string>(arc::kBasicSystrace));

  task_environment()->RunUntilIdle();

  re2::RE2 expected_msg_re{
      base::StrCat({"Trace started\n", "Building model...\n",
                    "Tracing model is ready: ", trace_outdir_.GetPath().value(),
                    "/overview_tracing_arctaskwindowdefaulttitle_2023-11-15_08-"
                    "43-22.json - ",
                    "perceived FPS=([0-9.]+), ", "duration=([0-9.]+)s"})};

  double fps, duration;
  std::string actual_msg = InvokeGetStatusMethod();

  ASSERT_TRUE(RE2::FullMatch(actual_msg, expected_msg_re, &fps, &duration))
      << actual_msg;
  EXPECT_NEAR(fps, 60, 0.5);
  EXPECT_NEAR(duration, 5, 0.2);
}

TEST_F(ArcTracingServiceProviderTest, StopTraceByLosingFocus) {
  SetTimeZone("Europe/Madrid");
  auto* handler = provider_->GetOrCreateNextHandler();
  base::Time time_base;
  ASSERT_TRUE(base::Time::FromString("2024-01-12 12:30:00 +0100", &time_base));
  handler->set_now(time_base + base::Hours(1));
  handler->set_trace_time_base(time_base);

  exo::Surface s;
  auto arc_widget = arc::ArcTaskWindowBuilder()
                        .SetTaskId(22)
                        .SetPackageName("org.funstuff.client")
                        .SetShellRootSurface(&s)
                        .BuildOwnsNativeWidget();

  auto max_time = base::Seconds(5);
  arc_widget->Show();
  ASSERT_EQ("Trace started", InvokeStartMethod(max_time.InSecondsF()));

  EXPECT_EQ("Trace started", InvokeGetStatusMethod());

  handler->StartTracingOnControllerRespond();

  // Present frames at 24 fps until 1 second before end of trace. This alone
  // does not stop the test since we don't hit the time limit.
  const auto frame_time = base::Milliseconds(42);
  CommitAndPresentFrames(
      handler, &s, (max_time - base::Seconds(1)) / frame_time, frame_time);

  // Minimizing window will lose focus and stop the trace.
  arc_widget->Minimize();

  // Pass results from trace controller to handler.
  handler->StopTracingOnControllerRespond(
      std::make_unique<std::string>(arc::kBasicSystrace));

  task_environment()->RunUntilIdle();

  re2::RE2 expected_msg_re{
      base::StrCat({"Trace started\n", "Building model...\n",
                    "Tracing model is ready: ", trace_outdir_.GetPath().value(),
                    "/overview_tracing_arctaskwindowdefaulttitle_2024-01-12_13-"
                    "30-00.json - ",
                    "perceived FPS=([0-9.]+), ", "duration=([0-9.]+)s"})};

  double fps, duration;
  std::string actual_msg = InvokeGetStatusMethod();

  ASSERT_TRUE(RE2::FullMatch(actual_msg, expected_msg_re, &fps, &duration))
      << actual_msg;
  EXPECT_NEAR(fps, 24, 0.5);
  EXPECT_NEAR(duration, 4, 0.2);
}

TEST_F(ArcTracingServiceProviderTest, FailedStart) {
  exo::Surface s;
  auto arc_widget = arc::ArcTaskWindowBuilder()
                        .SetTaskId(22)
                        .SetPackageName("org.funstuff.client")
                        .SetShellRootSurface(&s)
                        .BuildOwnsNativeWidget();
  arc_widget->ShowInactive();

  ASSERT_EQ("ARC window isn't active", InvokeStartMethod(5));

  EXPECT_EQ("", InvokeGetStatusMethod());
}

TEST_F(ArcTracingServiceProviderTest, FailedStartDueToOneExtraWindow) {
  exo::Surface arc_surface, extra_surface;
  auto arc_widget = arc::ArcTaskWindowBuilder()
                        .SetTaskId(22)
                        .SetPackageName("org.funstuff.client")
                        .SetShellRootSurface(&arc_surface)
                        .BuildOwnsNativeWidget();
  auto extra_widget = arc::ArcTaskWindowBuilder()
                          .SetTaskId(2244)
                          .SetPackageName("net.productive.notfun")
                          .SetShellRootSurface(&arc_surface)
                          .SetTitle("Looking busy")
                          .BuildOwnsNativeWidget();

  extra_widget->Show();
  arc_widget->Show();

  provider_->GetOrCreateNextHandler()->set_non_trace_app_windows(
      {extra_widget->GetNativeWindow()});
  ASSERT_EQ(
      "Extra windows are open. Close them and try the trace again: |Looking "
      "busy|",
      InvokeStartMethod(/*max_time_seconds=*/5));
}

TEST_F(ArcTracingServiceProviderTest, FailedStartDueToTwoExtraWindows) {
  constexpr int kWidgetCount = 3;
  // Note the trace widget is shown last, so it is active.
  constexpr int kTraceWidget = 2;
  std::array<exo::Surface, kWidgetCount> surfaces;
  std::array<std::unique_ptr<views::Widget>, kWidgetCount> widgets;
  arc::OverviewTracingHandler::AppWindowList non_trace_windows;

  for (int i = 0; i < kWidgetCount; i++) {
    widgets[i] = arc::ArcTaskWindowBuilder()
                     .SetTaskId(220 + i)
                     .SetPackageName("org.funstuff.client")
                     .SetShellRootSurface(&surfaces[i])
                     .SetTitle(base::StringPrintf("arc window %d", i))
                     .BuildOwnsNativeWidget();
    widgets[i]->Show();
    if (i != kTraceWidget) {
      non_trace_windows.emplace_back(widgets[i]->GetNativeWindow());
    }
  }

  provider_->GetOrCreateNextHandler()->set_non_trace_app_windows(
      std::move(non_trace_windows));
  ASSERT_EQ(
      "Extra windows are open. Close them and try the trace again: |arc window "
      "0|, |arc window 1|",
      InvokeStartMethod(/*max_time_seconds=*/42.42));
}

}  // namespace
}  // namespace ash