Version 1.1.0 in docker: excessive CPU usage

[adept]

Hi!
I am running photostructure in docker from the image photostructure/server:stable which gives me version 1.1.0, according to the About page.

Some time ago I reported a bug in 1.0.0-beta9 where sync process would sit in some sort of loop reading /proc/self/stat and consuming CPU cycles. @mrm replied there that problem is reproducible, but I don’t know whether it was fixed in the end or not.

I’ve now upgraded to 1.1.0 and the behavior is still there, except CPU usage is now higher than before.

this is except from ‘top’ for the photostructure sync process started 6 days ago:

  PID USER      PR  NI    VIRT    RES  %CPU %MEM     TIME+ S COMMAND                                                                                                          
 8504 adept     29   9  370.3m  87.7m  13.1  0.3   1351:18 S PhotoStructure sync

Note high TIME and 13% CPU.

There is nothing going on in the photstructure at the moment - nothing to import, web UI is not opened, and “photostructure logtail” just shows “Service(web) --health-check { ok: …” messages from time to time. And yet sync process consumes 13% CPU around the clock

Strace summary of about 10 seconds:

# strace -f -c -p 8504
strace: Process 8504 attached with 11 threads
^Cstrace: Process 8504 detached
strace: Process 8505 detached
strace: Process 8506 detached
strace: Process 8507 detached
strace: Process 8508 detached
strace: Process 8509 detached
strace: Process 8510 detached
strace: Process 8515 detached
strace: Process 8516 detached
strace: Process 8517 detached
strace: Process 8518 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.67    2.948000       15849       186        11 futex
  0.17    0.005080           2      3045           epoll_pwait
  0.09    0.002682           0     20284           open
  0.05    0.001460           0     20292           read
  0.02    0.000676           0     20284           close
  0.00    0.000000           0         8           write
  0.00    0.000000           0        24           mmap
  0.00    0.000000           0        24           munmap
  0.00    0.000000           0         8           getpid
------ ----------- ----------- --------- --------- ----------------
100.00    2.957898                 64155        11 total

Excerpt from the “strace -f -tt”:

[pid  8504] 00:07:07.799877 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.799948 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.800027 close(26)   = 0
[pid  8504] 00:07:07.800111 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.800182 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.800251 close(26)   = 0
[pid  8504] 00:07:07.800387 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.800456 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.800522 close(26)   = 0
[pid  8504] 00:07:07.800605 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.800676 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.800746 close(26)   = 0
[pid  8504] 00:07:07.800890 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.800987 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.801057 close(26)   = 0
[pid  8504] 00:07:07.801152 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.801243 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.801309 close(26)   = 0
[pid  8504] 00:07:07.801444 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.801513 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395
[pid  8504] 00:07:07.801580 close(26)   = 0
[pid  8504] 00:07:07.801662 open("/proc/self/stat", O_RDONLY|O_LARGEFILE) = 26
[pid  8504] 00:07:07.801732 read(26, "25217 (PhotoStructure ) R 28 21 "..., 1023) = 395

Expected Behavior

I would expect photostructure not to check /proc/self/stat million times each second

Environment

Operating system and version: Docker 20.10.3 on the Synology box

PhotoStructure edition: docker

[adept]

… aaaaand it looks like if I restart the container, it sometimes end up in this state, and sometimes does not. “logtail” does not show anything interesting

[mrm]

Hey there @adept !

I suspect this is node reading from /proc/self/stat to get CPU usage–in v1.1 I was trying to be “clever” with CPU usage, and self-throttle based on statistics I could gather every second or two. With v2.1 I’m using renice to make sure PhotoStructure is well-behaved (and an analogous approach for Windows users), which should be a much lighter weight (and more reliable) solution.

You could try running the latest v2.x alpha on your Synology–I’ve rewritten the work scheduler, db persistence, parallelism, and added a ton of new features. Just update the image name to photostructure/server:alpha.

Alpha/beta caveats apply:

Alpha, beta, stable, and latest; What should you use?

Here’s a question I got today over email: I’m having a hard time figuring out which version I should be using. I’m currently running PhotoStructure as a docker container. I am using the “beta” tag in the docker compose file. Is that correct? TL;DR: Please do not run alpha or beta builds unless: you have frequent, automatic backups of your data, and you’re willing to report bugs that you see to either discord or this forum. If you’re unsure, please use stable PhotoStructure’s re…