Task #10009: updating of cache; more logging; less frequent check

SAS/DataManagement/StorageQueryService/cache.py

@@ -28,7 +28,7 @@ from lofar.mom.momqueryservice.config import DEFAULT_MOMQUERY_BUSNAME, DEFAULT_M
 
 logger = logging.getLogger(__name__)
 
-MAX_CACHE_ENTRY_AGE = datetime.timedelta(minutes=60)
+MAX_CACHE_ENTRY_AGE = datetime.timedelta(days=1)
 
 class CacheManager:
     def __init__(self,
@@ -201,11 +201,17 @@ class CacheManager:
                 with self._cacheLock:
                     path_cache = self._cache['path_du_results']
                     old_entries = [cache_entry for cache_entry in path_cache.values()
-                                   if now - cache_entry['cache_timestamp'] > MAX_CACHE_ENTRY_AGE
-                                   or cache_entry.get('needs_update')]
+                                   if now - cache_entry['cache_timestamp'] > MAX_CACHE_ENTRY_AGE]
+                    needs_update_entries = [cache_entry for cache_entry in path_cache.values()
+                                            if cache_entry.get('needs_update', False)]
 
-                if old_entries:
-                    logger.info('%s old cache entries need to be updated', len(old_entries))
+                updateable_entries = old_entries + needs_update_entries
+
+                if updateable_entries:
+                    logger.info('%s old cache entries need to be updated, #age:%s #needs_update:%s',
+                                len(updateable_entries),
+                                len(old_entries),
+                                len(needs_update_entries))
 
                     # sort them oldest to newest, 'needs_update' paths first
                     def compareFunc(entry1, entry2):
@@ -220,29 +226,34 @@ class CacheManager:
                             return 1
                         return 0
 
-                    old_entries = sorted(old_entries, cmp=compareFunc)
+                    updateable_entries = sorted(updateable_entries, cmp=compareFunc)
 
                     cacheUpdateStart = datetime.datetime.utcnow()
 
-                    for i, cache_entry in enumerate(old_entries):
+                    for i, cache_entry in enumerate(updateable_entries):
                         try:
                             path = cache_entry.get('path')
                             if path:
-                                logger.info('examining old entry %s/%s in cache: %s', i, len(old_entries), path)
+                                logger.info('examining entry %s/%s in cache. timestamp:%s age:%s needs_update:%s path: %s',
+                                            i,
+                                            len(updateable_entries),
+                                            cache_entry['cache_timestamp'],
+                                            now - cache_entry['cache_timestamp'],
+                                            cache_entry.get('needs_update', False),
+                                            path)
                                 result = du_getDiskUsageForPath(path)
-                                if result['found']:
-                                    logger.debug('trying to update old entry in cache: %s', result)
-                                    self._updateCache(result)
+                                logger.debug('trying to update old entry in cache: %s', result)
+                                self._updateCache(result)
                         except Exception as e:
                             logger.error(str(e))
 
                         if not self._updateCacheThreadRunning:
                             return
 
-                        if datetime.datetime.utcnow() - cacheUpdateStart > datetime.timedelta(minutes=5):
-                            # break out of cache update loop if full update takes more than 5min
+                        if datetime.datetime.utcnow() - cacheUpdateStart > datetime.timedelta(minutes=10):
+                            # break out of cache update loop if full update takes more than 10min
                             # next loop we'll start with the oldest cache entries again
-                            logger.info('skipping remaining %s old cache entries updates, they will be updated next time', len(old_entries)-i)
+                            logger.info('skipping remaining %s old cache entries updates, they will be updated next time', len(updateable_entries)-i)
                             break
 
                 for i in range(60):