src/tests/end_to_end/screen_is_not_black/test/screen_is_not_black_test.dart - fuchsia - Git at Google

 // 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.

 // TODO(https://fxbug.dev/84961): Fix null safety and remove this language version.
 // @dart=2.9

 import 'dart:convert';
 import 'dart:io';

 import 'package:args/args.dart';
 import 'package:image/image.dart';
 import 'package:logging/logging.dart';
 import 'package:sl4f/sl4f.dart' as sl4f;
 import 'package:test/test.dart';

 int _ignoreAlpha(int pixel) => pixel & 0x00ffffff;

 /// Returns true if [image] is all black.
 bool _isAllBlack(Image image) =>
     image.data.every((pixel) => _ignoreAlpha(pixel) == 0);

 /// How many times to check the screen.
 const _tries = 10;

 /// How long to wait between screen checks.
 const _delay = Duration(seconds: 10);

 /// The path to the catapult converter binary.  It must exist in the package.
 const _catapultConverterPath = 'runtime_deps/catapult_converter';

 /// Wait at most this long for reboot to ensure all programs of interest have
 /// hit their measurement checkpoints.
 const _maxTestRuntime = Duration(seconds: 90);

 /// Collects uptime information.
 class Uptime {
   // Elapsed time since last reboot.
   Duration sinceReboot;

   // Elapsed time from power-on until the time measurement was taken.  Could be
   // different than duration since reboot if the system monotonic clock is not
   // reset to zero.
   Duration sincePowerOn;

   // Low estimate for when reboot measurement was taken, from host side, wall clock.
   DateTime lowRebootWallClock;

   // High estimate for when reboot measurement was taken, from host side, wall clock.
   DateTime highRebootWallClock;

   Uptime(this.lowRebootWallClock, this.sinceReboot, this.highRebootWallClock,
       this.sincePowerOn);

   /// Returns an estimate of how long it was from Unix epoch to reboot.
   Duration sinceEpoch() {
     final Duration diff = highRebootWallClock.difference(lowRebootWallClock);
     final Duration halfDiff = Duration(microseconds: diff.inMicroseconds ~/ 2);
     final DateTime average = lowRebootWallClock.add(halfDiff);
     final rebootWallClock =
         average.difference(DateTime.fromMillisecondsSinceEpoch(0));
     return rebootWallClock - sinceReboot;
   }

   /// Elapsed time from power on until last reboot.
   Duration get rebootSincePowerOn => sincePowerOn - sinceReboot;
 }

 void main(List<String> args) {
   Logger.root
     ..level = Level.ALL
     ..onRecord.listen((rec) => print('[${rec.level}]: ${rec.message}'));

   final parser = ArgParser()
     ..addOption('start',
         allowed: ['tiles'],
         help: 'If set, starts the specified program on device startup');

   final argResults = parser.parse(args);
   final String start = argResults['start'];
   final bool startTiles = start == 'tiles';

   sl4f.Sl4f sl4fDriver;
   sl4f.Scenic scenicDriver;
   sl4f.Tiles tilesController;

   final performance = sl4f.Performance(sl4fDriver);

   final log = Logger('screen_is_not_black_test');
   if (start != null) {
     log.info('Starting $start');
   }

   setUp(() async {
     sl4fDriver = sl4f.Sl4f.fromEnvironment();
     await sl4fDriver.startServer();
     scenicDriver = sl4f.Scenic(sl4fDriver);
     tilesController = sl4f.Tiles(sl4fDriver);
   });

   tearDown(() async {
     await sl4fDriver.stopServer();
     sl4fDriver.close();
   });

   // Finds the duration passed between the instant system timer showed zero and
   // the instant timekeeper was started.
   //
   // Uptime is tricky.  The system's uptime as reported by the monotonic clock
   // apparently doesn't always get reset to zero on a reboot.  So we may get a
   // monotonic clock reading that is showing a reading based on a zero reference
   // point unrelated to a recent reboot.
   //
   // Here's a proposed pragmatic way out.  Seeing as timekeeper is started
   // fairly early in a device's lifetime, we try to detect how long ago
   // timekeeper was started with reference to the zero point of the monotonic
   // clock.  If this time was too far in the past, assume that the duration
   // timer was not reset.  If it was reasonably recently with respect to the
   // zero reference point (see _maxElapsedSincePowerOn), assume that the clock
   // was indeed starting at zero.  Otherwise adopt an arbitrary reference point
   // which places startup of timekeeper.cmx about 15 seconds after reboot.
   //
   // While this makes relative time measurements meaningless, we can still
   // compare successive runs and measure absolute time changes.
   Future<Uptime> findRebootTimestamp(sl4f.Inspect inspect) async {
     final lowRebootWallClock = DateTime.now();
     final healthRoot = await inspect.snapshotRoot('timekeeper.cmx');
     final highRebootWallClock = DateTime.now();

     if (healthRoot == null) {
       log.info(
           'Timekeeper inspect root not found, using zero uptime values instead.');
       return Uptime(
           DateTime.now(), Duration.zero, DateTime.now(), Duration.zero);
     }

     final uptimeNanos = healthRoot['initialization']['monotonic'];
     if (uptimeNanos == null) {
       log.info(
           'Timekeeper init time not found, using zero uptime values instead.');
       return Uptime(
           DateTime.now(), Duration.zero, DateTime.now(), Duration.zero);
     }

     final uptime = Duration(microseconds: uptimeNanos ~/ 1e3);
     return Uptime(lowRebootWallClock, uptime, highRebootWallClock, uptime);
   }

   List<sl4f.TestCaseResults> record(String programName, String nodeName,
       dynamic root, String metricName, String renamedMetric, Duration reboot) {
     final node = root[nodeName];
     if (node == null) {
       return [];
     }
     final metricValue = (node[metricName] ?? 0) ~/ 1e3;
     final duration = Duration(microseconds: metricValue);
     List<sl4f.TestCaseResults> results = [
       sl4f.TestCaseResults(
           '$renamedMetric/$programName', sl4f.Unit.milliseconds, [
         duration.inMilliseconds.toDouble() - reboot.inMilliseconds.toDouble()
       ])
     ];
     return results;
   }

   // Records all results under 'node'.  The content of 'node' is assumed to
   // consist only of timestamps.
   //
   // The optional renaming parameter is used to rename the final data point,
   // and thereby aggregate several metrics into one.
   List<sl4f.TestCaseResults> recordAll(String programName, String nodeName,
       dynamic root, String renamedMetrics, Duration reboot,
       {Map<Pattern, String> renaming}) {
     final node = root[nodeName];
     if (node == null) {
       return [];
     }
     List<sl4f.TestCaseResults> result = [];
     node.forEach((metric, measuredNanos) {
       final Duration vd = Duration(microseconds: measuredNanos ~/ 1e3);
       final Duration record = vd - reboot;
       var metricName = '$renamedMetrics/$programName/$metric';
       void replace(pattern, replacement) {
         metricName = metricName.replaceFirst(pattern, replacement);
       }

       renaming?.forEach(replace);
       result.add(sl4f.TestCaseResults(metricName, sl4f.Unit.milliseconds,
           [record.inMilliseconds.toDouble()]));
     });
     return result;
   }

   /// Exports the reboot timing results to a fuchsiaperf file.  Requires that
   /// the `catapult_converter` binary is added to the runtime_deps, see the
   /// BUILD.gn file in this directory for the mechanics.
   Future<void> exportTimings(String testSuite, Duration rebootDuration) async {
     var rebootResults = [
       // The host-side measurement of reboot duration.
       sl4f.TestCaseResults('Reboot', sl4f.Unit.milliseconds,
           [rebootDuration.inMilliseconds.toDouble()]),
     ];

     final inspect = sl4f.Inspect(sl4fDriver);
     final Uptime uptime = await findRebootTimestamp(inspect);

     // Collect all health nodes and other metrics relevant for the boot process
     // from the running programs.  Some programs, like 'timekeeper' and
     // `diagnostics-kcounter` are more interesting since they have metrics
     // useful for analyzing the timing of the boot process.
     final diagnostics = await inspect.snapshotAll();
     for (final inspectResult in diagnostics) {
       final label = inspectResult['moniker'];
       final payload = inspectResult['payload'];
       if (payload == null || payload['root'] == null) {
         log.warning(
             'Null payload/root for $label. Metadata: ${inspectResult['metadata']}');
         continue;
       }
       final rootNode = payload['root'];

       // For all nodes that have it, add health node information.
       rebootResults.addAll(record(
             label,
             'fuchsia.inspect.Health',
             rootNode,
             'start_timestamp_nanos',
             'TimeToStart',
             uptime.rebootSincePowerOn,
           ) +
           // Record all durations under the node named 'fuchsia.inspect.Timestamps'.
           recordAll(
             label,
             'fuchsia.inspect.Timestamps',
             rootNode,
             'Durations',
             uptime.sinceEpoch(),
             renaming: {
               RegExp(r'\/session-[0-9]+'): '/session-NNN',
             },
           ));
     }

     List<Map<String, dynamic>> results = [];
     for (final result in rebootResults) {
       results.add(result.toJson(testSuite: testSuite));
     }

     File fuchsiaPerfFile = await sl4f.Dump().writeAsString(
         'screen_is_not_black_test', 'fuchsiaperf.json', json.encode(results));
     await performance.convertResults(
         _catapultConverterPath, fuchsiaPerfFile, Platform.environment);
     log.info('Catapult file created.');
   }

   test('the startup screen is not black', () async {
     // Reboot Fuchsia so that we are testing the initial startup state.
     //
     // This is necessary because other tests (currently
     // garnet_input_latency_benchmarks_test) kill Scenic, which would cause this
     // test to fail.  We use this as an opportunity to record the time taken
     // to reboot as a performance test result.
     var rebootDuration = await sl4fDriver.reboot();
     try {
       if (startTiles) {
         await tilesController.start();
       }
       for (var attempt = 0; attempt < _tries; attempt++) {
         try {
           final screen = await scenicDriver.takeScreenshot(dumpName: 'screen');
           if (!_isAllBlack(screen)) {
             final pause = _maxTestRuntime - rebootDuration;
             print('Saw a screen that is not black; waiting for $pause now.');
             await Future.delayed(
                 pause, () => exportTimings('fuchsia.boot', rebootDuration));
             return;
           }
         } on sl4f.JsonRpcException {
           print('Error taking screenshot; Scenic might not be ready yet.');
         }
         await Future.delayed(_delay);
       }
       fail('Screen was all black.');
     } finally {
       if (startTiles) {
         await tilesController.stop();
       }
     }
   },
       // This is a large test that waits for the DUT to come up and to start
       // rendering something.
       timeout: Timeout.none);
 }
	// 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.

	// TODO(https://fxbug.dev/84961): Fix null safety and remove this language version.
	// @dart=2.9

	import 'dart:convert';
	import 'dart:io';

	import 'package:args/args.dart';
	import 'package:image/image.dart';
	import 'package:logging/logging.dart';
	import 'package:sl4f/sl4f.dart' as sl4f;
	import 'package:test/test.dart';

	int _ignoreAlpha(int pixel) => pixel & 0x00ffffff;

	/// Returns true if [image] is all black.
	bool _isAllBlack(Image image) =>
	image.data.every((pixel) => _ignoreAlpha(pixel) == 0);

	/// How many times to check the screen.
	const _tries = 10;

	/// How long to wait between screen checks.
	const _delay = Duration(seconds: 10);

	/// The path to the catapult converter binary. It must exist in the package.
	const _catapultConverterPath = 'runtime_deps/catapult_converter';

	/// Wait at most this long for reboot to ensure all programs of interest have
	/// hit their measurement checkpoints.
	const _maxTestRuntime = Duration(seconds: 90);

	/// Collects uptime information.
	class Uptime {
	// Elapsed time since last reboot.
	Duration sinceReboot;

	// Elapsed time from power-on until the time measurement was taken. Could be
	// different than duration since reboot if the system monotonic clock is not
	// reset to zero.
	Duration sincePowerOn;

	// Low estimate for when reboot measurement was taken, from host side, wall clock.
	DateTime lowRebootWallClock;

	// High estimate for when reboot measurement was taken, from host side, wall clock.
	DateTime highRebootWallClock;

	Uptime(this.lowRebootWallClock, this.sinceReboot, this.highRebootWallClock,
	this.sincePowerOn);

	/// Returns an estimate of how long it was from Unix epoch to reboot.
	Duration sinceEpoch() {
	final Duration diff = highRebootWallClock.difference(lowRebootWallClock);
	final Duration halfDiff = Duration(microseconds: diff.inMicroseconds ~/ 2);
	final DateTime average = lowRebootWallClock.add(halfDiff);
	final rebootWallClock =
	average.difference(DateTime.fromMillisecondsSinceEpoch(0));
	return rebootWallClock - sinceReboot;
	}

	/// Elapsed time from power on until last reboot.
	Duration get rebootSincePowerOn => sincePowerOn - sinceReboot;
	}

	void main(List<String> args) {
	Logger.root
	..level = Level.ALL
	..onRecord.listen((rec) => print('[${rec.level}]: ${rec.message}'));

	final parser = ArgParser()
	..addOption('start',
	allowed: ['tiles'],
	help: 'If set, starts the specified program on device startup');

	final argResults = parser.parse(args);
	final String start = argResults['start'];
	final bool startTiles = start == 'tiles';

	sl4f.Sl4f sl4fDriver;
	sl4f.Scenic scenicDriver;
	sl4f.Tiles tilesController;

	final performance = sl4f.Performance(sl4fDriver);

	final log = Logger('screen_is_not_black_test');
	if (start != null) {
	log.info('Starting $start');
	}

	setUp(() async {
	sl4fDriver = sl4f.Sl4f.fromEnvironment();
	await sl4fDriver.startServer();
	scenicDriver = sl4f.Scenic(sl4fDriver);
	tilesController = sl4f.Tiles(sl4fDriver);
	});

	tearDown(() async {
	await sl4fDriver.stopServer();
	sl4fDriver.close();
	});

	// Finds the duration passed between the instant system timer showed zero and
	// the instant timekeeper was started.
	//
	// Uptime is tricky. The system's uptime as reported by the monotonic clock
	// apparently doesn't always get reset to zero on a reboot. So we may get a
	// monotonic clock reading that is showing a reading based on a zero reference
	// point unrelated to a recent reboot.
	//
	// Here's a proposed pragmatic way out. Seeing as timekeeper is started
	// fairly early in a device's lifetime, we try to detect how long ago
	// timekeeper was started with reference to the zero point of the monotonic
	// clock. If this time was too far in the past, assume that the duration
	// timer was not reset. If it was reasonably recently with respect to the
	// zero reference point (see _maxElapsedSincePowerOn), assume that the clock
	// was indeed starting at zero. Otherwise adopt an arbitrary reference point
	// which places startup of timekeeper.cmx about 15 seconds after reboot.
	//
	// While this makes relative time measurements meaningless, we can still
	// compare successive runs and measure absolute time changes.
	Future<Uptime> findRebootTimestamp(sl4f.Inspect inspect) async {
	final lowRebootWallClock = DateTime.now();
	final healthRoot = await inspect.snapshotRoot('timekeeper.cmx');
	final highRebootWallClock = DateTime.now();

	if (healthRoot == null) {
	log.info(
	'Timekeeper inspect root not found, using zero uptime values instead.');
	return Uptime(
	DateTime.now(), Duration.zero, DateTime.now(), Duration.zero);
	}

	final uptimeNanos = healthRoot['initialization']['monotonic'];
	if (uptimeNanos == null) {
	log.info(
	'Timekeeper init time not found, using zero uptime values instead.');
	return Uptime(
	DateTime.now(), Duration.zero, DateTime.now(), Duration.zero);
	}

	final uptime = Duration(microseconds: uptimeNanos ~/ 1e3);
	return Uptime(lowRebootWallClock, uptime, highRebootWallClock, uptime);
	}

	List<sl4f.TestCaseResults> record(String programName, String nodeName,
	dynamic root, String metricName, String renamedMetric, Duration reboot) {
	final node = root[nodeName];
	if (node == null) {
	return [];
	}
	final metricValue = (node[metricName] ?? 0) ~/ 1e3;
	final duration = Duration(microseconds: metricValue);
	List<sl4f.TestCaseResults> results = [
	sl4f.TestCaseResults(
	'$renamedMetric/$programName', sl4f.Unit.milliseconds, [
	duration.inMilliseconds.toDouble() - reboot.inMilliseconds.toDouble()
	])
	];
	return results;
	}

	// Records all results under 'node'. The content of 'node' is assumed to
	// consist only of timestamps.
	//
	// The optional renaming parameter is used to rename the final data point,
	// and thereby aggregate several metrics into one.
	List<sl4f.TestCaseResults> recordAll(String programName, String nodeName,
	dynamic root, String renamedMetrics, Duration reboot,
	{Map<Pattern, String> renaming}) {
	final node = root[nodeName];
	if (node == null) {
	return [];
	}
	List<sl4f.TestCaseResults> result = [];
	node.forEach((metric, measuredNanos) {
	final Duration vd = Duration(microseconds: measuredNanos ~/ 1e3);
	final Duration record = vd - reboot;
	var metricName = '$renamedMetrics/$programName/$metric';
	void replace(pattern, replacement) {
	metricName = metricName.replaceFirst(pattern, replacement);
	}

	renaming?.forEach(replace);
	result.add(sl4f.TestCaseResults(metricName, sl4f.Unit.milliseconds,
	[record.inMilliseconds.toDouble()]));
	});
	return result;
	}

	/// Exports the reboot timing results to a fuchsiaperf file. Requires that
	/// the `catapult_converter` binary is added to the runtime_deps, see the
	/// BUILD.gn file in this directory for the mechanics.
	Future<void> exportTimings(String testSuite, Duration rebootDuration) async {
	var rebootResults = [
	// The host-side measurement of reboot duration.
	sl4f.TestCaseResults('Reboot', sl4f.Unit.milliseconds,
	[rebootDuration.inMilliseconds.toDouble()]),
	];

	final inspect = sl4f.Inspect(sl4fDriver);
	final Uptime uptime = await findRebootTimestamp(inspect);

	// Collect all health nodes and other metrics relevant for the boot process
	// from the running programs. Some programs, like 'timekeeper' and
	// `diagnostics-kcounter` are more interesting since they have metrics
	// useful for analyzing the timing of the boot process.
	final diagnostics = await inspect.snapshotAll();
	for (final inspectResult in diagnostics) {
	final label = inspectResult['moniker'];
	final payload = inspectResult['payload'];
	if (payload == null \|\| payload['root'] == null) {
	log.warning(
	'Null payload/root for $label. Metadata: ${inspectResult['metadata']}');
	continue;
	}
	final rootNode = payload['root'];

	// For all nodes that have it, add health node information.
	rebootResults.addAll(record(
	label,
	'fuchsia.inspect.Health',
	rootNode,
	'start_timestamp_nanos',
	'TimeToStart',
	uptime.rebootSincePowerOn,
	) +
	// Record all durations under the node named 'fuchsia.inspect.Timestamps'.
	recordAll(
	label,
	'fuchsia.inspect.Timestamps',
	rootNode,
	'Durations',
	uptime.sinceEpoch(),
	renaming: {
	RegExp(r'\/session-[0-9]+'): '/session-NNN',
	},
	));
	}

	List<Map<String, dynamic>> results = [];
	for (final result in rebootResults) {
	results.add(result.toJson(testSuite: testSuite));
	}

	File fuchsiaPerfFile = await sl4f.Dump().writeAsString(
	'screen_is_not_black_test', 'fuchsiaperf.json', json.encode(results));
	await performance.convertResults(
	_catapultConverterPath, fuchsiaPerfFile, Platform.environment);
	log.info('Catapult file created.');
	}

	test('the startup screen is not black', () async {
	// Reboot Fuchsia so that we are testing the initial startup state.
	//
	// This is necessary because other tests (currently
	// garnet_input_latency_benchmarks_test) kill Scenic, which would cause this
	// test to fail. We use this as an opportunity to record the time taken
	// to reboot as a performance test result.
	var rebootDuration = await sl4fDriver.reboot();
	try {
	if (startTiles) {
	await tilesController.start();
	}
	for (var attempt = 0; attempt < _tries; attempt++) {
	try {
	final screen = await scenicDriver.takeScreenshot(dumpName: 'screen');
	if (!_isAllBlack(screen)) {
	final pause = _maxTestRuntime - rebootDuration;
	print('Saw a screen that is not black; waiting for $pause now.');
	await Future.delayed(
	pause, () => exportTimings('fuchsia.boot', rebootDuration));
	return;
	}
	} on sl4f.JsonRpcException {
	print('Error taking screenshot; Scenic might not be ready yet.');
	}
	await Future.delayed(_delay);
	}
	fail('Screen was all black.');
	} finally {
	if (startTiles) {
	await tilesController.stop();
	}
	}
	},
	// This is a large test that waits for the DUT to come up and to start
	// rendering something.
	timeout: Timeout.none);
	}