From 6047824405913cf49dfe0ae767da442ee262bf37 Mon Sep 17 00:00:00 2001
From: Rob McMullen <feedback@playermissile.com>
Date: Sun, 7 May 2017 12:23:51 -0700
Subject: [PATCH] Added 'if _xd:' wrapper around expensive debug logging calls
 * generating numpy lists for printing is pretty expensive when doing it
 thousands of time as in the unit tests

---
 atrcopy/ataridos.py   | 18 +++++++++++-------
 atrcopy/diskimages.py |  8 ++++++--
 atrcopy/dos33.py      | 38 +++++++++++++++++++++-----------------
 atrcopy/utils.py      | 16 ++++++++++------
 4 files changed, 48 insertions(+), 32 deletions(-)

diff --git a/atrcopy/ataridos.py b/atrcopy/ataridos.py
index b17f5a9..c508227 100644
--- a/atrcopy/ataridos.py
+++ b/atrcopy/ataridos.py
@@ -7,6 +7,10 @@ from utils import *
 
 import logging
 log = logging.getLogger(__name__)
+try:  # Expensive debugging
+    _xd = _expensive_debugging
+except NameError:
+    _xd = False
 
 
 class AtariDosWriteableSector(WriteableSector):
@@ -22,7 +26,7 @@ class AtariDosWriteableSector(WriteableSector):
         self.data[index + 0] = (self.file_num << 2) | (hi & 0x03)
         self.data[index + 1] = lo
         self.data[index + 2] = self.used
-        log.debug("sector metadata for %d: %s" % (self._sector_num, self.data[index:index + 3]))
+        if _xd: log.debug("sector metadata for %d: %s" % (self._sector_num, self.data[index:index + 3]))
         # file number will be added later when known.
 
 
@@ -31,10 +35,10 @@ class AtariDosVTOC(VTOC):
         self.vtoc1 = segments[0].data
         bits = np.unpackbits(self.vtoc1[0x0a:0x64])
         self.sector_map[0:720] = bits
-        log.debug("vtoc before:\n%s" % str(self))
+        if _xd: log.debug("vtoc before:\n%s" % str(self))
 
     def calc_bitmap(self):
-        log.debug("vtoc after:\n%s" % str(self))
+        if _xd: log.debug("vtoc after:\n%s" % str(self))
         packed = np.packbits(self.sector_map[0:720])
         self.vtoc1[0x0a:0x64] = packed
         s = WriteableSector(self.sector_size, self.vtoc1)
@@ -52,7 +56,7 @@ class AtariDosDirectory(Directory):
 
     def encode_dirent(self, dirent):
         data = dirent.encode_dirent()
-        log.debug("encoded dirent: %s" % data)
+        if _xd: log.debug("encoded dirent: %s" % data)
         return data
 
     def set_sector_numbers(self, image):
@@ -225,7 +229,7 @@ class AtariDosDirent(Dirent):
         self.file_num = index
         self.dos_2 = True
         self.in_use = True
-        log.debug("set_values: %s" % self)
+        if _xd: log.debug("set_values: %s" % self)
 
 
 class MydosDirent(AtariDosDirent):
@@ -279,7 +283,7 @@ class AtariDosFile(object):
         pos = 0
         style_pos = 0
         first = True
-        log.debug("Initial parsing: size=%d" % self.size)
+        if _xd: log.debug("Initial parsing: size=%d" % self.size)
         while pos < self.size:
             if pos + 1 < self.size:
                 header, = b[pos:pos+2].view(dtype='<u2')
@@ -294,7 +298,7 @@ class AtariDosFile(object):
                 continue
             elif first:
                 raise InvalidBinaryFile("Object file doesn't start with 0xffff")
-            log.debug("header parsing: header=0x%x" % header)
+            if _xd: log.debug("header parsing: header=0x%x" % header)
             if len(b[pos:pos + 4]) < 4:
                 self.segments.append(ObjSegment(r[pos:pos + 4], 0, 0, 0, len(b[pos:pos + 4]), "Short Segment Header"))
                 break
diff --git a/atrcopy/diskimages.py b/atrcopy/diskimages.py
index 2b0d4ac..794f436 100644
--- a/atrcopy/diskimages.py
+++ b/atrcopy/diskimages.py
@@ -6,6 +6,10 @@ from utils import *
 
 import logging
 log = logging.getLogger(__name__)
+try:  # Expensive debugging
+    _xd = _expensive_debugging
+except NameError:
+    _xd = False
 
 
 class BaseHeader(object):
@@ -348,7 +352,7 @@ class DiskImageBase(object):
     def write_sector_list(self, sector_list):
         for sector in sector_list:
             pos, size = self.header.get_pos(sector.sector_num)
-            log.debug("writing: %s at %d" % (sector, pos))
+            if _xd: log.debug("writing: %s at %d" % (sector, pos))
             self.bytes[pos:pos + size] = sector.data
 
     def delete_file(self, filename):
@@ -373,7 +377,7 @@ class DiskImageBase(object):
         try:
             vtoc = self.get_vtoc_object()
             for sector_num, pos, size in vtoc.iter_free_sectors():
-                log.debug("shredding: sector %s at %d, fill value=%d" % (sector_num, pos, fill_value))
+                if _xd: log.debug("shredding: sector %s at %d, fill value=%d" % (sector_num, pos, fill_value))
                 self.bytes[pos:pos + size] = fill_value
         except AtrError:
             self.rollback_transaction(state)
diff --git a/atrcopy/dos33.py b/atrcopy/dos33.py
index f2c228e..b915657 100644
--- a/atrcopy/dos33.py
+++ b/atrcopy/dos33.py
@@ -7,6 +7,10 @@ from segments import DefaultSegment, EmptySegment, ObjSegment, RawTrackSectorSeg
 
 import logging
 log = logging.getLogger(__name__)
+try:  # Expensive debugging
+    _xd = _expensive_debugging
+except NameError:
+    _xd = False
 
 
 class Dos33TSSector(WriteableSector):
@@ -24,7 +28,7 @@ class Dos33TSSector(WriteableSector):
             t, s = self.header.track_from_sector(sector.sector_num)
             self.data[index] = t
             self.data[index + 1] = s
-            log.debug("tslist entry #%d: %d, %d" % (index, t, s))
+            if _xd: log.debug("tslist entry #%d: %d, %d" % (index, t, s))
             index += 2
 
     def get_tslist(self):
@@ -93,10 +97,10 @@ class Dos33VTOC(VTOC):
         # so we need to reorder them using numpy's indexing before stuffing
         # them into the sector map
         self.sector_map[0:self.max_sectors] = bits[self.vtoc_bit_reorder_index]
-        log.debug("vtoc before:\n%s" % str(self))
+        if _xd: log.debug("vtoc before:\n%s" % str(self))  # expensive debugging call
 
     def calc_bitmap(self):
-        log.debug("vtoc after:\n%s" % str(self))
+        if _xd: log.debug("vtoc after:\n%s" % str(self))  # expensive debugging call
 
         # reverse the process from above, so swap the order of every 16 bits,
         # turn them into bytes, then stuff them back into the vtoc. The bit
@@ -129,7 +133,7 @@ class Dos33Directory(Directory):
 
     def encode_dirent(self, dirent):
         data = dirent.encode_dirent()
-        log.debug("encoded dirent: %s" % data)
+        if _xd: log.debug("encoded dirent: %s" % data)
         return data
 
     def set_sector_numbers(self, image):
@@ -140,7 +144,7 @@ class Dos33Directory(Directory):
             t, s = image.header.track_from_sector(next_sector)
             sector.data[1] = t
             sector.data[2] = s
-            log.debug("directory sector %d -> next = %d" % (sector.sector_num, next_sector))
+            if _xd: log.debug("directory sector %d -> next = %d" % (sector.sector_num, next_sector))
             current_sector = next_sector
 
 
@@ -266,7 +270,7 @@ class Dos33Dirent(Dirent):
         tslist = BaseSectorList(header)
         for start in range(0, len(sector_list), header.ts_pairs):
             end = min(start + header.ts_pairs, len(sector_list))
