drastic slow down of zoomable light table after GMIC integration in master

[upegelow]

Describe the bug
The zoomable light table (one of the view options in lighttable mode) has experienced a drastic slow down recently after integration of GMIC.

Panning and zooming to navigate within the lighttable used to be very fast, even with larger collections. Now it can be so slow that darktable practically freezes. Work is not possible any longer.

I bisected the issue and found to my surprise:

eb8a2bda321fa82bd92fd211ef46e1f88a10a5bc is the first bad commit
commit eb8a2bda321fa82bd92fd211ef46e1f88a10a5bc
Author: phweyland <philippe.weyland@libertysurf.fr>
Date:   Thu Dec 12 10:40:59 2019 +0100

    Squashed commit of the following:
    
      add compressed lut gmz files (GMIC)
      compressed lut is stored in params. sharing xmp file works without
    source lut now.
      use (default_user_folder)\gmic to store cache files (to speed
    up decompression)

:100644 100644 eef511391e60801f797eba2db2ea788586219dd9 5ada5322cf945c29d7e0a068186e12bc7d25b9c7 M      DefineOptions.cmake
:040000 040000 e62f680e64b81fab7fb3ad14173f5cf483acf5b2 6699b6b294d678233cda7f39334fd7ba0bdaabae M      cmake
:040000 040000 bd22a67945201970a7de18985994ce735474eb39 6a7a70f433fb2ebd9752ea2a3ddc28c7fd58255d M      data
:040000 040000 6c1d590bba3e494ef74e4a12362b4e18e34723ef 931e9b3c65f5d7c0b65aa675784ef947c61fbcbb M      packaging
:040000 040000 ef491e5b7e1ca1ff4eeac99de0a13f92228023bf 08eb417bfdcc03688b76973da5781e6882c91e3d M      src

To Reproduce

1. Open a large collection within darktable (in my case about 1500 images, thumbs are already in cache)
2. In lighttable view switch to "zoomable light table"
3. Try to pan or zoom within the view
4. Any action takes many seconds to complete (if darktable behaves normally, close it and start it again - the problem sometimes does not occur when visiting the collection for the first time).

Already tested: no influence from my existing library.db. I get the same behavior with a fresh setup.

Expected behavior
The lighttable should be as fast as in 3.0. If GMIC stands in the way and this cannot be sorted out quickly GMIC integration should be made optional at compile time.

Platform (please complete the following information):

• Darktable Version: after 3.1.0+308~g2f82a6e43
• OS: OpenSUSE Leap 15.1
• OpenCL: yes but probably of no relevance

[TurboGit]

No big deal see:
#4008 and #4103.

[upegelow]

No big deal see:

It is a big deal if your plan is to remove the zoomable light table. I am absolutely against.

[phweyland]

* OS: OpenSUSE Leap 15.1

I thought the gmic library was broken on opensuze. see #4067.
Which version of libgmic do you have ?
Have you built dt ? Any strange issue there ? Any message on the console when dt is running ?

1. (in my case about 1500 images, thumbs are already in cache)

I'm not a user of zoomable lighttable (I could become :-)), but I've tested your use case (with an 8Gb memory machine) and I don't find any speed difference with a collection of 150 images, once images are in cache.

[upegelow]

Which version of libgmic do you have ?

libgmic-devel-2.8.1-lp151.10.1.x86_64

Have you built dt ? Any strange issue there ? Any message on the console when dt is running ?

FWIW attached you find the output of darktable -d all. All I do within that one minute is trying to move and pan the lighttable. Everything is extremely lagging behind, reaction times in the range of several seconds on any action. Only towards the end of the exercise the lighttable reacts somewhat faster.
darktable.out.txt
I know that -d all is normally not of great help. But maybe the timestamp in each line might give an indication where performance is lost.

Any issues that could come from the mix of C++ code (garbage collection etc.) into the C world of darktable?

[phweyland]

Any issues that could come from the mix of C++ code (garbage collection etc.) into the C world of darktable?

In lighttable libgmic is not activated if you have not made use of lut3d with compressed luts. It could be an issue like that if you were on darkroom on lut3d using gmz file ...

darktable -d all

I don't see any issue with lut3d in your file. I've seen 2 images with that module, but no warning nor error message. Nothing about libgmic either (and not the issue #4067)

I see some difference between images:
37,185879 [lighttable] image expose took 0,0005 sec
and
35,739927 [lighttable] image expose took 0,0236 sec
The difference is huge to display thumbnails, but I don't know if that means anything.

Work is not possible any longer.

If you want a quick workaround you can uninstall libgmic and rebuild dt (after deleting build folder content). You would be free of this library.
But it would be better to understand the issue you have.
At least that would give some input about the role of libgmic.

[pitbuster]

Any issues that could come from the mix of C++ code (garbage collection etc.) into the C world of darktable?

C++ doesn't have garbage collection and usually projects doesn't automagically get slower just by introducing C++ code.

[upegelow]

After deleting libgmic-devel, rm -r ./build and recompilation of current master everything is as it should, i.e. lighttable runs fast.

[upegelow]

Here is the output of -d all after deleting libgmic-devel.
darktable.out.txt
Image exposet is at 0,0005 sec which seems to be the normal on my machine.

[phweyland]

darktable.out.txt

I've tried to compare the 2 log files. The only difference I've found so far is about the [lighttable] image expose time (0,0005 sec -> more than 0,0250, but not always).

How much memory has your machine ? Do (did) you see significant swap running dt ?

[TurboGit]

@upegelow : Sorry, I sent a message on the dev mailing list (to get feedback) pointing to the discussion about removing broken storages and the zoomanble lt which is very very difficult to maintain. Everybody who responded said that they were not using the zoomable lt so yes it was decided to go ahead and removing it as part of the big rewrite drived by @AlicVB.

So it seems that we need to reconsider this decision and see how we can manage keeping you and the maintainers of this code happy :)

[upegelow]

How much memory has your machine ? Do (did) you see significant swap running dt ?

16GB and no swapping.

[phweyland]

How much memory has your machine ? Do (did) you see significant swap running dt ?

16GB and no swapping.

plenty of space then.

[phweyland]

Any issues that could come from the mix of C++ code (garbage collection etc.) into the C world of darktable?

C++ doesn't have garbage collection and usually projects doesn't automagically get slower just by introducing C++ code.

