add trace to logging

sourmash/logging.py

@@ -1,13 +1,27 @@
+import atexit
+import os
 import sys
 from io import StringIO
 
 _quiet = False
 _debug = False
 def set_quiet(val, print_debug=False):
-    global _quiet, _debug
+    global _quiet, _debug, _trace
     _quiet = bool(val)
     _debug = bool(print_debug)
 
+#_trace = True if "SOURMASH_TRACE" in os.environ else False
+if "SOURMASH_TRACE" in os.environ:
+    _trace = open(os.environ["SOURMASH_TRACE"], "w")
+
+    @atexit.register
+    def flush_and_close():
+        global _trace
+        _trace.flush()
+        _trace.close()
+else:
+    _trace = None
+
 
 def print_results(s, *args, **kwargs):
     if _quiet:
@@ -41,6 +55,17 @@ def debug(s, *args, **kwargs):
         sys.stderr.flush()
 
 
+def trace(s, *args, **kwargs):
+    "Low level execution information (even more verbose than debug)"
+    if not _trace:
+        return
+
+    print(s.format(*args, **kwargs), file=_trace,
+          end=kwargs.get('end', u'\n'))
+    if kwargs.get('flush'):
+        sys.stderr.flush()
+
+
 def error(s, *args, **kwargs):
     "A simple error logging function => stderr."
     print(u'\r\033[K', end=u'', file=sys.stderr)

sourmash/sbt.py

@@ -57,7 +57,7 @@ def search_transcript(node, seq, threshold):
 
 from .exceptions import IndexNotSupported
 from .sbt_storage import FSStorage, IPFSStorage, RedisStorage, ZipStorage
-from .logging import error, notify, debug
+from .logging import error, notify, debug, trace
 from .index import Index
 from .nodegraph import Nodegraph, extract_nodegraph_info, calc_expected_collisions, optimal_size
 from .hll import HLL
@@ -339,19 +339,20 @@ def find(self, search_fn, *args, **kwargs):
             if node_p not in visited:
                 visited.add(node_p)
 
+                trace("(TRAVERSAL) {0}", node_p)
                 # apply search fn. If return false, truncate search.
                 if search_fn(node_g, *args):
-
                     # leaf node? it's a match!
                     if isinstance(node_g, Leaf):
                         matches.append(node_g)
                     # internal node? descend.
                     elif isinstance(node_g, Node):
                         if kwargs.get('dfs', True):  # defaults search to dfs
                             for c in self.children(node_p):
-                                queue.insert(0, c.pos)
+                                if c.node:
+                                    queue.insert(0, c.pos)
                         else: # bfs
-                            queue.extend(c.pos for c in self.children(node_p))
+                            queue.extend(c.pos for c in self.children(node_p) if c.node)
 
                 if unload_data:
                     node_g.unload()

sourmash/sbtmh.py

@@ -3,6 +3,7 @@
 
 from .sbt import Leaf, SBT, GraphFactory
 from . import signature
+from .logging import trace
 
 
 def load_sbt_index(filename, *, print_version_warning=True, cache_size=None):
@@ -112,6 +113,8 @@ def search_minhashes(node, sig, threshold, results=None):
     else:  # Node minhash comparison
         score = _max_jaccard_underneath_internal_node(node, sig_mh)
 
+    trace("(SCORE) {0}: {1}", node.name, score)
+
     if results is not None:
         results[node.name] = score
 
@@ -134,6 +137,7 @@ def search(self, node, sig, threshold, results=None):
         else:  # internal object, not leaf.
             score = _max_jaccard_underneath_internal_node(node, sig_mh)
 
+        trace("(SCORE) {0}: {1}", node.name, score)
         if results is not None:
             results[node.name] = score
 
@@ -156,10 +160,15 @@ def search_minhashes_containment(node, sig, threshold, results=None, downsample=
     else:  # Node or Leaf, Nodegraph by minhash comparison
         matches = node.data.matches(mh)
 
+    len_mh = max(len(mh), 1)
+
+    score = float(matches) / len_mh
+    trace("(SCORE) {0}: {1}", node.name, score)
+
     if results is not None:
-        results[node.name] = float(matches) / len(mh)
+        results[node.name] = score
 
-    if len(mh) and float(matches) / len(mh) >= threshold:
+    if len(mh) and score >= threshold:
         return 1
     return 0
 
@@ -170,7 +179,9 @@ def __init__(self):
 
     def search(self, node, query, threshold, results=None):
         mh = query.minhash
+        score = 0
         if not len(mh):
+            trace("(SCORE) {0}: 0", node.name)
             return 0
 
         if isinstance(node, SigLeaf):
@@ -179,9 +190,11 @@ def search(self, node, query, threshold, results=None):
             matches = node.data.matches(mh)
 
         if not matches:
+            trace("(SCORE) {0}: 0", node.name)
             return 0
 
         score = float(matches) / len(mh)
+        trace("(SCORE) {0}: {1}", node.name, score)
 
         if score < threshold:
             return 0