-            log.debug("ts: %d-%d" % (start, end))
+            if _xd: log.debug("ts: %d-%d" % (start, end))
             s = Dos33TSSector(header, sector_list, start, end)
             s.ts_start, s.ts_end = start, end
             tslist.append(s)
@@ -274,7 +278,7 @@ class Dos33Dirent(Dirent):
         vtoc.assign_sector_numbers(self, tslist)
         sector_list.extend(tslist)
         self.track, self.sector = header.track_from_sector(tslist[0].sector_num)
-        log.debug("track/sector lists:\n%s" % str(tslist))
+        if _xd: log.debug("track/sector lists:\n%s" % str(tslist))
 
     def sanity_check(self, image):
         if self.deleted:
@@ -294,7 +298,7 @@ class Dos33Dirent(Dirent):
         sector_map = []
         while sector_num > 0:
             image.assert_valid_sector(sector_num)
-            log.debug("reading track/sector list at %d for %s" % (sector_num, self))
+            if _xd: log.debug("reading track/sector list at %d for %s" % (sector_num, self))
             data, _ = image.get_sectors(sector_num)
             sector = Dos33TSSector(image.header, data=data)
             sector.sector_num = sector_num
@@ -318,7 +322,7 @@ class Dos33Dirent(Dirent):
         if not self.is_sane:
             raise InvalidDirent("Invalid directory entry '%s'" % str(self))
         self.get_track_sector_list(image)
-        log.debug("start_read: %s, t/s list: %s" % (str(self), str(self.sector_map)))
+        if _xd: log.debug("start_read: %s, t/s list: %s" % (str(self), str(self.sector_map)))
         self.current_sector_index = 0
         self.current_read = self.num_sectors
 
@@ -327,7 +331,7 @@ class Dos33Dirent(Dirent):
             sector = self.sector_map[self.current_sector_index]
         except IndexError:
             sector = -1  # force ByteNotInFile166 error at next read
-        log.debug("read_sector: index %d=%d in %s" % (self.current_sector_index,sector, str(self)))
+        if _xd: log.debug("read_sector: index %d=%d in %s" % (self.current_sector_index,sector, str(self)))
         last = (self.current_sector_index == len(self.sector_map) - 1)
         raw, pos, size = image.get_raw_bytes(sector)
         bytes, num_data_bytes = self.process_raw_sector(image, raw)
@@ -411,11 +415,11 @@ class Dos33DiskImage(DiskImageBase):
             if data[1] < 35 and data[2] < 16:
                 data, style = self.get_sectors(self.header.first_vtoc + 14)
                 if data[2] != 13:
+                    log.warning("DOS 3.3 byte swap needed!")
                     swap_order = True
             else:
                 raise InvalidDiskImage("Invalid VTOC location for DOS 3.3")
 
