EWS graphs have unusual data for patch waiting times
authorcommit-queue@webkit.org <commit-queue@webkit.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Thu, 31 Jan 2013 19:34:38 +0000 (19:34 +0000)
committercommit-queue@webkit.org <commit-queue@webkit.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Thu, 31 Jan 2013 19:34:38 +0000 (19:34 +0000)
https://bugs.webkit.org/show_bug.cgi?id=108427

Patch by Alan Cutter <alancutter@chromium.org> on 2013-01-31
Reviewed by Eric Seidel.

The max_patches_waiting QueueLog property may have missed recording patches waiting in idle times when no events are fired to update it. I added a cron job to take care of this issue.
The patch wait duration in PatchLogs was being incorrectly updated after a patch expired and was picked up again from the queue. That period should really count towards the processing time instead.
Added a WarningLog to record if any erroneous situations occur due to invalid contents in the datastore. These basically highlight if any "impossible" execution paths get executed.

* QueueStatusServer/app.yaml:
* QueueStatusServer/cron.yaml:
* QueueStatusServer/handlers/syncqueuelogs.py: Copied from Tools/QueueStatusServer/model/patchlog.py.
(SyncQueueLogs):
(SyncQueueLogs.get):
* QueueStatusServer/loggers/recordpatchevent.py:
(RecordPatchEvent.added):
(RecordPatchEvent.retrying):
(RecordPatchEvent.started):
(RecordPatchEvent.stopped):
(RecordPatchEvent.updated):
* QueueStatusServer/main.py:
* QueueStatusServer/model/patchlog.py:
(PatchLog.lookup):
(PatchLog):
(PatchLog.lookup_if_exists):
(PatchLog.calculate_process_duration):
(PatchLog._generate_key):
* QueueStatusServer/model/queuelog.py:
(QueueLog.update_max_patches_waiting):
(QueueLog._get_or_create_txn):
(QueueLog):
(QueueLog._get_patches_waiting):
* QueueStatusServer/model/warninglog.py: Copied from Tools/QueueStatusServer/model/patchlog.py.
(WarningLog):
(WarningLog.record):

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@141451 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Tools/ChangeLog
Tools/QueueStatusServer/app.yaml
Tools/QueueStatusServer/cron.yaml
Tools/QueueStatusServer/handlers/syncqueuelogs.py [new file with mode: 0644]
Tools/QueueStatusServer/loggers/recordpatchevent.py
Tools/QueueStatusServer/main.py
Tools/QueueStatusServer/model/patchlog.py
Tools/QueueStatusServer/model/queuelog.py
Tools/QueueStatusServer/model/warninglog.py [new file with mode: 0644]

index b74fdad..ee49dd3 100644 (file)
@@ -1,3 +1,41 @@
+2013-01-31  Alan Cutter  <alancutter@chromium.org>
+
+        EWS graphs have unusual data for patch waiting times
+        https://bugs.webkit.org/show_bug.cgi?id=108427
+
+        Reviewed by Eric Seidel.
+
+        The max_patches_waiting QueueLog property may have missed recording patches waiting in idle times when no events are fired to update it. I added a cron job to take care of this issue.
+        The patch wait duration in PatchLogs was being incorrectly updated after a patch expired and was picked up again from the queue. That period should really count towards the processing time instead.
+        Added a WarningLog to record if any erroneous situations occur due to invalid contents in the datastore. These basically highlight if any "impossible" execution paths get executed.
+
+        * QueueStatusServer/app.yaml:
+        * QueueStatusServer/cron.yaml:
+        * QueueStatusServer/handlers/syncqueuelogs.py: Copied from Tools/QueueStatusServer/model/patchlog.py.
+        (SyncQueueLogs):
+        (SyncQueueLogs.get):
+        * QueueStatusServer/loggers/recordpatchevent.py:
+        (RecordPatchEvent.added):
+        (RecordPatchEvent.retrying):
+        (RecordPatchEvent.started):
+        (RecordPatchEvent.stopped):
+        (RecordPatchEvent.updated):
+        * QueueStatusServer/main.py:
+        * QueueStatusServer/model/patchlog.py:
+        (PatchLog.lookup):
+        (PatchLog):
+        (PatchLog.lookup_if_exists):
+        (PatchLog.calculate_process_duration):
+        (PatchLog._generate_key):
+        * QueueStatusServer/model/queuelog.py:
+        (QueueLog.update_max_patches_waiting):
+        (QueueLog._get_or_create_txn):
+        (QueueLog):
+        (QueueLog._get_patches_waiting):
+        * QueueStatusServer/model/warninglog.py: Copied from Tools/QueueStatusServer/model/patchlog.py.
+        (WarningLog):
+        (WarningLog.record):
+
 2013-01-31  Anders Carlsson  <andersca@apple.com>
 
         Remove Web Intents code from WebKit2
