diff --git a/girder/girder_large_image/__init__.py b/girder/girder_large_image/__init__.py index 088275afc..ca7679079 100644 --- a/girder/girder_large_image/__init__.py +++ b/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) diff --git a/girder/girder_large_image/models/image_item.py b/girder/girder_large_image/models/image_item.py index 4431f96dc..170b4b2eb 100644 --- a/girder/girder_large_image/models/image_item.py +++ b/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,13 +76,25 @@ 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) @@ -89,6 +102,9 @@ def createImageItem(self, item, fileObj, user=None, token=None, 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 diff --git a/large_image/tilesource/base.py b/large_image/tilesource/base.py index 4dd04ffa5..01a576ebe 100644 --- a/large_image/tilesource/base.py +++ b/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: