Project

General

Profile

Bug #9710

Lighttable duplicate on selected images does not work - high cpu load

Added by Attila Gróf over 6 years ago. Updated over 6 years ago.

Status:
Closed: upstream
Priority:
Low
Assignee:
-
Category:
Lighttable
Start date:
12/06/2013
Due date:
% Done:

0%

Estimated time:
Affected Version:
git development version
System:
Ubuntu
bitness:
64-bit
hardware architecture:
amd64/x86

Description

I wanted to duplicate one the images in my collection by selecting it and clicking 'duplicate' in the 'selected image[s]' session in lighttable view. Nothing happened. Other operations such as grouping or ungrouping works.
darktable version is 1.4~rc1

Here is the output of top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
7352 smb 20 0 25,4g 874m 52m S 187,4 11,1 5:09.93 darktable

The amount of virtual memory used is very high and darktable uses practically all of the CPU cores (this is a 2 core Athlon cpu).
I waited for 15+ minutes, the high cpu utilization remained. The high cpu utilization is there even without trying to duplicate.
I have 30000+ images in the collection.
With less images (~5000) cpu utilization of darktable drops to normal in cca 5 minutes and duplicate starts to work. Other functionality of darktable such as darkroom view works though slowly.

Let me know what further information you need.

I have 8GB RAM.
uname: Linux alapgep 3.8.0-33-generic #48-Ubuntu SMP Wed Oct 23 09:16:58 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

dt.log.gz (254 KB) dt.log.gz before I deleted the mipmaps* Attila Gróf, 12/06/2013 10:07 PM
dt_mipmapcacheclear.log.gz (315 KB) dt_mipmapcacheclear.log.gz run after the mipmaps where deleted Attila Gróf, 12/06/2013 10:07 PM
Darktable_test-2013-12-08T00-05-25-365241000Z.webm (4.91 MB) Darktable_test-2013-12-08T00-05-25-365241000Z.webm Partial video of the testing Attila Gróf, 12/08/2013 02:11 AM
dt.bug.9710 (63.7 KB) dt.bug.9710 output of 'thread apply all bt' Attila Gróf, 12/17/2013 12:36 AM
9710.1.2.3saucy.gz (449 KB) 9710.1.2.3saucy.gz -d all output of version 1.2.3, i.e. the official ubuntu 13.10 package Attila Gróf, 12/22/2013 04:52 PM
9710.1.4.gz (2.32 MB) 9710.1.4.gz -d all output of the latest unstable version. Attila Gróf, 12/22/2013 04:52 PM
9710.1.4.aftercachedelete.gz (5.36 MB) 9710.1.4.aftercachedelete.gz -d all output of the latest unstable version after the cache was deleted Attila Gróf, 12/22/2013 04:52 PM
stacktrace.1.4 (62.2 KB) stacktrace.1.4 output of `thread apply all bt` in gdb Attila Gróf, 12/22/2013 04:52 PM
top.dt (1014 Bytes) top.dt output of top. 264 minutes spent in the loop before I stopped the unstable version after deleting the cache. Attila Gróf, 12/22/2013 04:52 PM
screenshot.png (97.7 KB) screenshot.png Ulrich Pegelow, 12/23/2013 12:19 PM
dt_1.4.9710.log (3.8 MB) dt_1.4.9710.log Log after increasing the image size for the first time Attila Gróf, 01/01/2014 10:12 PM
dt_1.4.9710_1300x1000.log (1.31 MB) dt_1.4.9710_1300x1000.log Log of a normal session after setting the image size back to 1300x1000 Attila Gróf, 01/01/2014 10:12 PM
dt_1.4.9710_2500x1400.log (17.3 MB) dt_1.4.9710_2500x1400.log a bit longer log when the image size is set to 2500x1400. Attila Gróf, 01/01/2014 10:12 PM

History

#1 Updated by Ulrich Pegelow over 6 years ago

  • Priority changed from Medium to Low

