Catalog unresponsive, CPU 100%

[Ethan Welty]

Photo Mechanic Plus Version 6.0, build 5215 (abbcb1f)
Mac OS 10.14.6

- I successfully added all of my 200 000 photos to the catalog.
- I cleared the list of folders to sync from.
- I selected and removed 4 000 photos from the catalog that should not have been included.

Unclear whether that last step ever completed. Instead, pm-task went to 100% CPU and the search features became unresponsive. I tried to quit PM, it said something like "Catalog is taking a long to close. Continue waiting?". I clicked "yes", and eventually PM closed (or crashed). I reopened PM and found the Catalog tabs (Search, Filter, Browse, Collections) completely blank, and the search box unresponsive. I quit again, this time answering "no" on whether to wait. I forced-quit pm-task in Activity Monitor, and reopened PM. Same problem. Catalog is MIA and pm-task is back up at 100% CPU. Ack!

Catalog Status is stuck on "Catalog Metadata Updates: Updating 1 catalog, 6 batches remaining".

p.s. Oddly, Active Catalogs shows "Search: 2, Modify: 1" even though there is only one catalog. But that was already like that before this trouble started.

[Kirk Baker]

Ethan,

Photo Mechanic Plus Version 6.0, build 5215 (abbcb1f)
Mac OS 10.14.6

- I successfully added all of my 200 000 photos to the catalog.
- I cleared the list of folders to sync from.
- I selected and removed 4 000 photos from the catalog that should not have been included.

Unclear whether that last step ever completed. Instead, pm-task went to 100% CPU and the search features became unresponsive. I tried to quit PM, it said something like "Catalog is taking a long to close. Continue waiting?". I clicked "yes", and eventually PM closed (or crashed). I reopened PM and found the Catalog tabs (Search, Filter, Browse, Collections) completely blank, and the search box unresponsive. I quit again, this time answering "no" on whether to wait. I forced-quit pm-task in Activity Monitor, and reopened PM. Same problem. Catalog is MIA and pm-task is back up at 100% CPU. Ack!

Catalog Status is stuck on "Catalog Metadata Updates: Updating 1 catalog, 6 batches remaining".

p.s. Oddly, Active Catalogs shows "Search: 2, Modify: 1" even though there is only one catalog. But that was already like that before this trouble started.

Could you turn on Catalog debug logging and post the log, please?  From the Help menu, choose "Edit Debug Settings..." and find the item titled CATALOG_DEBUG_LOGGING and set its checkbox.  Then click the Close button.  Then restart Photo Mechanic Plus and reproduce the problem.  From the Help menu choose "Reveal Support Data..." and moments later a Finder window will come forward with the zipped log file selected.  Use the 'Attachments and other options' link when you're composing your reply to this message and there you'll be able to upload your zipped PM log file.

Thanks,

-Kirk

[Ethan Welty]

Hi Kirk,

Eventually, the Catalog became accessible again. I turned on Catalog debugging and proceeded to remove more images from my catalog. Every time, the catalog stops responding (search/browse/filter/collections do not respond) for an amount of time seemingly proportional to the number of images removed, and CPU usage of pm-task shoots up during that time. It takes minutes to remove hundreds of images, and I cannot keep working during that time.

The logging does not offer much. Many rounds of very slow image removal resulted in just this:

Code: [Select]


********************************************************************************
Photo Mechanic Plus version 6.0.0.0 build 5215 (abbcb1f)
[Wed Oct-21-2020 11:15:32.997][10f2955c0][5066036] PMDocumentController.mm:2140 macOS version: 10.14.6
[Wed Oct-21-2020 11:15:33.067][10f2955c0][5070204] PMDocumentController.mm:2145 Current locale is: C
[Wed Oct-21-2020 11:15:35.658][70000f6d9000][5154316] [00003ffe1f4ae6d0] Initializing DNS resolver
[Wed Oct-21-2020 11:15:37.046][10f2955c0][5206912] PMCache.cpp:3180 cache: main thread startup
[Wed Oct-21-2020 11:15:37.046][10f2955c0][5207040] PMCache.cpp:1382 cache: spawning 4 worker threads (4 cpus) ...
[Wed Oct-21-2020 11:15:37.071][700012b84000][5215724] PMCache.cpp:3120 cache: found 1216 disk cache entries, 1216 usable
[Wed Oct-21-2020 11:15:37.072][10f2955c0][5273240] PMCache.cpp:661 PMCache::PMCacheWorker::set_memory_cache_size_limit_mb(1638 MB) [1717567488] bytes
[Wed Oct-21-2020 11:20:39.041][70000f8e6000][7095556] [00003ffe20107274] PMCache.cpp:1959 cache: prune oldest image info: 24448 30319 35606 43292 61572
[Wed Oct-21-2020 11:29:35.588][700016399000][7201680] NRFGIF.cpp:492 NRFGIFLoadImageScaled(): Width or Height of GIF image too small, GIF error code: 0, file:'/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/dot.GIF'
[Wed Oct-21-2020 11:29:35.589][700016399000][7201680] NRFBitmapBase.cpp:689 NRF failed to load '/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/dot.GIF' with error 5
[Wed Oct-21-2020 11:30:04.461][700016399000][7215496] NRFGIF.cpp:492 NRFGIFLoadImageScaled(): Width or Height of GIF image too small, GIF error code: 0, file:'/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/borderfade_h.GIF'
[Wed Oct-21-2020 11:30:04.461][700016399000][7215496] NRFBitmapBase.cpp:689 NRF failed to load '/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/borderfade_h.GIF' with error 5
[Wed Oct-21-2020 11:30:04.463][700016399000][7206300] NRFGIF.cpp:492 NRFGIFLoadImageScaled(): Width or Height of GIF image too small, GIF error code: 0, file:'/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/borderfade_v.GIF'
[Wed Oct-21-2020 11:30:04.463][700016399000][7206300] NRFBitmapBase.cpp:689 NRF failed to load '/Volumes/Photos/2005/050508 Wetlands Project/Web/galleries/res/borderfade_v.GIF' with error 5
[Wed Oct-21-2020 11:40:50.074][700012b84000][7641500] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:50.074][700012b84000][7641700] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:50.416][700012b84000][7643320] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:50.416][700012b84000][7643320] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:51.905][700012b84000][7583584] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:51.905][700012b84000][7583700] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:51.914][700012b84000][7584724] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:51.914][700012b84000][7584924] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:52.589][700012b84000][7446064] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:52.590][700012b84000][7446456] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:52.593][700014b90000][7447092] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:52.594][700014b90000][7447676] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:52.596][700014b90000][7447676] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:52.596][700014b90000][7447676] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:55.780][700012b84000][7414288] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:55.780][700012b84000][7414288] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:56.940][700016399000][7416956] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:56.940][700016399000][7416956] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:40:57.206][700013b8a000][7417564] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:40:57.207][700013b8a000][7417564] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:41:01.137][700015393000][7434424] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:41:01.142][700015393000][7434424] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID
[Wed Oct-21-2020 11:41:03.170][700013387000][7424920] ColorManagementCommon.cpp:21 LittleCMS error: 9, 'Wrong input color space on transform'
[Wed Oct-21-2020 11:41:03.170][700013387000][7424920] ColorManagementCommon.cpp:466 CreateColorManagedBitmap(): no transform found for image to profile ID


[Kirk Baker]

Ethan,

Eventually, the Catalog became accessible again. I turned on Catalog debugging and proceeded to remove more images from my catalog. Every time, the catalog stops responding (search/browse/filter/collections do not respond) for an amount of time seemingly proportional to the number of images removed, and CPU usage of pm-task shoots up during that time. It takes minutes to remove hundreds of images, and I cannot keep working during that time.

