[or-cvs] r22376: {torctl} Include queue delay in some of our log messages. Trying to t (torctl/trunk/python/TorCtl)

[Mike Perry <mikeperry-svn@xxxxxxxxxx>]

Author: mikeperry
Date: 2010-05-21 21:36:45 +0000 (Fri, 21 May 2010)
New Revision: 22376

Modified:
   torctl/trunk/python/TorCtl/PathSupport.py
   torctl/trunk/python/TorCtl/TorCtl.py
Log:

Include queue delay in some of our log messages. Trying to
track down a rare bw authority stall bug that may be related
to excessive server load/queue delay.



Modified: torctl/trunk/python/TorCtl/PathSupport.py
===================================================================
--- torctl/trunk/python/TorCtl/PathSupport.py	2010-05-20 16:26:46 UTC (rev 22375)
+++ torctl/trunk/python/TorCtl/PathSupport.py	2010-05-21 21:36:45 UTC (rev 22376)
@@ -1589,7 +1589,8 @@
     plog("DEBUG", "Set last exit to "+self.last_exit.idhex)
 
   def circ_status_event(self, c):
-    output = [c.event_name, str(c.circ_id), c.status]
+    output = [str(time.time()-c.arrived_at), c.event_name, str(c.circ_id),
+              c.status]
     if c.path: output.append(",".join(c.path))
     if c.reason: output.append("REASON=" + c.reason)
     if c.remote_reason: output.append("REMOTE_REASON=" + c.remote_reason)
@@ -1634,13 +1635,13 @@
         return
 
   def stream_status_event(self, s):
-    output = [s.event_name, str(s.strm_id), s.status, str(s.circ_id),
+    output = [str(time.time()-s.arrived_at), s.event_name, str(s.strm_id),
+              s.status, str(s.circ_id),
           s.target_host, str(s.target_port)]
     if s.reason: output.append("REASON=" + s.reason)
     if s.remote_reason: output.append("REMOTE_REASON=" + s.remote_reason)
     if s.purpose: output.append("PURPOSE=" + s.purpose)
     if s.source_addr: output.append("SOURCE_ADDR="+s.source_addr)
-    plog("DEBUG", " ".join(output))
     if not re.match(r"\d+.\d+.\d+.\d+", s.target_host):
       s.target_host = "255.255.255.255" # ignore DNS for exit policy check
 
@@ -1653,6 +1654,7 @@
         plog("DEBUG", "Ignoring stream: " + str(s.strm_id))
       return
 
+    plog("DEBUG", " ".join(output))
     # XXX: Copy s.circ_id==0 check+reset from StatsSupport here too?
 
     if s.status == "NEW" or s.status == "NEWRESOLVE":
@@ -1757,12 +1759,15 @@
         self.streams[s.strm_id].port = s.target_port
 
   def stream_bw_event(self, s):
-    output = [s.event_name, str(s.strm_id), str(s.bytes_written),
+    output = [str(time.time()-s.arrived_at), s.event_name, str(s.strm_id),
+              str(s.bytes_written),
               str(s.bytes_read)]
-    plog("DEBUG", " ".join(output))
     if not s.strm_id in self.streams:
+      plog("DEBUG", " ".join(output))
       plog("WARN", "BW event for unknown stream id: "+str(s.strm_id))
     else:
+      if not self.streams[s.strm_id].ignored:
+        plog("DEBUG", " ".join(output))
       self.streams[s.strm_id].bytes_read += s.bytes_read
       self.streams[s.strm_id].bytes_written += s.bytes_written
 

Modified: torctl/trunk/python/TorCtl/TorCtl.py
===================================================================
--- torctl/trunk/python/TorCtl/TorCtl.py	2010-05-20 16:26:46 UTC (rev 22375)
+++ torctl/trunk/python/TorCtl/TorCtl.py	2010-05-21 21:36:45 UTC (rev 22376)
@@ -1405,8 +1405,8 @@
   def new_consensus_event(self, n):
     self._update_consensus(n.nslist)
     self._read_routers(self.ns_map.values())
-    plog("DEBUG", "Read " + str(len(n.nslist))+" NC => " 
-       + str(len(self.sorted_r)) + " routers")
+    plog("DEBUG", str(time.time()-n.arrived_at)+" Read " + str(len(n.nslist))
+       +" NC => " + str(len(self.sorted_r)) + " routers")
  
   def new_desc_event(self, d):
     update = False
@@ -1439,8 +1439,8 @@
       self.sorted_r = filter(lambda r: not r.down, self.routers.itervalues())
       self.sorted_r.sort(lambda x, y: cmp(y.bw, x.bw))
       for i in xrange(len(self.sorted_r)): self.sorted_r[i].list_rank = i
-    plog("DEBUG", "Read " + str(len(d.idlist))+" ND => " 
-       + str(len(self.sorted_r)) + " routers. Update: "+str(update))
+    plog("DEBUG", str(time.time()-d.arrived_at)+ " Read " + str(len(d.idlist))
+       +" ND => "+str(len(self.sorted_r))+" routers. Update: "+str(update))
     # XXX: Verification only. Can be removed.
     self._sanity_check(self.sorted_r)
     return update