Is this something you can reproduce?

If yes I would be interested to see darktable's actions during the freeze period. You should start darktable with '-d all', collect the terminal output
and attach the file here.

Sometimes issues like that seem to be caused by a corrupted mipmap cache in which darktable stores its thumbnails. If the problem persists - and after
you have done the above debugging step - you could delete the file $HOME/.cache/darktable/mipmaps*. On startup darktable will generate a new one for you.

#2 Updated by Attila Gróf over 6 years ago

Yes, it can be reproduced all the time. I have attached two log files. Both are the output of darktable -d all

The symphtoms where the same as in the bug report in both cases.

#3 Updated by Ulrich Pegelow over 6 years ago

At first sight everything seems fine. In both cases there is a lot of activity on thumbnail generation over the whole session. But there is no obvious
deadlock. Even the OpenCL de-initialization at the end of the session works.

Could it be that darktable is just catching up in generating thumbnails? What happens if you start darktable and just leave it alone for some time?

#4 Updated by Attila Gróf over 6 years ago

I left it alone for 2 hours. Still it was crunching, probably the thumbs. I do not mind it much. The lack of duplicate functionality is why I opened this ticket. E.g. grouping works fine during the thumbs crunching.
There must be a bug, because 'duplicate' works fine with smaller databases. I could not thoroughly check, but I suspect that duplicate starts to work only after all the thumbs are created.
I will test it later today with different amount of images.

#5 Updated by Tobias Ellinghaus over 6 years ago

What I see every now and then is that duplicate doesn't do anything, but if I select the image again and hit ctrl-d again it works. I haven't found the time to debug this yet. Same with import, sometimes I have to import a folder a second time because the first time nothing happened.

Does it work for you if you try the duplication again?

#6 Updated by Ulrich Pegelow over 6 years ago

Attila,

having darktable process thumbs for 2h or even more is certainly a sign that you should reconsider your workflow, especially the way how you
set up your collections. This is especially relevant looking at the resource limits of your CPU.

I guess that each thumb takes about 1 second to process; this makes a whole working day till all have been generated. The other element to consider is
that darktable can only take a limited number of thumbs in its mipmap cache. With a huge collection any newly generated thumbnail will force an older
one to be deleted. There is no chance to have all thumbs in the cache.

Therefore you should really reorganize your collection, e.g. by splitting it up into several filmrolls each with maximum a few hundred images.
This is not a real limit as you can always generate collections based on other criteria.

#7 Updated by Tobias Ellinghaus over 6 years ago

Before you do any of that: please tell us what the preferences setting of "core options"->"memory in megabytes to use for mipmap cache" is. When that is 0 dt generates thumbnails over and over again.

#8 Updated by Attila Gróf over 6 years ago

Tobias Ellinghaus wrote:

What I see every now and then is that duplicate doesn't do anything, but if I select the image again and hit ctrl-d again it works. I haven't found the time to debug this yet. Same with import, sometimes I have to import a folder a second time because the first time nothing happened.

Does it work for you if you try the duplication again?

My experience was similar except that duplicate did not work during the whole session.

#9 Updated by Attila Gróf over 6 years ago

The memory used for mipmap cache is set to 512MB.

Regarding the workflow: I have imported all my images in a recursive step. The directory structure is 'year/year_month_date'. I have plenty of folders with less than 1000 images in each. I see each subfolder as separate filmroll, as I expect. However when I delete the filter in the 'collect images' module lighttable is supposed to show all 30000+ images. It seemed that the thumbs generation was started and kept on running even if I changed the filter to show only several 100s of images.

I have done some further testing with 5500 images with the newest development version: 1.4rc1+48~g70793b7. All the images were in a single filmroll.

I used a virtualbox VM with 32GB RAM and 2 vCPU cores. I have attached the video recording of a part of the testing session. I simply scrolled up/down and waited for darktable to settle. A terminal window with 'top' shows the CPU and memory utilization. DT settled always this time, though sometimes it took a while, i.e. CPU utilization remained high even without visible GUI operations. I believe it is only the thumb generation that raises the CPU utilization. The memory utilization is also moderate (<3GB) compared to my previous test.

