testing/awsy/awsy/awsy_test_case.py

   1 # -*- Mode: python; c-basic-offset: 4; indent-tabs-mode: nil; tab-width: 40 -*-
   2 # vim: set filetype=python:
   3 # This Source Code Form is subject to the terms of the Mozilla Public
   4 # License, v. 2.0. If a copy of the MPL was not distributed with this
   5 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
   6
   7 import fnmatch
   8 import glob
   9 import gzip
  10 import json
  11 import os
  12 import shutil
  13 import sys
  14 import tempfile
  15 import time
  16
  17 import mozlog.structured
  18 from marionette_driver import Wait
  19 from marionette_driver.errors import JavascriptException, ScriptTimeoutException
  20 from marionette_driver.keys import Keys
  21 from marionette_harness import MarionetteTestCase
  22
  23 AWSY_PATH = os.path.dirname(os.path.dirname(os.path.realpath(__file__)))
  24 if AWSY_PATH not in sys.path:
  25     sys.path.append(AWSY_PATH)
  26
  27 from awsy import (
  28     ITERATIONS,
  29     MAX_TABS,
  30     PER_TAB_PAUSE,
  31     SETTLE_WAIT_TIME,
  32     process_perf_data,
  33 )
  34
  35
  36 class AwsyTestCase(MarionetteTestCase):
  37     """
  38     Base test case for AWSY tests.
  39     """
  40
  41     def urls(self):
  42         raise NotImplementedError()
  43
  44     def perf_suites(self):
  45         raise NotImplementedError()
  46
  47     def perf_checkpoints(self):
  48         raise NotImplementedError()
  49
  50     def perf_extra_opts(self):
  51         return None
  52
  53     def iterations(self):
  54         return self._iterations
  55
  56     def pages_to_load(self):
  57         return self._pages_to_load if self._pages_to_load else len(self.urls())
  58
  59     def settle(self):
  60         """
  61         Pauses for the settle time.
  62         """
  63         time.sleep(self._settleWaitTime)
  64
  65     def setUp(self):
  66         MarionetteTestCase.setUp(self)
  67
  68         self.logger = mozlog.structured.structuredlog.get_default_logger()
  69         self.marionette.set_context("chrome")
  70         self._resultsDir = self.testvars["resultsDir"]
  71
  72         self._binary = self.testvars["bin"]
  73         self._run_local = self.testvars.get("run_local", False)
  74
  75         # Cleanup our files from previous runs.
  76         for patt in (
  77             "memory-report-*.json.gz",
  78             "perfherder-data.json",
  79             "dmd-*.json.gz",
  80         ):
  81             for f in glob.glob(os.path.join(self._resultsDir, patt)):
  82                 os.unlink(f)
  83
  84         # Optional testvars.
  85         self._pages_to_load = self.testvars.get("entities", 0)
  86         self._iterations = self.testvars.get("iterations", ITERATIONS)
  87         self._perTabPause = self.testvars.get("perTabPause", PER_TAB_PAUSE)
  88         self._settleWaitTime = self.testvars.get("settleWaitTime", SETTLE_WAIT_TIME)
  89         self._maxTabs = self.testvars.get("maxTabs", MAX_TABS)
  90         self._dmd = self.testvars.get("dmd", False)
  91
  92         self.logger.info(
  93             "areweslimyet run by %d pages, %d iterations,"
  94             " %d perTabPause, %d settleWaitTime"
  95             % (
  96                 self._pages_to_load,
  97                 self._iterations,
  98                 self._perTabPause,
  99                 self._settleWaitTime,
 100             )
 101         )
 102         self.reset_state()
 103
 104     def tearDown(self):
 105         MarionetteTestCase.tearDown(self)
 106
 107         try:
 108             self.logger.info("processing data in %s!" % self._resultsDir)
 109             perf_blob = process_perf_data.create_perf_data(
 110                 self._resultsDir,
 111                 self.perf_suites(),
 112                 self.perf_checkpoints(),
 113                 self.perf_extra_opts(),
 114             )
 115             self.logger.info("PERFHERDER_DATA: %s" % json.dumps(perf_blob))
 116
 117             perf_file = os.path.join(self._resultsDir, "perfherder-data.json")
 118             with open(perf_file, "w") as fp:
 119                 json.dump(perf_blob, fp, indent=2)
 120             self.logger.info("Perfherder data written to %s" % perf_file)
 121         except Exception:
 122             raise
 123         finally:
 124             # Make sure we cleanup and upload any existing files even if there
 125             # were errors processing the perf data.
 126             if self._dmd:
 127                 self.cleanup_dmd()
 128
 129             # copy it to moz upload dir if set
 130             if "MOZ_UPLOAD_DIR" in os.environ:
 131                 for file in os.listdir(self._resultsDir):
 132                     file = os.path.join(self._resultsDir, file)
 133                     if os.path.isfile(file):
 134                         shutil.copy2(file, os.environ["MOZ_UPLOAD_DIR"])
 135
 136     def cleanup_dmd(self):
 137         """
 138         Handles moving DMD reports from the temp dir to our resultsDir.
 139         """
 140         from dmd import fixStackTraces
 141
 142         # Move DMD files from temp dir to resultsDir.
 143         tmpdir = tempfile.gettempdir()
 144         tmp_files = os.listdir(tmpdir)
 145         for f in fnmatch.filter(tmp_files, "dmd-*.json.gz"):
 146             f = os.path.join(tmpdir, f)
 147             # We don't fix stacks on Windows, even though we could, due to the
 148             # tale of woe in bug 1626272.
 149             if not sys.platform.startswith("win"):
 150                 self.logger.info("Fixing stacks for %s, this may take a while" % f)
 151                 isZipped = True
 152                 fixStackTraces(f, isZipped, gzip.open)
 153             shutil.move(f, self._resultsDir)
 154
 155         # Also attempt to cleanup the unified memory reports.
 156         for f in fnmatch.filter(tmp_files, "unified-memory-report-*.json.gz"):
 157             try:
 158                 os.remove(f)
 159             except OSError:
 160                 self.logger.info("Unable to remove %s" % f)
 161
 162     def reset_state(self):
 163         self._pages_loaded = 0
 164
 165         # Close all tabs except one
 166         for x in self.marionette.window_handles[1:]:
 167             self.logger.info("closing window: %s" % x)
 168             self.marionette.switch_to_window(x)
 169             self.marionette.close()
 170
 171         self._tabs = self.marionette.window_handles
 172         self.marionette.switch_to_window(self._tabs[0])
 173
 174     def do_memory_report(self, checkpointName, iteration, minimize=False):
 175         """Creates a memory report for all processes and and returns the
 176         checkpoint.
 177
 178         This will block until all reports are retrieved or a timeout occurs.
 179         Returns the checkpoint or None on error.
 180
 181         :param checkpointName: The name of the checkpoint.
 182
 183         :param minimize: If true, minimize memory before getting the report.
 184         """
 185         self.logger.info("starting checkpoint %s..." % checkpointName)
 186
 187         checkpoint_file = "memory-report-%s-%d.json.gz" % (checkpointName, iteration)
 188         checkpoint_path = os.path.join(self._resultsDir, checkpoint_file)
 189         # On Windows, replace / with the Windows directory
 190         # separator \ and escape it to prevent it from being
 191         # interpreted as an escape character.
 192         if sys.platform.startswith("win"):
 193             checkpoint_path = checkpoint_path.replace("\\", "\\\\").replace("/", "\\\\")
 194
 195         checkpoint_script = r"""
 196             let [resolve] = arguments;
 197             let dumper =
 198             Cc["@mozilla.org/memory-info-dumper;1"].getService(
 199             Ci.nsIMemoryInfoDumper);
 200             dumper.dumpMemoryReportsToNamedFile(
 201                 "%s",
 202                 () => resolve("memory report done!"),
 203                 null,
 204                 /* anonymize */ false,
 205                 /* minimize memory usage */ %s);
 206             """ % (
 207             checkpoint_path,
 208             "true" if minimize else "false",
 209         )
 210
 211         checkpoint = None
 212         try:
 213             finished = self.marionette.execute_async_script(
 214                 checkpoint_script, script_timeout=60000
 215             )
 216             if finished:
 217                 checkpoint = checkpoint_path
 218         except JavascriptException as e:
 219             self.logger.error("Checkpoint JavaScript error: %s" % e)
 220         except ScriptTimeoutException:
 221             self.logger.error("Memory report timed out")
 222         except Exception:
 223             self.logger.error("Unexpected error: %s" % sys.exc_info()[0])
 224         else:
 225             self.logger.info("checkpoint created, stored in %s" % checkpoint_path)
 226
 227         # Now trigger a DMD report if requested.
 228         if self._dmd:
 229             self.do_dmd(checkpointName, iteration)
 230
 231         return checkpoint
 232
 233     def do_dmd(self, checkpointName, iteration):
 234         """
 235         Triggers DMD reports that are used to help identify sources of
 236         'heap-unclassified'.
 237
 238         NB: This will dump DMD reports to the temp dir. Unfortunately it also
 239         dumps memory reports, but that's all we have to work with right now.
 240         """
 241         self.logger.info("Starting %s DMD reports..." % checkpointName)
 242
 243         ident = "%s-%d" % (checkpointName, iteration)
 244
 245         # TODO(ER): This actually takes a minimize argument. We could use that
 246         # rather than have a separate `do_gc` function. Also it generates a
 247         # memory report so we could combine this with `do_checkpoint`. The main
 248         # issue would be moving everything out of the temp dir.
 249         #
 250         # Generated files have the form:
 251         #   dmd-<checkpoint>-<iteration>-pid.json.gz, ie:
 252         #   dmd-TabsOpenForceGC-0-10885.json.gz
 253         #
 254         # and for the memory report:
 255         #   unified-memory-report-<checkpoint>-<iteration>.json.gz
 256         dmd_script = (
 257             r"""
 258             let dumper =
 259             Cc["@mozilla.org/memory-info-dumper;1"].getService(
 260             Ci.nsIMemoryInfoDumper);
 261             dumper.dumpMemoryInfoToTempDir(
 262                 "%s",
 263                 /* anonymize = */ false,
 264                 /* minimize = */ false);
 265             """
 266             % ident
 267         )
 268
 269         try:
 270             # This is async and there's no callback so we use the existence
 271             # of an incomplete memory report to check if it hasn't finished yet.
 272             self.marionette.execute_script(dmd_script, script_timeout=60000)
 273             tmpdir = tempfile.gettempdir()
 274             prefix = "incomplete-unified-memory-report-%s-%d-*" % (
 275                 checkpointName,
 276                 iteration,
 277             )
 278             max_wait = 240
 279             elapsed = 0
 280             while fnmatch.filter(os.listdir(tmpdir), prefix) and elapsed < max_wait:
 281                 self.logger.info("Waiting for memory report to finish")
 282                 time.sleep(1)
 283                 elapsed += 1
 284
 285             incomplete = fnmatch.filter(os.listdir(tmpdir), prefix)
 286             if incomplete:
 287                 # The memory reports never finished.
 288                 self.logger.error("Incomplete memory reports leftover.")
 289                 for f in incomplete:
 290                     os.remove(os.path.join(tmpdir, f))
 291
 292         except JavascriptException as e:
 293             self.logger.error("DMD JavaScript error: %s" % e)
 294         except ScriptTimeoutException:
 295             self.logger.error("DMD timed out")
 296         except Exception:
 297             self.logger.error("Unexpected error: %s" % sys.exc_info()[0])
 298         else:
 299             self.logger.info("DMD started, prefixed with %s" % ident)
 300
 301     def open_and_focus(self):
 302         """Opens the next URL in the list and focuses on the tab it is opened in.
 303
 304         A new tab will be opened if |_maxTabs| has not been exceeded, otherwise
 305         the URL will be loaded in the next tab.
 306         """
 307         page_to_load = self.urls()[self._pages_loaded % len(self.urls())]
 308         tabs_loaded = len(self._tabs)
 309         open_tab_script = r"""
 310             gBrowser.addTab("about:blank", {
 311                 inBackground: false,
 312                 triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),
 313             });
 314         """
 315
 316         if tabs_loaded < self._maxTabs and tabs_loaded <= self._pages_loaded:
 317             full_tab_list = self.marionette.window_handles
 318
 319             self.marionette.execute_script(open_tab_script, script_timeout=60000)
 320
 321             Wait(self.marionette).until(
 322                 lambda mn: len(mn.window_handles) == tabs_loaded + 1,
 323                 message="No new tab has been opened",
 324             )
 325
 326             # NB: The tab list isn't sorted, so we do a set diff to determine
 327             #     which is the new tab
 328             new_tab_list = self.marionette.window_handles
 329             new_tabs = list(set(new_tab_list) - set(full_tab_list))
 330
 331             self._tabs.append(new_tabs[0])
 332             tabs_loaded += 1
 333
 334         tab_idx = self._pages_loaded % self._maxTabs
 335
 336         tab = self._tabs[tab_idx]
 337
 338         # Tell marionette which tab we're on
 339         # NB: As a work-around for an e10s marionette bug, only select the tab
 340         #     if we're really switching tabs.
 341         if tabs_loaded > 1:
 342             self.logger.info("switching to tab")
 343             self.marionette.switch_to_window(tab)
 344             self.logger.info("switched to tab")
 345
 346         with self.marionette.using_context("content"):
 347             self.logger.info("loading %s" % page_to_load)
 348             self.marionette.navigate(page_to_load)
 349             self.logger.info("loaded!")
 350
 351         # The tab handle can change after actually loading content
 352         # First build a set up w/o the current tab
 353         old_tabs = set(self._tabs)
 354         old_tabs.remove(tab)
 355         # Perform a set diff to get the (possibly) new handle
 356         new_tabs = set(self.marionette.window_handles) - old_tabs
 357         # Update the tab list at the current index to preserve the tab
 358         # ordering
 359         if new_tabs:
 360             self._tabs[tab_idx] = list(new_tabs)[0]
 361
 362         # give the page time to settle
 363         time.sleep(self._perTabPause)
 364
 365         self._pages_loaded += 1
 366
 367     def signal_user_active(self):
 368         """Signal to the browser that the user is active.
 369
 370         Normally when being driven by marionette the browser thinks the
 371         user is inactive the whole time because user activity is
 372         detected by looking at key and mouse events.
 373
 374         This would be a problem for this test because user inactivity is
 375         used to schedule some GCs (in particular shrinking GCs), so it
 376         would make this unrepresentative of real use.
 377
 378         Instead we manually cause some inconsequential activity (a press
 379         and release of the shift key) to make the browser think the user
 380         is active.  Then when we sleep to allow things to settle the
 381         browser will see the user as becoming inactive and trigger
 382         appropriate GCs, as would have happened in real use.
 383         """
 384         try:
 385             action = self.marionette.actions.sequence("key", "keyboard_id")
 386             action.key_down(Keys.SHIFT)
 387             action.key_up(Keys.SHIFT)
 388             action.perform()
 389         finally:
 390             self.marionette.actions.release()
 391
 392     def open_pages(self):
 393         """
 394         Opens all pages with our given configuration.
 395         """
 396         for _ in range(self.pages_to_load()):
 397             self.open_and_focus()
 398             self.signal_user_active()