diff --git a/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart b/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart index c35e9cb901..3b79ecc214 100644 --- a/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart +++ b/mobile/apps/photos/lib/services/machine_learning/face_thumbnail_generator.dart @@ -35,14 +35,27 @@ class FaceThumbnailGenerator extends SuperIsolate { /// Uses [generateFaceThumbnailsUsingCanvas] inside the isolate. Future> generateFaceThumbnails( String imagePath, - List faceBoxes, - ) async { + List faceBoxes, { + int? fileID, + }) async { try { _logger.info( - "Generating face thumbnails for ${faceBoxes.length} face boxes in $imagePath", + "[$fileID] FaceThumbnailGenerator START: Generating face thumbnails for ${faceBoxes.length} face boxes in $imagePath", ); + + _logger + .info("[$fileID] Converting ${faceBoxes.length} face boxes to JSON"); final List> faceBoxesJson = faceBoxes.map((box) => box.toJson()).toList(); + _logger.info( + "[$fileID] Face boxes converted to JSON, preparing isolate operation", + ); + + _logger.info( + "[$fileID] Running generateFaceThumbnails in isolate with imagePath: $imagePath", + ); + final stopwatch = Stopwatch()..start(); + final List faces = await runInIsolate( IsolateOperation.generateFaceThumbnails, { @@ -50,15 +63,54 @@ class FaceThumbnailGenerator extends SuperIsolate { 'faceBoxesList': faceBoxesJson, }, ).then((value) => value.cast()); - _logger.info("Generated face thumbnails"); - final compressedFaces = - await compressFaceThumbnails({'listPngBytes': faces}); + + stopwatch.stop(); _logger.info( - "Compressed face thumbnails from sizes ${faces.map((e) => e.length / 1024).toList()} to ${compressedFaces.map((e) => e.length / 1024).toList()} kilobytes", + "[$fileID] Isolate operation completed in ${stopwatch.elapsedMilliseconds}ms", ); + _logger.info( + "[$fileID] Generated ${faces.length} face thumbnails with sizes: ${faces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}", + ); + + if (faces.length != faceBoxes.length) { + _logger.severe( + "[$fileID] Mismatch: Expected ${faceBoxes.length} face thumbnails but got ${faces.length}", + ); + } + + _logger.info("[$fileID] Starting face thumbnail compression"); + final compressionStopwatch = Stopwatch()..start(); + + final compressedFaces = + await compressFaceThumbnails({'listPngBytes': faces}, fileID: fileID); + + compressionStopwatch.stop(); + _logger.info( + "[$fileID] Compression completed in ${compressionStopwatch.elapsedMilliseconds}ms", + ); + _logger.info( + "[$fileID] Compressed face thumbnails from sizes ${faces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()} to ${compressedFaces.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}", + ); + + final totalOriginalSize = + faces.fold(0, (sum, face) => sum + face.length); + final totalCompressedSize = + compressedFaces.fold(0, (sum, face) => sum + face.length); + final compressionRatio = totalOriginalSize > 0 + ? (totalCompressedSize / totalOriginalSize * 100).toStringAsFixed(1) + : "0.0"; + + _logger.info( + "[$fileID] FaceThumbnailGenerator END: Total size reduced from ${(totalOriginalSize / 1024).toStringAsFixed(1)}KB to ${(totalCompressedSize / 1024).toStringAsFixed(1)}KB (${compressionRatio}% of original)", + ); + return compressedFaces; } catch (e, s) { - _logger.severe("Failed to generate face thumbnails", e, s); + _logger.severe( + "[$fileID] Failed to generate face thumbnails for $imagePath", + e, + s, + ); rethrow; } } diff --git a/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart b/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart index 8e34b28677..46e40ca124 100644 --- a/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart +++ b/mobile/apps/photos/lib/utils/face/face_thumbnail_cache.dart @@ -46,8 +46,12 @@ Uint8List? checkInMemoryCachedCropForPersonOrClusterID( return cachedCover; } -Uint8List? _checkInMemoryCachedCropForFaceID(String faceID) { +Uint8List? _checkInMemoryCachedCropForFaceID(String faceID, int? fileID) { + _logger.info("[$fileID] Checking in-memory cache for faceID: $faceID"); final Uint8List? cachedCover = _faceCropCache.get(faceID); + _logger.info( + "[$fileID] In-memory cache result for faceID $faceID: ${cachedCover != null ? 'found (${cachedCover.length} bytes)' : 'not found'}", + ); return cachedCover; } @@ -80,10 +84,21 @@ Future _putCachedCropForFaceID( String faceID, Uint8List data, [ String? personOrClusterID, + int? fileID, ]) async { + _logger.info( + "[$fileID] _putCachedCropForFaceID: faceID=$faceID, dataSize=${data.length} bytes, personOrClusterID=$personOrClusterID", + ); _faceCropCache.put(faceID, data); + _logger.info("[$fileID] Put faceID $faceID in memory cache"); if (personOrClusterID != null) { + _logger.info( + "[$fileID] Putting faceID $faceID for personOrClusterID $personOrClusterID in DB", + ); await putFaceIdCachedForPersonOrCluster(personOrClusterID, faceID); + _logger.info( + "[$fileID] Successfully put faceID $faceID for personOrClusterID $personOrClusterID in DB", + ); } } @@ -108,104 +123,265 @@ Future?> getCachedFaceCrops( String? personOrClusterID, required bool useTempCache, }) async { + _logger.info( + "[${enteFile.uploadedFileID}] getCachedFaceCrops START: faces=${faces.length}, fetchAttempt=$fetchAttempt, useFullFile=$useFullFile, personOrClusterID=$personOrClusterID, useTempCache=$useTempCache", + ); try { final faceIdToCrop = {}; final facesWithoutCrops = {}; - _logger.info("Now getting cached face crops for ${faces.length} faces"); + _logger.info( + "[${enteFile.uploadedFileID}] Initialized maps: faceIdToCrop and facesWithoutCrops", + ); + _logger.info( + "[${enteFile.uploadedFileID}] Processing ${faces.length} faces with IDs: ${faces.map((f) => f.faceID).toList()}", + ); + + // Validate faces have valid detection boxes for (final face in faces) { - final Uint8List? cachedFace = - _checkInMemoryCachedCropForFaceID(face.faceID); + if (face.detection.box.width <= 0 || face.detection.box.height <= 0) { + _logger.severe( + "[${enteFile.uploadedFileID}] Face ${face.faceID} has invalid detection box: ${face.detection.box}", + ); + } + } + + for (final face in faces) { + _logger.info( + "[${enteFile.uploadedFileID}] face ${face.faceID} has score ${face.score}", + ); + _logger + .info("[${enteFile.uploadedFileID}] Processing face ${face.faceID}"); + final Uint8List? cachedFace = _checkInMemoryCachedCropForFaceID( + face.faceID, + enteFile.uploadedFileID, + ); if (cachedFace != null) { + _logger.info( + "[${enteFile.uploadedFileID}] Found face ${face.faceID} in memory cache, size: ${cachedFace.length} bytes", + ); faceIdToCrop[face.faceID] = cachedFace; } else { - final faceCropCacheFile = cachedFaceCropPath(face.faceID, useTempCache); - if ((await faceCropCacheFile.exists())) { + _logger.info( + "[${enteFile.uploadedFileID}] Face ${face.faceID} not in memory cache, checking file cache", + ); + final faceCropCacheFile = cachedFaceCropPath( + face.faceID, + useTempCache, + enteFile.uploadedFileID, + ); + _logger.info( + "[${enteFile.uploadedFileID}] Cache file path for face ${face.faceID}: ${faceCropCacheFile.path}", + ); + + // Check if cache directory exists + final cacheDir = faceCropCacheFile.parent; + if (!(await cacheDir.exists())) { + _logger.severe( + "[${enteFile.uploadedFileID}] Cache directory does not exist: ${cacheDir.path}", + ); try { - final data = await faceCropCacheFile.readAsBytes(); - if (data.isNotEmpty) { - await _putCachedCropForFaceID( - face.faceID, - data, - personOrClusterID, - ); - faceIdToCrop[face.faceID] = data; - } else { - _logger.severe( - "Cached face crop for faceID ${face.faceID} is empty, deleting file ${faceCropCacheFile.path}", - ); - await faceCropCacheFile.delete(); - facesWithoutCrops[face.faceID] = face.detection.box; - } + await cacheDir.create(recursive: true); + _logger.info( + "[${enteFile.uploadedFileID}] Created cache directory: ${cacheDir.path}", + ); } catch (e, s) { _logger.severe( - "Error reading cached face crop for faceID ${face.faceID} from file ${faceCropCacheFile.path}", + "[${enteFile.uploadedFileID}] Failed to create cache directory: ${cacheDir.path}", e, s, ); facesWithoutCrops[face.faceID] = face.detection.box; + continue; + } + } + + if ((await faceCropCacheFile.exists())) { + _logger.info( + "[${enteFile.uploadedFileID}] Cache file exists for face ${face.faceID}, attempting to read", + ); + try { + final data = await faceCropCacheFile.readAsBytes(); + _logger.info( + "[${enteFile.uploadedFileID}] Read ${data.length} bytes from cache file for face ${face.faceID}", + ); + if (data.isNotEmpty) { + _logger.info( + "[${enteFile.uploadedFileID}] Cache file data is valid for face ${face.faceID}, putting in memory cache", + ); + await _putCachedCropForFaceID( + face.faceID, + data, + personOrClusterID, + enteFile.uploadedFileID, + ); + faceIdToCrop[face.faceID] = data; + _logger.info( + "[${enteFile.uploadedFileID}] Successfully cached face ${face.faceID} from file", + ); + } else { + _logger.severe( + "[${enteFile.uploadedFileID}] Cached face crop for faceID ${face.faceID} is empty, deleting file ${faceCropCacheFile.path}", + ); + await faceCropCacheFile.delete(); + facesWithoutCrops[face.faceID] = face.detection.box; + _logger.info( + "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops due to empty cache file", + ); + } + } catch (e, s) { + _logger.severe( + "[${enteFile.uploadedFileID}] Error reading cached face crop for faceID ${face.faceID} from file ${faceCropCacheFile.path}", + e, + s, + ); + facesWithoutCrops[face.faceID] = face.detection.box; + _logger.info( + "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops due to read error", + ); } } else { + _logger.info( + "[${enteFile.uploadedFileID}] Cache file does not exist for face ${face.faceID}", + ); facesWithoutCrops[face.faceID] = face.detection.box; + _logger.info( + "[${enteFile.uploadedFileID}] Added face ${face.faceID} to facesWithoutCrops", + ); } } } + _logger.info( + "[${enteFile.uploadedFileID}] Cache check complete: ${faceIdToCrop.length} faces found in cache, ${facesWithoutCrops.length} faces need generation", + ); if (facesWithoutCrops.isEmpty) { - _logger.info("All face crops gotten from cache"); + _logger.info( + "[${enteFile.uploadedFileID}] All face crops gotten from cache, returning ${faceIdToCrop.length} crops", + ); return faceIdToCrop; } + _logger.info( + "[${enteFile.uploadedFileID}] Faces without crops: ${facesWithoutCrops.keys.toList()}", + ); if (!useFullFile) { + _logger.info( + "[${enteFile.uploadedFileID}] Using thumbnail mode, checking thumbnail cache for ${facesWithoutCrops.length} faces", + ); for (final face in faces) { if (facesWithoutCrops.containsKey(face.faceID)) { final Uint8List? cachedFaceThumbnail = _faceCropThumbnailCache.get(face.faceID); if (cachedFaceThumbnail != null) { + _logger.info( + "[${enteFile.uploadedFileID}] Found face ${face.faceID} in thumbnail cache, size: ${cachedFaceThumbnail.length} bytes", + ); faceIdToCrop[face.faceID] = cachedFaceThumbnail; facesWithoutCrops.remove(face.faceID); + } else { + _logger.info( + "[${enteFile.uploadedFileID}] Face ${face.faceID} not found in thumbnail cache", + ); } } } + _logger.info( + "[${enteFile.uploadedFileID}] After thumbnail cache check: ${facesWithoutCrops.length} faces still need generation", + ); if (facesWithoutCrops.isEmpty) { + _logger.info( + "[${enteFile.uploadedFileID}] All faces found in thumbnail cache, returning ${faceIdToCrop.length} crops", + ); return faceIdToCrop; } } + _logger.info( + "[${enteFile.uploadedFileID}] Starting face crop generation for ${facesWithoutCrops.length} faces using ${useFullFile ? 'full file' : 'thumbnail'}", + ); final result = await _getFaceCropsUsingHeapPriorityQueue( enteFile, facesWithoutCrops, useFullFile: useFullFile, ); + _logger.info( + "[${enteFile.uploadedFileID}] Face crop generation completed, result: ${result != null ? 'success with ${result.length} crops' : 'null'}", + ); if (result == null) { + _logger.severe( + "[${enteFile.uploadedFileID}] Face crop generation returned null, returning ${faceIdToCrop.isEmpty ? 'null' : '${faceIdToCrop.length} cached crops'}", + ); return (faceIdToCrop.isEmpty) ? null : faceIdToCrop; } + _logger.info( + "[${enteFile.uploadedFileID}] Processing ${result.length} generated face crops", + ); for (final entry in result.entries) { final Uint8List? computedCrop = result[entry.key]; if (computedCrop != null) { + _logger.info( + "[${enteFile.uploadedFileID}] Processing generated crop for face ${entry.key}, size: ${computedCrop.length} bytes", + ); faceIdToCrop[entry.key] = computedCrop; if (useFullFile) { + _logger.info( + "[${enteFile.uploadedFileID}] Caching generated crop for face ${entry.key} in memory and file", + ); await _putCachedCropForFaceID( entry.key, computedCrop, personOrClusterID, + enteFile.uploadedFileID, + ); + final faceCropCacheFile = cachedFaceCropPath( + entry.key, + useTempCache, + enteFile.uploadedFileID, ); - final faceCropCacheFile = cachedFaceCropPath(entry.key, useTempCache); try { - // ignore: unawaited_futures - faceCropCacheFile.writeAsBytes(computedCrop); + _logger.info( + "[${enteFile.uploadedFileID}] Writing crop to file: ${faceCropCacheFile.path}", + ); + + // Ensure directory exists before writing + final cacheDir = faceCropCacheFile.parent; + if (!(await cacheDir.exists())) { + _logger.severe( + "[${enteFile.uploadedFileID}] Creating cache directory before write: ${cacheDir.path}", + ); + await cacheDir.create(recursive: true); + } + + await faceCropCacheFile.writeAsBytes(computedCrop); + _logger.info( + "[${enteFile.uploadedFileID}] Successfully wrote crop file for face ${entry.key}", + ); } catch (e, s) { _logger.severe( - "Error writing cached face crop for faceID ${entry.key} to file ${faceCropCacheFile.path}", + "[${enteFile.uploadedFileID}] Error writing cached face crop for faceID ${entry.key} to file ${faceCropCacheFile.path}", e, s, ); } } else { + _logger.info( + "[${enteFile.uploadedFileID}] Caching generated crop for face ${entry.key} in thumbnail cache", + ); _faceCropThumbnailCache.put(entry.key, computedCrop); } + } else { + _logger.severe( + "[${enteFile.uploadedFileID}] Generated crop for face ${entry.key} is null", + ); } } + _logger.info( + "[${enteFile.uploadedFileID}] Final result: ${faceIdToCrop.length} total face crops, returning ${faceIdToCrop.isEmpty ? 'null' : 'map with ${faceIdToCrop.length} entries'}", + ); return faceIdToCrop.isEmpty ? null : faceIdToCrop; } catch (e, s) { + _logger.severe( + "[${enteFile.uploadedFileID}] getCachedFaceCrops EXCEPTION: faces=${faces.map((face) => face.faceID).toList()}, error=$e", + ); if (e is! TaskQueueTimeoutException && e is! TaskQueueOverflowException && e is! TaskQueueCancelledException) { @@ -213,9 +389,12 @@ Future?> getCachedFaceCrops( final backoff = Duration( milliseconds: 100 * pow(2, fetchAttempt + 1).toInt(), ); + _logger.info( + "[${enteFile.uploadedFileID}] Will retry after ${backoff.inMilliseconds}ms delay", + ); await Future.delayed(backoff); _logger.severe( - "Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}, retrying (attempt ${fetchAttempt + 1}) in ${backoff.inMilliseconds} ms", + "[${enteFile.uploadedFileID}] Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}, retrying (attempt ${fetchAttempt + 1}) in ${backoff.inMilliseconds} ms", e, s, ); @@ -228,15 +407,18 @@ Future?> getCachedFaceCrops( ); } _logger.severe( - "Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}", + "[${enteFile.uploadedFileID}] Error getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()}", e, s, ); } else { _logger.severe( - "Stopped getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()} due to $e", + "[${enteFile.uploadedFileID}] Stopped getting face crops for faceIDs: ${faces.map((face) => face.faceID).toList()} due to $e", ); } + _logger.info( + "[${enteFile.uploadedFileID}] getCachedFaceCrops returning null due to exception", + ); return null; } } @@ -303,6 +485,9 @@ Future?> _getFaceCropsUsingHeapPriorityQueue( Map faceBoxeMap, { bool useFullFile = true, }) async { + _logger.info( + "[${file.uploadedFileID}] _getFaceCropsUsingHeapPriorityQueue START: faces=${faceBoxeMap.length}, useFullFile=$useFullFile", + ); final completer = Completer?>(); late final TaskQueue relevantTaskQueue; @@ -310,21 +495,46 @@ Future?> _getFaceCropsUsingHeapPriorityQueue( if (useFullFile) { relevantTaskQueue = _queueFullFileFaceGenerations; taskId = [file.uploadedFileID!, "-full"].join(); + _logger.info( + "[${file.uploadedFileID}] Using full file task queue with taskId: $taskId", + ); } else { relevantTaskQueue = _queueThumbnailFaceGenerations; taskId = [file.uploadedFileID!, "-thumbnail"].join(); + _logger.info( + "[${file.uploadedFileID}] Using thumbnail task queue with taskId: $taskId", + ); } - await relevantTaskQueue.addTask(taskId, () async { - final faceCrops = await _getFaceCrops( - file, - faceBoxeMap, - useFullFile: useFullFile, + _logger.info("[${file.uploadedFileID}] Adding task to queue: $taskId"); + try { + await relevantTaskQueue.addTask(taskId, () async { + _logger.info("[${file.uploadedFileID}] Task $taskId started execution"); + final faceCrops = await _getFaceCrops( + file, + faceBoxeMap, + useFullFile: useFullFile, + ); + _logger.info( + "[${file.uploadedFileID}] Task $taskId completed, result: ${faceCrops != null ? '${faceCrops.length} crops' : 'null'}", + ); + completer.complete(faceCrops); + }); + } catch (e, s) { + _logger.severe( + "[${file.uploadedFileID}] Error adding task $taskId to queue", + e, + s, ); - completer.complete(faceCrops); - }); + completer.complete(null); + } - return completer.future; + _logger.info("[${file.uploadedFileID}] Waiting for task $taskId to complete"); + final result = await completer.future; + _logger.info( + "[${file.uploadedFileID}] _getFaceCropsUsingHeapPriorityQueue END: taskId=$taskId, result=${result != null ? '${result.length} crops' : 'null'}", + ); + return result; } Future?> _getFaceCrops( @@ -333,39 +543,79 @@ Future?> _getFaceCrops( bool useFullFile = true, }) async { _logger.info( - "`_getFaceCrops` started for ${file.uploadedFileID} and ${faceBoxeMap.length} faces", + "[${file.uploadedFileID}] _getFaceCrops START: faces=${faceBoxeMap.length}, useFullFile=$useFullFile, fileType=${file.fileType}", ); late String? imagePath; if (useFullFile && file.fileType != FileType.video) { + _logger.info("[${file.uploadedFileID}] Getting full file"); final File? ioFile = await getFile(file); if (ioFile == null) { - _logger.severe("Failed to get file for face crop generation"); + _logger.severe( + "[${file.uploadedFileID}] Failed to get file for face crop generation", + ); return null; } imagePath = ioFile.path; + _logger.info( + "[${file.uploadedFileID}] Got full file path: $imagePath, exists: ${await ioFile.exists()}", + ); } else { + _logger.info("[${file.uploadedFileID}] Getting thumbnail"); final thumbnail = await getThumbnailForUploadedFile(file); if (thumbnail == null) { - _logger.severe("Failed to get thumbnail for face crop generation"); + _logger.severe( + "[${file.uploadedFileID}] Failed to get thumbnail for face crop generation", + ); return null; } imagePath = thumbnail.path; + _logger.info( + "[${file.uploadedFileID}] Got thumbnail path: $imagePath, exists: ${await thumbnail.exists()}", + ); } + + _logger.info("[${file.uploadedFileID}] Preparing face data for generation"); final List faceIds = []; final List faceBoxes = []; for (final e in faceBoxeMap.entries) { faceIds.add(e.key); faceBoxes.add(e.value); + _logger.info( + "[${file.uploadedFileID}] Face ${e.key}: box=${e.value.x}, ${e.value.y}, ${e.value.width}, ${e.value.height}", + ); } - final List faceCrop = - await FaceThumbnailGenerator.instance.generateFaceThumbnails( - // await generateJpgFaceThumbnails( - imagePath, - faceBoxes, + + _logger.info( + "[${file.uploadedFileID}] Calling FaceThumbnailGenerator with ${faceBoxes.length} face boxes", ); - final Map result = {}; - for (int i = 0; i < faceCrop.length; i++) { - result[faceIds[i]] = faceCrop[i]; + try { + final List faceCrop = + await FaceThumbnailGenerator.instance.generateFaceThumbnails( + imagePath, + faceBoxes, + fileID: file.uploadedFileID, + ); + _logger.info( + "[${file.uploadedFileID}] FaceThumbnailGenerator returned ${faceCrop.length} crops", + ); + + final Map result = {}; + for (int i = 0; i < faceCrop.length; i++) { + result[faceIds[i]] = faceCrop[i]; + _logger.info( + "[${file.uploadedFileID}] Mapped face ${faceIds[i]} to crop of size ${faceCrop[i].length} bytes", + ); + } + _logger.info( + "[${file.uploadedFileID}] _getFaceCrops END: returning ${result.length} face crops", + ); + return result; + } catch (e, s) { + _logger.severe( + "[${file.uploadedFileID}] Error in FaceThumbnailGenerator.generateFaceThumbnails", + e, + s, + ); + return null; } - return result; } diff --git a/mobile/apps/photos/lib/utils/image_ml_util.dart b/mobile/apps/photos/lib/utils/image_ml_util.dart index 8c8167a3fb..3365b89684 100644 --- a/mobile/apps/photos/lib/utils/image_ml_util.dart +++ b/mobile/apps/photos/lib/utils/image_ml_util.dart @@ -146,20 +146,43 @@ Future> generateFaceThumbnailsUsingCanvas( List faceBoxes, ) async { int i = 0; // Index of the faceBox, initialized here for logging purposes + + _logger.info( + "generateFaceThumbnailsUsingCanvas START: Processing ${faceBoxes.length} face boxes from $imagePath", + ); + try { + _logger.info("Decoding image from path: $imagePath"); + final stopwatch = Stopwatch()..start(); + final decodedImage = await decodeImageFromPath( imagePath, includeRgbaBytes: false, ); final Image img = decodedImage.image; + + stopwatch.stop(); + _logger.info( + "Image decoded successfully: ${img.width}x${img.height} in ${stopwatch.elapsedMilliseconds}ms", + ); final futureFaceThumbnails = >[]; + _logger.info("Starting face crop processing for ${faceBoxes.length} faces"); + for (final faceBox in faceBoxes) { + _logger.info( + "Processing face $i/${faceBoxes.length}: relative box=(${faceBox.x.toStringAsFixed(3)}, ${faceBox.y.toStringAsFixed(3)}, ${faceBox.width.toStringAsFixed(3)}, ${faceBox.height.toStringAsFixed(3)})", + ); + // Note that the faceBox values are relative to the image size, so we need to convert them to absolute values first final double xMinAbs = faceBox.x * img.width; final double yMinAbs = faceBox.y * img.height; final double widthAbs = faceBox.width * img.width; final double heightAbs = faceBox.height * img.height; + _logger.info( + "Face $i absolute coordinates: (${xMinAbs.toStringAsFixed(1)}, ${yMinAbs.toStringAsFixed(1)}, ${widthAbs.toStringAsFixed(1)}, ${heightAbs.toStringAsFixed(1)})", + ); + // Calculate the crop values by adding some padding around the face and making sure it's centered const regularPadding = 0.4; const minimumPadding = 0.1; @@ -178,6 +201,10 @@ Future> generateFaceThumbnailsUsingCanvas( final widthCropSafe = widthCrop.clamp(0, img.width - xCropSafe); final heightCropSafe = heightCrop.clamp(0, img.height - yCropSafe); + _logger.info( + "Face $i final crop area: (${xCropSafe.toStringAsFixed(1)}, ${yCropSafe.toStringAsFixed(1)}, ${widthCropSafe.toStringAsFixed(1)}, ${heightCropSafe.toStringAsFixed(1)})", + ); + futureFaceThumbnails.add( _cropAndEncodeCanvas( img, @@ -189,12 +216,22 @@ Future> generateFaceThumbnailsUsingCanvas( ); i++; } + + _logger.info("All face crop futures created, waiting for completion..."); + final cropStopwatch = Stopwatch()..start(); + final List faceThumbnails = await Future.wait(futureFaceThumbnails); + + cropStopwatch.stop(); + _logger.info( + "generateFaceThumbnailsUsingCanvas END: Generated ${faceThumbnails.length} thumbnails in ${cropStopwatch.elapsedMilliseconds}ms, sizes: ${faceThumbnails.map((t) => '${(t.length / 1024).toStringAsFixed(1)}KB').toList()}", + ); + return faceThumbnails; } catch (e, s) { _logger.severe( - 'Error generating face thumbnails. cropImage problematic input argument: ${i}th facebox: ${faceBoxes[i].toString()}', + 'generateFaceThumbnailsUsingCanvas ERROR: Failed at face $i/${faceBoxes.length}. FaceBox: ${i < faceBoxes.length ? faceBoxes[i].toString() : "index out of bounds"}. ImagePath: $imagePath', e, s, ); @@ -533,6 +570,11 @@ Future _cropAndEncodeCanvas( required double width, required double height, }) async { + _logger.info( + "_cropAndEncodeCanvas: Cropping ${image.width}x${image.height} image at (${x.toStringAsFixed(1)}, ${y.toStringAsFixed(1)}) with size ${width.toStringAsFixed(1)}x${height.toStringAsFixed(1)}", + ); + + final cropStopwatch = Stopwatch()..start(); final croppedImage = await _cropImage( image, x: x, @@ -540,14 +582,39 @@ Future _cropAndEncodeCanvas( width: width, height: height, ); - return await _encodeImageToPng(croppedImage); + cropStopwatch.stop(); + + _logger.info( + "_cropAndEncodeCanvas: Crop completed in ${cropStopwatch.elapsedMilliseconds}ms, result: ${croppedImage.width}x${croppedImage.height}", + ); + + final encodeStopwatch = Stopwatch()..start(); + final result = await _encodeImageToPng(croppedImage); + encodeStopwatch.stop(); + + _logger.info( + "_cropAndEncodeCanvas: PNG encoding completed in ${encodeStopwatch.elapsedMilliseconds}ms, size: ${(result.length / 1024).toStringAsFixed(1)}KB", + ); + + return result; } -Future> compressFaceThumbnails(Map args) async { +Future> compressFaceThumbnails(Map args, {int? fileID}) async { + _logger.info("[$fileID] compressFaceThumbnails START"); final listPngBytes = args['listPngBytes'] as List; final List> compressedBytesList = []; + + _logger.info( + "[$fileID] compressFaceThumbnails START: Processing ${listPngBytes.length} thumbnails with quality=$_faceThumbnailCompressionQuality, minDimension=$_faceThumbnailMinDimension", + ); + try { - for (final pngBytes in listPngBytes) { + for (int i = 0; i < listPngBytes.length; i++) { + final pngBytes = listPngBytes[i]; + _logger.info( + "[$fileID] Compressing thumbnail $i/${listPngBytes.length}, original size: ${(pngBytes.length / 1024).toStringAsFixed(1)}KB", + ); + final compressedBytes = FlutterImageCompress.compressWithList( pngBytes, quality: _faceThumbnailCompressionQuality, @@ -557,10 +624,29 @@ Future> compressFaceThumbnails(Map args) async { ); compressedBytesList.add(compressedBytes); } - return await Future.wait(compressedBytesList); + + _logger.info( + "[$fileID] Starting Future.wait for ${compressedBytesList.length} compression tasks", + ); + final stopwatch = Stopwatch()..start(); + + final result = await Future.wait(compressedBytesList); + + stopwatch.stop(); + _logger.info( + "[$fileID] compressFaceThumbnails END: All ${result.length} compressions completed in ${stopwatch.elapsedMilliseconds}ms", + ); + + for (int i = 0; i < result.length; i++) { + _logger.info( + "[$fileID] Thumbnail $i: ${(listPngBytes[i].length / 1024).toStringAsFixed(1)}KB -> ${(result[i].length / 1024).toStringAsFixed(1)}KB (${((result[i].length / listPngBytes[i].length) * 100).toStringAsFixed(1)}%)", + ); + } + + return result; } catch (e, s) { _logger.severe( - 'Failed to compress face thumbnail, using original. Size: ${listPngBytes.map((e) => e.length).toList()} bytes', + '[$fileID] Failed to compress face thumbnails. Original sizes: ${listPngBytes.map((e) => '${(e.length / 1024).toStringAsFixed(1)}KB').toList()}', e, s, ); diff --git a/mobile/apps/photos/lib/utils/thumbnail_util.dart b/mobile/apps/photos/lib/utils/thumbnail_util.dart index 3df6122c36..6214422eb7 100644 --- a/mobile/apps/photos/lib/utils/thumbnail_util.dart +++ b/mobile/apps/photos/lib/utils/thumbnail_util.dart @@ -242,16 +242,28 @@ File cachedThumbnailPath(EnteFile file) { ); } -File cachedFaceCropPath(String faceID, bool useTempCache) { +File cachedFaceCropPath(String faceID, bool useTempCache, [int? fileID]) { + final logger = Logger("FaceCropUtils"); + logger.info( + "[$fileID] cachedFaceCropPath called: faceID=$faceID, useTempCache=$useTempCache", + ); + late final String thumbnailCacheDirectory; if (useTempCache) { thumbnailCacheDirectory = Configuration.instance.getThumbnailCacheDirectory(); + logger + .info("[$fileID] Using temp cache directory: $thumbnailCacheDirectory"); } else { thumbnailCacheDirectory = Configuration.instance.getPersonFaceThumbnailCacheDirectory(); + logger.info( + "[$fileID] Using person face cache directory: $thumbnailCacheDirectory", + ); } - return File( - thumbnailCacheDirectory + "/" + faceID, - ); + + final filePath = thumbnailCacheDirectory + "/" + faceID; + logger.info("[$fileID] Generated cache file path: $filePath"); + + return File(filePath); }