-        log.debug("DOS 3.3 byte swap: %s" % swap_order)
 
     vtoc_type = np.dtype([
         ('unused1', 'S1'),
@@ -453,7 +457,7 @@ class Dos33DiskImage(DiskImageBase):
         files = []
         while sector > 0:
             self.assert_valid_sector(sector)
-            log.debug("reading catalog sector: %d" % sector)
+            if _xd: log.debug("reading catalog sector: %d" % sector)
             values, style = self.get_sectors(sector)
             sector = self.header.sector_from_track(values[1], values[2])
             i = 0xb
@@ -468,7 +472,7 @@ class Dos33DiskImage(DiskImageBase):
                     files.append(dirent)
                 if directory is not None:
                     directory.set(num, dirent)
-                log.debug("valid directory entry %s" % dirent)
+                if _xd: log.debug("valid directory entry %s" % dirent)
                 i += 0x23
                 num += 1
         self.files = files
@@ -525,7 +529,7 @@ class Dos33DiskImage(DiskImageBase):
         sector = self.header.first_directory
         while sector > 0:
             self.assert_valid_sector(sector)
-            log.debug("loading directory segment from catalog sector %d" % sector)
+            if _xd: log.debug("loading directory segment from catalog sector %d" % sector)
             raw, pos, size = self.get_raw_bytes(sector)
             byte_order.extend(range(pos, pos + size))
             sector = self.header.sector_from_track(raw[1], raw[2])
@@ -557,7 +561,7 @@ class Dos33DiskImage(DiskImageBase):
         self.assert_valid_sector(sector_num)
         raw, _, _ = self.get_raw_bytes(sector_num)
         next_sector = self.header.sector_from_track(raw[1], raw[2])
-        log.debug("checking catalog sector %d, next catalog sector: %d" % (sector_num, next_sector))
+        if _xd: log.debug("checking catalog sector %d, next catalog sector: %d" % (sector_num, next_sector))
         if next_sector == 0:
             raise NoSpaceInDirectory("No space left in catalog")
         return sector_num, next_sector
@@ -596,7 +600,7 @@ class Dos33DiskImage(DiskImageBase):
         for s in segments:
             origin = min(origin, s.start_addr)
             last = max(last, s.start_addr + len(s))
-            log.debug("contiguous bytes needed: %04x - %04x" % (origin, last))
+            if _xd: log.debug("contiguous bytes needed: %04x - %04x" % (origin, last))
         if run_addr and run_addr != origin:
             # check if run_addr points to some location that has data
             found = False
@@ -652,7 +656,7 @@ class Dos33BinFile(object):
         pos = 0
         style_pos = 0
         first = True
-        log.debug("Initial parsing: size=%d" % self.size)
+        if _xd: log.debug("Initial parsing: size=%d" % self.size)
         if len(b[pos:pos + 4]) == 4:
             start, count = b[pos:pos + 4].view(dtype='<u2')
             s[pos:pos + 4] = get_style_bits(data=True)
diff --git a/atrcopy/utils.py b/atrcopy/utils.py
index c112737..014351c 100644
--- a/atrcopy/utils.py
+++ b/atrcopy/utils.py
@@ -6,6 +6,10 @@ from errors import *
 
 import logging
 log = logging.getLogger(__name__)
+try:  # Expensive debugging
+    _xd = _expensive_debugging
+except NameError:
+    _xd = False
 
 
 def to_numpy(value):
@@ -176,7 +180,7 @@ class Directory(BaseSectorList):
 
     def set(self, index, dirent):
         self.dirents[index] = dirent
-        log.debug("set dirent #%d: %s" % (index, dirent))
+        if _xd: log.debug("set dirent #%d: %s" % (index, dirent))
 
     def get_free_dirent(self):
         used = set()
@@ -240,10 +244,10 @@ class Directory(BaseSectorList):
         current = 0
         for index, dirent in d:
             for missing in range(current, index):
-                log.debug("Encoding empty dirent at %d" % missing)
+                if _xd: log.debug("Encoding empty dirent at %d" % missing)
                 data = self.encode_empty()
                 self.store_encoded(data)
-            log.debug("Encoding dirent: %s" % dirent)
+            if _xd: log.debug("Encoding dirent: %s" % dirent)
             data = self.encode_dirent(dirent)
             self.store_encoded(data)
             current = index + 1
@@ -260,7 +264,7 @@ class Directory(BaseSectorList):
 
     def store_encoded(self, data):
         while True:
-            log.debug("store_encoded: %d bytes in %s" % (len(data), self.current_sector))
+            if _xd: log.debug("store_encoded: %d bytes in %s" % (len(data), self.current_sector))
             data = self.current_sector.add_data(data)
             if len(data) > 0:
                 self.sectors.append(self.current_sector)
@@ -329,7 +333,7 @@ class VTOC(BaseSectorList):
         order = []
         for i in range(num):
             order.append(self.get_next_free_sector())
-        log.debug("Sectors reserved: %s" % order)
+        if _xd: log.debug("Sectors reserved: %s" % order)
         self.calc_bitmap()
         return order
 
@@ -337,7 +341,7 @@ class VTOC(BaseSectorList):
         free = np.nonzero(self.sector_map)[0]
         if len(free) > 0:
             num = free[0]
-            log.debug("Found sector %d free" % num)
+            if _xd: log.debug("Found sector %d free" % num)
             self.sector_map[num] = 0
             return num
         raise NotEnoughSpaceOnDisk("No space left in VTOC")