Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Moments: Don't back up albums in worker to avoid disk activity #4237

Open
sgflt opened this issue May 8, 2024 · 18 comments
Open

Moments: Don't back up albums in worker to avoid disk activity #4237

sgflt opened this issue May 8, 2024 · 18 comments
Assignees
Labels
bug Something isn't working tested Changes have been tested successfully

Comments

@sgflt
Copy link

sgflt commented May 8, 2024

1. What is not working as documented?

I was curious why disk storage was spinning up each hour.

It corelated to PHOTOPRISM_WAKEUP_INTERVAL: 3600

2. How can we reproduce it?

Steps to reproduce the behavior:

  1. Set PHOTOPRISM_WAKEUP_INTERVAL: 3600
  2. Upload some photos
  3. see log
time="2024-05-07T04:59:10Z" level=debug msg="index: running face recognition"
[mysql] 2024/05/07 04:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 04:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 04:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 04:59:10 connection.go:173: driver: bad connection
[mysql] 2024/05/07 04:59:10 packets.go:122: closing bad idle connection: connection timed out
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no orphan markers [17.923862ms]"
time="2024-05-07T04:59:10Z" level=debug msg="markers: found no invalid references [90.414088ms]"
time="2024-05-07T04:59:10Z" level=debug msg="markers: found no missing subjects [2.52045ms]"
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no ambiguous subjects [53.984301ms]"
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no clusters to be merged [42.853371ms]"
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no existing clusters"
time="2024-05-07T04:59:10Z" level=debug msg="faces: skipped clustering"
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no new faces [86.790648ms]"
time="2024-05-07T04:59:10Z" level=debug msg="faces: found no unmatched markers"
time="2024-05-07T04:59:10Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [128.757901ms]"
time="2024-05-07T04:59:10Z" level=debug msg="index: updating metadata"
time="2024-05-07T04:59:11Z" level=debug msg="moments: analyzing 112 photos and 19 videos, with threshold 8"
time="2024-05-07T04:59:11Z" level=trace msg="moments: Camera already exists (path:\"Xiaomi 2201116SG/Camera\" public:true)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'February 2024' already exists (public:true year:2024 month:2)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'January 2024' already exists (public:true year:2024 month:1)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'December 2023' already exists (public:true year:2023 month:12)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'November 2023' already exists (public:true year:2023 month:11)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'October 2023' already exists (public:true year:2023 month:10)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'September 2023' already exists (public:true year:2023 month:9)"
time="2024-05-07T04:59:11Z" level=trace msg="moments: 'August 2023' already exists (public:true year:2023 month:8)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: 'Switzerland 2023' already exists (public:true country:ch year:2023)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: 'Czech Republic 2023' already exists (public:true country:cz year:2023)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: 'Czech Republic 2024' already exists (public:true country:cz year:2024)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: Bern already exists (public:true country:ch state:Bern)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: Zürich already exists (public:true country:ch state:Zürich)"
time="2024-05-07T04:59:12Z" level=trace msg="moments: Jihozápad already exists (public:true country:cz state:Jihozápad)"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qdrl17dlzhs3i.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qdrl11bibxipi.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qeue33ocudw2i.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2rgq04lzl.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1xamttz5e.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2ckqqr7ew.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1tz1u21x6.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1ib05u66t.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2o7dcy5tg.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1ujwr7uyq.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1bwbd749f.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u4o6oz2id4.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2umjjzgq3yy.yml"
time="2024-05-07T04:59:12Z" level=trace msg="backup: saved album yaml file as9qf2ua5uz0u79k.yml"
time="2024-05-07T04:59:13Z" level=trace msg="backup: saved album yaml file as9qf2u1kijzggvt.yml"
time="2024-05-07T04:59:13Z" level=trace msg="backup: saved album yaml file as9qf2u20vop41ao.yml"
time="2024-05-07T04:59:13Z" level=debug msg="moments: 16 albums saved as yaml files"
time="2024-05-07T04:59:13Z" level=debug msg="index: updating counts"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 places [44.338141ms]"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 subjects [14.152954ms]"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 labels [46.338469ms]"
time="2024-05-07T04:59:13Z" level=debug msg="index: updating covers"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 albums [3.231447ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 folders [45.549567ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 months [44.400212ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 labels [46.759854ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 subjects [55.15086ms]"
time="2024-05-07T05:59:10Z" level=debug msg="index: running face recognition"

[mysql] 2024/05/07 05:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 05:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 05:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 05:59:10 packets.go:122: closing bad idle connection: connection timed out
[mysql] 2024/05/07 05:59:10 connection.go:173: driver: bad connection
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no orphan markers [18.987781ms]"
time="2024-05-07T05:59:10Z" level=debug msg="markers: found no invalid references [90.909226ms]"
time="2024-05-07T05:59:10Z" level=debug msg="markers: found no missing subjects [2.59121ms]"
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no ambiguous subjects [54.566123ms]"
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no clusters to be merged [44.155431ms]"
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no existing clusters"
time="2024-05-07T05:59:10Z" level=debug msg="faces: skipped clustering"
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no new faces [87.595976ms]"
time="2024-05-07T05:59:10Z" level=debug msg="faces: found no unmatched markers"
time="2024-05-07T05:59:10Z" level=debug msg="faces: updated 0 markers, recognized 0 faces, 0 unknown [130.453028ms]"
time="2024-05-07T05:59:10Z" level=debug msg="index: updating metadata"
time="2024-05-07T05:59:11Z" level=debug msg="moments: analyzing 112 photos and 19 videos, with threshold 8"
time="2024-05-07T05:59:11Z" level=trace msg="moments: Camera already exists (path:\"Xiaomi 2201116SG/Camera\" public:true)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'February 2024' already exists (public:true year:2024 month:2)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'January 2024' already exists (public:true year:2024 month:1)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'December 2023' already exists (public:true year:2023 month:12)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'November 2023' already exists (public:true year:2023 month:11)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'October 2023' already exists (public:true year:2023 month:10)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'September 2023' already exists (public:true year:2023 month:9)"
time="2024-05-07T05:59:11Z" level=trace msg="moments: 'August 2023' already exists (public:true year:2023 month:8)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: 'Switzerland 2023' already exists (public:true country:ch year:2023)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: 'Czech Republic 2023' already exists (public:true country:cz year:2023)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: 'Czech Republic 2024' already exists (public:true country:cz year:2024)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: Bern already exists (public:true country:ch state:Bern)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: Zürich already exists (public:true country:ch state:Zürich)"
time="2024-05-07T05:59:12Z" level=trace msg="moments: Jihozápad already exists (public:true country:cz state:Jihozápad)"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qdrl17dlzhs3i.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qdrl11bibxipi.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qeue33ocudw2i.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2rgq04lzl.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1xamttz5e.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2ckqqr7ew.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1tz1u21x6.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1ib05u66t.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u2o7dcy5tg.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1ujwr7uyq.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u1bwbd749f.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2u4o6oz2id4.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2umjjzgq3yy.yml"
time="2024-05-07T05:59:12Z" level=trace msg="backup: saved album yaml file as9qf2ua5uz0u79k.yml"
time="2024-05-07T05:59:13Z" level=trace msg="backup: saved album yaml file as9qf2u1kijzggvt.yml"
time="2024-05-07T05:59:13Z" level=trace msg="backup: saved album yaml file as9qf2u20vop41ao.yml"
time="2024-05-07T05:59:13Z" level=debug msg="moments: 16 albums saved as yaml files"
time="2024-05-07T05:59:13Z" level=debug msg="index: updating counts"
time="2024-05-07T05:59:13Z" level=debug msg="counts: updated 0 places [44.535066ms]"
time="2024-05-07T05:59:13Z" level=debug msg="counts: updated 0 subjects [14.419046ms]"
time="2024-05-07T05:59:13Z" level=debug msg="counts: updated 0 labels [45.688216ms]"
time="2024-05-07T05:59:13Z" level=debug msg="index: updating covers"
time="2024-05-07T05:59:13Z" level=debug msg="covers: updated 0 albums [3.852531ms]"
time="2024-05-07T05:59:13Z" level=debug msg="covers: updated 0 folders [45.768655ms]"
time="2024-05-07T05:59:13Z" level=debug msg="covers: updated 0 months [44.885742ms]"
time="2024-05-07T05:59:13Z" level=debug msg="covers: updated 0 labels [46.928296ms]"
time="2024-05-07T05:59:13Z" level=debug msg="covers: updated 0 subjects [44.185595ms]"

Check history of power usage.
orico-power

3. What behavior do you expect?

Backup to yaml only if there is change in metadata.

6. Which software versions do you use?

(a) PhotoPrism x86_64 & Build 240420-ef5f14bc4
(b) Database Type MariaDB
(c) Operating System: Fedora 40, Podman 5.0.2, SELinux

7. On what kind of device is PhotoPrism installed?

(a) Device / Processor Type: Intel Celeron N5105

(b) Physical Memory & Swap Space in GB 16 GiB

(c) Storage Type: HDD main data, SSD storage/cache
(d) Anything else that might be helpful to know?

After setting PHOTOPRISM_DISABLE_BACKUPS: "true" are wake ups gone.

@sgflt sgflt added the bug Something isn't working label May 8, 2024
@lastzero
Copy link
Member

lastzero commented May 8, 2024

Are you sure that the YAML files are updated every 15 minutes (edit: or whatever you have configured as worker interval)? Is there any other activity, like changes to the index or faces, that could trigger an update?

According to this, the YAML files / Moments should only be updated if updateIndex is true:

// Check time when worker was last executed.
updateIndex := force || w.lastRun.Before(time.Now().Add(-1*entity.IndexUpdateInterval))

While this background worker does perform a query to determine if files need to be checked (e.g. the generated title is updated if people have recently been recognised in an image), this should only cause brief activity in the form of a database query and other steps, like updating Moment albums, should be skipped except every 3 hours (as currently implemented, it can of course be further improved):

var IndexUpdateInterval = 3 * time.Hour // 3 Hours

@lastzero lastzero added the needs-analysis Requires further investigation label May 8, 2024
@sgflt
Copy link
Author

sgflt commented May 8, 2024

In log I can see just the repeated sequence attached in fist comment. It seems there is no other update or background processing. Photo set were stable a few days without adding new photos.

@lastzero
Copy link
Member

lastzero commented May 8, 2024

I wonder if the background activity really depends on the YAML backup files being enabled, or if the worker is constantly checking the index for changes anyway and the main increase in power consumption is due to the magnetic disks spinning up? We could of course check the existing backup files to see if the data has changed, but then the files would have to be read first, which might be enough to wake the disks up - so this wouldn't solve your particular problem.

@sgflt
Copy link
Author

sgflt commented May 8, 2024

I am looking into code now.

moments.go:269

// Make sure that the albums have been backed up before, otherwise back up all albums.
	if fs.PathExists(filepath.Join(w.conf.AlbumsPath(), entity.AlbumManual)) &&
		fs.PathExists(filepath.Join(w.conf.AlbumsPath(), entity.AlbumMonth)) {
		// Skip.
	} else if count, err := BackupAlbums(w.conf.AlbumsPath(), false); err != nil {
		log.Errorf("moments: %s (backup albums)", err.Error())
	} else if count > 0 {
		log.Debugf("moments: %d albums saved as yaml files", count)
	}

There is no time constraint. Each moments generation updates yaml files?

@sgflt
Copy link
Author

sgflt commented May 8, 2024

I wonder if the background activity really depends on the YAML backup files being enabled, or if the worker is constantly checking the index for changes anyway and the main increase in power consumption is due to the magnetic disks spinning up? We could of course check the existing backup files to see if the data has changed, but then the files would have to be read first, which might be enough to wake the disks up - so this wouldn't solve your particular problem.

Yes, increases of power consuption are caused by disks spinning up.

I think if there is nothing changed at all, it could skip backup phase.

time="2024-05-07T04:59:13Z" level=debug msg="index: updating counts"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 places [44.338141ms]"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 subjects [14.152954ms]"
time="2024-05-07T04:59:13Z" level=debug msg="counts: updated 0 labels [46.338469ms]"
time="2024-05-07T04:59:13Z" level=debug msg="index: updating covers"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 albums [3.231447ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 folders [45.549567ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 months [44.400212ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 labels [46.759854ms]"
time="2024-05-07T04:59:13Z" level=debug msg="covers: updated 0 subjects [55.15086ms]"

@lastzero
Copy link
Member

lastzero commented May 8, 2024

These are dynamic search filters generated based on the currently indexed files, and at the moment there is no cache or timestamp indicating when the files were last backed up. However, as mentioned above, the code should not be executed every 15 minutes (or hourly), but only every 3 hours if updateIndex is false:

// Only update index if necessary.
if updateIndex {
// Set photo quality scores to -1 if files are missing.
if err = query.FlagHiddenPhotos(); err != nil {
log.Warnf("index: %s in optimization worker", err)
}
// Run moments worker.
if moments := photoprism.NewMoments(w.conf); moments == nil {
log.Errorf("index: failed to update moments")
} else if err = moments.Start(); err != nil {
log.Warnf("moments: %s in optimization worker", err)
}

@lastzero lastzero changed the title Unnecessary storage of backups even if there is no change Moments: Don't write unmodified YAML backup files to prevent disks from spinning up May 8, 2024
@sgflt
Copy link
Author

sgflt commented May 8, 2024

Really interesting. I have dropped database and used default wake up time and now it runs each 10 minutes.

It is probably caused by

OR (cell_id = 'zz' AND photo_lat <> 0)

Some photos have that values that never changes.

@sgflt
Copy link
Author

sgflt commented May 8, 2024

Maybe there could be counter that counts failed attemtps of coordinates translation.

@lastzero
Copy link
Member

lastzero commented May 8, 2024

Thanks, that's really helpful! Never thought of this and we have SSDs in our severs, so you don't hear the disks either way.

@sgflt
Copy link
Author

sgflt commented May 8, 2024

Also photos do not have location in exif.

@sgflt
Copy link
Author

sgflt commented May 8, 2024

Thanks, that's really helpful! Never thought of this and we have SSDs in our severs, so you don't hear the disks either way.

So fix could help also for SSD wearing a very tiny little bit :)

@lastzero
Copy link
Member

lastzero commented May 8, 2024

Seems possible to remove "(cell_id = 'zz' AND photo_lat <> 0)" all together. I would think this was meant to resolve coordinates in case a request failed. However, the metadata will be periodically checked/updated either way. So the worst thing that could happen is that the location information is added with a longer delay (if available).

lastzero added a commit that referenced this issue May 9, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
lastzero added a commit that referenced this issue May 9, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
lastzero added a commit that referenced this issue May 9, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
@lastzero
Copy link
Member

lastzero commented May 9, 2024

It would be great if you could test these changes with trace log mode enabled:

An updated development preview build will be available for this soon. Thank you very much!

Edit: Should location information be missing, you can now run photoprism places update --yes in a terminal to fetch it and update the related pictures.

@lastzero lastzero added please-test Ready for acceptance test and removed needs-analysis Requires further investigation labels May 9, 2024
lastzero added a commit that referenced this issue May 9, 2024
This should effectively prevent all related disk activity.

Signed-off-by: Michael Mayer <michael@photoprism.app>
lastzero added a commit that referenced this issue May 9, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
@lastzero lastzero changed the title Moments: Don't write unmodified YAML backup files to prevent disks from spinning up Moments: Don't back up albums in worker to avoid disk activity May 9, 2024
@lastzero
Copy link
Member

lastzero commented May 9, 2024

I decided to remove the album backups completely from the Moments Worker because even checking if the directory already exists could cause disk activity in your case.

@lastzero
Copy link
Member

lastzero commented May 9, 2024

Our release notes have been updated to mention this change:

@sgflt
Copy link
Author

sgflt commented May 9, 2024

Testing preview over night.

@sgflt
Copy link
Author

sgflt commented May 10, 2024

Disks are still sleeping. 👍

lastzero added a commit that referenced this issue May 10, 2024
In the next step, this worker can be configured to automatically create
index and/or album backups at regular intervals.

Signed-off-by: Michael Mayer <michael@photoprism.app>
lastzero added a commit that referenced this issue May 14, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
@lastzero
Copy link
Member

@sgflt After further testing, we found that the timestamp of the background worker was reset after each run, as a new instance was created every time. Also, the album/moment update methods did not check if the data had changed. All this together explains why the YAML backup files were constantly updated in the background. Both should be fixed now. Thank you for bringing this to our attention!

lastzero added a commit that referenced this issue May 22, 2024
Signed-off-by: Michael Mayer <michael@photoprism.app>
@graciousgrey graciousgrey added tested Changes have been tested successfully and removed please-test Ready for acceptance test labels May 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working tested Changes have been tested successfully
Projects
Status: Preview 🐳
Development

No branches or pull requests

3 participants