libgmic library has one (but I don't know the detail).

[upegelow]

Some further insights: there is no general slowdown of darktable. Exporting an image on CPU takes the same time regardless if gmic is loaded or not.

Some other thought. On my system the libgmic-devel install includes a file /usr/lib64/cmake/gmic/GmicTargets.cmake that seems to pull a ton of further libraries:

set_target_properties(libgmic PROPERTIES
  INTERFACE_LINK_LIBRARIES "/usr/lib64/libSM.so;/usr/lib64/libICE.so;/usr/lib64/libX11.so;/usr/lib64/libXext.so;/usr/lib64/libtiff.so;/usr/lib64/libpng.so;/usr/lib64/libz.so;/usr/lib64/libjpeg.so;GraphicsMagick++;GraphicsMagick;IlmImf-2_4;Imath-2_4;Half-2_4;Iex-2_4;IexMath-2_4;IlmThread-2_4;opencv_dnn;opencv_face;opencv_ml;opencv_objdetect;opencv_shape;opencv_stitching;opencv_superres;opencv_videostab;opencv_calib3d;opencv_features2d;opencv_highgui;opencv_videoio;opencv_imgcodecs;opencv_video;opencv_photo;opencv_imgproc;opencv_flann;opencv_core;/usr/lib64/libz.so;/usr/lib64/libcurl.so;fftw3;-lgomp;-lfftw3_threads;-lpthread"
)

[AlicVB]

@upegelow : I've tried to reproduce with no luck atm.
What I've done to try to find where we spend the time is to put code like this one :

end = dt_get_wtime();
if(darktable.unmuted & DT_DEBUG_PERF)
    dt_print(DT_DEBUG_LIGHTTABLE, "[lighttable] IMAGE 1 took %0.04f sec\n", end - start);
start = dt_get_wtime();

everywhere in dt_view_image_expose and run dt with -d perf -d lighttable

So it will be easier to find the problematic part. I personally suspect it's somewhere after

darktable/src/views/view.c

Line 1250 in 1befa7d

rgbbuf = (uint8_t *)calloc(buf_wd * buf_ht * 4, sizeof(uint8_t));

(and yes, there's certainly better ways for debugging ;))

[phweyland]

Some other thought. On my system the libgmic-devel install includes a file /usr/lib64/cmake/gmic/GmicTargets.cmake that seems to pull a ton of further libraries:

set_target_properties(libgmic PROPERTIES
  INTERFACE_LINK_LIBRARIES "/usr/lib64/libSM.so;/usr/lib64/libICE.so;/usr/lib64/libX11.so;/usr/lib64/libXext.so;/usr/lib64/libtiff.so;/usr/lib64/libpng.so;/usr/lib64/libz.so;/usr/lib64/libjpeg.so;GraphicsMagick++;GraphicsMagick;IlmImf-2_4;Imath-2_4;Half-2_4;Iex-2_4;IexMath-2_4;IlmThread-2_4;opencv_dnn;opencv_face;opencv_ml;opencv_objdetect;opencv_shape;opencv_stitching;opencv_superres;opencv_videostab;opencv_calib3d;opencv_features2d;opencv_highgui;opencv_videoio;opencv_imgcodecs;opencv_video;opencv_photo;opencv_imgproc;opencv_flann;opencv_core;/usr/lib64/libz.so;/usr/lib64/libcurl.so;fftw3;-lgomp;-lfftw3_threads;-lpthread"
)

This list is really the list of dependencies of gmic. This side seems ok.
But some of them are common with dt. Would not there be here some library conflicts ? With one that view_image_expose needs in particular ?

[upegelow]

I think I need to do a session with gperftools in order to get closer to the issue. I hope to find time on Friday.

[upegelow]

All time is lost in the following section:

darktable/src/views/view.c

Lines 1291 to 1312 in e56b0e7

	#ifdef _OPENMP
	#pragma omp parallel for schedule(static) default(none) shared(buf, rgbbuf, transform)
	#endif
	for(int i = 0; i < buf.height; i++)
	{
	const uint8_t *in = buf.buf + i * buf.width * 4;
	uint8_t *out = rgbbuf + i * buf.width * 4;
	if(transform)
	{
	cmsDoTransform(transform, in, out, buf.width);
	}
	else
	{
	for(int j = 0; j < buf.width; j++, in += 4, out += 4)
	{
	out[0] = in[2];
	out[1] = in[1];
	out[2] = in[0];
	}
	}
	}

This is regardless of color management yes or no. However, it's closely linked to using OPENMP here: if I skip OPENMP in that part all runs normal.

For comparison:

• with OPENMP about 0.02 secs per image
• without OPENMP about 0.0004 secs per image

This is for thumbnails of about 160 x 110 pixels.

Now anybody can explain what role gmic plays here and if this could happen in other code places as well?

[TurboGit]

@upegelow : As this indeed makes no sense let's explore one possibility.

Do you have a Linux kernel 5.3 ? It has been reported to be buggy and could produce large slowdown. Maybe the key in this story ?

[upegelow]

Linux version 5.1.14-lp151.5-default (geeko@buildhost) (gcc version 7.4.0 (SUSE Linux)) #1 SMP Sat Jun 22 11:55:38 UTC 2019 (f291042)

[AlicVB]

if this could happen in other code places as well?

If you have some time, can you by any chance do timing tests with an iop where openmp is used (with and without gmic). With opencl deactivated of course ;) So we can see if gmic break somehow all OPENMP uses or just this one...

[upegelow]

Here is a test in the tonecurve module:

OPENMP on:

pegelow@zaphod:~> /usr/local/test/bin/darktable --disable-opencl
[tonecurve] image processing took 0.0005 sec
[tonecurve] image processing took 0.0133 sec
[tonecurve] image processing took 0.0193 sec
[tonecurve] image processing took 0.0202 sec
[tonecurve] image processing took 0.0158 sec
[tonecurve] image processing took 0.0207 sec
[tonecurve] image processing took 0.0229 sec
[tonecurve] image processing took 0.0308 sec
[tonecurve] image processing took 0.0181 sec
[tonecurve] image processing took 0.0309 sec
[tonecurve] image processing took 0.0165 sec
[tonecurve] image processing took 0.0292 sec
[tonecurve] image processing took 0.0287 sec

OPENMP off:

pegelow@zaphod:~> /usr/local/test/bin/darktable --disable-opencl
[tonecurve] image processing took 0.0016 sec
[tonecurve] image processing took 0.0699 sec
[tonecurve] image processing took 0.0802 sec
[tonecurve] image processing took 0.0706 sec
[tonecurve] image processing took 0.0766 sec
[tonecurve] image processing took 0.0730 sec
[tonecurve] image processing took 0.0851 sec
[tonecurve] image processing took 0.0726 sec
[tonecurve] image processing took 0.0833 sec
[tonecurve] image processing took 0.0802 sec
[tonecurve] image processing took 0.0891 sec
[tonecurve] image processing took 0.0716 sec
[tonecurve] image processing took 0.0823 sec

As it should be.

[TurboGit]

That's probably one of the strangest issue I have seen :( Sorry no more idea at this point.

One more thing I would check is the shared libraries used in both cases. Maybe libgmic compiled in your distrib is using a different OpenMP library? Mixing would cause this slow down ? Or maybe it is compiled with another version of GCC ?

[TurboGit]

BTW, this is exactly what we are doing for rawspeed for example.

[parafin]

distro maintainers won't be happy. So we will end up where we started - they will rip out gmic git submodule and link to the system library (with the same dependencies) instead.

[TurboGit]

@parafin : as we've done with the OpenCL headers. It will be optional.

[phweyland]

When I started to work on this, I added gmic.h in dt code. I don't remember I needed any other library to compile and use it.
With my current first test the build is ok (including gmic.h). But I've a run time crash with that message when I try to use a gmz file:

$ /opt/darktable/bin/darktable
/opt/darktable/bin/darktable: symbol lookup error: /opt/darktable/lib/darktable/plugins/liblut3d.so: undefined symbol: _ZN4gmicC1Ev

Why I don't see this at build time ?

[parafin]

Because DT is built without -Wl,--no-undefined flag. iop plugin is a shared library, by default it is assumed, that it's OK to have unresolved symbols in it.
gmic is not a header only library.

[parafin]

@parafin : as we've done with the OpenCL headers. It will be optional.

And how will this idea help then, if most users use packages from distributions which will use system library and therefore this bug will be present for them?

[TurboGit]

And how will this idea help then, if most users use packages from distributions which will use system library and therefore this bug will be present for them?

I don't now and we don't know as we don't have a single idea about the issue at the moment. It is happening for a single user at the moment. At least we will be able to provide a version with a very minimal version of GMIC built and so with less dependencies for all people building from sources. And I hope this will solve @upegelow issue and maybe it will give us an idea about what is going on.

I have nothing better to propose at the moment.

[phweyland]

Because DT is built without -Wl,--no-undefined flag.

Just removed them. But yet no warning / error at build time (and still crash :-)). Something is missing ...

