Exception in Export

[eecue]

Describe the bug

I'm receiving this error when using export:

Exception ignored in: <function ExportDBInMemory.__del__ at 0x105633040>
Traceback (most recent call last):
  File "/Users/eecue/mambaforge/lib/python3.9/site-packages/osxphotos/export_db.py", line 901, in __del__
    self.close()
  File "/Users/eecue/mambaforge/lib/python3.9/site-packages/tenacity/__init__.py", line 326, in wrapped_f
    return self(f, *args, **kw)
  File "/Users/eecue/mambaforge/lib/python3.9/site-packages/tenacity/__init__.py", line 406, in __call__
    do = self.iter(retry_state=retry_state)
  File "/Users/eecue/mambaforge/lib/python3.9/site-packages/tenacity/__init__.py", line 363, in iter
    raise retry_exc from fut.exception()
tenacity.RetryError: RetryError[<Future at 0x48a68b790 state=finished raised ProgrammingError>]

Note that the exports actually seem to work. Here's the code:

photo = photosdb.photos(uuid=[uuid])[0]
pe = osxphotos.PhotoExporter(photo)
e = osxphotos.ExportOptions()
e.convert_to_jpeg = True
e.download_missing = True
e.overwrite = True
# e.use_photokit = True
pe.export("/tmp", f"photo_{hash}.jpeg", options=e)

Desktop (please complete the following information):

• OS: Ventura 13.2.1
• osxphotos version 0.57.3

[RhetTbull]

Weird. Your code snippet worked fine on my machine (M1 Mini Ventura 13.1). The error is in closing the export database and in this case, since you didn't pass an export database path to ExportOptions, a temporary in-memory database is created and used. (osxphotos always uses an export database whether you create one or not as it simplifies the export code).

A number of osxphotos users use osxphotos over a NAS. If the network connection to the NAS is flaky, sqlite operations can fail and because of that, I've added automatic retry to all sqlite operations. In this case, the retry on the close() call to the in-memory database is failing but this can be safely ignored (the database will be discarded anyway).

[RhetTbull]

I've added a fix to ignore this error. Will include in the next release which I intend to push this weekend with a couple new features. If this is happening for you on every export, in the mean time you could wrap the export() in a try:/except: to ignore tenacity.RetryError.

[eecue]

I'm also seeing this, not sure if it's related:

2023-02-25 10:39:33,863 - root - WARNING - photosdb.py - 123 - WARNING: This module has only been tested with macOS versions [10.12, 10.13, 10.14, 10.15, 10.16, 11.0, 11.1, 11.2, 11.3, 11.4, 11.5, 11.6, 11.7, 12.0, 12.1, 12.2, 12.3, 12.4, 12.5, 12.6, 13.0, 13.1]: you have Darwin, OS version: 13.2

[eecue]

Also, if this helps, I'm basically exporting thousands of photos individually based on criteria that doesn't exist in the Photos db. So I'm doing that code block above many many times. At first I thought it was related to running it using concurrent.futures.ThreadPoolExecutor but I switched to just running single threaded and still saw the errors.

[eecue]

Btw, I actually am try/catching but I think you already do that in the library so the noisy warning still gets printed.

[eecue]

try:
    photo = photosdb.photos(uuid=[uuid])[0]
    pe = osxphotos.PhotoExporter(photo)
    e = osxphotos.ExportOptions()
    e.convert_to_jpeg = True
    e.download_missing = True
    e.overwrite = True
    # e.use_photokit = True
    pe.export("/tmp", f"photo_{hash}.jpeg", options=e)
    # output = os.system(
    #     f"sips -s format jpeg --setProperty formatOptions 100 '{path}' --out /tmp/photo_{hash}.jpg >/dev/null")
    path = f"/tmp/photo_{hash}.jpeg"
except tenacity.RetryError as e:
    pass
except Exception as e:
    print(f"Error {e} with {hash} {traceback.format_exc()}")

[RhetTbull]

At first I thought it was related to running it using concurrent.futures.ThreadPoolExecutor

osxphotos is definitely not thread safe. I have a design for a multi-process capable export but it's on the back burner for now while I work some other projects.

I'm also seeing this, not sure if it's related:

Very unlikely it's related but I'm extra careful about testing osxphotos on each version of macOS and as I've not updated to 13.2 yet the warning is there.

I'm basically exporting thousands of photos individually

One thing that might help is using an export database for the duration of your export instead of the throw-away in-memory database that gets created each time if you don't explicitly pass a database.

from osxphotos.export_db import ExportDB

...
e.export_db = ExportDB(dbfile="/tmp/export.db", export_dir="/tmp")
...

[eecue]

That fixed the warning fwiw... also it's working fine in threaded mode (mostly because everything I'm doing is independent between threads)

[eecue]

And actually, I think it was more than a warning, I think it was actually breaking the export.

[RhetTbull]

also it's working fine in threaded mode (mostly because everything I'm doing is independent between threads)

That's good to know! I'll do some more testing and maybe I'll be able to enable multi-threading in the command line export.

[RhetTbull]

@all-contributors please add @eecue for bug

[allcontributors[bot]]

@RhetTbull

I've put up a pull request to add @eecue! :tada:

[RhetTbull]

I believe this is fixed in v0.58.0. Please let me know if you continue to see the issue.

[eecue]

It for sure fixed the version warning! Let me. I'll test my next export with the in memory db next time and let you know if I see the issue.

[eecue]

Confirmed that I no longer see the memory db warning.

[eecue]

So I think that catching these is now causing parallelized exports to fail silently.

[RhetTbull]

Osxphotos makes no guarantees on parallelization. In fact I'm surprised if it works at all. The PhotoExporter and PhotosDB classes maintain open SQLite connections which cannot be shared among threads. Additionally PhotosDB cannot be pickled which means it cannot be shared between processes. There's an open issue to add multiprocessing #582 but it's a "back burner" issue for me.

I have a design for a way to do this without too much rework: create a new PhotoInfo subclass which instead of using PhotosDB to get the class properties would be instantiated with a dict (PhotoInfo already has an as_dict() method). This would then be passed to PhotoExporter for exporting. The SQLite exportdb issue would still need to be solved as open connections can't be shared. For the on disk exportdb we could use the database path and have each process reopen the data base or we could use a sub process that provides a server interface. For the in memory use case we could use a temp db on disk or a server process.

I've held off on working on this because another alternative is a complete rewrite of osxphotos core code to use dynamic queries instead of slurping the entire Photos db into the PhotosDB class. This is a much bigger effort but would solve other issues like slow startup, dynamic reloading, etc.

I've got several projects at the moment and only a few hours per week to work on osxphotos so this will like continue to simmer on the back burner for now.

[RhetTbull]