index 8e11cbf..ea3f7ea 100644 (file)
@@ -1,5 +1,5 @@
 application: webkit-commit-queue
-version: 98957 # Bugzilla bug ID of last major change
+version: 108427 # Bugzilla bug ID of last major change
 runtime: python
 api_version: 1
 
index 09b9945..d1b0d59 100644 (file)
@@ -2,3 +2,7 @@ cron:
 - description: collect the garbage
   url: /gc
   schedule: every 4 hours
+
+- description: Sync new queue logs up with unchanging data
+  url: /sync-queue-logs
+  schedule: every 10 minutes
diff --git a/Tools/QueueStatusServer/handlers/syncqueuelogs.py b/Tools/QueueStatusServer/handlers/syncqueuelogs.py
new file mode 100644 (file)
index 0000000..e2a55f9
--- /dev/null
@@ -0,0 +1,42 @@
+# Copyright (C) 2013 Google Inc. All rights reserved.
+#
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+#
+#     * Redistributions of source code must retain the above copyright
+# notice, this list of conditions and the following disclaimer.
+#     * Redistributions in binary form must reproduce the above
+# copyright notice, this list of conditions and the following disclaimer
+# in the documentation and/or other materials provided with the
+# distribution.
+#     * Neither the name of Google Inc. nor the names of its
+# contributors may be used to endorse or promote products derived from
+# this software without specific prior written permission.
+#
+# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+from google.appengine.ext import webapp
+
+from config.queues import all_queue_names
+from config.logging import queue_log_duration
+from model.queuelog import QueueLog
+
+
+class SyncQueueLogs(webapp.RequestHandler):
+    def get(self):
+        for queue_name in all_queue_names:
+            queue_log = QueueLog.get_current(queue_name, queue_log_duration)
+            if queue_log.update_max_patches_waiting():
+                queue_log.put()
+        self.response.out.write("Done!")
index cb55925..4cddb60 100644 (file)
@@ -29,8 +29,7 @@
 from config.logging import queue_log_duration
 from model.patchlog import PatchLog
 from model.queuelog import QueueLog
-from model.workitems import WorkItems
-from model.activeworkitems import ActiveWorkItems
+from model.warninglog import WarningLog
 
 
 class RecordPatchEvent(object):
@@ -38,14 +37,16 @@ class RecordPatchEvent(object):
     def added(cls, attachment_id, queue_name):
         PatchLog.lookup(attachment_id, queue_name)
         queue_log = QueueLog.get_current(queue_name, queue_log_duration)
-        patches_waiting = cls._get_patches_waiting(queue_name)
-        if patches_waiting and queue_log.max_patches_waiting < patches_waiting:
-            queue_log.max_patches_waiting = patches_waiting
+        if queue_log.update_max_patches_waiting():
             queue_log.put()
 
     @classmethod
     def retrying(cls, attachment_id, queue_name, bot_id=None):
-        patch_log = PatchLog.lookup(attachment_id, queue_name)
+        patch_log = PatchLog.lookup_if_exists(attachment_id, queue_name)
+        if not patch_log:
+            WarningLog.record("patchlog missing", "In retrying event.", attachment_id, queue_name, bot_id)
+            return
+
         if bot_id:
             patch_log.bot_id = bot_id
         patch_log.retry_count += 1
@@ -57,33 +58,50 @@ class RecordPatchEvent(object):
 
     @classmethod
     def started(cls, attachment_id, queue_name, bot_id=None):