It seems that this version behaves much better than the one I created the ticker for.

#10 Updated by Attila Gróf over 6 years ago

Here is the steps to keep the background threads running all the time even on a fresh install:
- Import several TIF files (cca 200). The TIFs are generated by Digital Photo Professional and darktable.
- Import 5000+ CR2 raw files
- Delete the TIFs from the disk
- Close the right hand side module area in lighttable view and bring the deleted files in the lighttable area.

This way the CPU utilization is roughly 80%*number of darktable background threads. There is absolutely no disk I/O by darktable during this time. The messages below are printed on the console.
If I open the right hand side module area, then CPU utilization drops to 0%. Reopening it increases it to the aforementioned value.

The VIRT memory used is 23G+ even on the fresh install without importing any images.

Darktable can not be closed using the window close button if started from a terminal window. Only <CTRL-C> does it. Could be a different issue. Let me know if I shall open another ticker for it.

Not a JPEG file: starts with 0x49 0x49
[tiff_open] warning: config other than contig found, trying anyways
TIFFReadDirectory: Warning, Unknown field with tag 18246 (0x4746) encountered.
TIFFReadDirectory: Warning, Unknown field with tag 18249 (0x4749) encountered.

TIFFFetchNormalTag: Warning, ASCII value for tag "Make" contains null byte in value; value incorrectly truncated during reading due to implementation limitations.
TIFFFetchNormalTag: Warning, ASCII value for tag "Model" contains null byte in value; value incorrectly truncated during reading due to implementation limitations.
TIFFFetchNormalTag: Warning, ASCII value for tag "Software" contains null byte in value; value incorrectly truncated during reading due to implementation limitations.
[tiff_open] warning: config other than contig found, trying anyways
[exiv2] Directory (Last IFD item) with 27721 entries considered invalid; not read.

#11 Updated by Tobias Ellinghaus over 6 years ago

  • % Done changed from 0 to 20
  • Status changed from New to Incomplete

Could you please attach gdb to the running process when that happens:

gdb /opt/darktable/bin/darktable `pidof darktable`
thread apply all bt

so we can see what it is doing?

#12 Updated by Attila Gróf over 6 years ago

I am not able to reproduce the constantly high CPU utilization. Here is the gdb output. 25 threads. The amount of background threads is 2 in the core config. I expected definitely less threads, however you know whether it is in the right ballpark.
Thread 25 (Thread 0x7f6449912700 (LWP 6145)):
#0 0x00007f6456fbf82c in __lll_lock_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6456fbb1b2 in _L_lock_1142 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007f6456fbb130 in pthread_mutex_lock ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f64569745c1 in g_mutex_lock ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#4 0x00007f6457292c6e in dt_control_gdk_lock ()
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1670
#5 dt_control_gdk_lock ()
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1649
#6 0x00007f6457298fc6 in dt_control_signal_raise (ctlsig=0x23c45b0,
signal=signal@entry=DT_SIGNAL_DEVELOP_MIPMAP_UPDATED)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/signal.c:123
#7 0x00007f64572783e5 in dt_mipmap_cache_read_get (cache=<optimized out>,
buf=buf@entry=0x7f64498ff370, imgid=imgid@entry=3759,
mip=mip@entry=DT_MIPMAP_F, flags=flags@entry=DT_MIPMAP_BLOCKING)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/mipmap_cache.c:989
#8 0x00007f645726c3c9 in dt_imageio_export_with_flags (
imgid=imgid@entry=3759, filename=filename@entry=0x7f64573af3e2 "unused",
format=0x7f6449910610, format_params=format_params@entry=0x7f6449910170,
ignore_exif=ignore_exif@entry=1,
display_byteorder=display_byteorder@entry=1,
high_quality=high_quality@entry=0,
thumbnail_export=thumbnail_export@entry=1, filter=filter@entry=0x0)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/imageio.c:592
#9 0x00007f64572760c1 in _init_8 (buf=0x7f64094c1b20 "\033\027\022",
width=<optimized out>, height=0x7f64094c1b14, imgid=imgid@entry=3759,
size=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/mipmap_cache.c:1321
#10 0x00007f6457278403 in dt_mipmap_cache_read_get (cache=0x2b3a450,
buf=buf@entry=0x7f6449911b50, imgid=3759, mip=DT_MIPMAP_1,
flags=flags@entry=DT_MIPMAP_BLOCKING)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/mipmap_cache.c:982
#11 0x00007f6457298d8a in dt_image_load_job_run (job=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/jobs/image_jobs.c:38
#12 0x00007f6457291ab8 in dt_control_run_job (s=s@entry=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1120
#13 0x00007f6457291bab in dt_control_work (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1320
#14 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#15 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 24 (Thread 0x7f6449111700 (LWP 6146)):
#0 0x00007f6456fc043d in nanosleep ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f645695a4f2 in g_usleep ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2 0x00007f645723914c in dt_cache_sleep_ms (ms=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/cache.c:97
#3 dt_cache_read_get (cache=cache@entry=0x2b3a510, key=key@entry=536874670)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/cache.c:705
#4 0x00007f64572781ab in dt_mipmap_cache_read_get (cache=0x2b3a450,
buf=buf@entry=0x7f6449110b50, imgid=3759, mip=DT_MIPMAP_1,
flags=flags@entry=DT_MIPMAP_BLOCKING)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/common/mipmap_cache.c:886
#5 0x00007f6457298d8a in dt_image_load_job_run (job=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/jobs/image_jobs.c:38
#6 0x00007f6457291ab8 in dt_control_run_job (s=s@entry=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1120
#7 0x00007f6457291bab in dt_control_work (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1320
#8 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#9 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 23 (Thread 0x7f6448910700 (LWP 6147)):
#0 0x00007f6456ca98dd in nanosleep () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f6456ca9781 in sleep () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007f645729099a in _control_worker_kicker (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1302
#3 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#4 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 22 (Thread 0x7f644810f700 (LWP 6148)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 21 (Thread 0x7f644790e700 (LWP 6149)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 20 (Thread 0x7f644710d700 (LWP 6150)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 19 (Thread 0x7f644690c700 (LWP 6151)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 18 (Thread 0x7f644610b700 (LWP 6152)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 17 (Thread 0x7f644590a700 (LWP 6153)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 16 (Thread 0x7f6445109700 (LWP 6154)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 15 (Thread 0x7f6444908700 (LWP 6155)):
#0 0x00007f6456fbcca4 in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6457291ca3 in dt_control_work_res (ptr=0x2401010)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1289
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 14 (Thread 0x7f643f59f700 (LWP 6156)):
#0 0x00007f6456cdae23 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f643fbb8e1b in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f68f87b in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 13 (Thread 0x7f643e39a700 (LWP 6157)):
#0 0x00007f6456fbef80 in sem_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f643fbb887e in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f725fed in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 12 (Thread 0x7f643db99700 (LWP 6158)):
#0 0x00007f6456fbef80 in sem_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f643fbb887e in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f725fed in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 11 (Thread 0x7f643d398700 (LWP 6159)):
#0 0x00007f6456fbef80 in sem_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f643fbb887e in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f725fed in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 10 (Thread 0x7f643cb97700 (LWP 6160)):
#0 0x00007f6456fbef80 in sem_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f643fbb887e in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f725fed in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 9 (Thread 0x7f6437fff700 (LWP 6161)):
#0 0x00007f6456fbef80 in sem_wait ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f643fbb887e in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#2 0x00007f643f725fed in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#3 0x00007f643fbba1c9 in ?? () from /usr/lib/nvidia-304/libnvidia-opencl.so.1
#4 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 8 (Thread 0x7f63edd6e700 (LWP 6162)):
#0 0x00007f6456cd5fbd in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f64569351dc in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2 0x00007f64569356ba in g_main_loop_run ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#3 0x00007f6454b3e4f6 in ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#4 0x00007f6456958eb5 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#5 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#6 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 7 (Thread 0x7f63cb72b700 (LWP 6167)):
#0 0x00007f6456cd5fbd in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f64569351dc in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2 0x00007f6456935304 in g_main_context_iteration ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#3 0x00007f6456935361 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#4 0x00007f6456958eb5 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#5 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#6 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 6 (Thread 0x7f63ed56d700 (LWP 6195)):
#0 0x00007f6451c2b016 in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#1 0x00007f6451c2987e in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 5 (Thread 0x7f63bb7fe700 (LWP 6203)):
#0 0x00007f6451c2b016 in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#1 0x00007f6451c2987e in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 4 (Thread 0x7f63cc11e700 (LWP 7310)):
#0 0x00007f6451c2b016 in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#1 0x00007f6451c2987e in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 3 (Thread 0x7f63bbfff700 (LWP 7311)):
#0 0x00007f6451c2b016 in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#1 0x00007f6451c2987e in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 2 (Thread 0x7f63ca729700 (LWP 7452)):
#0 0x00007f6451c2b016 in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#1 0x00007f6451c2987e in ?? () from /usr/lib/x86_64-linux-gnu/libgomp.so.1
#2 0x00007f6456fb8f8e in start_thread ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007f6456ce2a0d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 1 (Thread 0x7f645784ea00 (LWP 6144)):
#0 0x00007f644f74871d in ?? () from /usr/lib/x86_64-linux-gnu/libpixman-1.so.0
#1 0x00007f644f7811d2 in ?? () from /usr/lib/x86_64-linux-gnu/libpixman-1.so.0
#2 0x00007f644f73d069 in pixman_image_composite32 ()
from /usr/lib/x86_64-linux-gnu/libpixman-1.so.0
#3 0x00007f6455adeb22 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#4 0x00007f6455b0a31e in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#5 0x00007f6455b0b5a0 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#6 0x00007f6455b11f34 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#7 0x00007f6455b12c72 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#8 0x00007f6455b1347e in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#9 0x00007f6455b13646 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#10 0x00007f6455ad2d7a in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#11 0x00007f6455ae36df in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#12 0x00007f6455b16b74 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#13 0x00007f6455ada9f4 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#14 0x00007f6455ad4634 in ?? () from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#15 0x00007f6455acd875 in cairo_fill ()
from /usr/lib/x86_64-linux-gnu/libcairo.so.2
#16 0x00007f6457331a18 in dt_view_image_expose (
image_over=image_over@entry=0x2eb104c, imgid=3787, cr=cr@entry=0x507e730,
width=width@entry=188, height=height@entry=188, zoom=zoom@entry=7,
px=px@entry=43, py=py@entry=94, full_preview=0, full_preview@entry=188)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/views/view.c:845
#17 0x00007f642424cd42 in expose_filemanager (pointery=10, pointerx=43,
height=48959564, width=84426768, cr=0xffffffff, self=0x0)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/views/lighttable.c:616
#18 expose (self=0x0, cr=0xffffffff, width=84426768, height=48959564,
pointerx=43, pointery=10)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/views/lighttable.c:1258
#19 0x00007f6457330a1d in dt_view_manager_expose (vm=<optimized out>,
cr=0x507e730, width=<optimized out>, height=<optimized out>,
pointerx=1931, pointery=661)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/views/view.c:420
#20 0x00007f6457291fa5 in dt_control_expose (voidptr=voidptr@entry=0x0)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/control/control.c:1386
#21 0x00007f645730b950 in expose (da=0x2c24870, event=<optimized out>,
user_data=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/gui/gtk.c:465
#22 0x00007f6455ee8929 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#23 0x00007f64566ad620 in g_closure_invoke ()
from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#24 0x00007f64566bef00 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#25 0x00007f64566c6996 in g_signal_emit_valist ()
from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#26 0x00007f64566c6f92 in g_signal_emit ()
from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#27 0x00007f6456001d9e in ?? ()
from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#28 0x00007f6455ee7237 in gtk_main_do_event ()
from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#29 0x00007f645642e03c in ?? ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#30 0x00007f645642dfe3 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#31 0x00007f6456428fe7 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#32 0x00007f645642b191 in gdk_window_process_all_updates ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#33 0x00007f645642b1f9 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#34 0x00007f6456408ea7 in ?? ()
from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#35 0x00007f6456934f05 in g_main_context_dispatch ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#36 0x00007f6456935248 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#37 0x00007f64569356ba in g_main_loop_run ()
from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#38 0x00007f6455ee5fe7 in gtk_main ()
from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#39 0x00007f645730d43b in dt_gui_gtk_run (gui=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/gui/gtk.c:1046
#40 0x0000000000400808 in main (argc=<optimized out>, argv=<optimized out>)
at /build/buildd/darktable-1.4~rc1+48~g70793b7/src/main.c:25

#13 Updated by Attila Gróf over 6 years ago

Finally on a fresh installation of lubuntu 13.10 darktable 1.4rc1+94~gd8335ea was stuck in a loop using a single CPU core. I have attached the out of the gdb session described by Tobias

#14 Updated by Tobias Ellinghaus over 6 years ago

The only thing I noticed in that backtrace was that fglrx is mentioned which confuses me, since other backtraces in this ticket mentioned nvidia drivers. What GPU do you use?

#15 Updated by Attila Gróf over 6 years ago

I have 2 computers. One with avidia and one with amd GPU.

#16 Updated by Tobias Ellinghaus over 6 years ago

Ah, I see. Does darktable work correctly if you disable OpenCL in the preferences?

#17 Updated by Ulrich Pegelow over 6 years ago

Re posting number 10 by Atila:

Your observation that collapsing and expanding one of the panels make a big difference in terms of CPU utilization is consistent with what was
discussed before. If you collapse a panel the available screen space for thumbs gets bigger and thumbnails with an adapted, i.e. higher resolution need to be
created. What surprises me is that you don't see I/O activity. At least darktable should access the CR2 files.

It would be great if you could try to construct a method to reproduce with a somewhat less monster-like number of files. I don't have the capacity here to
try your last example (might not even have enough RAWs for that, let alone those TIFFs).

#18 Updated by Attila Gróf over 6 years ago

I was using darktable on ubuntu 13.10 fresh install. I started with the official ubuntu package: dt 1.2.3.
I have imported 770 images and executed several operations such as grouping, using darktable view for several images. It was a course of several days, therefore I do not have detailed list of actions.
Today I filtered roughly 170 images and wanted to move with the "move operation" if the "selected images" module. The target directory selection went fine, the confirmation question appeared and I pressed 'yes'. Nothing happened. Tried several times, nothing happened.
I have restarted darktable if -d all. Output attached.
Then I installed the newest version from the unstable repo. Its version is 1.4rc1+120~gee46e3d.
Started with -d all and run for roughly half an hour. Output attached.
I checked the output and it was spinning in mipmap creation. There were plenty of 'revive_job' lines with the same image id.
I have deleted the mipmap cache (actual a complete .cache/darktable directory) before the next run. I let it run for almost 2 hours. Output attached. I have also attached the output of 'top' and the stacktraces from gdb.

Even if all the thumbnails have to be generated 2 hours for 770 images on a 3.6GHz dual core athlon shall be more than enough. Even if it takes very long time, the block functionality such as moving or duplicating files is the real problem here.

This time darktable gets into this loop all the time whenever I start it. I will keep the system as it is. Let me know if further information is needed.

#19 Updated by Attila Gróf over 6 years ago

I mean the blocked functionality, such as the operation with the 'selected images' is the real Problem.

#20 Updated by Ulrich Pegelow over 6 years ago

I'd like you to do the following experiment:

1) open a terminal and from there start darktable with '-d all'
2) wait until all thumbnails are present
3) bring the terminal into the foreground (you should see something like in the attached screenshot)
4) leave the system as it is (no mouse movement etc), just watch the output

Do you see a continuous stream of new debug output or does it just stay as it is?

#21 Updated by Attila Gróf over 6 years ago

Ulrich Pegelow wrote:

I'd like you to do the following experiment:

1) open a terminal and from there start darktable with '-d all'
2) wait until all thumbnails are present
3) bring the terminal into the foreground (you should see something like in the attached screenshot)
4) leave the system as it is (no mouse movement etc), just watch the output

Do you see a continuous stream of new debug output or does it just stay as it is?

I collected the attachments above the way you just described except I redirected the output to a file. These are really huge ones. It might not be obvious for the first sight as the compression ration is somewhere between 50:1 or 100:1. It hints to me that the content is repetitive.

The 9710.1.4.aftercachedetele.gz file above contains 7.3M lines. It is the complete session that last for almost 2 hours (real time). There was a continuous stream of debug messages. I checked with tail -f.
All the thumbnails were already created, I could scroll quickly up and down. I did not have to wait for the thumbs to appear.

#22 Updated by Ulrich Pegelow over 6 years ago

From the debug output you attached it seems that darktable receives a continuous stream of events. These events cause darktable to steadily
update its GUI and makes it more or less unresponsive - darktable drowns in events. Normally when left alone and no user action takes
place (e.g. mouse is not moved) darktable is idle. My guess is that these events are caused by the system, maybe even by some failing hardware.

Now you need to find out what events darktable receives. Please try the following.

1) start darktable
2) from a separate terminal start xwininfo and then click into the darktable window -> xwininfo displays the numerical ID of that window -> dtwinid
3) start program 'xev -id dtwinid'
4) watch the output of xev while leaving your system untouched

My suspicion is that you will see a continuous stream of events like:

MotionNotify event, serial 18, synthetic NO, window 0x3c00003,
    root 0xb4, subw 0x0, time 1294816, (1160,0), root:(1625,86),
    state 0x10, is_hint 0, same_screen YES

#23 Updated by Attila Gróf over 6 years ago

Ulrich Pegelow wrote:

From the debug output you attached it seems that darktable receives a continuous stream of events. These events cause darktable to steadily
update its GUI and makes it more or less unresponsive - darktable drowns in events. Normally when left alone and no user action takes
place (e.g. mouse is not moved) darktable is idle. My guess is that these events are caused by the system, maybe even by some failing hardware.

Now you need to find out what events darktable receives. Please try the following.

1) start darktable
2) from a separate terminal start xwininfo and then click into the darktable window -> xwininfo displays the numerical ID of that window -> dtwinid
3) start program 'xev -id dtwinid'
4) watch the output of xev while leaving your system untouched

My suspicion is that you will see a continuous stream of events like:

[...]

The output of xev is silent when the system is untouched. I get the motionevents when I hover over the darktable window with my mouse.

I have installed the new release on my other system. It shows now the same symptoms as the system I created this bug for. Similar mipmap related messages flood the output if -d all is used in the command line. I am not able to export any images with that system. There are less than 300 images imported.

#24 Updated by Ulrich Pegelow over 6 years ago

So it's not any external events that keep darktable busy. Then it must be internal in darktable.
In your '-d all' outputs it is obvious that darktable in the beginning spends its time in generating
thumbs - ca. 0.3 seconds per image, which is very reasonable. After thumbs are generated you get a
steady flow of

[revive_job] load image 549 mip 1
[add_job] 30 load image 549 mip 1
[add_job] too many jobs in queue!
[revive_job] load image 548 mip 1
[add_job] 30 load image 548 mip 1
[add_job] too many jobs in queue!
[revive_job] load image 547 mip 1
[add_job] 30 load image 547 mip 1
[add_job] too many jobs in queue!
[revive_job] load image 546 mip 1
[add_job] 30 load image 546 mip 1
...

followed by lighttable updates. This is something I do not see on my system. Maybe Jo has an idea.

BTW: I have once experienced on my box that an OpenCL driver consumed significant CPU circles even when the GPU was idle.
Did you ever test if things are different when darktable is started with --disable-opencl?

#25 Updated by Attila Gróf over 6 years ago

Ulrich Pegelow wrote:

So it's not any external events that keep darktable busy. Then it must be internal in darktable.
In your '-d all' outputs it is obvious that darktable in the beginning spends its time in generating
thumbs - ca. 0.3 seconds per image, which is very reasonable. After thumbs are generated you get a
steady flow of

[...]

followed by lighttable updates. This is something I do not see on my system. Maybe Jo has an idea.

BTW: I have once experienced on my box that an OpenCL driver consumed significant CPU circles even when the GPU was idle.
Did you ever test if things are different when darktable is started with --disable-opencl?

The CPU usage is 0% when darktable is idle with --disable-opencl. It must be the fglrx driver. I use the version shipped with ubuntu 13.10. I tried to upgrade to the newest version (13.251 ubuntu package version), however my GUI did not start with that.

It is strange to me that the opencl driver sends motion events though. Anyway this is an acceptable workaround for me.

Thanks!

#26 Updated by Ulrich Pegelow over 6 years ago

Good to hear that finally we have an idea what's going on.

We had a discussion about that issue in February on darktable-devel when I observed something similar on my system (but with a less dramatic slowdown):

[[http://sourceforge.net/mailarchive/forum.php?thread_name=51228AB2.90007%40tongareva.de&forum_name=darktable-devel]]

My interpretation boils down to the assumption that the AMD OpenCL driver actively polls the GPU using significant resources. The good news is that at some
point in time (after some driver upgrade) the problem went away for me. I can't tell though what driver version solved the issue.

#27 Updated by Attila Gróf over 6 years ago

Finally I managed to install the 13.251 version of the AMD driver. It fixed this issues. The installation package of this version is buggy at least for ubuntu 13.10: the dkms creation fails. Here is the bug report with a workaround

I propose to close his bug in a way to indicate the workaround on the issue tracker list.

#28 Updated by Ulrich Pegelow over 6 years ago

  • % Done changed from 20 to 0
  • Status changed from Incomplete to Closed: upstream

Bottom line: it's a bug in some older AMD Catalyst drivers and can be fixed by a driver upgrade to version 13.25.x or above.

#29 Updated by Attila Gróf over 6 years ago

fglrxinfo:
display: :0 screen: 0
OpenGL vendor string: Advanced Micro Devices, Inc.
OpenGL renderer string: AMD Radeon HD 7900 Series
OpenGL version string: 4.3.12618 Compatibility Profile Context 13.251

darktable version: release 1.4

I managed to trigger this issue again by changing the image size in the drawing area to 2500x1400. Darktable enters into the endless mipmap generation(?) loop without external events. I have checked it with xwininfo and xev, there are no external events, -d all still prints mipmap messages continuously.

Setting the image size to 1300x1000 and restarting darktable gets back everything to normal. I think it is not a driver issue. I can trigger the endless loop even on an nvidia system just by setting the image size to 2500x1400. Let me know if logs are needed from that system too.

Please reopen this bug or let me know if I shall create a new one.

#30 Updated by Ulrich Pegelow over 6 years ago

I cannot reproduce here. Even with that high resolution darktable runs normal and is idle after all thumbs are generated.

I fear we can't solve that issue for you. It might be very specific to your system and probably only uncovered but not caused
by darktable.

Also available in: Atom PDF

Go to top