I've got an idea that might make this easier than I thought. PhotoInfo already has a json() method. The json produced from this can be reconstituted into a class using json.loads and SimpleNamespace as the object hook to produce a "walks like a duck, quacks like a duck" class that implements the PhotoInfo interface but doesn't need a PhotosDB. It's not fast as it requires calling every PhotoInfo property (some of which have lazy implementations) but it would be simple. We can have PhotoExporter do this in init() so it doesn't even keep a reference to the original object thus making it threadable. For the export db, we can close the export database and pass the path to database to each thread to open its own connection. Again, an inefficiency but SQLite can handle concurrent connections.

I still want to rewrite the core bits of PhotosDB but this might be something that can be implemented relatively easily with very little code change. This could even be a flag to the PhotoExporter initializer to use threadsafe or fast mode. The default would be threadsafe but if don't need that, setting threadsafe=False would use the default PhotoInfo object instead of the reconstituted object.

[RhetTbull]

See this on thread safety. This might have to be a "Python 3.11+" feature as only in ^3.11 is SQLite serialized mode (thread safe connections) enabled.

[eecue]

That would be awesome, yeah the export is where I'm seeing the crash, which makes sense.

[eecue]

And the places where I load the full database vs where I export are two different scripts so having the option to do it both ways would be great.

[RhetTbull]

So I've gotten a very rough alpha implementation of a thread-safe export and it appears to actually be slower than single threaded. The test case was exporting 615 photos from my library to my internal SSD (M1 Mac Mini, 8 cores) with 8 max workers (concurrent.futures.ThreadPoolExecutor). The concurrent test took about twice as long as the single threaded case. Looking at profile data, it looks like there's a lot of time spent managing threads:

     5542    9.896    0.002    9.896    0.002 {method 'acquire' of '_thread.lock' objects}
      615    0.001    0.000    9.850    0.016 _base.py:646(__exit__) # <-- this is in concurrent.futures
      615    0.001    0.000    9.849    0.016 thread.py:216(shutdown)
      622    0.001    0.000    9.848    0.016 threading.py:1080(join)
      622    0.001    0.000    9.846    0.016 threading.py:1118(_wait_for_tstate_lock)

To get this fully working I'll also need to parallelize the exiftool code (which currently runs as singleton process).

I tried ProcessPoolExecutor() but it doesn't work because the ExportDB object cannot be pickled so I'd have to refactor that too.

[eecue]

Awesome! Fwiw I don’t actually use exiftool, I strip off all my exif as I don’t fully trust what’s hidden away in there lol

[eecue]

I’m out of town for a few days but honestly twice as slow is actually 8x faster as I do 16 threads for my image scaler tool which does the exporting.

[RhetTbull]

Fwiw I don’t actually use exiftool,

I'm most interested in the general export case for the CLI as that's what most people use.

For the general case, I'm not sure multi-threaded is really worth it though if I can parallelize exiftool (which a lot of people use) then we might get some speedups for large exports.

I think I'll be able to at least get PhotoInfo.export() to be thread-safe for your use case but it will be python 3.11 only as earlier versions of python don't use the right sqlite concurrency setting.

[RhetTbull]

I thought I was close to pushing this release but then testing starting randomly breaking with things like: sqlite3.OperationalError: cannot commit - no transaction is active and sqlite3.OperationalError: cannot start a transaction within a transaction. After reading far more than I wanted to about concurrency in SQLite I've figured out that getting PhotoExporter to work concurrently is going to be a lot more work. This is because the export database (upon which the entire export design is built) is SQLite and this causes lots of problems when multiple threads are trying to read/write to the database which happens many times for each export. This is more work than I have time for at the moment.

However, I do think I can get it working for the simple case where there is no export database (in this case, all state management such as collision detection must be done by the user). An export database is still used in this instance but if called without an explicit ExportDB instance, a throw-away, in-memory database is used and since only the calling thread is accessing this database, no problems. There is some performance hit from using a database when one isn't needed but it greatly simplifies the code design.

[RhetTbull]

For the long term fix, I think rewriting ExportDB is the best answer. As all reads/writes of the export database pass through ExportDB methods (instead of raw SQL in the rest of the code) it should be possible to have ExportDB manage a single lock that must be acquired before reading/writing. This would block threads until the lock could be acquired but is the only way (AFAIK) to safely manage concurrent threads accessing the export database which is an integral part of the export process.

[eecue]

However, I do think I can get it working for the simple case where there is no export database (in this case, all state management such as collision detection must be done by the user). An export database is still used in this instance but if called without an explicit ExportDB instance, a throw-away, in-memory database is used and since only the calling thread is accessing this database, no problems. There is some performance hit from using a database when one isn't needed but it greatly simplifies the code design.

That works great for me! Thanks for digging in to this!

[RhetTbull]

I believe this is now fixed in v0.59.0. I've also added an example script that performs concurrent export. In some quick testing, it does appear that on my M1 mini, there is a performance boost using concurrent export. Note that this only works on Python 3.11+ and only applies to the API; the osxphotos export CLI does not yet support concurrent export.

❯ python examples/concurrent_export.py $TESTDIR --added-after 2023-03-01 --workers 40
Exporting 653 photos to /Volumes/OWC_SDD/rhet/test using 40 workers
Exported 579 photos to /Volumes/OWC_SDD/rhet/test in 7.1581 seconds

❯ python examples/concurrent_export.py $TESTDIR --added-after 2023-03-01 --workers 1
Exporting 653 photos to /Volumes/OWC_SDD/rhet/test using 1 workers
Exported 579 photos to /Volumes/OWC_SDD/rhet/test in 19.0723 seconds

[RhetTbull]

Also, I think this will work even if you use an export database (so it can be ported to the CLI) because I've added thread-level locking to all sqlite transactions in the ExportDB code but I have not yet tested this (besides a simple test case in the test code).

[RhetTbull]

I did some benchmarking. On my M1 Mac Mini (8 cores), the sweet spot appears to be 8 thread workers. The python default is number of processors * 5 but this appears to offer no benefit. This makes sense to me as a single thread per core allows the thread to saturate the core while reducing the number of thread joins. Using more threads doesn't get more out of the CPU but increases the thread joins (which from profiling, appear to consume much of the time). All this testing was done to a fast external SSD connected directly to the Mac Mini using Thunderbolt 4. I did this to include the file transfer time in the test as doing an export on the same SSD uses copy-on-write and is very fast regardless of how many threads are used.

[oPromessa]

Super!

Will test it out also as I've noticed my export of 90k pics has been steadily taking more time -- on my setup iMac i7, SSD disk to Synology NAS via 1GB LAN -- from around 3,5 hours with version 0.57 up to 7,5 hours with version 0.58.

[RhetTbull]

I'll look into the slowdown. Unfortunately this fix likely won't help your case and may even make it worse. This will help those writing their own export code but the osxphotos export command is very complex and not yet thread safe.