About dependencies, looking at the Makefile (if I understand correctly) only zlib library is mandatory.

Makefile.txt

[parafin]

Because DT is built without -Wl,--no-undefined flag.

Just removed them. But yet no warning / error at build time (and still crash :-)). Something is missing ...

Not sure what have you removed, but that flag is missing, so you should have added it, not removed. You probably changed if(WIN32) part.

[parafin]

And how will this idea help then, if most users use packages from distributions which will use system library and therefore this bug will be present for them?

I don't now and we don't know as we don't have a single idea about the issue at the moment. It is happening for a single user at the moment. At least we will be able to provide a version with a very minimal version of GMIC built and so with less dependencies for all people building from sources. And I hope this will solve @upegelow issue and maybe it will give us an idea about what is going on.

I have nothing better to propose at the moment.

If the idea is to have a minimal build of gmic, then you don't need to include it in dt sources, just do a minimal build of gmic and install it instead of system version;)

[phweyland]

Not sure what have you removed, but that flag is missing,

My bad! So I have to find out where to put it ...

[phweyland]

If the idea is to have a minimal build of gmic, then you don't need to include it in dt sources, just do a minimal build of gmic and install it instead of system version;)

But in that case if the user needs to use gmic as an application we get back the compatibility issue.

My idea currently is to add the code (normally with no or very few dependencies) to dt. So it should run whatever the context.
And to keep the possibility to use DefineOptions.make to remove USE_GMIC if we don't want it. I can let the conditional code to let lut3d works without GMIC.

