Fix several problems with the calculation of working time per client …

…event

The first problem is that in the following case, the algorithm would accrue more
working time than was actually spent:

              A
        |-----------|
    ---------+------------+------> time
             B            C

A, B and C are events. Let's say that Te(A) is the timestamp of the end of A,
while T(B) and T(C) are the timestamps of B and C, respectively.

The current code in `ClientEventsSerializer.to_internal_value` adjusts
`last_timestamp` after processing every event. After A is processed,
`last_timestamp` is set to Te(A). After B is processed, `last_timestamp`
goes _backwards_ to T(B). So when the algorithm calculates the working time
for C, it gets T(C) - T(B), when the correct answer is T(C) - Te(A). The
span from T(B) to Te(A) gets counted twice.

Fix this by rewriting the algorithm, so that `last_timestamp` (now renamed
`previous_end_timestamp`) can only go forwards.

The second problem is that the algorithm is unable to calculate the working
time for the first event in each batch that the client sends. This is
because to calculate working time for an event, you need the
timestamp/duration of the previous event, and this information is unavailable
for the first event in the batch.

Fix this by resending the most recently sent event along with each batch,
and using it to initialize the algorithm.

changelog.d/20240223_131040_roman_better_timekeeping.md

@@ -0,0 +1,9 @@
+### Fixed
+
+- Fixed incorrect working time calculation in the case where an event
+  occurred during another event
+  (<https://github.com/opencv/cvat/pull/7511>)
+
+- Fixed working time not being calculated for the first event in each batch
+  sent from the UI
+  (<https://github.com/opencv/cvat/pull/7511>)

cvat-core/src/logger.ts

@@ -34,6 +34,7 @@ type IgnoredRules = EventScope.zoomImage | EventScope.changeAttribute | EventSco
 class Logger {
     public clientID: string;
     public collection: Array<Event>;
+    public lastSentEvent: Event | null;
     public ignoreRules: Record<IgnoredRules, IgnoreRule>;
     public isActiveChecker: (() => boolean) | null;
     public saving: boolean;
@@ -42,6 +43,7 @@ class Logger {
     constructor() {
         this.clientID = Date.now().toString().substr(-6);
         this.collection = [];
+        this.lastSentEvent = null;
         this.isActiveChecker = null;
         this.saving = false;
         this.compressedScopes = [EventScope.changeFrame];
@@ -209,9 +211,12 @@ Object.defineProperties(Logger.prototype.save, {
                 this.collection = [];
                 await serverProxy.events.save({
                     events: collectionToSend.map((event) => event.dump()),
+                    previous_event: this.lastSentEvent?.dump(),
                     timestamp: new Date().toISOString(),
                 });
 
+                this.lastSentEvent = collectionToSend[collectionToSend.length - 1];
+
                 for (const rule of Object.values<IgnoreRule>(this.ignoreRules)) {
                     rule.lastEvent = null;
                 }

cvat/apps/events/serializers.py

@@ -1,4 +1,4 @@
-# Copyright (C) 2023 CVAT.ai Corporation
+# Copyright (C) 2023-2024 CVAT.ai Corporation
 #
 # SPDX-License-Identifier: MIT
 
@@ -28,11 +28,19 @@ class EventSerializer(serializers.Serializer):
 
 class ClientEventsSerializer(serializers.Serializer):
     events = EventSerializer(many=True, default=[])
+    previous_event = EventSerializer(default=None, allow_null=True, write_only=True)
     timestamp = serializers.DateTimeField()
     _TIME_THRESHOLD = datetime.timedelta(seconds=100)
     _WORKING_TIME_RESOLUTION = datetime.timedelta(milliseconds=1)
     _COLLAPSED_EVENT_SCOPES = frozenset(("change:frame",))
 
+    @classmethod
+    def _end_timestamp(cls, event: dict) -> datetime.datetime:
+        if event["scope"] in cls._COLLAPSED_EVENT_SCOPES:
+            return event["timestamp"] + datetime.timedelta(milliseconds=event["duration"])
+
+        return event["timestamp"]
+
     def to_internal_value(self, data):
         data = super().to_internal_value(data)
         request = self.context.get("request")
@@ -43,25 +51,29 @@ def to_internal_value(self, data):
         send_time = data["timestamp"]
         receive_time = datetime.datetime.now(datetime.timezone.utc)
         time_correction = receive_time - send_time
-        last_timestamp = datetime.datetime(datetime.MINYEAR, 1, 1, tzinfo=datetime.timezone.utc)
-        zero_t_delta = datetime.timedelta()
+
+        if previous_event := data["previous_event"]:
+            previous_end_timestamp = self._end_timestamp(previous_event)
+        elif data["events"]:
+            previous_end_timestamp = data["events"][0]["timestamp"]
 
         for event in data["events"]:
-            timestamp = event["timestamp"]
             working_time = datetime.timedelta()
-            event_duration = datetime.timedelta()
-            t_diff = timestamp - last_timestamp
-
-            payload = json.loads(event.get("payload", "{}"))
-
-            if t_diff >= zero_t_delta:
-                if event["scope"] in self._COLLAPSED_EVENT_SCOPES:
-                    event_duration += datetime.timedelta(milliseconds=event["duration"])
-                    working_time += event_duration
 
+            timestamp = event["timestamp"]
+            if timestamp > previous_end_timestamp:
+                t_diff = timestamp - previous_end_timestamp
                 if t_diff < self._TIME_THRESHOLD:
                     working_time += t_diff
 
+                previous_end_timestamp = timestamp
+
+            end_timestamp = self._end_timestamp(event)
+            if end_timestamp > previous_end_timestamp:
+                working_time += end_timestamp - previous_end_timestamp
+                previous_end_timestamp = end_timestamp
+
+            payload = json.loads(event.get("payload", "{}"))
             payload.update({
                 "working_time": working_time // self._WORKING_TIME_RESOLUTION,
                 "username": request.user.username,
@@ -78,6 +90,4 @@ def to_internal_value(self, data):
                 "payload": json.dumps(payload),
             })
 
-            last_timestamp = timestamp + event_duration
-
         return data

cvat/apps/events/tests/test_events.py

@@ -0,0 +1,177 @@
+# Copyright (C) 2024 CVAT.ai Corporation
+#
+# SPDX-License-Identifier: MIT
+
+import json
+import unittest
+from datetime import datetime, timedelta, timezone
+from typing import List, Optional
+
+from django.contrib.auth import get_user_model
+from django.test import RequestFactory
+
+from cvat.apps.events.serializers import ClientEventsSerializer
+from cvat.apps.organizations.models import Organization
+
+class WorkingTimeTestCase(unittest.TestCase):
+    _START_TIMESTAMP = datetime(2024, 1, 1, 12)
+    _SHORT_GAP = ClientEventsSerializer._TIME_THRESHOLD - timedelta(milliseconds=1)
+    _SHORT_GAP_INT = _SHORT_GAP / ClientEventsSerializer._WORKING_TIME_RESOLUTION
+    _LONG_GAP = ClientEventsSerializer._TIME_THRESHOLD
+    _LONG_GAP_INT = _LONG_GAP / ClientEventsSerializer._WORKING_TIME_RESOLUTION
+
+    @staticmethod
+    def _instant_event(timestamp: datetime) -> dict:
+        return {
+            "scope": "click:element",
+            "timestamp": timestamp.isoformat(),
+            "duration": 123,
+        }
+
+    @staticmethod
+    def _compressed_event(timestamp: datetime, duration: timedelta) -> dict:
+        return {
+            "scope": "change:frame",
+            "timestamp": timestamp.isoformat(),
+            "duration": duration // ClientEventsSerializer._WORKING_TIME_RESOLUTION,
+        }
+
+    @staticmethod
+    def _working_time(event: dict) -> int:
+        payload = json.loads(event["payload"])
+        return payload["working_time"]
+
+    @staticmethod
+    def _deserialize(events: List[dict], previous_event: Optional[dict] = None) -> List[dict]:
+        request = RequestFactory().post("/api/events")
+        request.user = get_user_model()(id=100, username="testuser", email="testuser@example.org")
+        request.iam_context = {
+            "organization": Organization(id=101, slug="testorg", name="Test Organization"),
+        }
+
+        s = ClientEventsSerializer(
+            data={
+                "events": events,
+                "previous_event": previous_event,
+                "timestamp": datetime.now(timezone.utc)
+            },
+            context={"request": request},
+        )
+
+        s.is_valid(raise_exception=True)
+
+        return s.validated_data["events"]
+
+    def test_instant(self):
+        events = self._deserialize([
+            self._instant_event(self._START_TIMESTAMP),
+        ])
+        self.assertEqual(self._working_time(events[0]), 0)
+
+    def test_compressed(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, self._LONG_GAP),
+        ])
+        self.assertEqual(self._working_time(events[0]), self._LONG_GAP_INT)
+
+    def test_instants_with_short_gap(self):
+        events = self._deserialize([
+            self._instant_event(self._START_TIMESTAMP),
+            self._instant_event(self._START_TIMESTAMP + self._SHORT_GAP),
+        ])
+        self.assertEqual(self._working_time(events[0]), 0)
+        self.assertEqual(self._working_time(events[1]), self._SHORT_GAP_INT)
+
+    def test_instants_with_long_gap(self):
+        events = self._deserialize([
+            self._instant_event(self._START_TIMESTAMP),
+            self._instant_event(self._START_TIMESTAMP + self._LONG_GAP),
+        ])
+        self.assertEqual(self._working_time(events[0]), 0)
+        self.assertEqual(self._working_time(events[1]), 0)
+
+    def test_compressed_with_short_gap(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=1)),
+            self._compressed_event(
+                self._START_TIMESTAMP + timedelta(seconds=1) + self._SHORT_GAP,
+                timedelta(seconds=5)
+            ),
+        ])
+        self.assertEqual(self._working_time(events[0]), 1000)
+        self.assertEqual(self._working_time(events[1]), self._SHORT_GAP_INT + 5000)
+
+    def test_compressed_with_long_gap(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=1)),
+            self._compressed_event(
+                self._START_TIMESTAMP + timedelta(seconds=1) + self._LONG_GAP,
+                timedelta(seconds=5)
+            ),
+        ])
+        self.assertEqual(self._working_time(events[0]), 1000)
+        self.assertEqual(self._working_time(events[1]), 5000)
+
+    def test_compressed_contained(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=5)),
+            self._compressed_event(
+                self._START_TIMESTAMP + timedelta(seconds=3),
+                timedelta(seconds=1)
+            ),
+        ])
+        self.assertEqual(self._working_time(events[0]), 5000)
+        self.assertEqual(self._working_time(events[1]), 0)
+
+    def test_compressed_overlapping(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=5)),
+            self._compressed_event(
+                self._START_TIMESTAMP + timedelta(seconds=3),
+                timedelta(seconds=6)
+            ),
+        ])
+        self.assertEqual(self._working_time(events[0]), 5000)
+        self.assertEqual(self._working_time(events[1]), 4000)
+
+    def test_instant_inside_compressed(self):
+        events = self._deserialize([
+            self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=5)),
+            self._instant_event(self._START_TIMESTAMP + timedelta(seconds=3)),
+            self._instant_event(self._START_TIMESTAMP + timedelta(seconds=6)),
+        ])
+        self.assertEqual(self._working_time(events[0]), 5000)
+        self.assertEqual(self._working_time(events[1]), 0)
+        self.assertEqual(self._working_time(events[2]), 1000)
+
+    def test_previous_instant_short_gap(self):
+        events = self._deserialize(
+            [self._instant_event(self._START_TIMESTAMP + self._SHORT_GAP)],
+            previous_event=self._instant_event(self._START_TIMESTAMP),
+        )
+
+        self.assertEqual(self._working_time(events[0]), self._SHORT_GAP_INT)
+
+    def test_previous_instant_long_gap(self):
+        events = self._deserialize(
+            [self._instant_event(self._START_TIMESTAMP + self._LONG_GAP)],
+            previous_event=self._instant_event(self._START_TIMESTAMP),
+        )
+
+        self.assertEqual(self._working_time(events[0]), 0)
+
+    def test_previous_compressed_short_gap(self):
+        events = self._deserialize(
+            [self._instant_event(self._START_TIMESTAMP + timedelta(seconds=1) + self._SHORT_GAP)],
+            previous_event=self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=1)),
+        )
+
+        self.assertEqual(self._working_time(events[0]), self._SHORT_GAP_INT)
+
+    def test_previous_compressed_long_gap(self):
+        events = self._deserialize(
+            [self._instant_event(self._START_TIMESTAMP + timedelta(seconds=1) + self._LONG_GAP)],
+            previous_event=self._compressed_event(self._START_TIMESTAMP, timedelta(seconds=1)),
+        )
+
+        self.assertEqual(self._working_time(events[0]), 0)

cvat/schema.yml

@@ -6487,6 +6487,11 @@ components:
           items:
             $ref: '#/components/schemas/EventRequest'
           default: []
+        previous_event:
+          allOf:
+          - $ref: '#/components/schemas/EventRequest'
+          writeOnly: true
+          nullable: true
         timestamp:
           type: string
           format: date-time