If you want to try an export with the --profile flag ( added directly after osxphotos and before export: osxphotos --profile export...) that will help collect data on what's causing the slowdown.

[oPromessa]

CLI Performance

Thanks so much. Will run tonight the CLI export with profile on versions 0.58.1 so as to have a baseline then

API Workers

On the API testing I've done one can see an improvement of about 36% for 251 pics. Of course, as you pointed out the API interface does not have all the other (nice) options, update, delete, exiftool template, etc...

Summary results

Pics	Workers	Time (s)	CPU, LAN, NAS	Remarks
251	1	119.4311	iMac i7, LAN 1GB, NAS	No exiftool, templates, etc.
251	40	76.1256	iMac i7, LAN 1GB, NAS	No exiftool, templates, etc.

Workers: 1

2023-04-02 18:38:40.624183 -- Processing database /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary/database/photos.db
2023-04-02 18:38:55.741986 -- Done processing details from Photos library.
2023-04-02 18:38:56.508798 -- Exporting 251 photos to /Volumes/photo/Multi.Photos using 1 workers
2023-04-02 18:40:55.939137 -- Exported 251 photos to /Volumes/photo/Multi.Photos in 119.4311 seconds

Workers: 40 (default)

2023-04-02 18:42:12.651548 -- Processing database /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary/database/Photos.sqlite
2023-04-02 18:42:27.883363 -- Done processing details from Photos library.
2023-04-02 18:42:28.669775 -- Exporting 251 photos to /Volumes/photo/Multi.Photos using 40 workers
2023-04-02 18:43:44.795103 -- Exported 251 photos to /Volumes/photo/Multi.Photos in 76.1256 seconds

[oPromessa]

CLI Performance

(below the info for the runs...) A bump on the duration from 3h to 4h and then 7h was around version 0.57.0 although there was a session with 4h after that. But since then... always around 7h.

On occasion I see the verbose output line per line on a particular pic export to take more than 60seconds... it seems as if the Mac sleeps or maybe the NAS responds slowly... but I'm running caffeinate alongside the run to repent it. But still. It's not always the same pic and the total of such delays (if I add them up!) would not amount to justify the 7+ hours.

2023-02-13 03:44:04.573387 -- osxphotos version: 0.57.0
2023-02-13 07:31:18.799642 -- Processed: 89467 photos, exported: 0, updated: 90, skipped: 89379, updated EXIF data: 90, missing: 0, error: 0, touched date: 116
2023-02-13 07:31:18.800252 -- Elapsed time: 3:46:02
2023-02-17 04:13:17.166804 -- osxphotos version: 0.57.0
2023-02-17 08:58:47.737548 -- Processed: 89467 photos, exported: 0, updated: 92, skipped: 89377, updated EXIF data: 92, missing: 0, error: 0, touched date: 118
2023-02-17 08:58:47.738274 -- Elapsed time: 4:44:14
2023-02-18 06:33:06.805235 -- osxphotos version: 0.57.0
2023-02-18 10:53:03.280851 -- Processed: 89474 photos, exported: 7, updated: 337, skipped: 89132, updated EXIF data: 344, missing: 0, error: 0, touched date: 370
2023-02-18 10:53:03.281486 -- Elapsed time: 4:18:37
2023-02-18 12:18:05.956351 -- osxphotos version: 0.57.0
2023-02-18 19:51:04.325478 -- Processed: 89474 photos, exported: 7, updated: 337, skipped: 89132, updated EXIF data: 344, missing: 0, error: 0, touched date: 111
2023-02-18 19:51:04.326106 -- Elapsed time: 7:26:16
2023-02-19 03:44:05.745053 -- osxphotos version: 0.57.0
2023-02-19 07:19:28.565068 -- Processed: 89502 photos, exported: 58774, updated: 182, skipped: 28944, updated EXIF data: 58952, missing: 0, error: 1604, touched date: 29
2023-02-19 07:19:28.565739 -- Elapsed time: 3:34:15
2023-02-20 03:44:04.306268 -- osxphotos version: 0.57.1
2023-02-20 07:43:37.205226 -- Processed: 89503 photos, exported: 36, updated: 361, skipped: 89108, updated EXIF data: 397, missing: 0, error: 0, touched date: 111
2023-02-20 07:43:37.205844 -- Elapsed time: 3:58:31
2023-02-21 03:44:05.322260 -- osxphotos version: 0.57.3
2023-02-21 07:49:03.400516 -- Processed: 89505 photos, exported: 62, updated: 358, skipped: 89087, updated EXIF data: 420, missing: 0, error: 0, touched date: 111
2023-02-21 07:49:03.401191 -- Elapsed time: 4:03:51
2023-02-22 14:20:03.501724 -- osxphotos version: 0.57.3
2023-02-22 21:24:25.180989 -- Processed: 89505 photos, exported: 62, updated: 359, skipped: 89086, updated EXIF data: 421, missing: 0, error: 0, touched date: 447
2023-02-22 21:24:25.181656 -- Elapsed time: 7:02:28

(...)

2023-03-27 03:44:07.018251 -- osxphotos version: 0.58.1
2023-03-27 11:34:55.682748 -- Processed: 89580 photos, exported: 0, updated: 128, skipped: 89454, updated EXIF data: 128, missing: 0, error: 0, touched date: 154
2023-03-27 11:34:55.683387 -- Elapsed time: 7:49:33
2023-04-01 03:44:05.067088 -- osxphotos version: 0.58.1
2023-04-01 11:03:35.225139 -- Processed: 89580 photos, exported: 0, updated: 125, skipped: 89457, updated EXIF data: 125, missing: 0, error: 0, touched date: 151
2023-04-01 11:03:35.226221 -- Elapsed time: 7:18:11
2023-04-02 03:44:04.891046 -- osxphotos version: 0.58.1
2023-04-02 11:16:13.369890 -- Processed: 89580 photos, exported: 0, updated: 125, skipped: 89457, updated EXIF data: 125, missing: 0, error: 0, touched date: 151
2023-04-02 11:16:13.370522 -- Elapsed time: 7:01:56

[RhetTbull]

0.57.1 added lock files to reserve names for exported photos to reduce name collision (this was in prep for moving export to multithreaded operation). This is likely the culprit as it's causing an additional round trip to the NAS for each photo.

I may be able to add an option to eliminate the lock files when running single threaded. Currently they're not required as the export code is single threaded. This was a refactor done to make multithreaded code easier in the future.

[RhetTbull]

