Merge pull request #1187 from girder/more-logging

Log more often when importing files or making large images.

girder/girder_large_image/__init__.py

@@ -26,6 +26,7 @@
 import girder
 import large_image
 from girder import events, logger
+from girder.api import filter_logging
 from girder.constants import AccessType, SortDir
 from girder.exceptions import RestException, ValidationException
 from girder.models.file import File
@@ -154,6 +155,7 @@ def _updateJob(event):
 
 def checkForLargeImageFiles(event):
     file = event.info
+    logger.info('Handling file %s (%s)', file['_id'], file['name'])
     possible = False
     mimeType = file.get('mimeType')
     if mimeType in girder_tilesource.KnownMimeTypes:
@@ -656,6 +658,9 @@ def load(self, info):
         events.bind('model.item.copy.after', 'large_image', handleCopyItem)
         events.bind('model.item.save.after', 'large_image', invalidateLoadModelCache)
         events.bind('model.file.save.after', 'large_image', checkForLargeImageFiles)
+        filter_logging.addLoggingFilter(
+            r'Handling file ([0-9a-f]{24}) \(',
+            frequency=1000, duration=10)
         events.bind('model.item.remove', 'large_image.removeThumbnails', removeThumbnails)
         events.bind('server_fuse.unmount', 'large_image', large_image.cache_util.cachesClear)
         events.bind('model.file.remove', 'large_image', handleRemoveFile)

girder/girder_large_image/models/image_item.py

@@ -59,6 +59,7 @@ def initialize(self):
 
     def createImageItem(self, item, fileObj, user=None, token=None,
                         createJob=True, notify=False, **kwargs):
+        logger.info('createImageItem called on item %s (%s)', item['_id'], item['name'])
         # Using setdefault ensures that 'largeImage' is in the item
         if 'fileId' in item.setdefault('largeImage', {}):
             raise TileGeneralError('Item already has largeImage set.')
@@ -75,20 +76,35 @@ def createImageItem(self, item, fileObj, user=None, token=None,
 
         item['largeImage']['fileId'] = fileObj['_id']
         job = None
+        logger.debug(
+            'createImageItem checking if item %s (%s) can be used directly',
+            item['_id'], item['name'])
         sourceName = girder_tilesource.getGirderTileSourceName(item, fileObj)
         if sourceName:
+            logger.info(
+                'createImageItem using source %s for item %s (%s)',
+                sourceName, item['_id'], item['name'])
             item['largeImage']['sourceName'] = sourceName
         if not sourceName or createJob == 'always':
             if not createJob:
+                logger.info(
+                    'createImageItem will not use item %s (%s) as a largeImage',
+                    item['_id'], item['name'])
                 raise TileGeneralError(
                     'A job must be used to generate a largeImage.')
+            logger.debug(
+                'createImageItem creating a job to generate a largeImage for item %s (%s)',
+                item['_id'], item['name'])
             # No source was successful
             del item['largeImage']['fileId']
             job = self._createLargeImageJob(item, fileObj, user, token, **kwargs)
             item['largeImage']['expected'] = True
             item['largeImage']['notify'] = notify
             item['largeImage']['originalId'] = fileObj['_id']
             item['largeImage']['jobId'] = job['_id']
+            logger.debug(
+                'createImageItem created a job to generate a largeImage for item %s (%s)',
+                item['_id'], item['name'])
         self.save(item)
         return job
 

large_image/tilesource/base.py

@@ -932,8 +932,8 @@ def _pilFormatMatches(self, image, match=True, **kwargs):
         # compatibility could be an issue.
         return False
 
-    @methodcache()
-    def histogram(self, dtype=None, onlyMinMax=False, bins=256,
+    @methodcache()  # noqa
+    def histogram(self, dtype=None, onlyMinMax=False, bins=256,  # noqa
                   density=False, format=None, *args, **kwargs):
         """
         Get a histogram for a region.
@@ -963,10 +963,16 @@ def histogram(self, dtype=None, onlyMinMax=False, bins=256,
             array one longer than the hist array that contains the boundaries
             between bins.
         """
+        lastlog = time.time()
         kwargs = kwargs.copy()
         histRange = kwargs.pop('range', None)
         results = None
         for tile in self.tileIterator(format=TILE_FORMAT_NUMPY, *args, **kwargs):
+            if time.time() - lastlog > 10:
+                self.logger.info(
+                    'Calculating histogram min/max %d/%d',
+                    tile['tile_position']['position'], tile['iterator_range']['position'])
+                lastlog = time.time()
             tile = tile['tile']
             if dtype is not None and tile.dtype != dtype:
                 if tile.dtype == numpy.uint8 and dtype == numpy.uint16:
@@ -1018,6 +1024,11 @@ def histogram(self, dtype=None, onlyMinMax=False, bins=256,
             'density': bool(density),
         } for idx in range(len(results['min']))]
         for tile in self.tileIterator(format=TILE_FORMAT_NUMPY, *args, **kwargs):
+            if time.time() - lastlog > 10:
+                self.logger.info(
+                    'Calculating histogram %d/%d',
+                    tile['tile_position']['position'], tile['iterator_range']['position'])
+                lastlog = time.time()
             tile = tile['tile']
             if dtype is not None and tile.dtype != dtype:
                 if tile.dtype == numpy.uint8 and dtype == numpy.uint16: