#2381 record total frame latency and guess client frame latency

git-svn-id: https://xpra.org/svn/Xpra/trunk@23539 3bb7dfac-3a0b-4e04-842a-767bc560f471

src/xpra/server/source/source_stats.py

@@ -63,6 +63,9 @@ def reset(self):
                                                             #(event_time, no of pixels, quality)
         self.speed = deque(maxlen=NRECS)                    #speed used for sending updates:
                                                             #(event_time, no of pixels, speed)
+        self.frame_total_latency = deque(maxlen=NRECS)      #how long it takes from the time we get a damage event
+                                                            #until we get the ack back from the client
+                                                            #(wid, event_time, no_of_pixels, latency)
         self.client_load = None
         self.last_congestion_time = 0
         self.congestion_value = 0
@@ -80,8 +83,9 @@ def reset(self):
         self.avg_server_ping_latency = self.DEFAULT_LATENCY
         self.recent_server_ping_latency = self.DEFAULT_LATENCY
         self.avg_congestion_send_speed = 0
+        self.avg_frame_total_latency = 0
 
-    def record_latency(self, wid, decode_time, start_send_at, end_send_at, pixels, bytecount):
+    def record_latency(self, wid, decode_time, start_send_at, end_send_at, pixels, bytecount, latency):
         now = monotonic_time()
         send_diff = now-start_send_at
         echo_diff = now-end_send_at
@@ -91,7 +95,8 @@ def record_latency(self, wid, decode_time, start_send_at, end_send_at, pixels, b
                 send_diff*1000, echo_diff*1000, decode_time/1000, pixels, bytecount, send_latency*1000, echo_latency*1000)
         if self.min_client_latency is None or self.min_client_latency>send_latency:
             self.min_client_latency = send_latency
-        self.client_latency.append((wid, monotonic_time(), pixels, send_latency))
+        self.client_latency.append((wid, now, pixels, send_latency))
+        self.frame_total_latency.append((wid, now, pixels, latency))
 
     def get_damage_pixels(self, wid):
         """ returns the list of (event_time, pixelcount) for the given window id """
@@ -142,6 +147,11 @@ def latency_averages(values):
             cps.append((etime, sum(matches)))
         #log("cps(%s)=%s (now=%s)", cst, cps, now)
         self.congestion_value = time_weighted_average(cps)
+        ftl = tuple(self.frame_total_latency)
+        if ftl:
+            edata = tuple((event_time, pixels, latency) for _, event_time, pixels, latency in ftl)
+            #(wid, event_time, no_of_pixels, latency)
+            self.avg_frame_total_latency = int(calculate_size_weighted_average(edata)[1])
 
     def get_factors(self, pixel_count):
         factors = []
@@ -207,6 +217,8 @@ def get_info(self):
         pqsizes = tuple(x[1] for x in tuple(self.packet_qsizes))
         now = monotonic_time()
         time_limit = now-60             #ignore old records (60s)
+        client_latency = max(0, self.avg_frame_total_latency-
+                             int((self.avg_client_ping_latency+self.avg_server_ping_latency)//2))
         info = {
             "damage" : {
                 "events"        : self.damage_events_count,
@@ -217,6 +229,8 @@ def get_info(self):
                 "packet_queue"  : {
                     "size"   : get_list_stats(pqsizes),
                     },
+                "frame-total-latency" : self.avg_frame_total_latency,
+                "client-latency"    : client_latency,
                 },
             "encoding" : {"decode_errors"   : self.decode_errors},
             "congestion" : {

src/xpra/server/window/window_source.py

@@ -2024,7 +2024,7 @@ def queue_damage_packet(self, packet, damage_time=0, process_damage_time=0, opti
         width, height, coding, data, damage_packet_sequence, _, client_options = packet[4:11]
         ldata = len(data)
         actual_batch_delay = process_damage_time-damage_time
-        ack_pending = [0, coding, 0, 0, 0, width*height, client_options]
+        ack_pending = [0, coding, 0, 0, 0, width*height, client_options, damage_time]
         statistics = self.statistics
         statistics.damage_ack_pending[damage_packet_sequence] = ack_pending
         def start_send(bytecount):
@@ -2144,14 +2144,17 @@ def damage_packet_acked(self, damage_packet_sequence, width, height, decode_time
             return
         del self.statistics.damage_ack_pending[damage_packet_sequence]
         gs = self.global_statistics
-        start_send_at, _, start_bytes, end_send_at, end_bytes, pixels, client_options = pending
+        start_send_at, _, start_bytes, end_send_at, end_bytes, pixels, client_options, damage_time = pending
         bytecount = end_bytes-start_bytes
         #it is possible
         #that we get the ack before we've had a chance to call
         #damage_packet_sent, so we must validate the data:
         if bytecount>0 and end_send_at>0:
+            now = monotonic_time()
             if decode_time>0:
-                self.global_statistics.record_latency(self.wid, decode_time, start_send_at, end_send_at, pixels, bytecount)
+                latency = int(1000*(now-damage_time))
+                self.global_statistics.record_latency(self.wid, decode_time,
+                                                      start_send_at, end_send_at, pixels, bytecount, latency)
             #we can ignore some packets:
             # * the first frame (frame=0) of video encoders can take longer to decode
             #   as we have to create a decoder context
@@ -2163,7 +2166,6 @@ def damage_packet_acked(self, damage_packet_sequence, width, height, decode_time
                 netlatency = int(1000*gs.min_client_latency*(100+ACK_JITTER)//100)
                 sendlatency = min(200, self.estimate_send_delay(bytecount))
                 #decode = pixels//100000         #0.1MPixel/s: 2160p -> 8MPixels, 80ms budget
-                now = monotonic_time()
                 live_time = int(1000*(now-self.statistics.init_time))
                 ack_tolerance = self.jitter + ACK_TOLERANCE + max(0, 200-live_time//10)
                 latency = netlatency + sendlatency + decode_time + ack_tolerance