-        patch_log = PatchLog.lookup(attachment_id, queue_name)
-        if bot_id:
-            patch_log.bot_id = bot_id
-        patch_log.calculate_wait_duration()
-        patch_log.put()
+        patch_log = PatchLog.lookup_if_exists(attachment_id, queue_name)
+        if not patch_log:
+            WarningLog.record("patchlog missing", "In started event.", attachment_id, queue_name, bot_id)
+            return
 
-        queue_log = QueueLog.get_current(queue_name, queue_log_duration)
-        queue_log.patch_wait_durations.append(patch_log.wait_duration)
-        queue_log.put()
+        # An existing wait_duration implies the patch had been started previously and is being picked up again because it had expired.
+        if not patch_log.wait_duration:
+            if bot_id:
+                patch_log.bot_id = bot_id
+            patch_log.calculate_wait_duration()
+            patch_log.put()
+
+            queue_log = QueueLog.get_current(queue_name, queue_log_duration)
+            queue_log.patch_wait_durations.append(patch_log.wait_duration)
+            queue_log.put()
 
     @classmethod
     def stopped(cls, attachment_id, queue_name, bot_id=None):
-        patch_log = PatchLog.lookup(attachment_id, queue_name)
+        patch_log = PatchLog.lookup_if_exists(attachment_id, queue_name)
+        if not patch_log:
+            WarningLog.record("patchlog missing", "In stopped event.", attachment_id, queue_name, bot_id)
+            return
+
+        if not patch_log.wait_duration:
+            WarningLog.record("patchlog wait duration missing", "In stopped event.", attachment_id, queue_name, bot_id)
+            return
+
         if bot_id:
             patch_log.bot_id = bot_id
         patch_log.finished = True
         patch_log.calculate_process_duration()
         patch_log.put()
 
-        if patch_log.process_duration:
-            queue_log = QueueLog.get_current(queue_name, queue_log_duration)
-            queue_log.patch_process_durations.append(patch_log.process_duration)
-            queue_log.put()
+        queue_log = QueueLog.get_current(queue_name, queue_log_duration)
+        queue_log.patch_process_durations.append(patch_log.process_duration)
+        queue_log.put()
 
     @classmethod
     def updated(cls, attachment_id, queue_name, bot_id=None):
-        patch_log = PatchLog.lookup(attachment_id, queue_name)
+        patch_log = PatchLog.lookup_if_exists(attachment_id, queue_name)
+        if not patch_log:
+            WarningLog.record("patchlog missing", "In updated event.", attachment_id, queue_name, bot_id)
+            return
+
         if bot_id:
             patch_log.bot_id = bot_id
         patch_log.status_update_count += 1
@@ -93,9 +111,3 @@ class RecordPatchEvent(object):
         queue_log.status_update_count += 1
         queue_log.put()
 
-    @classmethod
-    def _get_patches_waiting(cls, queue_name):
-        work_items = WorkItems.lookup_by_queue(queue_name)
-        active_work_items = ActiveWorkItems.lookup_by_queue(queue_name)
-        if work_items and active_work_items:
-            return len(set(work_items.item_ids) - set(active_work_items.item_ids))
index 7ba59de..a626f83 100644 (file)
@@ -47,6 +47,7 @@ from handlers.showresults import ShowResults
 from handlers.statusbubble import StatusBubble
 from handlers.submittoews import SubmitToEWS
 from handlers.svnrevision import SVNRevision
+from handlers.syncqueuelogs import SyncQueueLogs
 from handlers.updatestatus import UpdateStatus
 from handlers.updatesvnrevision import UpdateSVNRevision
 from handlers.updateworkitems import UpdateWorkItems
