From d6e767b921dfc461ef603c4483313a54bef1e0f7 Mon Sep 17 00:00:00 2001 From: David Manthey Date: Wed, 31 May 2023 15:24:44 -0400 Subject: [PATCH] Log more often when importing files or making large images. Also log slow histograms. Note that the logs will be somewhat more chatty at info level and very noisy at debug level. --- girder/girder_large_image/__init__.py | 5 +++++ girder/girder_large_image/models/image_item.py | 16 ++++++++++++++++ large_image/tilesource/base.py | 15 +++++++++++++-- 3 files changed, 34 insertions(+), 2 deletions(-) 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: