[tor-commits] [stem/master] Close control socket faster when under load

[atagar at torproject.org]

commit 02760c0638ee57b456920beccba178669a378537
Merge: d138f557 7d639f21
Author: Damian Johnson <atagar at torproject.org>
Date:   Thu Sep 21 10:23:36 2017 -0700

    Close control socket faster when under load
    
    When receiving a high volume of traffic (such as DEBUG events on a busy relay)
    our controller can take seconds or even minutes to close. This is because we
    send a QUIT signal, then wait for the response which is stuck behind
    potentially thousands of events.
    
    From what I can tell there's little point in issuing a QUIT so dropping that,
    and setting a time limit for processing backlogged events.
    
    I've done what I can to lighten our socket's recv() method, and even without
    the timeout we now process events much faster. But on busy relays under DEBUG
    load we simply cannot keep up. Clearly an edge case though, hence this
    compromise. The timeout is high enough that users will effectively never hit
    it, but when the controller connection is saturated we still work.
    
    Tested via the following script on my relay...
    
      import os
      import time
    
      import stem.control
      import stem.util.proc
      import stem.util.str_tools
    
      start_time = time.time()
      samplings = []
      last_sample = None
    
      with stem.control.Controller.from_port() as controller:
        controller.authenticate()
        controller.add_event_listener(lambda *args: None, 'DEBUG')
    
        while True:
          utime, stime = stem.util.proc.stats(os.getpid(), stem.util.proc.Stat.CPU_UTIME, stem.util.proc.Stat.CPU_STIME)
          total_cpu_time = float(utime) + float(stime)
    
          if last_sample:
            samplings.append(total_cpu_time - last_sample)
            print '%0.1f%% (%s)' % (sum(samplings) / len(samplings) * 100, stem.util.str_tools.time_label(time.time() - start_time))
    
          last_sample = total_cpu_time
          time.sleep(1)

 docs/change_log.rst                   |   4 +-
 stem/control.py                       |  29 +++++----
 stem/response/__init__.py             |   2 +-
 stem/socket.py                        | 115 +++++++++++++++++-----------------
 stem/util/log.py                      |  19 ++++++
 stem/util/system.py                   |  18 +++---
 test/settings.cfg                     |   1 +
 test/unit/response/control_message.py |  15 ++---
 test/unit/util/__init__.py            |   1 +
 test/unit/util/log.py                 |  23 +++++++
 10 files changed, 141 insertions(+), 86 deletions(-)