[parafin]

Which problem are we trying to fix here?

If it's the bug with lighttable slowdown - then we should debug it first, not make some decisions already. @upegelow is unwilling to help right now, so I would suggest to wait for someone to reproduce the issue who is able to run the tests I proposed. Custom build of gmic was suggested as a test, not as a solution. At best it's a workaround.

If we are talking about the amount of dependencies gmic pulls and we want to reduce them, then I guess it's a question for packagers of libgmic. In Gentoo it is solved by USE-flags, and in binary distributions it's a foundational limitation. Copying code doesn't sound like a good idea, and will be actively opposed by various distributions due to their policy on bundled libraries.

[phweyland]

Which problem are we trying to fix here?

From my standpoint, to find a way to use the desired features without bringing bug, build or distributions issue...

About the right to include or not piece of codes, I don't know, but that's the gmic team itself which suggested to do that way (that was also on their site).

[parafin]

And I'm saying that copying code will introduce distribution (or rather packaging) problems. It's not about a right to do it (if licenses are compatible, it's not a problem), but the fact that code duplication is considered bad.

[upegelow]

With some significant trouble I managed to compile gmic and libs myself with the following settings:

%cmake \
        -DENABLE_CURL=OFF \
        -DENABLE_X=OFF \
        -DENABLE_FFMPEG=OFF \
        -DENABLE_FFTW=OFF \
        -DENABLE_GRAPHICSMAGICK=OFF \
        -DENABLE_JPEG=OFF \
        -DENABLE_OPENCV=OFF \
        -DENABLE_OPENEXR=OFF \
        -DENABLE_OPENMP=OFF \
        -DENABLE_PNG=OFF \
        -DENABLE_TIFF=OFF \
        -DENABLE_ZLIB=OFF \
        -DENABLE_DYNAMIC_LINKING=ON \
        -DBUILD_LIB_STATIC=OFF

A few observations:

1. with this version the slowdown is still present
2. image exposure with this self compiled version is faster than with the version from OpenSUSE (ca. 0.004 secs compared to 0.02 secs - without gmic: 0.0005secs)
3. once any image is opened in the darkroom and then lighttable is entered again the slowdown is gone only to come back the next time darktable is started

[parafin]

Could you produce the same library comparison pdf like you did before?

[upegelow]

ldd-comparison.pdf

Only libmvec comes as an additional dependency specific to gmic.

[parafin]

Could you try also to remove "-Ofast" flag from gmic's CMakeLists.txt and rebuild it? It should get rid of libmvec too, I think. But honestly I don't know what to make of it, especially since we now have 3 different behaviours (rendering speeds)...

[upegelow]

Could you try also to remove "-Ofast" flag f

That's it probably. Without -Ofast / libmvec export image takes about 0.0005 secs, the same as when compiled without gmic.

[parafin]

Still, I'm not sure what it means... So at least 2 gmic dependencies affect darktable performance - one from the original long list of libraries dropped render speed from 0.02 to 0.004, then libmvec (it seems) dropped 0.004 to original 0.0005. libmvec seems to replace some mathematical functions with optimized implementation, which doesn't explain the slowdown, especially since the code that is slow does just plain old memcpy.
Which CPU does your system have? Could you show /proc/cpuinfo?

[upegelow]

Which CPU does your system have? Could you show /proc/cpuinfo?

Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz with active hyperthreading

A bit of clarification on the numbers. So far I have four cases:

1. without gmic. typical image expose time is 0.0005 secs
2. with gmic as supplied for my system. typical image expose time is 0.02 secs
3. with gmic compiled by myself (see remark below). typical image expose time is 0.004 secs
4. with gmic compiled without -Ofast and without all opt. dependencies. typical image expose time is 0.0005 secs

The difference between 2 and 3: the original library is likely compiled with gcc/g++ version 7 (standard on Leap 15.1). That compiler version would generate an internal g++ error here on one of the gmic source files so I needed to move to version 8. Additionally I was not able to compile with opencv, so I needed to discard the zart part of gmic.

[ptilopteri]

fwiw: I do not build but use darix's openSUSE Tumbleweed builds and I experienced very noticeable delays switching images during the time gmic was in the Tumbleweed builds. Not seeing it now.

hope this may help

[upegelow]

I have now narrowed down the issue and could revise some of my previous findings. The problem seems to arise from opencv3 which is linked in the standard gmic package on my system. By moving to opencv4 I could generate a gmic package that would not slow down darktable. I needed to skip building of zart as I have not been able to make the build process accepting opencv4, but that's fine for me.

The imminent cause of the slowdown has been that our code in view.c only sees one CPU core:

darktable/src/views/view.c

Lines 1291 to 1312 in e56b0e7

	#ifdef _OPENMP
	#pragma omp parallel for schedule(static) default(none) shared(buf, rgbbuf, transform)
	#endif
	for(int i = 0; i < buf.height; i++)
	{
	const uint8_t *in = buf.buf + i * buf.width * 4;
	uint8_t *out = rgbbuf + i * buf.width * 4;
	if(transform)
	{
	cmsDoTransform(transform, in, out, buf.width);
	}
	else
	{
	for(int j = 0; j < buf.width; j++, in += 4, out += 4)
	{
	out[0] = in[2];
	out[1] = in[1];
	out[2] = in[0];
	}
	}
	}

As a consequence we get a massive accumulation of OPENMP overhead (processing many images with low resolution) without any advantage. IMHO we should revise the code above a bit. There could be one codepath with OPENMP and one without. Based on image dimensions and number of cores the path could be chosen dynamically. This would require a bit investigations to find the break even point.

[parafin]

To clarify:

1. With OpenCV4 you get original speed (0.0005 s)?
2. With OpenCV3 openmp code in view.c is dispatched only to 1 CPU?

Regarding OpenCV affecting OpenMP, I've found only one thing to try - set OPENCV_FOR_OPENMP_DYNAMIC_DISABLE environment variable to 1.

Are both OpenCV3 and OpenCV4 built with OpenMP support on your system?

[upegelow]

Yes, Yes.

Are both OpenCV3 and OpenCV4 built with OpenMP support on your system?

I don't know. Both do not link against libgomp.

[parafin]

Then probably no? Is opencv the only different library from ldd output when you change from opencv3 to opencv4?
Have you tried OPENCV_FOR_OPENMP_DYNAMIC_DISABLE=1 with opencv3?

I'm sadly not very familiar with OpenMP and how it uses threads, so I'm afraid this is all the help I can provide with this bug...

[upegelow]

Just for the records: I can no longer reproduce the slow down on my system. After a recent upgrade of several system libraries (incl. gmic) the problem is gone.

I am closing this issue.