xpra icon
Bug tracker and wiki

This bug tracker and wiki are being discontinued
please use https://github.com/Xpra-org/xpra instead.


Ticket #132: xpra-unthreadeddamage-addlatencymeasurements.patch

File xpra-unthreadeddamage-addlatencymeasurements.patch, 23.3 KB (added by Antoine Martin, 9 years ago)

updated patch which dumps the damage latency at various points in the pipeline

  • src/xpra/protocol.py

    ### Eclipse Workspace Patch 1.0
    #P Xpra
     
    204204    def _flush_one_packet_into_buffer(self):
    205205        if not self.source:
    206206            return
    207         packet, self._source_has_more = self.source.next_packet()
     207        packet, cb, self._source_has_more = self.source.next_packet()
    208208        if packet is not None:
    209             self._add_packet_to_queue(packet)
     209            self._add_packet_to_queue(packet, cb)
    210210
    211211    def encode(self, packet):
    212212        """
     
    252252        packets.append((0, True, main_packet))
    253253        return packets
    254254
    255     def _add_packet_to_queue(self, packet):
     255    def _add_packet_to_queue(self, packet, cb=None):
    256256        packets = self.encode(packet)
    257257        if not self.raw_packets:
    258258            assert len(packets)==1
     
    291291                        self._compressor = None
    292292            self.output_packetcount += 1
    293293            self._write_lock.release()
     294            if cb:
     295                cb()
    294296
    295297    def _write_thread_loop(self):
    296298        try:
  • src/xpra/client_base.py

     
    5858        has_more = packet is not None and \
    5959                (bool(self._priority_packets) or bool(self._ordinary_packets) \
    6060                 or self._mouse_position is not None)
    61         return packet, has_more
     61        return packet, None, has_more
    6262
    6363
    6464class XpraClientBase(gobject.GObject):
  • src/xpra/server.py

     
    8080
    8181MAX_CONCURRENT_CONNECTIONS = 20
    8282
    83 def _get_rgb_rawdata(wid, pixmap, x, y, width, height, encoding, sequence, options):
     83def _get_rgb_rawdata(damage_time, wid, pixmap, x, y, width, height, encoding, sequence, options):
     84    start = time.time()
    8485    pixmap_w, pixmap_h = pixmap.get_size()
    8586    # Just in case we somehow end up with damage larger than the pixmap,
    8687    # we don't want to start requesting random chunks of memory (this
     
    9899    pixbuf.get_from_drawable(pixmap, pixmap.get_colormap(), x, y, 0, 0, width, height)
    99100    raw_data = pixbuf.get_pixels()
    100101    rowstride = pixbuf.get_rowstride()
    101     return (wid, x, y, width, height, encoding, raw_data, rowstride, sequence, options)
     102    log.info("get_rgb_rawdata(..) took %s ms", int(1000*(time.time()-start)))
     103    return (damage_time, wid, x, y, width, height, encoding, raw_data, rowstride, sequence, options)
    102104
    103105
    104106class DesktopManager(gtk.Widget):
     
    242244        self._mmap_size = mmap_size
    243245        self._mmap_bytes_sent = 0
    244246        protocol.source = self
    245         self._damage_request_queue = Queue()
    246247        self._damage_data_queue = Queue()
    247248        self._damage_packet_queue = Queue()
    248249
     
    256257            t.daemon = True
    257258            t.start()
    258259            return t
    259         self._damagedata_thread = start_daemon_thread(self.damage_to_data, "damage_to_data")
    260260        self._datapacket_thread = start_daemon_thread(self.data_to_packet, "data_to_packet")
    261261
    262262    def close(self):
    263263        self._closed = True
    264         self._damage_request_queue.put(None, block=False)
    265264        self._damage_data_queue.put(None, block=False)
    266265        self.video_encoder_cleanup()
    267266
     
    283282
    284283    def next_packet(self):
    285284        if self._closed:
    286             return  None, False
     285            return  None, None, False
    287286        if self._ordinary_packets:
    288287            packet = self._ordinary_packets.pop(0)
     288            cb = None
    289289        else:
    290290            try:
    291                 packet = self._damage_packet_queue.get(False)
     291                packet, cb = self._damage_packet_queue.get(False)
    292292            except Empty:
    293                 packet = None
    294         return packet, packet is not None and self._have_more()
     293                packet, cb = None, None
     294        return packet, cb, packet is not None and self._have_more()
    295295
    296296    def queue_ordinary_packet(self, packet):
    297297        assert self._protocol
     
    360360            return batch.encoding or self._encoding
    361361        return self._encoding
    362362
     363    def is_cancelled(self, wid, sequence):
     364        return sequence>0 and self._damage_cancelled.get(wid, 0)>=sequence
     365
     366    def get_window_pixmap(self, wid, window, sequence):
     367        # It's important to acknowledge changes *before* we extract them,
     368        # to avoid a race condition.
     369        window.acknowledge_changes()
     370        if self.is_cancelled(wid, sequence):
     371            log("get_window_pixmap: dropping damage request with sequence=%s", sequence)
     372            return  None
     373        pixmap = window.get_property("client-contents")
     374        if pixmap is None and not self.is_cancelled(wid, sequence):
     375            log.error("send_delayed_regions: wtf, pixmap is None for window %s, wid=%s", window, wid)
     376        return pixmap
     377
     378    def get_window_dimensions(self, window):
     379        is_or = isinstance(window, OverrideRedirectWindowModel)
     380        try:
     381            if is_or:
     382                (_, _, ww, wh) = window.get_property("geometry")
     383            else:
     384                ww, wh = window.get_property("actual-size")
     385        except KeyError:
     386            ww, wh = 512, 512
     387        return ww,wh
     388
    363389    def damage(self, wid, window, x, y, w, h, options=None):
    364390        """ decide what to do with the damage area:
    365391            * send it now (if not congested or batch.enabled is off)
     
    374400            the options may get quashed! So, specify a "batching"=False
    375401            option to ensure no batching will occur for this request.
    376402        """
     403        now = time.time()
    377404        batch = self.get_batch_config(wid)
     405        coding = self.get_encoding(wid)
     406        if coding in ["x264", "vpx"]:
     407            w,h = self.get_window_dimensions(window)
     408            x,y = 0,0
    378409        def damage_now(reason):
    379410            self._sequence += 1
    380411            log("damage(%s, %s, %s, %s, %s) %s, sending now with sequence %s", wid, x, y, w, h, reason, self._sequence)
    381             region = gtk.gdk.Region()
    382             region.union_with_rect(gtk.gdk.Rectangle(x, y, w, h))
    383             item = wid, window, region, self._sequence, options
    384             self._damage_request_queue.put(item)
    385             batch.last_delays.append(0)
     412            pixmap = self.get_window_pixmap(wid, window, self._sequence)
     413            if pixmap:
     414                self._process_damage_region(now, pixmap, wid, x, y, w, h, coding, self._sequence, options)
     415                batch.last_delays.append(0)
    386416        #record this damage event in the damage_last_events queue:
    387417        now = time.time()
    388418        last_events = self._damage_last_events.setdefault(wid, maxdeque(100))
     
    395425
    396426        delayed = self._damage_delayed.get(wid)
    397427        if delayed:
    398             (_, _, region, _, _) = delayed
     428            region = delayed[3]
    399429            region.union_with_rect(gtk.gdk.Rectangle(x, y, w, h))
    400430            log("damage(%s, %s, %s, %s, %s) using existing delayed region: %s", wid, x, y, w, h, delayed)
    401431            return
     
    411441        region = gtk.gdk.Region()
    412442        region.union_with_rect(gtk.gdk.Rectangle(x, y, w, h))
    413443        self._sequence += 1
    414         self._damage_delayed[wid] = (wid, window, region, self._sequence, options)
     444        self._damage_delayed[wid] = (now, wid, window, region, coding, self._sequence, options)
    415445        def send_delayed():
    416446            """ move the delayed rectangles to the expired list """
    417             log("send_delayed for %s", wid)
    418447            delayed = self._damage_delayed.get(wid)
    419448            if delayed:
     449                damage_time = delayed[0]
     450                log.info("send_delayed for wid %s, batch delay is %s, elapsed time is %s", wid, batch.delay, int(1000*(time.time()-damage_time)))
    420451                del self._damage_delayed[wid]
    421                 self._damage_request_queue.put(delayed)
     452                self.send_delayed_regions(*delayed)
    422453                log("moving region %s to expired list", delayed)
    423454            else:
    424455                log("window %s already removed from delayed list?", wid)
     
    427458        batch.last_delays.append(batch.delay)
    428459        gobject.timeout_add(int(batch.delay), send_delayed)
    429460
     461    def send_delayed_regions(self, damage_time, wid, window, damage, coding, sequence, options):
     462        log.info("send_delayed_regions: processing sequence=%s", sequence)
     463        if self.is_cancelled(wid, sequence):
     464            log("send_delayed_regions: dropping request with sequence=%s", sequence)
     465            return
     466        regions = []
     467        ww,wh = self.get_window_dimensions(window)
     468        def send_full_screen_update():
     469            log.info("send_delayed_regions: using full screen update")
     470            pixmap = self.get_window_pixmap(wid, window, sequence)
     471            if pixmap:
     472                self._process_damage_region(damage_time, pixmap, wid, 0, 0, ww, wh, coding, sequence, options)
     473
     474        try:
     475            count_threshold = 60
     476            pixels_threshold = ww*wh*9/10
     477            packet_cost = 1024
     478            if self._mmap and self._mmap_size>0:
     479                #with mmap, we can move lots of data around easily
     480                #so favour large screen updates over many small packets
     481                pixels_threshold = ww*wh/2
     482                packet_cost = 4096
     483            pixel_count = 0
     484            while not damage.empty():
     485                try:
     486                    if self.is_cancelled(wid, sequence):
     487                        return
     488                    (x, y, w, h) = get_rectangle_from_region(damage)
     489                    pixel_count += w*h
     490                    #favor full screen updates over many regions:
     491                    if len(regions)>count_threshold or pixel_count+packet_cost*len(regions)>=pixels_threshold:
     492                        send_full_screen_update()
     493                        return
     494                    regions.append((x, y, w, h))
     495                    rect = gtk.gdk.Rectangle(x, y, w, h)
     496                    damage.subtract(gtk.gdk.region_rectangle(rect))
     497                except ValueError:
     498                    log.error("send_delayed_regions: damage is empty: %s", damage)
     499                    break
     500            log("send_delayed_regions: to regions: %s items, %s pixels", len(regions), pixel_count)
     501        except Exception, e:
     502            log.error("send_delayed_regions: error processing region %s: %s", damage, e)
     503            return
     504        log("send_delayed_regions: regions=%s, sending damage ack", regions)
     505        pixmap = self.get_window_pixmap(wid, window, sequence)
     506        if pixmap is None:
     507            return
     508        log("send_delayed_regions: pixmap size=%s, window size=%s", pixmap.get_size(), (ww, wh))
     509        for region in regions:
     510            x, y, w, h = region
     511            if self.is_cancelled(wid, sequence):
     512                return
     513            self._process_damage_region(damage_time, pixmap, wid, x, y, w, h, coding, sequence, options)
     514
     515    def _process_damage_region(self, damage_time, pixmap, wid, x, y, w, h, coding, sequence, options):
     516        data = _get_rgb_rawdata(damage_time, wid, pixmap, x, y, w, h, coding, sequence, options)
     517        if data:
     518            log("process_damage_regions: adding pixel data %s to queue, elapsed time=%s, queue size=%s", data[:6], int(1000*(time.time()-damage_time)), self._damage_data_queue.qsize())
     519            self._damage_data_queue.put(data)
     520
     521    def data_to_packet(self):
     522        while not self._closed:
     523            item = self._damage_data_queue.get(True)
     524            if item is None:
     525                return              #empty marker
     526            try:
     527                damage_time = item[0]
     528                log.info("data_to_packet: elapsed time before encoding=%s, size=%s", int(1000*(time.time()-damage_time)), self._damage_packet_queue.qsize())
     529                packet = self.make_data_packet(*item)
     530                if packet:
     531                    log.info("data_to_packet: adding packet to queue, damage elapsed time=%s ms, size=%s, full=%s", int(1000*(time.time()-damage_time)), self._damage_packet_queue.qsize(), self._damage_packet_queue.full())
     532                    if self._damage_packet_queue.full():
     533                        self._protocol.source_has_more()
     534                    def show_damage_time():
     535                        log.info("show_damage_time: %s ms", int(1000*(time.time()-damage_time)))
     536                    self._damage_packet_queue.put((packet, show_damage_time))
     537                    self._protocol.source_has_more()
     538            except Exception, e:
     539                log.error("error processing damage data: %s", e, exc_info=True)
     540
     541
    430542    def calculate_batch_delay(self, wid, batch):
    431543        now = time.time()
    432544        if batch.last_updated+0.025>=now:
     
    435547        def update_batch_delay(reason, factor=1, delta=0):
    436548            batch.delay = max(batch.min_delay, min(batch.max_delay, int(100.0*batch.delay*factor)/100.0)-delta)
    437549            batch.last_updated = now
    438             log("update_batch_delay: %s, wid=%s, factor=%s, delta=%s, new batch delay=%s", reason, wid, factor, delta, batch.delay)
     550            log.info("update_batch_delay: %s, wid=%s, factor=%s, delta=%s, new batch delay=%s", reason, wid, factor, delta, batch.delay)
    439551
    440552        last_delta = self.last_client_delta
    441553        delta = self._damage_packet_sequence-self.last_client_packet_sequence
     
    444556            if self._damage_packet_queue.qsize()>3:
    445557                #packets ready for sending by network layer
    446558                update_batch_delay("damage packet queue overflow: %s" % self._damage_packet_queue.qsize(), logp2(self._damage_packet_queue.qsize()-2))
    447             if self._damage_request_queue.qsize()>3:
    448                 #processes damage requests and places them on the damage_data_queue
    449                 update_batch_delay("damage request queue overflow: %s" % self._damage_request_queue.qsize(), logp10(self._damage_request_queue.qsize()-2))
    450559            if self._damage_data_queue.qsize()>3:
    451560                #contains pixmaps before they get converted to a packet that goes to the damage_packet_queue
    452561                update_batch_delay("damage data queue overflow: %s" % self._damage_data_queue.qsize(), logp10(self._damage_data_queue.qsize()-2))
     
    477586            if packets_due<10 and packets_due<last_packets_due:
    478587                return update_batch_delay("client is only %s pixels and %s packets behind" % (pixels_behind, packets_due), 0.9, 0)
    479588        if pixels_behind>=high_limit:
    480             return update_batch_delay("client is %s pixels behind!" % pixels_behind, min(2.0, logp2(1.0*pixels_behind/high_limit)))
     589            return update_batch_delay("client is %s pixels behind!" % pixels_behind, min(1.5, logp2(1.0*pixels_behind/high_limit)))
    481590        if pixels_behind<last_pixels_behind:
    482591            #things are getting better:
    483592            return update_batch_delay("client is only %s pixels behind, from %s last time around" % (pixels_behind, last_pixels_behind), 0.4+(10.0*pixels_behind/(1+last_pixels_behind)/2)/10.0)
     
    485594            return update_batch_delay("client is %s packets behind, up from %s" % (packets_due, last_packets_due), logp10(1.0*packets_due/(1+last_packets_due)))
    486595        return update_batch_delay("client is %s pixels behind, from %s last time around" % (pixels_behind, last_pixels_behind), min(2.0, logp2(1.0*pixels_behind/last_pixels_behind)))
    487596
    488     def damage_to_data(self):
    489         """ pick items off the damage_request_queue
    490             and places the damage pixel data in the _damage_data_queue.
    491             this method runs in a thread but most of the actual processing
    492             is done in process_regions() which runs in the gtk main thread
    493             via idle_add.
    494         """
    495         while not self._closed:
    496             damage_request = self._damage_request_queue.get(True)
    497             if damage_request is None:
    498                 return              #empty marker
    499             wid, window, damage, sequence, options = damage_request
    500             log("damage_to_data: processing sequence=%s", sequence)
    501             if self._damage_cancelled.get(wid, 0)>=sequence:
    502                 log("damage_to_data: dropping request with sequence=%s", sequence)
    503                 continue
    504             regions = []
    505             coding = self.get_encoding(wid)
    506             is_or = isinstance(window, OverrideRedirectWindowModel)
    507             try:
    508                 if is_or:
    509                     (_, _, ww, wh) = window.get_property("geometry")
    510                 else:
    511                     ww, wh = window.get_property("actual-size")
    512             except KeyError, e:
    513                 ww, wh = 512, 512
    514             try:
    515                 pixels_threshold = ww*wh*9/10
    516                 packet_cost = 1024
    517                 if self._mmap and self._mmap_size>0:
    518                     #with mmap, we can move lots of data around easily
    519                     #so favour large screen updates over many small packets
    520                     pixels_threshold = ww*wh/2
    521                     packet_cost = 4096
    522                 pixel_count = 0
    523                 while not damage.empty():
    524                     try:
    525                         (x, y, w, h) = get_rectangle_from_region(damage)
    526                         pixel_count += w*h
    527                         #favor full screen updates over many regions:
    528                         #x264 and vpx need full screen updates all the time
    529                         if pixel_count+packet_cost*len(regions)>=pixels_threshold or coding in ["x264", "vpx"]:
    530                             regions = [(0, 0, ww, wh, True)]
    531                             break
    532                         regions.append((x, y, w, h, False))
    533                         rect = gtk.gdk.Rectangle(x, y, w, h)
    534                         damage.subtract(gtk.gdk.region_rectangle(rect))
    535                     except ValueError:
    536                         log.error("damage_to_data: damage is empty: %s", damage)
    537                         break
    538                 log("damage_to_data: to regions: %s items, %s pixels", len(regions), pixel_count)
    539             except Exception, e:
    540                 log.error("damage_to_data: error processing region %s: %s", damage, e)
    541                 continue
    542             gobject.idle_add(self._process_damage_regions, wid, window, ww, wh, regions, coding, sequence, options)
    543             time.sleep(0)
    544597
    545     def _process_damage_regions(self, wid, window, ww, wh, regions, coding, sequence, options):
    546         if self._damage_cancelled.get(wid, 0)>=sequence:
    547             log("process_damage_regions: dropping damage request with sequence=%s", sequence)
    548             return
    549         # It's important to acknowledge changes *before* we extract them,
    550         # to avoid a race condition.
    551         log("process_damage_regions: regions=%s, sending damage ack", regions)
    552         window.acknowledge_changes()
    553         pixmap = window.get_property("client-contents")
    554         if pixmap is None:
    555             log.error("wtf, pixmap is None for window %s, wid=%s", window, wid)
    556             return
    557         log("process_damage_regions: pixmap size=%s, window size=%s", pixmap.get_size(), (ww, wh))
    558         for region in regions:
    559             (x, y, w, h, full_window) = region
    560             if full_window:
    561                 log("process_damage_regions: sending full window: %s", pixmap.get_size())
    562                 w, h = pixmap.get_size()
    563             data = _get_rgb_rawdata(wid, pixmap, x, y, w, h, coding, sequence, options)
    564             if data:
    565                 log("process_damage_regions: adding pixel data %s to queue, queue size=%s", data[:6], self._damage_data_queue.qsize())
    566                 self._damage_data_queue.put(data)
    567 
    568     def data_to_packet(self):
    569         while not self._closed:
    570             item = self._damage_data_queue.get(True)
    571             if item is None:
    572                 return              #empty marker
    573             try:
    574                 packet = self.make_data_packet(item)
    575                 if packet:
    576                     log("data_to_packet: adding to packet queue, size=%s, full=%s", self._damage_packet_queue.qsize(), self._damage_packet_queue.full())
    577                     if self._damage_packet_queue.full():
    578                         self._protocol.source_has_more()
    579                     self._damage_packet_queue.put(packet)
    580                     self._protocol.source_has_more()
    581             except Exception, e:
    582                 log.error("error processing damage data: %s", e, exc_info=True)
    583 
    584     def make_data_packet(self, item):
    585         wid, x, y, w, h, coding, data, rowstride, sequence, options = item
    586         if sequence>=0 and self._damage_cancelled.get(wid, 0)>=sequence:
     598    def make_data_packet(self, damage_time, wid, x, y, w, h, coding, data, rowstride, sequence, options):
     599        if sequence>=0 and self.is_cancelled(wid, sequence):
    587600            log("make_data_packet: dropping data packet for window %s with sequence=%s", wid, sequence)
    588601            return  None
    589         log("make_data_packet: damage data: %s", (wid, x, y, w, h, coding))
     602        log.info("make_data_packet: damage data: %s", (wid, x, y, w, h, coding))
    590603        start = time.time()
    591604        #send via mmap?
    592605        if self._mmap and self._mmap_size>0 and len(data)>256:
     
    617630            buf.close()
    618631        elif coding=="x264":
    619632            assert coding in ENCODINGS
    620             assert x==0 and y==0
    621633            #x264 needs sizes divisible by 2:
    622634            w = w & 0xFFFE
    623635            h = h & 0xFFFE
     
    625637            data = self.video_encode(x264_encoders, x264Encoder, wid, x, y, w, h, coding, data, rowstride)
    626638        elif coding=="vpx":
    627639            assert coding in ENCODINGS
    628             assert x==0 and y==0
    629640            from xpra.vpx.codec import ENCODERS as vpx_encoders, Encoder as vpxEncoder      #@UnresolvedImport
    630641            data = self.video_encode(vpx_encoders, vpxEncoder, wid, x, y, w, h, coding, data, rowstride)
    631642        elif coding=="rgb24":
     
    637648
    638649        #check cancellation list again since the code above may take some time:
    639650        #but always send mmap data so we can reclaim the space!
    640         if coding!="mmap" and sequence>=0 and self._damage_cancelled.get(wid, 0)>=sequence:
     651        if coding!="mmap" and sequence>=0 and self.is_cancelled(wid, sequence):
    641652            log("make_data_packet: dropping data packet for window %s with sequence=%s", wid, sequence)
    642653            return  None
    643654        #actual network packet:
     
    649660
    650661    def video_encode(self, encoders, factory, wid, x, y, w, h, coding, data, rowstride):
    651662        assert coding in ENCODINGS
    652         assert x==0 and y==0
     663        assert x==0 and y==0, "invalid position: %sx%s" % (x,y)
    653664        #time_before = time.clock()
    654665        try:
    655666            self._video_encoder_lock.acquire()
     
    18981909            import Image
    18991910            image = Image.new("RGBA", (width, height))
    19001911            for wid, x, y, w, h, pixmap in reversed(regions):
    1901                 (wid, _, _, w, h, _, raw_data, rowstride, _, _) = _get_rgb_rawdata(wid, pixmap, 0, 0, w, h, "rgb24", -1, None)
     1912                (_, wid, _, _, w, h, _, raw_data, rowstride, _, _) = _get_rgb_rawdata(wid, pixmap, 0, 0, w, h, "rgb24", -1, None)
    19021913                window_image = Image.fromstring("RGB", (w, h), raw_data, "raw", "RGB", rowstride)
    19031914                tx = x-minx
    19041915                ty = y-miny