|
9 | 9 | from pathlib import Path |
10 | 10 | from wsgiref.util import FileWrapper |
11 | 11 | from io import BytesIO |
| 12 | +import time |
12 | 13 |
|
13 | 14 | import pandas as pd |
14 | 15 | import requests |
|
39 | 40 |
|
40 | 41 | from .deepzoom_util import DeepZoomWrapper |
41 | 42 |
|
| 43 | +# Create dedicated loggers with direct console output |
42 | 44 | logger = logging.getLogger(__name__) |
43 | 45 |
|
| 46 | +# Create a WSI logger specifically for WSI operations |
| 47 | +wsi_logger = logging.getLogger('server') |
| 48 | +if not wsi_logger.handlers: |
| 49 | + wsi_handler = logging.StreamHandler() |
| 50 | + wsi_handler.setFormatter(logging.Formatter('[%(asctime)s] [WSI] %(levelname)s: %(message)s')) |
| 51 | + wsi_logger.addHandler(wsi_handler) |
| 52 | + wsi_logger.setLevel(logging.INFO) # Make sure it's visible |
| 53 | + wsi_logger.propagate = False # Don't propagate to root logger |
| 54 | + |
44 | 55 |
|
45 | 56 | _PARAGRAPH_SAMPLE = None |
46 | 57 |
|
@@ -200,81 +211,183 @@ def heidi_tips(request): |
200 | 211 | @api_view(['GET']) |
201 | 212 | @permission_classes([IsAuthenticated]) |
202 | 213 | def localfiles_data(request): |
203 | | - """Serving files for LocalFilesImportStorage""" |
| 214 | + """Serving files for LocalFilesImportStorage with optimized WSI handling""" |
| 215 | + # Start timing the entire request |
| 216 | + api_start = time.time() |
| 217 | + |
| 218 | + # Log request details |
| 219 | + request_path = request.GET.get('d', '') |
| 220 | + wsi_logger.debug(f'Request: {request_path}') |
| 221 | + |
204 | 222 | user = request.user |
205 | 223 | path = request.GET.get('d') |
206 | | - |
207 | 224 | level = request.GET.get('level') |
208 | 225 | col = request.GET.get('col') |
209 | 226 | row = request.GET.get('row') |
210 | 227 |
|
| 228 | + wsi_logger.info(f'Request started: path={path}, level={level}, col={col}, row={row}') |
| 229 | + |
211 | 230 | if settings.LOCAL_FILES_SERVING_ENABLED is False: |
| 231 | + wsi_logger.debug(f'Request rejected: LOCAL_FILES_SERVING_ENABLED is False') |
212 | 232 | return HttpResponseForbidden( |
213 | 233 | "Serving local files can be dangerous, so it's disabled by default. " |
214 | 234 | 'You can enable it with LOCAL_FILES_SERVING_ENABLED environment variable, ' |
215 | 235 | 'please check docs: https://labelstud.io/guide/storage.html#Local-storage' |
216 | 236 | ) |
217 | 237 |
|
| 238 | + # Start timing path resolution and permissions |
| 239 | + path_start = time.time() |
| 240 | + |
218 | 241 | local_serving_document_root = settings.LOCAL_FILES_DOCUMENT_ROOT |
219 | 242 | if path and request.user.is_authenticated: |
220 | 243 | path = posixpath.normpath(path).lstrip('/') |
221 | 244 | full_path = Path(safe_join(local_serving_document_root, path)) |
| 245 | + |
| 246 | + wsi_logger.debug(f'Path resolution: {time.time() - path_start:.4f}s, full_path={full_path}') |
222 | 247 |
|
223 | 248 | # Check if the file is a WSI file |
224 | 249 | ext = os.path.splitext(full_path)[1].lower() |
225 | 250 | is_wsi = ext in ['.svs', '.sdpc', '.tif', '.tiff', '.csp', '.kfb'] |
| 251 | + |
| 252 | + # Log file type |
| 253 | + wsi_logger.debug(f'File type check: extension={ext}, is_wsi={is_wsi}') |
226 | 254 |
|
| 255 | + # Start timing database operations |
| 256 | + db_start = time.time() |
| 257 | + |
227 | 258 | # Try to find Local File Storage connection based prefix: |
228 | 259 | # storage.path=/home/user, full_path=/home/user/a/b/c/1.jpg => |
229 | 260 | # full_path.startswith(path) => True |
230 | 261 | localfiles_storage = LocalFilesImportStorage.objects.annotate( |
231 | 262 | _full_path=Value(os.path.dirname(full_path), output_field=CharField()) |
232 | 263 | ).filter(_full_path__startswith=F('path')) |
233 | | - |
| 264 | + |
| 265 | + wsi_logger.debug(f'Database query: {time.time() - db_start:.4f}s') |
| 266 | + |
| 267 | + # Start timing permission check |
| 268 | + perm_start = time.time() |
| 269 | + |
234 | 270 | # Check if user has permissions to access this storage |
235 | 271 | user_has_permissions = False |
236 | 272 | if localfiles_storage.exists(): |
237 | 273 | user_has_permissions = any(storage.project.has_permission(user) for storage in localfiles_storage) |
238 | | - |
239 | | - if not user_has_permissions or not os.path.exists(full_path): |
240 | | - return HttpResponseNotFound() |
| 274 | + |
| 275 | + wsi_logger.debug(f'Permission check: {time.time() - perm_start:.4f}s, has_permission={user_has_permissions}') |
241 | 276 |
|
242 | | - # Check if the file is a WSI file and has level, col, and row parameters |
243 | | - if is_wsi and level and col and row: |
244 | | - try: |
245 | | - level = int(level) |
246 | | - col = int(col) |
247 | | - row = int(row) |
248 | | - except ValueError: |
249 | | - return HttpResponseForbidden('Invalid level, col, or row parameter') |
250 | | - |
251 | | - # Get the tile image |
252 | | - dz = DeepZoomWrapper(full_path) |
253 | | - tile_image = dz.get_tile(level, (col, row)) |
254 | | - |
255 | | - # Create a response with the tile image |
256 | | - buf = BytesIO() |
257 | | - tile_image.save(buf, 'jpeg') |
258 | | - buf.seek(0) |
259 | | - return HttpResponse(buf, content_type='image/jpeg') |
| 277 | + # Log file existence |
| 278 | + if not os.path.exists(full_path): |
| 279 | + wsi_logger.debug(f'File not found: {full_path}') |
| 280 | + return HttpResponseNotFound() |
| 281 | + elif not user_has_permissions: |
| 282 | + wsi_logger.debug(f'Permission denied for user: {user.email}') |
| 283 | + return HttpResponseNotFound() |
260 | 284 |
|
261 | | - # Check if the file is a WSI file without level, col, and row parameters |
| 285 | + # Optimized WSI file handling |
262 | 286 | if is_wsi: |
263 | | - # Create a DeepZoomWrapper instance |
264 | | - dz = DeepZoomWrapper(full_path) |
265 | | - |
266 | | - # Get the DZI (Deep Zoom Image) for the WSI file |
267 | | - dzi_xml = dz.get_dzi(format='jpeg') |
268 | | - return HttpResponse(dzi_xml, content_type='application/xml') |
| 287 | + # Start timing WSI processing |
| 288 | + wsi_start = time.time() |
| 289 | + |
| 290 | + # Import SLIDE_CACHE here to avoid circular imports |
| 291 | + from .wsi_optimizations import SLIDE_CACHE |
| 292 | + wsi_logger.debug(f'Import modules: {time.time() - wsi_start:.4f}s') |
| 293 | + |
| 294 | + # Get the slide from cache or load it |
| 295 | + cache_start = time.time() |
| 296 | + try: |
| 297 | + # Check if we have a cache hit before accessing |
| 298 | + cache_hit = full_path in SLIDE_CACHE._cache |
| 299 | + |
| 300 | + # Get the slide (either from cache or load it) |
| 301 | + dz = SLIDE_CACHE.get(full_path) |
| 302 | + cache_time = time.time() - cache_start |
| 303 | + |
| 304 | + # Log cache access details |
| 305 | + cache_size = len(SLIDE_CACHE._cache) |
| 306 | + cache_max = SLIDE_CACHE.cache_size |
| 307 | + wsi_logger.info(f'Slide cache access: time={cache_time:.4f}s, hit={cache_hit}, size={cache_size}/{cache_max}') |
| 308 | + except Exception as e: |
| 309 | + wsi_logger.error(f"Error loading file {full_path}: {e}") |
| 310 | + return HttpResponseNotFound() |
| 311 | + |
| 312 | + # Serve a specific tile if level, col, and row are provided |
| 313 | + if level and col and row: |
| 314 | + try: |
| 315 | + level = int(level) |
| 316 | + col = int(col) |
| 317 | + row = int(row) |
| 318 | + wsi_logger.debug(f'Parsing tile parameters: level={level}, col={col}, row={row}') |
| 319 | + except ValueError: |
| 320 | + wsi_logger.error(f'Invalid tile parameters: level={level}, col={col}, row={row}') |
| 321 | + return HttpResponseForbidden('Invalid level, col, or row parameter') |
| 322 | + |
| 323 | + try: |
| 324 | + # Start timing tile extraction |
| 325 | + tile_start = time.time() |
| 326 | + |
| 327 | + # Get the tile bytes directly (optimized for transfer) |
| 328 | + # Use quality 75 for JPEG, matches server.py settings |
| 329 | + tile_bytes = dz.get_tile_bytes(level, (col, row), format='jpeg', quality=75) |
| 330 | + |
| 331 | + # Log tile extraction time |
| 332 | + tile_time = time.time() - tile_start |
| 333 | + |
| 334 | + # Return the tile with proper content type |
| 335 | + total_time = time.time() - api_start |
| 336 | + cache_hit = 'hit' if full_path in SLIDE_CACHE._cache else 'miss' |
| 337 | + wsi_logger.info(f'Tile served: path={full_path}, level={level}, col={col}, row={row}, cache={cache_hit}, tile_time={tile_time:.4f}s, total_time={total_time:.4f}s') |
| 338 | + |
| 339 | + # Print a performance summary to make it easy to spot slow operations |
| 340 | + wsi_logger.info(f'WSI PERFORMANCE SUMMARY - Tile: cache={cache_hit}, tile_extraction={tile_time:.4f}s, total={total_time:.4f}s') |
| 341 | + |
| 342 | + return HttpResponse(tile_bytes, content_type='image/jpeg') |
| 343 | + except Exception as e: |
| 344 | + wsi_logger.error(f"Error getting tile for {full_path} at level {level}, col={col}, row={row}: {e}") |
| 345 | + return HttpResponseNotFound() |
| 346 | + else: |
| 347 | + # Return DZI XML for the WSI file |
| 348 | + try: |
| 349 | + # Start timing DZI generation |
| 350 | + dzi_start = time.time() |
| 351 | + |
| 352 | + dzi_xml = dz.get_dzi(format='jpeg') |
| 353 | + |
| 354 | + # Log DZI generation time |
| 355 | + dzi_time = time.time() - dzi_start |
| 356 | + total_time = time.time() - api_start |
| 357 | + cache_hit = 'hit' if full_path in SLIDE_CACHE._cache else 'miss' |
| 358 | + |
| 359 | + wsi_logger.info(f'DZI served: path={full_path}, cache={cache_hit}, dzi_time={dzi_time:.4f}s, total_time={total_time:.4f}s') |
| 360 | + |
| 361 | + # Print a performance summary |
| 362 | + wsi_logger.info(f'WSI PERFORMANCE SUMMARY - DZI: cache={cache_hit}, generation={dzi_time:.4f}s, total={total_time:.4f}s') |
| 363 | + |
| 364 | + return HttpResponse(dzi_xml, content_type='application/xml') |
| 365 | + except Exception as e: |
| 366 | + wsi_logger.error(f"Error getting DZI for {full_path}: {e}") |
| 367 | + return HttpResponseNotFound() |
269 | 368 |
|
270 | 369 | # If the file is not a WSI file, serve it as a regular file |
271 | 370 | if user_has_permissions and os.path.exists(full_path): |
| 371 | + # Start timing regular file serving |
| 372 | + file_start = time.time() |
| 373 | + |
272 | 374 | content_type, encoding = mimetypes.guess_type(str(full_path)) |
273 | 375 | content_type = content_type or 'application/octet-stream' |
| 376 | + |
| 377 | + # Log file serving time |
| 378 | + file_time = time.time() - file_start |
| 379 | + total_time = time.time() - api_start |
| 380 | + wsi_logger.info(f'Regular file served: path={full_path}, content_type={content_type}, file_time={file_time:.4f}s, total_time={total_time:.4f}s') |
| 381 | + |
| 382 | + # Print a performance summary for comparison |
| 383 | + wsi_logger.info(f'WSI PERFORMANCE SUMMARY - Regular file: size={os.path.getsize(full_path)}, file_time={file_time:.4f}s, total={total_time:.4f}s') |
| 384 | + |
274 | 385 | return RangedFileResponse(request, open(full_path, mode='rb'), content_type) |
275 | 386 | else: |
276 | 387 | return HttpResponseNotFound() |
277 | 388 |
|
| 389 | + # Log total time for rejected requests |
| 390 | + wsi_logger.info(f'Request rejected: total_time={time.time() - api_start:.4f}s') |
278 | 391 | return HttpResponseForbidden() |
279 | 392 |
|
280 | 393 |
|
|
0 commit comments