Bug 767315 - Add 'TEST_END' event to logger which shows the duration …

…of the test. r=jhammel, r=hskupin
mozilla · Oct 4, 2012 · 05dd020 · 05dd020
1 parent 15189c8
commit 05dd020
Show file tree

Hide file tree

Showing 2 changed files with 31 additions and 6 deletions.
diff --git a/mozmill/mozmill/extension/resource/modules/frame.js b/mozmill/mozmill/extension/resource/modules/frame.js
@@ -269,9 +269,26 @@ events.endTest = function (test) {
   }
 }
 
-events.setModule = function (v) {
-  return stateChangeBase( null, [function (v) {return (v.__file__ != undefined)}], 
-                          'currentModule', 'setModule', v);
+events.setModule = function (aModule) {
+  aModule.__start__ = Date.now();
+  var result = stateChangeBase( null, [function (aModule) {return (aModule.__file__ != undefined)}], 
+                          'currentModule', 'setModule', aModule);
+  aModule.__status__ = 'running';
+
+  return result;
+}
+
+events.endModule = function (aModule) {
+  aModule.__end__ = Date.now();
+  aModule.__status__ = 'done';
+
+  var obj = {
+    'filename': aModule.__file__,
+    'time_start': aModule.__start__,
+    'time_end': aModule.__end__
+  }
+
+  events.fireEvent('endModule', obj);
 }
 
 events.pass = function (obj) {
@@ -651,7 +668,6 @@ Runner.prototype.wrapper = function (func, arg) {
 
 Runner.prototype.runTestModule = function (module) {
   events.setModule(module);
-  module.__status__ = 'running';
 
   var observer = new AppQuitObserver(this);
 
@@ -725,7 +741,7 @@ Runner.prototype.runTestModule = function (module) {
 
   observer.unregister();
 
-  module.__status__ = 'done';
+  events.endModule(module);
 }
 
 var runTestFile = function (filename, name) {

diff --git a/mozmill/mozmill/logger.py b/mozmill/mozmill/logger.py
@@ -14,6 +14,7 @@
 import sys
 import uuid
 
+from datetime import datetime
 
 class LoggerListener(object):
     stack_regex = re.compile("(.*)@(.*?)(?: -> (file\:\/\/\/\S*))?\:(\d*)$")
@@ -41,6 +42,7 @@ def __init__(self, log_file=None, console_level="INFO", file_level="INFO",
             "TEST-UNEXPECTED-PASS": 43,
             "TEST-UNEXPECTED-FAIL": 42,
             "TEST-SKIPPED": 31,
+            "TEST-END": 24,
             "TEST-KNOWN-FAIL": 23,
             "TEST-PASS": 22,
             "TEST-START": 21,
@@ -209,7 +211,8 @@ def clean_stack_as_string(self, stack):
 
     def events(self):
         return {'mozmill.setTest': self.startTest,
-                'mozmill.endTest': self.endTest}
+                'mozmill.endTest': self.endTest,
+                'mozmill.endModule': self.endModule}
 
     def stop(self, results, fatal):
         """Print pass/failed/skipped statistics."""
@@ -250,6 +253,12 @@ def endTest(self, test):
             self.logger.log(self.custom_levels[level],
                             "%s | %s" % (filename, test['name']))
 
+    def endModule(self, module):
+        filename = self.mozmill.running_test.get('relpath', module['filename'])
+        duration = module['time_end'] - module['time_start']
+        self.logger.log(self.custom_levels["TEST-END"],
+                        "%s | finished in %dms" % (filename, duration))
+
 
 class ColorFormatter(logging.Formatter):
     # http://stackoverflow.com/questions/384076/