@oPromessa the lock file code is contained in two utility functions, lock_filename() and unlock_filename(). I can easily add an option for --no-lock or just disable these two for now (make them no-op but retain the code for when it's eventually needed). Will take a look at what's the best option. Interestingly, in my profiling, these take basically no time. But--I'm running on fast APFS formatted SSD, not a NAS. I really wish there was a way I could "mock" the NAS (slow network, flaky copies, etc.) for testing to catch these types of things.

      682    0.001    0.000    0.056    0.000 utils.py:425(lock_filename)
     1048    0.002    0.000    0.055    0.000 utils.py:443(unlock_filename)

While profiling, I found some other inefficiencies where I can pull code out of a loop to further speed-up export. Will implement these.

[RhetTbull]

@oPromessa Give v0.59.1 a try. I believe it should restore performance to what you'd experienced under 0.57.0. Will still need to work on the multi-threaded code / lock files but putting that on the back burner again as I've got several other projects demanding attention.

[oPromessa]

So I'm giving 0.59.1 a "spin".

For reference on 0.58.1 the profile results for 8hours is as follows. I attach for reference.

• profile.0.58.1.txt

For 0.59.1 results seem similar (about 8 hours) but with a few caveats/issues which I mention below and will attach/report more correctly.

2023-04-08 11:55:38.386869 -- Elapsed time: 8:08:33

2023-04-08 12:11:04.547428 -- Deleted: 7716 files, 55 directories
2023-04-08 12:11:13.263940 -- Writing export database changes back to /Users/MSP/Pictures/Pictures/Logs/.osxphotos_export.db
2023-04-08 12:26:07.676602 -- Cleaning up lock files
Profiling completed
         12099852465 function calls (11803689538 primitive calls) in 31505.312 seconds 

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001 31281.228 31281.228 core.py:1393(invoke)
        1    0.005    0.005 31281.227 31281.227 core.py:709(invoke)
        1    0.003    0.003 31281.211 31281.211 decorators.py:37(new_func)
        1    0.003    0.003 31281.208 31281.208 decorators.py:25(new_func)
        1    0.001    0.001 31281.205 31281.205 crash_reporter.py:33(wrapped)
        1    2.606    2.606 31281.204 31281.204 export.py:98(export)
    89580    3.177    0.000 29068.968    0.325 export.py:1685(export_photo)
    90927    2.976    0.000 28246.781    0.311 export.py:2110(export_photo_to_directory)
   105014    2.721    0.000 28136.283    0.268 photoexporter.py:391(export)
   105014    5.570    0.000 27409.345    0.261 photoexporter.py:1067(_export_photo)
   187133    8.719    0.000 14267.504    0.076 photoexporter.py:1579(_exiftool_dict)
   186754    0.785    0.000 14261.395    0.076 photoexporter.py:1888(exiftool_json_sidecar)
   105014    1.333    0.000 14020.674    0.134 photoexporter.py:720(_should_update_photo)

Issues found on 0.59.1 -- Will make specific reports for each one!

1. One of the issues is that the export database jumped from 500MB to 3.9GB in size!
2. Although my log file presents the profile information (normally presented at the end of the run), the process is still running and the exit code is not caught(which I normally catch and report). Will probably be forced to kill it.

   $ ps axuu | grep osxphoto
   MSP              56947  15.4  7.7 82569508 1289156   ??  U     3:44am 216:40.54 /usr/local/Cellar/python@3.9/3.9.16/Frameworks/Python.framework/Versions/3.9/Resources/Python.app/Contents/MacOS/Python /Users/MSP/Documents/Apps/osxphotos/venv/bin/osxphotos --profile export /Volumes/photo/Family.Photos --exportdb /Users/MSP/Pictures/Pictures/Logs/.osxphotos_export.db --load-config /Users/MSP/Pictures/Pictures/Apps/colibri.toml

3. Some files have errors while exporting (possibly due to some exiftool error), re-attempts and success... only to generate a delete file at the end (with --update option). Already saw this behaviour in the past (#872) -- for which we've agreed to let it be as it is with the current behaviour. Luckily found one file which I can partially reproduce the error with (while exporting to a local disk so non NAS related!).Will tinker a bit more to figure out why the export/exiftool fails and try to fiz that from my side.
   • May be relevant to say that the same Photos origin and export location on version 0.59.1 deleted about 7716 files which from a first glance where caused by something going wrong on the export.Which was not the case on 0.58.1 (maybe because it detected no changes and skipped the copy)!!

     $ egrep "\-\- Start|\-\- End|osxphotos version|Deleted|Processed" runOSxPhotos.cron.err
     [notice] --- Start Mon 3 Apr 2023 03:44:01 WEST
     2023-04-03 03:44:04.825589 -- osxphotos version: 0.58.1
     2023-04-03 11:54:45.932397 -- Processed: 89580 photos, exported: 0, updated: 376, skipped: 89206, updated EXIF data: 376, missing: 0, error: 0, touched date: 402
     2023-04-03 12:00:36.346917 -- Deleted: 0 files, 0 directories
     [notice] --- End Mon 3 Apr 2023 12:01:31 WEST
     [notice] --- Start Sat 8 Apr 2023 03:44:01 WEST
     2023-04-08 03:44:46.732642 -- osxphotos version: 0.59.1
     2023-04-08 11:55:38.384600 -- Processed: 89580 photos, exported: 0, updated: 373, skipped: 81493, updated EXIF data: 373, missing: 0, error: 7716, touched date: 399
     2023-04-08 12:11:04.547428 -- Deleted: 7716 files, 55 directories
     [notice] --- End Sat 8 Apr 2023 14:42:24 WEST

4. (small issue)The overall counter is not being incremented.Counter is always 0: "counter at 0/850000"

   2023-04-08 03:47:04.990936 -- Exporting 89580 photos to /Volumes/photo/Family.Photos...
   2023-04-08 03:47:05.107643 -- Exporting DSC00783.JPG (DSC00783.JPG) (0/89580)
   2023-04-08 03:47:09.363666 -- Skipped up to date file /Volumes/photo/XXX
   2023-04-08 03:47:09.369534 -- Exporting fotos 339.jpg (fotos 339.jpg) (0/89580)
   2023-04-08 03:47:09.686381 -- Skipped up to date file /Volumes/photo/XXX
   2023-04-08 03:47:09.693072 -- Exporting IMG_20170224_194318.JPG (IMG_20170224_194318.JPG) (0/89580)
   2023-04-08 03:47:10.028128 -- Skipped up to date file /Volumes/photo/XXX
   2023-04-08 03:47:10.032463 -- Exporting 20151121_152344.jpg (20151121_152344.jpg) (0/89580)
   (...)
   2023-04-08 11:55:38.139061 -- Exporting DSC03009.JPG (DSC03009.JPG) (0/89580)

5. While troubleshooting a specific pic with export error, used query --uuid with csv output correclty. But json options fails. Using python 3.11 for this one in particular. The main export I still use 3.9 python.

   
   $  osxphotos query --uuid  18CD34E6-8E32-4873-BBA7-0EE8C9822EC0 
   Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
   uuid,filename,original_filename,date,description,title,keywords,albums,persons,path,ismissing,hasadjustments,external_edit,favorite,hidden,shared,latitude,longitude,path_edited,isphoto,ismovie,uti,burst,live_photo,path_live_photo,iscloudasset,incloud,date_modified,portrait,screenshot,slow_mo,time_lapse,hdr,selfie,panorama,has_raw,uti_raw,path_raw,intrash
   18CD34E6-8E32-4873-BBA7-0EE8C9822EC0,IMG_0855.JPG,IMG_0855.JPG,XXX,                               ,,"XXX",XXXX,,/Volumes/Macintosh HD/Users/Shared/Pictures/Pictures/iPhoto/XXXJPG,False,False,False,False,False,False,XXX,XXXX,,True,False,public.jpeg,False,False,,False,,,False,False,False,False,False,False,False,False,,,False
   $ osxphotos query --uuid  18CD34E6-8E32-4873-BBA7-0EE8C9822EC0 --json
   Using last opened Photos library: /Users/Shared/Pictures/iPhoto Shared Library.photoslibrary
   ╭─────────────────────────────── Traceback (most recent call last) ────────────────────────────────╮
   │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/albuminfo.py │
   │ :244 in folder_list                                                                              │
   │                                                                                                  │
   │   241 │   │   """                                                                                │
   │   242 │   │                                                                                      │
   │   243 │   │   try:                                                                               │
   │ ❱ 244 │   │   │   return self._folders                                                           │
   │   245 │   │   except AttributeError:                                                             │
   │   246 │   │   │   self._folders = self._db._album_folder_hierarchy_folderinfo(self._uuid)        │
   │   247 │   │   │   return self._folders                                                           │
   ╰──────────────────────────────────────────────────────────────────────────────────────────────────╯
   AttributeError: 'ProjectInfo' object has no attribute '_folders'

During handling of the above exception, another exception occurred:

╭─────────────────────────────── Traceback (most recent call last) ────────────────────────────────╮ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/bin/osxphotos:8 in │ │ │ │ 5 from osxphotos.main import cli_main │ │ 6 if name == 'main': │ │ 7 │ sys.argv[0] = re.sub(r'(-script.pyw|.exe)?$', '', sys.argv[0]) │ │ ❱ 8 │ sys.exit(cli_main()) │ │ 9 │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/core.py:1130 in │ │ call │ │ │ │ 1127 │ │ │ 1128 │ def call(self, *args: t.Any, kwargs: t.Any) -> t.Any: │ │ 1129 │ │ """Alias for :meth:main.""" │ │ ❱ 1130 │ │ return self.main(*args, kwargs) │ │ 1131 │ │ 1132 │ │ 1133 class Command(BaseCommand): │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/core.py:1055 in │ │ main │ │ │ │ 1052 │ │ try: │ │ 1053 │ │ │ try: │ │ 1054 │ │ │ │ with self.make_context(prog_name, args, extra) as ctx: │ │ ❱ 1055 │ │ │ │ │ rv = self.invoke(ctx) │ │ 1056 │ │ │ │ │ if not standalone_mode: │ │ 1057 │ │ │ │ │ │ return rv │ │ 1058 │ │ │ │ │ # it's not safe to ctx.exit(rv) here! │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/core.py:1657 in │ │ invoke │ │ │ │ 1654 │ │ │ │ super().invoke(ctx) │ │ 1655 │ │ │ │ sub_ctx = cmd.make_context(cmd_name, args, parent=ctx) │ │ 1656 │ │ │ │ with sub_ctx: │ │ ❱ 1657 │ │ │ │ │ return _process_result(sub_ctx.command.invoke(sub_ctx)) │ │ 1658 │ │ │ │ 1659 │ │ # In chain mode we create the contexts step by step, but after the │ │ 1660 │ │ # base command has been invoked. Because at that point we do not │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/core.py:1404 in │ │ invoke │ │ │ │ 1401 │ │ │ echo(style(message, fg="red"), err=True) │ │ 1402 │ │ │ │ 1403 │ │ if self.callback is not None: │ │ ❱ 1404 │ │ │ return ctx.invoke(self.callback, *ctx.params) │ │ 1405 │ │ │ 1406 │ def shell_complete(self, ctx: Context, incomplete: str) -> t.List["CompletionItem"]: │ │ 1407 │ │ """Return a list of completions for the incomplete value. Looks │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/core.py:760 in │ │ invoke │ │ │ │ 757 │ │ │ │ 758 │ │ with augment_usage_errors(self): │ │ 759 │ │ │ with ctx: │ │ ❱ 760 │ │ │ │ return callback(args, kwargs) │ │ 761 │ │ │ 762 │ def forward( │ │ 763 │ │ self, cmd: "Command", *args: t.Any, kwargs: t.Any # noqa: B902 │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/decorators.py:38 │ │ in new_func │ │ │ │ 35 │ """ │ │ 36 │ │ │ 37 │ def new_func(*args, *kwargs): # type: ignore │ │ ❱ 38 │ │ return f(get_current_context().obj, args, kwargs) │ │ 39 │ │ │ 40 │ return update_wrapper(t.cast(F, new_func), f) │ │ 41 │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/click/decorators.py:26 │ │ in new_func │ │ │ │ 23 │ """ │ │ 24 │ │ │ 25 │ def new_func(*args, *kwargs): # type: ignore │ │ ❱ 26 │ │ return f(get_current_context(), args, **kwargs) │ │ 27 │ │ │ 28 │ return update_wrapper(t.cast(F, new_func), f) │ │ 29 │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/cli/query.py │ │ :164 in query │ │ │ │ 161 │ │ │ │ │ print(rendered_template) │ │ 162 │ │ │ 163 │ if not quiet and not field: │ │ ❱ 164 │ │ print_photo_info(photos, clijson or json, print_func=click.echo) │ │ 165 │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/cli/print_ph │ │ oto_info.py:16 in print_photo_info │ │ │ │ 13 ): │ │ 14 │ dump = [] │ │ 15 │ if json: │ │ ❱ 16 │ │ dump.extend(p.json() for p in photos) │ │ 17 │ │ print_func(f"[{', '.join(dump)}]") │ │ 18 │ else: │ │ 19 │ │ # dump as CSV │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/cli/print_ph │ │ oto_info.py:16 in │ │ │ │ 13 ): │ │ 14 │ dump = [] │ │ 15 │ if json: │ │ ❱ 16 │ │ dump.extend(p.json() for p in photos) │ │ 17 │ │ print_func(f"[{', '.join(dump)}]") │ │ 18 │ else: │ │ 19 │ │ # dump as CSV │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/photoinfo.py │ │ :1898 in json │ │ │ │ 1895 │ │ │ if isinstance(o, (datetime.date, datetime.datetime)): │ │ 1896 │ │ │ │ return o.isoformat() │ │ 1897 │ │ │ │ ❱ 1898 │ │ dict_data = self.asdict() │ │ 1899 │ │ for k, v in dict_data.items(): │ │ 1900 │ │ │ # sort lists such as keywords so JSON is consistent │ │ 1901 │ │ │ # but do not sort certain items like location │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/photoinfo.py │ │ :1795 in asdict │ │ │ │ 1792 │ │ likes = [like.asdict() for like in self.likes] │ │ 1793 │ │ person_info = [p.asdict() for p in self.person_info] │ │ 1794 │ │ place = self.place.asdict() if self.place else {} │ │ ❱ 1795 │ │ project_info = [p.asdict() for p in self.project_info] │ │ 1796 │ │ score = dataclasses.asdict(self.score) if self.score else {} │ │ 1797 │ │ search_info = self.search_info.asdict() if self.search_info else {} │ │ 1798 │ │ search_info_normalized = ( │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/photoinfo.py │ │ :1795 in │ │ │ │ 1792 │ │ likes = [like.asdict() for like in self.likes] │ │ 1793 │ │ person_info = [p.asdict() for p in self.person_info] │ │ 1794 │ │ place = self.place.asdict() if self.place else {} │ │ ❱ 1795 │ │ project_info = [p.asdict() for p in self.project_info] │ │ 1796 │ │ score = dataclasses.asdict(self.score) if self.score else {} │ │ 1797 │ │ search_info = self.search_info.asdict() if self.search_info else {} │ │ 1798 │ │ search_info_normalized = ( │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/albuminfo.py │ │ :306 in asdict │ │ │ │ 303 │ │ dict_data = super().asdict() │ │ 304 │ │ dict_data["title"] = self.title │ │ 305 │ │ dict_data["folder_names"] = self.folder_names │ │ ❱ 306 │ │ dict_data["folder_list"] = [f.uuid for f in self.folder_list] │ │ 307 │ │ dict_data["sort_order"] = self.sort_order │ │ 308 │ │ dict_data["parent"] = self.parent.uuid if self.parent else None │ │ 309 │ │ return dict_data │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/albuminfo.py │ │ :246 in folder_list │ │ │ │ 243 │ │ try: │ │ 244 │ │ │ return self._folders │ │ 245 │ │ except AttributeError: │ │ ❱ 246 │ │ │ self._folders = self._db._album_folder_hierarchy_folderinfo(self._uuid) │ │ 247 │ │ │ return self._folders │ │ 248 │ │ │ 249 │ @property │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/photosdb/pho │ │ tosdb.py:2736 in _album_folder_hierarchy_folderinfo │ │ │ │ 2733 │ │ if self._db_version <= _PHOTOS_4_VERSION: │ │ 2734 │ │ │ return self._album_folder_hierarchy_folderinfo_4(album_uuid) │ │ 2735 │ │ else: │ │ ❱ 2736 │ │ │ return self._album_folder_hierarchy_folderinfo_5(album_uuid) │ │ 2737 │ │ │ 2738 │ def _album_folder_hierarchy_folderinfo_4(self, album_uuid): │ │ 2739 │ │ """return hierarchical list of FolderInfo objects album_uuid is contained in │ │ │ │ /Users/MSP/Documents/Apps/osxphotos/venv3.11/lib/python3.11/site-packages/osxphotos/photosdb/pho │ │ tosdb.py:2777 in _album_folder_hierarchy_folderinfo_5 │ │ │ │ 2774 │ │ ["Top level folder", "sub folder 1", "sub folder 2"] │ │ 2775 │ │ returns empty list of album is not in any folders""" │ │ 2776 │ │ # title = photosdb._dbalbum_details[album_uuid]["title"] │ │ ❱ 2777 │ │ folders = self._dbalbum_folders[album_uuid] │ │ 2778 │ │ │ │ 2779 │ │ def _recurse_folder_hierarchy(folders, hierarchy=[]): │ │ 2780 │ │ │ """recursively walk the folders dict to build list of folder hierarchy""" │ ╰──────────────────────────────────────────────────────────────────────────────────────────────────╯ KeyError: '0634722E-DB05-4F18-B6A3-9E612256E1F2'

[RhetTbull]

Thanks for the report.

The incrementing counter is simple -- I spotted the problem and have pushed a fix to the main branch.

I think I know what's going on with the JSON and the export db size. I completely changed the json() method for photos to get a more complete dump of all the photo's data into the JSON. This makes the output much larger. In some cases the JSON output is 2x or 3x the size. For storing in the database I can probably just gzip the data to shrink it again but that means it's not easily usable directly from the database.

For the --json error, I see the issue -- you've got photos in Projects and I don't have any of those in the test data so didn't catch this. Shouldn't be hard to fix.

The speed slow down may be due to the errors being generated by the bad json code as well as crazy large export db (I believe you're using --ramdb?)

[RhetTbull]

Another option for the json issue is to offer both a "shallow" and a "deep" json method. The deep method (0.59.1) is needed for multithreading / multiprocessing. The shallow method (0.58.1) should be sufficient for export.

[RhetTbull]

Actually I do have a project in the test suite but wasn't testing the asdict()/json() output for this. Added a test (currently failing), and now I can work a fix.

[oPromessa]

I think I know what's going on with the JSON and the export db size. I completely changed the json() method for photos to get a more complete dump of all the photo's data into the JSON. This makes the output much larger. In some cases the JSON output is 2x or 3x the size. For storing in the database I can probably just gzip the data to shrink it again but that means it's not easily usable directly from the database.

• Got it. Enough to know it is explained and we have data storage for the 4GB for 90K pics and it doesn't increase, that's ok.

For the --json error, I see the issue -- you've got photos in Projects and I don't have any of those in the test data so didn't catch this. Shouldn't be hard to fix.

• Yes, I have Projects folder from way back when. Currently not using them.

The speed slow down may be due to the errors being generated by the bad json code as well as crazy large export db (I believe you're using --ramdb?)

• Yes, using ramdb
• I have the made a small filter on the log file for each sequence/run.
  • It shows the start and End times
  • osxphotos version
  • Elapsed time
  • Entries that take over 60 seconds
    • Oddly enough there are some cases of a few minutes to 20 or more. Weirdly either the MAC of the NAS are sleeping!
  • Total time, number lines and average per line.

--------
Sequence:   7 2023-02-19 03:44:05.745053 -- osxphotos version: 0.57.0
Sequence:   7 2023-02-19 07:19:28.565739 -- Elapsed time: 3:34:15
Sequence:   7 [notice] --- Start Sun 19 Feb 2023 03:44:01 WET Lines:    307758 Lines over [ 60 secs]:   0 Total Duration:  12923.00 03:35:23.003206 Average per line:  0.04 00:00:00.041991
--------
Sequence:   8 2023-02-20 03:44:04.306268 -- osxphotos version: 0.57.1
Sequence:   8 2023-02-20 07:43:37.205844 -- Elapsed time: 3:58:31
Sequence:   8 Line:   1599521 over [ 60 secs]     121.41 Duration: 00:02:01.409387 2023-02-20 07:48:41.750446 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:   8 [notice] --- Start Mon 20 Feb 2023 03:44:00 WET Lines:    184309 Lines over [ 60 secs]:   1 Total Duration:  14512.28 04:01:52.281395 Average per line:  0.08 00:00:00.078739
--------
Sequence:   9 2023-02-21 03:44:05.322260 -- osxphotos version: 0.57.3
Sequence:   9 2023-02-21 07:49:03.401191 -- Elapsed time: 4:03:51
Sequence:   9 Line:   1783895 over [ 60 secs]     124.64 Duration: 00:02:04.640536 2023-02-21 07:54:35.746010 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:   9 [notice] --- Start Tue 21 Feb 2023 03:44:00 WET Lines:    184357 Lines over [ 60 secs]:   1 Total Duration:  14841.61 04:07:21.611304 Average per line:  0.08 00:00:00.080505
--------
Sequence:  10 2023-02-22 14:20:03.501724 -- osxphotos version: 0.57.3
Sequence:  10 Line:   1783915 over [ 60 secs]      91.34 Duration: 00:01:31.340035 2023-02-22 14:20:03.570850 -- Warning: export database '/Users/Shared/Pictures/Logs/.osxphotos_export.db' is in a different directory than export destination '/Volumes/photo/Family.Photos'
Sequence:  10 2023-02-22 21:24:25.181656 -- Elapsed time: 7:02:28
Sequence:  10 Line:   1968638 over [ 60 secs]     231.38 Duration: 00:03:51.377555 2023-02-22 21:24:29.374690 -- Deleting /Volumes/photo/Family.Photos/.DS_Store
Sequence:  10 [notice] --- Start Wed 22 Feb 2023 14:20:01 WET Lines:    184762 Lines over [ 60 secs]:   2 Total Duration:  25806.30 07:10:06.295208 Average per line:  0.14 00:00:00.139673
--------
(...)
--------
Sequence:  14 2023-03-04 03:44:18.817022 -- osxphotos version: 0.58.0
Sequence:  14 Line:   2522737 over [ 60 secs]      73.11 Duration: 00:01:13.109628 2023-03-04 03:44:18.863070 -- Warning: export database '/Users/Shared/Pictures/Logs/.osxphotos_export.db' is in a different directory than export destination '/Volumes/photo/Family.Photos'
Sequence:  14 Line:   2595348 over [ 60 secs]     898.78 Duration: 00:14:58.781396 2023-03-04 09:46:09.211000 -- Skipped up to date file /Volumes/photo/Family.Photos/XXX/IMG_9627.JPG
Sequence:  14 Line:   2595521 over [ 60 secs]    1042.24 Duration: 00:17:22.237695 2023-03-04 10:02:05.551966 -- Exporting 19XXX.jpg) (35371/89505)
Sequence:  14 Line:   2598845 over [ 60 secs]      66.76 Duration: 00:01:06.759231 2023-03-04 10:42:38.445871 -- Exporting P3190452-a-2.JPG (P3190452-a-2.JPG) (36993/89505)
Sequence:  14 Line:   2615356 over [ 60 secs]      67.00 Duration: 00:01:07.004625 2023-03-04 12:27:23.888725 -- Exporting IMG_7928.JPG (IMG_7928.JPG) (45014/89505)
Sequence:  14 Line:   2638913 over [ 60 secs]    1737.27 Duration: 00:28:57.271953 2023-03-04 13:58:50.774711 -- Exporting DSCF9869.MOV (DSCF9869.MOV) (56435/89505)
Sequence:  14 Line:   2655222 over [ 60 secs]    1722.77 Duration: 00:28:42.773094 2023-03-04 15:35:11.474438 -- Skipped up to date file /Volumes/photo/Family.Photos/2012-12-21 Visita Tios Norte/IMG_2386.JPG
Sequence:  14 Line:   2666276 over [ 60 secs]     202.11 Duration: 00:03:22.111955 2023-03-04 17:23:25.011864 -- Exporting IMG_0886.JPG (IMG_0886.JPG) (69719/89505)
Sequence:  14 Line:   2678389 over [ 60 secs]     129.33 Duration: 00:02:09.328671 2023-03-04 18:39:49.587240 -- Exporting IMG_0037.JPG (IMG_0037.JPG) (75626/89505)
Sequence:  14 Line:   2691326 over [ 60 secs]     118.82 Duration: 00:01:58.816218 2023-03-04 19:46:16.785321 -- Exporting IMG_8640.JPG (IMG_8640.JPG) (81910/89505)
Sequence:  14 Line:   2705104 over [ 60 secs]     116.11 Duration: 00:01:56.107381 2023-03-04 20:54:56.014992 -- Exporting FutXXXXjpg) (88601/89505)
Sequence:  14 2023-03-04 21:05:14.633341 -- Elapsed time: 15:48:04
Sequence:  14 Line:   2706972 over [ 60 secs]     312.24 Duration: 00:05:12.238938 2023-03-04 21:05:14.685992 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:  14 Line:   2706974 over [ 60 secs]     310.20 Duration: 00:05:10.198200 2023-03-04 21:10:28.826140 -- Writing export database changes back to /Users/MSP/Pictures/Pictures/Logs/.osxphotos_export.db
Sequence:  14 [notice] --- Start Sat 4 Mar 2023 03:44:12 WET Lines:    184239 Lines over [ 60 secs]:  13 Total Duration:  63079.75 17:31:19.745872 Average per line:  0.34 00:00:00.342380
--------
(...)
--------
Sequence:  12 2023-04-02 03:44:04.891046 -- osxphotos version: 0.58.1
Sequence:  12 Line:   2052637 over [ 60 secs]    1736.61 Duration: 00:28:56.608461 2023-04-02 04:43:04.462108 -- Exporting IMG_8319.JPG (IMG_8319.JPG) (13939/89580)
Sequence:  12 2023-04-02 11:16:13.370522 -- Elapsed time: 7:01:56
Sequence:  12 Line:   2207971 over [ 60 secs]     398.77 Duration: 00:06:38.773502 2023-04-02 11:16:13.397083 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:  12 [notice] --- Start Sun 2 Apr 2023 03:44:01 WEST Lines:    183963 Lines over [ 60 secs]:   2 Total Duration:  27543.37 07:39:03.369094 Average per line:  0.15 00:00:00.149722
--------
Sequence:  13 2023-04-03 03:44:04.825589 -- osxphotos version: 0.58.1
Sequence:  13 2023-04-03 11:54:45.933518 -- Elapsed time: 8:09:15
Sequence:  13 Line:   2392706 over [ 60 secs]     350.39 Duration: 00:05:50.386594 2023-04-03 11:54:45.960323 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:  13 [notice] --- Start Mon 3 Apr 2023 03:44:01 WEST Lines:    184718 Lines over [ 60 secs]:   1 Total Duration:  29811.08 08:16:51.078723 Average per line:  0.16 00:00:00.161387
--------
Sequence:  14 2023-04-08 03:44:46.732642 -- osxphotos version: 0.59.1
Sequence:  14 Line:   2455953 over [ 60 secs]      76.74 Duration: 00:01:16.738749 2023-04-08 05:39:56.179796 -- Exporting P2030949.JPG (P2030949.JPG) (0/89580)
Sequence:  14 Line:   2469591 over [ 60 secs]     104.88 Duration: 00:01:44.882939 2023-04-08 06:05:09.282053 -- Exporting IMG_5552.JPG (IMG_5552.JPG) (0/89580)
Sequence:  14 Line:   2486241 over [ 60 secs]     144.27 Duration: 00:02:24.265085 2023-04-08 06:35:33.506152 -- Exporting IMG_1807.JPG (IMG_1807.JPG) (0/89580)
Sequence:  14 Line:   2505918 over [ 60 secs]     269.31 Duration: 00:04:29.312473 2023-04-08 07:13:43.812808 -- Exporting P9150778.JPG (P9150778.JPG) (0/89580)
Sequence:  14 Line:   2530180 over [ 60 secs]     735.55 Duration: 00:12:15.549511 2023-04-08 08:02:17.423698 -- Exporting IMG_20190713_130320.JPG (IMG_20190713_130320.JPG) (0/89580)
Sequence:  14 Line:   2560335 over [ 60 secs]    1628.95 Duration: 00:27:08.949242 2023-04-08 09:09:42.392816 -- Exporting IMG_9448.JPG (IMG_9448.JPG) (0/89580)
Sequence:  14 Line:   2596824 over [ 60 secs]    2778.28 Duration: 00:46:18.276605 2023-04-08 10:43:25.199190 -- Exporting IMG_4895.JPG (IMG_4895.JPG) (0/89580)
Sequence:  14 2023-04-08 11:55:38.386869 -- Elapsed time: 8:08:33
Sequence:  14 Line:   2609935 over [ 60 secs]      81.04 Duration: 00:01:21.037986 2023-04-08 11:55:40.699848 -- Cleaning up /Volumes/photo/Family.Photos
Sequence:  14 Line:   2617651 over [ 60 secs]     144.38 Duration: 00:02:24.377114 2023-04-08 12:07:13.897742 -- Deleting /Volumes/photo/Family.Photos/XXX/MyPicture.jpg
Sequence:  14 Line:   2617708 over [ 60 secs]     894.41 Duration: 00:14:54.412662 2023-04-08 12:11:13.263940 -- Writing export database changes back to /Users/MSP/Pictures/Pictures/Logs/.osxphotos_export.db
Sequence:  14 [notice] --- Start Sat 8 Apr 2023 03:44:01 WEST Lines:    223355 Lines over [ 60 secs]:  10 Total Duration:  31278.53 08:41:18.529103 Average per line:  0.14 00:00:00.140040
--------

[RhetTbull]

Thanks for the run time -- that's helpful! I've got a shallow json method implemented that is sufficient for export purposes and will add that in which will bring export db size back down.

[oPromessa]

Issues found on 0.59.1 -- Will make specific reports for each one!

1. One of the issues is that the export database jumped from 500MB to 3.9GB in size!
   • Understood. related with json size.

2. Although my log file presents the profile information (normally presented at the end of the run), the process is still running and the exit code is not caught(which I normally catch and report). Will probably be forced to kill it.

   • Maybe with a smaller json and no --profile the run will finish normally. Will test.
     3. Some files have errors while exporting (possibly due to some exiftool error), re-attempts and success... only to generate a delete file at the end (with --update option).(...)
   • Added more info on #872 on this comment. I'm trying to debug it... do not yet master --breakpoint option ;)
   4. (small issue)The overall counter is not being incremented.Counter is always 0: "counter at 0/850000"
      • Fixed!
   5. While troubleshooting a specific pic with export error, used query --uuid with csv output correclty. But json options fails. Using python 3.11 for this one in particular. The main export I still use 3.9 python.
      • Should be fixed ( Projects folder on Photos would be the off/case !)

[RhetTbull]

@oPromessa Please give v0.59.2 a try. I think it will resolve the issues you identified but not sure if it'll help performance yet.

[RhetTbull]

@oPromessa There were bugs in 0.59.2, notably a memory leak, that would have caused it to slow down. There was also some unnecessary calls to the AlbumInfo code that was pretty slow so I've refactored those out. Give 0.59.3 a try. In my testing with my 125GB library, exporting to external Thunderbolt 4 drive, it's slightly faster than 0.58.2.

[oPromessa]

UAU! Amazing! 0.59.3 brought my 90K export back down to 3:23:23.

That's simply Great!

2023-04-11 17:17:10.768877 -- Processed: 89851 photos, exported: 271, updated: 128, skipped: 89454, updated EXIF data: 399, missing: 0, error: 0, touched date: 425

Real Memory and Virtual Memory peaked at 6.4 GB and 43 GB respectively.

   RSS      VSZ 
86088 34284600
1005548 35192900
3101100 37269516
3113152 37298700
2743564 37324492
2774900 37338316
2809376 37373132
2840900 37388748
2874960 37415372
(...)
6432112 41674172
6454196 41696956
6386356 41734572
5608324 41745068
5227772 41752492
4881112 41761452
4339416 41775020
3330028 43585624

And also no slowdowns !!! No executions over 60secs. On average 0.07 seconds per operation compared to 0.19!

Sequence:  18 2023-04-11 13:52:04.083373 -- osxphotos version: 0.59.3
Sequence:  18 Line:   2835879 over [ 60 secs]      69.41 Duration: 00:01:09.406722 2023-04-11 13:52:04.101336 -- Warning: export database '/Users/Shared/Pictures/Logs/.osxphotos_export.db' is in a different directory than export destination '/Volumes/photo/Family.Photos'
Sequence:  18 2023-04-11 17:17:10.769537 -- Elapsed time: 3:23:23
Sequence:  18 [notice] --- Start Tue 11 Apr 2023 13:52:00 WEST Lines:    185398 Lines over [ 60 secs]:   2 Total Duration:  12631.43 03:30:31.433289 Average per line:  0.07 00:00:00.068131