@@ -58,6 +59,7 @@ routes = [
     ('/', QueuesOverview),
     ('/dashboard', Dashboard),
     ('/gc', GC),
+    ('/sync-queue-logs', SyncQueueLogs),
     (r'/patch-status/(.*)/(.*)', PatchStatus),
     (r'/patch/(.*)', Patch),
     (r'/submit-to-ews', SubmitToEWS),
index ccdbef2..78254da 100644 (file)
@@ -44,17 +44,25 @@ class PatchLog(db.Model):
 
     @classmethod
     def lookup(cls, attachment_id, queue_name):
-        key = "%s-%s" % (attachment_id, queue_name)
+        key = cls._generate_key(attachment_id, queue_name)
         return cls.get_or_insert(key, attachment_id=attachment_id, queue_name=queue_name)
 
+    @classmethod
+    def lookup_if_exists(cls, attachment_id, queue_name):
+        key = cls._generate_key(attachment_id, queue_name)
+        return cls.get_by_key_name(key)
+
     def calculate_wait_duration(self):
         time_delta = datetime.utcnow() - self.date
         self.wait_duration = int(self._time_delta_to_seconds(time_delta))
 
     def calculate_process_duration(self):
-        if self.wait_duration:
-            time_delta = datetime.utcnow() - self.date
-            self.process_duration = int(self._time_delta_to_seconds(time_delta)) - self.wait_duration
+        time_delta = datetime.utcnow() - self.date
+        self.process_duration = int(self._time_delta_to_seconds(time_delta)) - (self.wait_duration or 0)
+
+    @classmethod
+    def _generate_key(cls, attachment_id, queue_name):
+        return "%s-%s" % (attachment_id, queue_name)
 
     # Needed to support Python 2.5's lack of timedelta.total_seconds().
     @classmethod
index 98e3b1e..ee3e9de 100644 (file)
@@ -31,6 +31,9 @@ from datetime import datetime
 
 from google.appengine.ext import db
 
+from model.workitems import WorkItems
+from model.activeworkitems import ActiveWorkItems
+
 
 class QueueLog(db.Model):
     date = db.DateTimeProperty()
@@ -64,9 +67,22 @@ class QueueLog(db.Model):
     def get_or_create(cls, key_name, **kwargs):
         return db.run_in_transaction(cls._get_or_create_txn, key_name, **kwargs)
 
+    def update_max_patches_waiting(self):
+        patches_waiting = self._get_patches_waiting(self.queue_name)
+        if patches_waiting > self.max_patches_waiting:
+            self.max_patches_waiting = patches_waiting
+            return True
+        return False
+
     @classmethod
     def _get_or_create_txn(cls, key_name, **kwargs):
         entity = cls.get_by_key_name(key_name, parent=kwargs.get('parent'))
         if entity is None:
             entity = cls(key_name=key_name, **kwargs)
         return entity
+
+    @classmethod
+    def _get_patches_waiting(cls, queue_name):
+        work_items = WorkItems.lookup_by_queue(queue_name)
+        active_work_items = ActiveWorkItems.lookup_by_queue(queue_name)
+        return len(set(work_items.item_ids) - set(active_work_items.item_ids))
diff --git a/Tools/QueueStatusServer/model/warninglog.py b/Tools/QueueStatusServer/model/warninglog.py
new file mode 100644 (file)
index 0000000..b9677eb
--- /dev/null
@@ -0,0 +1,47 @@
+# Copyright (C) 2013 Google Inc. All rights reserved.
+#
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+#
+#     * Redistributions of source code must retain the above copyright
+# notice, this list of conditions and the following disclaimer.
+#     * Redistributions in binary form must reproduce the above
+# copyright notice, this list of conditions and the following disclaimer
+# in the documentation and/or other materials provided with the
+# distribution.
+#     * Neither the name of Google Inc. nor the names of its
+# contributors may be used to endorse or promote products derived from
+# this software without specific prior written permission.
+#
+# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+from time import time
+from datetime import datetime
+
+from google.appengine.ext import db
+
+
+class WarningLog(db.Model):
+    date = db.DateTimeProperty(auto_now_add=True)
+    event = db.StringProperty()
+    message = db.StringProperty()
+    attachment_id = db.IntegerProperty()
+    queue_name = db.StringProperty()
+    bot_id = db.StringProperty()
+
+    @classmethod
+    def record(cls, event, message=None, attachment_id=None, queue_name=None, bot_id=None):
+        entity = cls(event=event, message=message, queue_name=queue_name, bot_id=bot_id, attachment_id=attachment_id)
+        entity.put()
+        return entity