darktable - slower _add to library_?

Software darktable
1

Hi, I noticed that adding images to library in v 3.6 is getting slower than it was in v 3.4.
I ran darktable from terminal with debug switches for imageio and sql on. ( darktable -d perf -d imageio -d sql )
In summary, from the i/o standpoint (the images are on a local server), there are three phases:
1 - High network usage - Getting image data, I suppose.
2 - Very slow network usage - This is where darktable seems to get stuck.
3 - High network usage again - Getting image data again?? Anyway, this is where the Add to library window is closed and images start to show up in lighttable.

Below is a screenshot from debug on phase 2:

image
image784Ɨ422 286 KB

Attached are screenshots of typical activity on each of the above phases.
debug session dt 2021-07-18.pdf (415.7 KB)

Finally, I havenā€™t noticed before this kind of behavior regarding this pattern of network activity in previous versions, with two phases of high activity and one phase in between of slow to no activity.

EDIT: As requested, follows log file (-d all)
dt_debug.txt (2.9 MB)

2

why would DT talk to the network in first place?

is your data on a NAS? any lua scripts?

i mean if you get rate limited by some network service that you talk to during importā€¦ then it is not DT that is slow but that service.

some more details from your side would be helpful.

3

Yes, like I said the images are on a local server.
Iā€™m not complaining about network activity. Of course I expect it if I have the images on the network.

4

Yes, Iā€™m aware of that. The images have always been on the network and I got used to the slow times.
But now theyā€™re noticeably bigger, and, like I mentioned above, I see high netowork activity two times, as if images were being loaded twice (my impression). This is new.

5

Do you still need more information? Or my posts plus the attachment are enough?

Please, let me know

6

Can you provide the logs in a simple text file? Screenshots in a PDF are hard to read.

1 Like
7

I added it to the first post, thanks.

1 Like
8

Have you changed the setting ā€œuse raw file instead of embedded jpegā€ ?
When inactive the images are not developped at import time.

9

Thanks, @phweyland .

Havenā€™t changed it, and it shows as inactive.

To illustrate what Iā€™m trying to show, I made this quick screencast (not as quick as Iā€™d expect :stuck_out_tongue_winking_eye:ā€¦

First, I reinforce that Iā€™m not complaining about the naturally slow network speed. As show in the video, and due to the fact that at that moment I was connected via wifi, it max out at around 2.5 Mbps, which Iā€™m absolutely used to.
The ā€œissueā€ is shown starting at 0:27 along to 1:42, where network activity almost ceased to exist, and darktable seems frozen (actually it is not, as the dump above shows, where intense database activity occurs). In summary, this is a real time import of only five nef files stored in the local network.
After 1:42, network activity restarts, the import dialog is closed, and the images start showing. This last part is ok to me, Iā€™m used to it.

10

What seems to be clear is the network load at the end. Import is reading the files to get the thumbnails (this is consistent with your settings).

Yes, this is not clear.
In the dump file there is several times this sequence (this is first one), 10 seconds between the 2 queries (to do what ?):

87,000179 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder       FROM main.film_rolls)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
97,537506 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare "SELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > '0001:01:01 00:00:00' COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1"

until:

297,753687 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder       FROM main.film_rolls)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
308,192918 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare "SELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > '0001:01:01 00:00:00' COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1"

200 seconds spent there ā€¦

Afterwards there are 4125 times ā€œfound job already in scheduledā€ ā€¦ Which does nothing ā€¦

Could you try to import the same set of images into an empty db (fresh darktable environment) ?

1 Like
11

Sure.
What I did? (in Linux)

  1. Renamed folder ~/.config/darktable to ~/.config/darktable.old
  2. Renamed folder ~/.cache/darktable to ~/.cache/darktable.old

Results: no issue at all. The import dialog window closed as soon as I clicked Import and the only noticeable delay was when it was loading from the network, as expected. It took no longer than some 20s, not a couple of minutes as before.

So, am I correct to presume that the database/cache with around 50k images has some kind of issue?

Anyway, thanks for having taken your time.

EDIT: hereā€™s the log file
dt_debug1.txt (562.7 KB)

12

Ok this seems to be related to your current db/settings.
But I really donā€™t understand what are the issues.
The first question is about this multiple 10 seconds delay in collection to display film rolls.
The second one, which seems to be related to mipmap of few images (around 50118 ā†’ 50127). Maybe here you could try to remove them from your db and check what does happen. EDIT save you db beforeā€¦

1 Like
13

In fact! dt is taking around three minutes, apparently just doing that.
These log entries are related to 20 images from the same collection, and all of them have local copies.
Back into the original database/settings, I synced local copies, removed the 5 nefs from the database, closed it, and restarted it on debug mode.
It seems to have taken more time.
I noticed some offenders:

4,823065 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder       FROM main.film_rolls)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
47,505239 [lib_load_module] loading `copy_history' from /usr/lib/x86_64-linux-gnu/darktable/plugins/lighttable/libcopy_history.so

48,598759 [lighttable] expose took 0,0119 sec
48,672360 [lighttable] expose took 0,0023 sec
48,952859 [lighttable] expose took 0,0033 sec
52,937226 [lighttable] expose took 0,0029 sec
53,252990 [sql] /usr/src/packages/BUILD/src/common/image.c:1662, function dt_images_already_imported(): prepare "SELECT * FROM main.images, main.film_rolls WHERE film_rolls.folder = ?1       AND images.film_id = film_rolls.id       AND images.filename = ?2"
53,253772 [sql] /usr/src/packages/BUILD/src/common/image.c:1662, function dt_images_already_imported(): prepare "SELECT * FROM main.images, main.film_rolls WHERE film_rolls.folder = ?1       AND images.film_id = film_rolls.id       AND images.filename = ?2"
53,254261 [sql] /usr/src/packages/BUILD/src/common/image.c:1662, function dt_images_already_imported(): prepare "SELECT * FROM main.images, main.film_rolls WHERE film_rolls.folder = ?1       AND images.film_id = film_rolls.id       AND images.filename = ?2"
53,255560 [sql] /usr/src/packages/BUILD/src/common/image.c:1662, function dt_images_already_imported(): prepare "SELECT * FROM main.images, main.film_rolls WHERE film_rolls.folder = ?1       AND images.film_id = film_rolls.id       AND images.filename = ?2"
53,256841 [sql] /usr/src/packages/BUILD/src/common/image.c:1662, function dt_images_already_imported(): prepare "SELECT * FROM main.images, main.film_rolls WHERE film_rolls.folder = ?1       AND images.film_id = film_rolls.id       AND images.filename = ?2"
59,984840 [add_job] 0 | 59,985164 import | queue: 0 | priority: 059,985254

ā€¦

62,450221 [sql] /usr/src/packages/BUILD/src/common/history.c:1498, function dt_history_hash_read(): prepare "SELECT basic_hash, auto_hash, current_hash FROM main.history_hash WHERE imgid = ?1"
66,063802 [sql] /usr/src/packages/BUILD/src/common/image.c:2412, function dt_image_write_sidecar_file(): prepare "UPDATE main.images SET write_timestamp = STRFTIME('%s', 'now') WHERE id = ?1"

ā€¦

75,941093 [sql] /usr/src/packages/BUILD/src/common/collection.c:172, function dt_collection_memory_update(): prepare "INSERT INTO memory.collected_images (imgid) SELECT DISTINCT mi.id FROM (SELECT  id, group_id, film_id, filename, datetime_taken,   flags, version,  position, aspect_ratio,  maker, model, lens, aperture, exposure, focal_length,  iso, import_timestamp, change_timestamp,  export_timestamp, print_timestamp  FROM main.images AS mi  ) AS mi WHERE   (flags & 256) != 256  AND  (1=1 AND (film_id IN (SELECT id FROM main.film_rolls WHERE folder LIKE '/home/gustavo/media/gustavo/fotos/Media/2021/20210724_NEF_Santa Teresa'))) ORDER BY filename, filename , version LIMIT ?1, ?2"
75,943972 [run_job-] 04 336622741,507507 75,944042 import | queue: 0 | priority: 475,944072 
83,214949 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare "SELECT db.datetime_taken

ā€¦

83,274527 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder       FROM main.film_rolls)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
91,695537 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare "SELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > '0001:01:01 00:00:00' COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1"

ā€¦

91,703593 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare ā€œSELECT folder, film_rolls_id, COUNT() AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder FROM main.film_rolls) ON film_id = film_rolls_id WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
100,321944 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare ā€œSELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > ā€˜0001:01:01 00:00:00ā€™ COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1ā€
ā€¦
100,330257 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT() AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder FROM main.film_rolls) ON film_id = film_rolls_id WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESCā€
109,301072 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare ā€œSELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > ā€˜0001:01:01 00:00:00ā€™ COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1ā€
ā€¦
109,313256 [sql] /usr/src/packages/BUILD/src/libs/collect.c:1887, function list_view(): prepare ā€œSELECT folder, film_rolls_id, COUNT(*) AS count FROM main.images AS mi JOIN (SELECT id AS film_rolls_id, folder FROM main.film_rolls) ON film_id = film_rolls_id WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESCā€
118,554028 [sql] /usr/src/packages/BUILD/src/libs/tools/timeline.c:621, function _time_read_bounds_from_collection(): prepare ā€œSELECT db.datetime_taken FROM main.images AS db, memory.collected_images AS col WHERE db.id=col.imgid AND LENGTH(db.datetime_taken) = 19 AND db.datetime_taken > ā€˜0001:01:01 00:00:00ā€™ COLLATE NOCASE ORDER BY db.datetime_taken ASC LIMIT 1ā€

ā€¦ and so on up to 222,534556

During these longer database transactions, thereā€™s no significant network or cpu activity.

Anyway, thanks for helping me investigate it. I feel more confident analyzing the log now, although I lack the knowledge to understand each step. But, at least, Iā€™m able to identify offenders by looking at the timestamp hops.

Attached, the log from this last session.
dt_debug2.txt (657.6 KB)

14

Youā€™re welcome.
I donā€™t know anything about local copy ā€¦
Another idea coming in mind (but maybe somehow related to local copy) is your cache. Is your cache on a local drive ? Better on an SSD ? Is it updated properly when you add a new image ?