Thanks for the log.  It is the dyn.log that will contain the information related to Catalog operations.  Those PM.log messages are unrelated to your problem.  We will investigate and see what can be done.

-Kirk

[Kirk Baker]

Ethan,

Can you please download this build and give it a try?

https://www.camerabits.com/download/PhotoMechanicPlusR5221_994a5988.dmg

It may also be helpful to use the "Reintegrate Forgotten Catalog" maintenance option in the Catalog Management window for your catalog.

Thanks,

-Kirk

[Ethan Welty]

I tried "Reintegrate Forgotten Catalog". It didn't find any missing files. Not sure it made a difference.
The test build fixes the catalog count in "Active Catalogs", but the main issue persists. For example, after removing 300 images, the search box was unresponsive for two minutes. One thing I noticed is that during this time, one pm-task is at ~100%, a second is at ~5%, and the remaining two are at 0%.

[Kirk Baker]

I tried "Reintegrate Forgotten Catalog". It didn't find any missing files. Not sure it made a difference.
The test build fixes the catalog count in "Active Catalogs", but the main issue persists. For example, after removing 300 images, the search box was unresponsive for two minutes. One thing I noticed is that during this time, one pm-task is at ~100%, a second is at ~5%, and the remaining two are at 0%.

Thanks Ethan.  Can you send us the log again, please?

Thanks,

-Kirk

[Ethan Welty]

The logs have gotten very large, so sending you a download link:
https://drive.google.com/file/d/1xeH5J8zFgkut4RsI8vj_zNX_kvomNecy/view

[Kirk Baker]

Ethan,

The logs have gotten very large, so sending you a download link:
https://drive.google.com/file/d/1xeH5J8zFgkut4RsI8vj_zNX_kvomNecy/view

Thanks for the log.  If you want, you could delete the numbered dyn.log files in between runs.

We've added some more logging.  Can you please try this build and repeat your remove operation?

https://www.camerabits.com/download/PhotoMechanicPlusR5242_d979e5e1.dmg

It also should address those Collection renaming issues you reported (existing Collection tab doesn't rename/rescan of a Collection tab after renaming produces empty view) so please try them when you get a chance.

Thanks,

-Kirk

[Ethan Welty]

Logs from the new build are attached for an operation adding, then removing, ~1600 images.

I noticed that when adding the images, CPU of pm-tasks hit upwards of 500% (and took maybe 2 minutes), while when removing, no more than 100% total (and took maybe 10 minutes before catalog responded again). Which is definitely odd, given that removing images should be a much faster catalog operation than scanning and adding the image metadata.

Yes, collection renaming bug is fixed! Will update bug thread.

[Kirk Baker]

Ethan,

Logs from the new build are attached for an operation adding, then removing, ~1600 images.

I noticed that when adding the images, CPU of pm-tasks hit upwards of 500% (and took maybe 2 minutes), while when removing, no more than 100% total (and took maybe 10 minutes before catalog responded again). Which is definitely odd, given that removing images should be a much faster catalog operation than scanning and adding the image metadata.

Thank you for the log.  We have added some more logging.  Can you please repeat your tests with this build and post the log?

Yes, collection renaming bug is fixed! Will update bug thread.

That's good to hear.  Thanks!

-Kirk

[Ethan Welty]

I did repeat the tests with the new build and attached the result to my previous email.
In any case, here is yet another log, on a 466 image add and remove.

[Kirk Baker]

Ethan,

I did repeat the tests with the new build and attached the result to my previous email.
In any case, here is yet another log, on a 466 image add and remove.

Wow, I forgot to paste in the URL for the new build: https://www.camerabits.com/download/PhotoMechanicPlusR5251_bf557ff7.dmg

It was a long day yesterday.

Please try again with the above build.

Thanks,

-Kirk

[Ethan Welty]

Logs for build 5251 attached.

[Kirk Baker]

Ethan,

Please try the interim build, available here: http://forums.camerabits.com/index.php?topic=13663.0

Thanks,

-Kirk