Implement iOS startup time tracing (#2355)

* Fix scripts to work on macOS

* Implement iOS startup time tracing

* chmod Startup

* Revert "chmod Startup"

This reverts commit 9ce4445.

* Move .logarchive to TMPDIR

* Add comment about host/device time

* Add warmup iteration and kill app after each run

Author: akoeplinger

src/scenarios/init.sh

@@ -1,3 +1,5 @@
+#!/bin/sh
+
 print_usage() {
     echo "***Please run this script as SOURCE. ex: . ./init.sh***"
     echo "This script sets up PYTHONPATH and determines which dotnet to use."
@@ -32,17 +34,17 @@ export PYTHONPATH=$PYTHONPATH:$scriptPath:$absolutePath
 echo "PYTHONPATH=$PYTHONPATH"
 
 # Parse arguments
-if [ "$1" == "-help" ] || [ "$1" == "-h" ]
+if [ "$1" = "-help" ] || [ "$1" = "-h" ]
 then
     print_usage
 elif [ "$#" -gt 2 ]
 then 
     print_usage
-elif [ "$1" == "-dotnetdir" ] && [ "$2" != "" ]
+elif [ "$1" = "-dotnetdir" ] && [ "$2" != "" ]
 then
     dotnetDirectory="$2"
     setup_env $dotnetDirectory
-elif [ "$1" == "-channel" ] && [ "$2" != "" ]
+elif [ "$1" = "-channel" ] && [ "$2" != "" ]
 then
     channel="$2"
     download_dotnet $channel

src/scenarios/shared/runner.py

@@ -8,13 +8,15 @@
 import glob
 import re
 import time
+from datetime import datetime
+import json
 
 from logging import exception, getLogger
 from collections import namedtuple
 from argparse import ArgumentParser
 from argparse import RawTextHelpFormatter
 from io import StringIO
-from shutil import move
+from shutil import move, rmtree
 from shared.crossgen import CrossgenArguments
 from shared.startup import StartupWrapper
 from shared.util import publishedexe, pythoncommand, appfolder, xharnesscommand
@@ -57,12 +59,12 @@ def parseargs(self):
 
         # parse only command
         parseonlyparser = subparsers.add_parser(const.DEVICESTARTUP,
-                                              description='measure time to main for Android apps')
+                                              description='measure time to startup for Android/iOS apps')
         parseonlyparser.add_argument('--device-type', choices=['android','ios'],type=str.lower,help='Device type for testing', dest='devicetype')
         parseonlyparser.add_argument('--package-path', help='Location of test application', dest='packagepath')
-        parseonlyparser.add_argument('--package-name', help='Classname of application', dest='packagename')
+        parseonlyparser.add_argument('--package-name', help='Classname (Android) or Bundle ID (iOS) of application', dest='packagename')
         parseonlyparser.add_argument('--startup-iterations', help='Startups to run (1+)', type=int, default=10, dest='startupiterations')
-        parseonlyparser.add_argument('--disable-animations', help='Disable Android device animations', action='store_true', dest='animationsdisabled')
+        parseonlyparser.add_argument('--disable-animations', help='Disable Android device animations, does nothing on iOS.', action='store_true', dest='animationsdisabled')
         self.add_common_arguments(parseonlyparser)
 
         # inner loop command
@@ -306,7 +308,7 @@ def run(self):
             startup.runtests(self.traits)
 
 
-        elif self.testtype == const.DEVICESTARTUP:
+        elif self.testtype == const.DEVICESTARTUP and self.devicetype == 'android':
             # ADB Key Event corresponding numbers: https://gist.github.com/arjunv/2bbcca9a1a1c127749f8dcb6d36fb0bc
             # Regex used to split the response from starting the activity and saving each value
             #Example:
@@ -327,7 +329,7 @@ def run(self):
                     getLogger().info("Removed: " + os.path.join(const.TRACEDIR, file))
                     os.remove(file)
 
-            cmdline = xharnesscommand() + [self.devicetype, 'state', '--adb']
+            cmdline = xharnesscommand() + ['android', 'state', '--adb']
             adb = RunCommand(cmdline, verbose=True)
             adb.run()
 
@@ -427,7 +429,7 @@ def run(self):
                 getLogger().info(f"Animation values successfully set to {animationValue}.")
 
             installCmd = xharnesscommand() + [
-                self.devicetype,
+                'android',
                 'install',
                 '--app', self.packagepath,
                 '--package-name',
@@ -588,6 +590,184 @@ def run(self):
             self.traits.add_traits(overwrite=True, apptorun="app", startupmetric=const.STARTUP_DEVICETIMETOMAIN, tracefolder='PerfTest/', tracename='runoutput.trace', scenarioname=self.scenarioname)
             startup.parsetraces(self.traits)
 
+        elif self.testtype == const.DEVICESTARTUP and self.devicetype == 'ios':
+
+            getLogger().info("Clearing potential previous run nettraces")
+            for file in glob.glob(os.path.join(const.TRACEDIR, 'PerfTest', 'runoutput.trace')):
+                if exists(file):   
+                    getLogger().info("Removed: " + os.path.join(const.TRACEDIR, file))
+                    os.remove(file)
+
+            if not exists(const.TMPDIR):
+                os.mkdir(const.TMPDIR)
+
+            getLogger().info("Clearing potential previous run *.logarchive")
+            for logarchive in glob.glob(os.path.join(const.TMPDIR, '*.logarchive')):
+                if exists(logarchive):
+                    getLogger().info("Removed: " + os.path.join(const.TMPDIR, logarchive))
+                    rmtree(logarchive)
+
+            getLogger().info("Checking device state.")
+            cmdline = xharnesscommand() + ['apple', 'state']
+            adb = RunCommand(cmdline, verbose=True)
+            adb.run()
+
+            getLogger().info("Installing app on device.")
+            installCmd = xharnesscommand() + [
+                'apple',
+                'install',
+                '--app', self.packagepath,
+                '--target', 'ios-device',
+                '-o',
+                const.TRACEDIR,
+                '-v'
+            ]
+            RunCommand(installCmd, verbose=True).run()
+            getLogger().info("Completed install.")
+
+            allResults = []
+            for i in range(self.startupiterations + 1): # adding one iteration to account for the warmup iteration
+                getLogger().info("Waiting 10 secs to ensure we're not getting confused with previous app run.")
+                time.sleep(10)
+
+                getLogger().info(f"Collect startup data for iteration {i}.")
+                runCmdTimestamp = datetime.now()
+                runCmd = xharnesscommand() + [
+                    'apple',
+                    'mlaunch',
+                    '--',
+                    f'--launchdevbundleid={self.packagename}',
+                ]
+                runCmdCommand = RunCommand(runCmd, verbose=True)
+                runCmdCommand.run()
+                app_pid_search = re.search("Launched application.*with pid (?P<app_pid>\d+)", runCmdCommand.stdout)
+                app_pid = int(app_pid_search.group('app_pid'))
+
+                logarchive_filename = os.path.join(const.TMPDIR, f'iteration{i}.logarchive')
+                getLogger().info(f"Waiting 5 secs to ensure app with PID {app_pid} is fully started.")
+                time.sleep(5)
+                collectCmd = [
+                    'sudo',
+                    'log',
+                    'collect',
+                    '--device',
+                    '--start', runCmdTimestamp.strftime("%Y-%m-%d %H:%M:%S"),
+                    '--output', logarchive_filename,
+                ]
+                RunCommand(collectCmd, verbose=True).run()
+
+                getLogger().info(f"Kill app with PID {app_pid}.")
+                killCmd = xharnesscommand() + [
+                    'apple',
+                    'mlaunch',
+                    '--',
+                    f'--killdev={app_pid}',
+                ]
+                killCmdCommand = RunCommand(killCmd, verbose=True)
+                killCmdCommand.run()
+
+                # Process Data
+
+                # There are four watchdog events from SpringBoard during an application startup:
+                #
+                # [application<net.dot.maui>:770] [realTime] Now monitoring resource allowance of 20.00s (at refreshInterval -1.00s)
+                # [application<net.dot.maui>:770] [realTime] Stopped monitoring.
+                # [application<net.dot.maui>:770] [realTime] Now monitoring resource allowance of 19.28s (at refreshInterval -1.00s)
+                # [application<net.dot.maui>:770] [realTime] Stopped monitoring.
+                #
+                # The first two are monitoring the time it takes the OS to create the process, load .dylibs and call into the app's main()
+                # The second two are monitoring the time it takes the app to draw the first frame of UI from main()
+                #
+                # An app has 20 seconds to complete this sequence or the OS will kill the app.
+                # We collect these log events to do our measurements.
+
+                logShowCmd = [
+                    'log',
+                    'show',
+                    '--predicate', '(process == "SpringBoard") && (category == "Watchdog")',
+                    '--info',
+                    '--style', 'ndjson',
+                    logarchive_filename,
+                ]
+                logShowCmdCommand = RunCommand(logShowCmd, verbose=True)
+                logShowCmdCommand.run()
+
+                events = []
+                for line in logShowCmdCommand.stdout.splitlines():
+                    try:
+                        lineData = json.loads(line)
+                        if 'Now monitoring resource allowance' in lineData['eventMessage'] or 'Stopped monitoring' in lineData['eventMessage']:
+                            events.append (lineData)
+                    except:
+                        break
+
+                # the startup measurement relies on the date/time of the device to be pretty much in sync with the host
+                # since we use the timestamps from the host to decide which parts of the device log to get and
+                # we then use that to calculate the time delta from watchdog events
+                if len(events) != 4:
+                    raise Exception("Didn't get the right amount of watchdog events, this could mean the app crashed or the device clock is not in sync with the host.")
+
+                timeToMainEventStart = events[0]
+                timeToMainEventStop = events[1]
+                timeToFirstDrawEventStart = events[2]
+                timeToFirstDrawEventStop = events[3]
+
+                # validate log messages
+                if f'application<{self.packagename}>:{app_pid}' not in timeToMainEventStart['eventMessage'] or 'Now monitoring resource allowance of 20.00s' not in timeToMainEventStart['eventMessage']:
+                    raise Exception(f"Invalid timeToMainEventStart: {timeToMainEventStart['eventMessage']}")
+
+                if f'application<{self.packagename}>:{app_pid}' not in timeToMainEventStop['eventMessage'] or 'Stopped monitoring' not in timeToMainEventStop['eventMessage']:
+                    raise Exception(f"Invalid timeToMainEventStop: {timeToMainEventStop['eventMessage']}")
+
+                if f'application<{self.packagename}>:{app_pid}' not in timeToFirstDrawEventStart['eventMessage'] or 'Now monitoring resource allowance of' not in timeToFirstDrawEventStart['eventMessage']:
+                    raise Exception(f"Invalid timeToFirstDrawEventStart: {timeToFirstDrawEventStart['eventMessage']}")
+
+                if f'application<{self.packagename}>:{app_pid}' not in timeToFirstDrawEventStop['eventMessage'] or 'Stopped monitoring' not in timeToFirstDrawEventStop['eventMessage']:
+                    raise Exception(f"Invalid timeToFirstDrawEventStop: {timeToFirstDrawEventStop['eventMessage']}")
+
+                timeToMainEventStartDateTime = datetime.strptime(timeToMainEventStart['timestamp'], '%Y-%m-%d %H:%M:%S.%f%z')
+                timeToMainEventEndDateTime = datetime.strptime(timeToMainEventStop['timestamp'], '%Y-%m-%d %H:%M:%S.%f%z')
+                timeToMainMilliseconds = (timeToMainEventEndDateTime - timeToMainEventStartDateTime).total_seconds() * 1000
+
+                timeToFirstDrawEventStartDateTime = datetime.strptime(timeToFirstDrawEventStart['timestamp'], '%Y-%m-%d %H:%M:%S.%f%z')
+                timeToFirstDrawEventEndDateTime = datetime.strptime(timeToFirstDrawEventStop['timestamp'], '%Y-%m-%d %H:%M:%S.%f%z')
+                timeToFirstDrawMilliseconds = (timeToFirstDrawEventEndDateTime - timeToFirstDrawEventStartDateTime).total_seconds() * 1000
+
+                totalTimeMilliseconds = timeToMainMilliseconds + timeToFirstDrawMilliseconds
+
+                if i == 0:
+                    # ignore the warmup iteration
+                    getLogger().info(f'Warmup iteration took {totalTimeMilliseconds}')
+                else:
+                    # TODO: this isn't really a COLD run, we should have separate measurements for starting the app right after install
+                    launchState = 'COLD'
+                    allResults.append(f'LaunchState: {launchState}\nTotalTime: {int(totalTimeMilliseconds)}\nTimeToMain: {int(timeToMainMilliseconds)}\n\n')
+
+            # Done with testing, uninstall the app
+            getLogger().info("Uninstalling app")
+            uninstallAppCmd = xharnesscommand() + [
+                'apple',
+                'uninstall',
+                '--app', self.packagename,
+                '--target', 'ios-device',
+                '-o',
+                const.TRACEDIR,
+                '-v'
+            ]
+            RunCommand(uninstallAppCmd, verbose=True).run()
+
+            # Create traces to store the data so we can keep the current general parse trace flow
+            getLogger().info(f"Logs: \n{allResults}")
+            os.makedirs(f"{const.TRACEDIR}/PerfTest", exist_ok=True)
+            traceFile = open(f"{const.TRACEDIR}/PerfTest/runoutput.trace", "w")
+            for result in allResults:
+                traceFile.write(result)
+            traceFile.close()
+
+            startup = StartupWrapper()
+            self.traits.add_traits(overwrite=True, apptorun="app", startupmetric=const.STARTUP_DEVICETIMETOMAIN, tracefolder='PerfTest/', tracename='runoutput.trace', scenarioname=self.scenarioname)
+            startup.parsetraces(self.traits)
+
         elif self.testtype == const.SOD:
             sod = SODWrapper()
             builtdir = const.PUBDIR if os.path.exists(const.PUBDIR) else None

src/scenarios/shared/util.py

@@ -42,6 +42,8 @@ def getruntimeidentifier():
         rid = 'win-'
     elif sys.platform == 'linux' or sys.platform == 'linux2':
         rid = 'linux-'
+    elif sys.platform == 'darwin':
+        rid = 'osx-'
     else:
         raise Exception('Platform %s not supported.' % sys.platform)