Merge pull request #591 from devoncarew/log_time

print logging timestamps to profile app launch

packages/flutter_tools/lib/executable.dart

@@ -32,14 +32,21 @@ import 'src/process.dart';
 ///
 /// This function is intended to be used from the [flutter] command line tool.
 Future main(List<String> args) async {
+  DateTime startTime = new DateTime.now();
+
   // This level can be adjusted by users through the `--verbose` option.
   Logger.root.level = Level.WARNING;
   Logger.root.onRecord.listen((LogRecord record) {
+    String prefix = '';
+    if (Logger.root.level <= Level.FINE) {
+      Duration elapsed = record.time.difference(startTime);
+      prefix = '[${elapsed.inMilliseconds.toString().padLeft(4)} ms] ';
+    }
     String level = record.level.name.toLowerCase();
     if (record.level >= Level.WARNING) {
-      stderr.writeln('$level: ${record.message}');
+      stderr.writeln('$prefix$level: ${record.message}');
     } else {
-      print('$level: ${record.message}');
+      print('$prefix$level: ${record.message}');
     }
     if (record.error != null)
       stderr.writeln(record.error);

packages/flutter_tools/lib/src/commands/build.dart

@@ -9,6 +9,7 @@ import 'dart:typed_data';
 import 'package:archive/archive.dart';
 import 'package:flx/bundle.dart';
 import 'package:flx/signing.dart';
+import 'package:logging/logging.dart';
 import 'package:path/path.dart' as path;
 import 'package:yaml/yaml.dart';
 
@@ -21,6 +22,8 @@ const List<String> _kDensities = const ['drawable-xxhdpi'];
 const List<String> _kThemes = const ['white', 'black'];
 const List<int> _kSizes = const [18, 24, 36, 48];
 
+final Logger _logging = new Logger('flutter_tools.build');
+
 class _Asset {
   final String base;
   final String key;
@@ -179,6 +182,8 @@ class BuildCommand extends FlutterCommand {
     String privateKeyPath: _kDefaultPrivateKeyPath,
     bool precompiledSnapshot: false
   }) async {
+    _logging.fine('Building $outputPath');
+
     Map manifestDescriptor = _loadManifest(manifestPath);
 
     Iterable<_Asset> assets = _parseAssets(manifestDescriptor, manifestPath);

packages/flutter_tools/lib/src/commands/daemon.dart

@@ -25,8 +25,6 @@ final Logger _logging = new Logger('flutter_tools.daemon');
 // TODO: Create a `device` domain in order to list devices and fire events when
 // devices are added or removed.
 
-// TODO: Is this the best name? Server? Daemon?
-
 /// A server process command. This command will start up a long-lived server.
 /// It reads JSON-RPC based commands from stdin, executes them, and returns
 /// JSON-RPC based responses and events to stdout.

packages/flutter_tools/lib/src/commands/start.dart

@@ -51,6 +51,8 @@ class StartCommand extends FlutterCommand {
 
   @override
   Future<int> runInProject() async {
+    _logging.fine('downloading toolchain');
+
     await Future.wait([
       downloadToolchain(),
       downloadApplicationPackagesAndConnectToDevices(),
@@ -58,10 +60,14 @@ class StartCommand extends FlutterCommand {
 
     bool poke = argResults['poke'];
     if (!poke) {
+      _logging.fine('running stop command');
+
       StopCommand stopper = new StopCommand();
       stopper.inheritFromParent(this);
       stopper.stop();
 
+      _logging.fine('running install command');
+
       // Only install if the user did not specify a poke
       InstallCommand installer = new InstallCommand();
       installer.inheritFromParent(this);
@@ -74,6 +80,7 @@ class StartCommand extends FlutterCommand {
       ApplicationPackage package = applicationPackages.getPackageForPlatform(device.platform);
       if (package == null || !device.isConnected())
         continue;
+
       if (device is AndroidDevice) {
         String mainPath = findMainDartFile(argResults['target']);
         if (!FileSystemEntity.isFileSync(mainPath)) {
@@ -84,11 +91,15 @@ class StartCommand extends FlutterCommand {
           continue;
         }
 
+        _logging.fine('running build command for $device');
+
         BuildCommand builder = new BuildCommand();
         builder.inheritFromParent(this);
         await builder.buildInTempDir(
           mainPath: mainPath,
           onBundleAvailable: (String localBundlePath) {
+            _logging.fine('running start bundle for $device');
+
             if (device.startBundle(package, localBundlePath,
                                    poke: poke,
                                    checked: argResults['checked'],
@@ -97,6 +108,8 @@ class StartCommand extends FlutterCommand {
           }
         );
       } else {
+        _logging.fine('running start command for $device');
+
         if (await device.startApp(package))
           startedSomething = true;
       }
@@ -110,6 +123,8 @@ class StartCommand extends FlutterCommand {
       }
     }
 
+    _logging.fine('finished start command');
+
     return startedSomething ? 0 : 2;
   }
 }

packages/flutter_tools/lib/src/device.dart

@@ -43,6 +43,8 @@ abstract class Device {
 
   /// Stop an app package on the current device
   Future<bool> stopApp(ApplicationPackage app);
+
+  String toString() => '$runtimeType $id';
 }
 
 class IOSDevice extends Device {
@@ -773,6 +775,8 @@ class AndroidDevice extends Device {
     bool checked,
     String route
   }) {
+    _logging.fine('$this startBundle');
+
     if (!FileSystemEntity.isFileSync(bundlePath)) {
       _logging.severe('Cannot find $bundlePath');
       return false;

packages/flutter_tools/lib/src/process.dart

@@ -87,15 +87,13 @@ String _runWithLoggingSync(List<String> cmd, {
   if (results.exitCode != 0) {
     String errorDescription = 'Error code ${results.exitCode} '
         'returned when attempting to run command: ${cmd.join(' ')}';
-    _logging.fine(errorDescription);
-    if (results.stderr.length > 0) {
+    _logging.info(errorDescription);
+    if (results.stderr.length > 0)
       _logging.info('Errors logged: ${results.stderr.trim()}');
-    }
-
-    if (checked) {
+    if (checked)
       throw errorDescription;
   }
-  }
+  if (results.stdout.trim().isNotEmpty)
     _logging.fine(results.stdout.trim());
   return results.stdout;
 }