How cheap a GPU will still speed up darktable?

kofa · December 9, 2022, 3:23pm

If you only get that message after the error, I’d assume it’s genuine. However…

If you are processing multiple pipelines (for example, the darkroom uses one for the top-left small preview, and one for the editor area), darktable will try to work on them in parallel.
The GPU will start working on a module, in one of the pipelines. If GPU processing is mandatory (e.g., when using the very fast GPU scheduling profile, or using the default scheduling profile with an appropriately configured priority string), the 2nd pipeline will:

first wait for the GPU to become available (see opencl_mandatory_timeout in darktablerc - the default value is 400, the unit is 5 ms).
if the timeout (400 * 5 ms = 2 s) expires, and the GPU is still busy, it’ll fall back to the CPU path. This is when you see reached opencl_mandatory_timeout trying to lock mandatory device, fallback to CPU in the log, if you have OpenCL debug logging enabled.

In some cases (e.g., when you are processing large files with heavy modules, like diffuse or sharpen or highlight reconstruction with guided laplacians), a timeout will occur even if everything is OK.
Now, if your GPU is faster than your CPU (which is usually the case), this may be detrimental:

2nd pipeline waits for 2 seconds
starts processing on the CPU, let’s say 20 seconds
total time is 22 seconds
if it waited, and got the GPU after, say, 5 seconds, and then took 5 seconds to process the module on the GPU, the total time would have been 10 seconds.

So, you may want to increase that timeout significantly. It will either cause a hang (in that case, simply back out the change), or, possibly, a speed-up (like it did for me - OpenCL is mandatory, yet CPU is used (solved) - #4 by kofa).

g-man · December 9, 2022, 3:58pm

In this case, the first lockout was at 432. Then the system used CPU. The second was at 438, so 6seconds later and the GPU was still not available? It is like the kernel fault is keeping the GPU unavailable.

kofa · December 11, 2022, 10:50am

I get no issue with your NEF and XMP. NVidia 1060/6GB, driver v525.

Export:

2133.631487 [dev] took 0.000 secs (0.000 CPU) to load the image.
2133.671617 [export] creating pixelpipe took 0.036 secs (0.043 CPU)
2133.671655 [dev_pixelpipe] took 0.000 secs (0.000 CPU) initing base buffer [export]
2133.679577 [dev_pixelpipe] took 0.008 secs (0.008 CPU) [export] processed `raw black/white point' on GPU, blended on GPU
2133.682465 [dev_pixelpipe] took 0.003 secs (0.000 CPU) [export] processed `white balance' on GPU, blended on GPU
2133.772011 [dev_pixelpipe] took 0.090 secs (0.337 CPU) [export] processed `highlight reconstruction' on CPU, blended on CPU
2133.859552 [dev_pixelpipe] took 0.088 secs (0.057 CPU) [export] processed `demosaic' on GPU, blended on GPU
2133.871214 [dev_pixelpipe] took 0.012 secs (0.003 CPU) [export] processed `exposure' on GPU, blended on GPU
2133.888416 [dev_pixelpipe] took 0.017 secs (0.005 CPU) [export] processed `input color profile' on GPU, blended on GPU
image colorspace transform Lab-->RGB took 0.013 secs (0.005 GPU) [diffuse ]
2134.327287 [dev_pixelpipe] took 0.439 secs (0.380 CPU) [export] processed `diffuse or sharpen' on GPU, blended on GPU
2136.258503 [dev_pixelpipe] took 1.931 secs (1.968 CPU) [export] processed `diffuse or sharpen 1' on GPU, blended on GPU
2136.296198 [dev_pixelpipe] took 0.038 secs (0.013 CPU) [export] processed `color balance rgb' on GPU, blended on GPU
2136.336304 [dev_pixelpipe] took 0.040 secs (0.016 CPU) [export] processed `filmic rgb' on GPU, blended on GPU
image colorspace transform RGB-->Lab took 0.014 secs (0.006 GPU) [colorout ]
2136.376052 [dev_pixelpipe] took 0.040 secs (0.019 CPU) [export] processed `output color profile' on GPU, blended on GPU
2136.408767 [dev_pixelpipe] took 0.033 secs (0.021 CPU) [export] processed `scale into final size' on GPU, blended on GPU
2136.430748 [dev_pixelpipe] took 0.022 secs (0.014 CPU) [export] processed `dithering' on CPU, blended on CPU
2136.430777 [opencl_profiling] profiling device 0 ('NVIDIA GeForce GTX 1060 6GB'):
2136.430783 [opencl_profiling] spent  0.0154 seconds in [Write Image (from host to device)]
2136.430785 [opencl_profiling] spent  0.0014 seconds in rawprepare_1f
2136.430787 [opencl_profiling] spent  0.0015 seconds in whitebalance_1f
2136.430788 [opencl_profiling] spent  0.0348 seconds in [Read Image (from device to host)]
2136.430789 [opencl_profiling] spent  0.0005 seconds in border_interpolate
2136.430790 [opencl_profiling] spent  0.0026 seconds in rcd_border_green
2136.430791 [opencl_profiling] spent  0.0035 seconds in rcd_border_redblue
2136.430793 [opencl_profiling] spent  0.0027 seconds in rcd_populate
2136.430794 [opencl_profiling] spent  0.0027 seconds in rcd_step_1_1
2136.430795 [opencl_profiling] spent  0.0020 seconds in rcd_step_1_2
2136.430797 [opencl_profiling] spent  0.0013 seconds in rcd_step_2_1
2136.430799 [opencl_profiling] spent  0.0035 seconds in rcd_step_3_1
2136.430800 [opencl_profiling] spent  0.0019 seconds in rcd_step_4_1
2136.430801 [opencl_profiling] spent  0.0010 seconds in rcd_step_4_2
2136.430802 [opencl_profiling] spent  0.0029 seconds in rcd_step_5_1
2136.430803 [opencl_profiling] spent  0.0046 seconds in rcd_step_5_2
2136.430803 [opencl_profiling] spent  0.0048 seconds in rcd_write_output
2136.430804 [opencl_profiling] spent  0.0182 seconds in [Copy Image (on device)]
2136.430807 [opencl_profiling] spent  0.0054 seconds in exposure
2136.430808 [opencl_profiling] spent  0.0068 seconds in colorin_unbound
2136.430809 [opencl_profiling] spent  0.0055 seconds in colorspaces_transform_lab_to_rgb_matrix
2136.430810 [opencl_profiling] spent  0.1759 seconds in blur_2D_Bspline_horizontal
2136.430811 [opencl_profiling] spent  0.6118 seconds in blur_2D_Bspline_vertical
2136.430812 [opencl_profiling] spent  0.2600 seconds in wavelets_detail_level
2136.430813 [opencl_profiling] spent  1.1835 seconds in diffuse_pde
2136.430814 [opencl_profiling] spent  0.0087 seconds in colorbalancergb
2136.430815 [opencl_profiling] spent  0.0053 seconds in filmic_mask_clipped_pixels
2136.430818 [opencl_profiling] spent  0.0073 seconds in filmicrgb_chroma
2136.430819 [opencl_profiling] spent  0.0055 seconds in colorspaces_transform_rgb_matrix_to_lab
2136.430820 [opencl_profiling] spent  0.0102 seconds in colorout
2136.430821 [opencl_profiling] spent  0.0231 seconds in interpolation_resample
2136.430822 [opencl_profiling] spent  2.4144 seconds totally in command queue (with 0 events missing)
2136.430838 [dev_process_export] pixel pipeline processing took 2.759 secs (2.841 CPU)
[export_job] exported to `/tmp/darktable_exported/DSC_9619.jpg'

Open in darkroom:

2245.463973 [dev] took 0.000 secs (0.000 CPU) to load the image.
2245.818420 [histogram] took 0.002 secs (0.002 CPU) scope draw
2245.832930 [dev] took 0.000 secs (0.000 CPU) to load the image.
2245.844915 [histogram] took 0.002 secs (0.005 CPU) scope draw
2245.858378 [histogram] took 0.002 secs (0.006 CPU) scope draw
2245.875788 [histogram] took 0.003 secs (0.001 CPU) scope draw
2245.893706 [histogram] took 0.004 secs (0.008 CPU) scope draw
2245.908368 [histogram] took 0.003 secs (0.006 CPU) scope draw
2245.925496 [histogram] took 0.003 secs (0.007 CPU) scope draw
2245.940832 [histogram] took 0.002 secs (0.006 CPU) scope draw
2245.957964 [histogram] took 0.003 secs (0.002 CPU) scope draw
2245.973814 [histogram] took 0.002 secs (0.004 CPU) scope draw
2245.991754 [histogram] took 0.003 secs (0.003 CPU) scope draw
2245.998469 [dev_pixelpipe] took 0.127 secs (0.130 CPU) [full] processed `demosaic' on GPU, blended on GPU
2246.005656 [dev_pixelpipe] took 0.007 secs (0.000 CPU) [full] processed `exposure' on GPU, blended on GPU
2246.006978 [dev_pixelpipe] took 0.001 secs (0.001 CPU) [full] processed `input color profile' on GPU, blended on GPU
2246.007378 [histogram] took 0.002 secs (0.003 CPU) scope draw
image colorspace transform Lab-->RGB took 0.002 secs (0.005 GPU) [diffuse ]
2246.024243 [dev_pixelpipe] took 0.017 secs (0.017 CPU) [full] processed `diffuse or sharpen' on GPU, blended on GPU
2246.024665 [histogram] took 0.003 secs (0.007 CPU) scope draw
2246.068068 [dev_pixelpipe] took 0.044 secs (0.043 CPU) [full] processed `diffuse or sharpen 1' on GPU, blended on GPU
2246.075405 [dev_pixelpipe] took 0.007 secs (0.003 CPU) [full] processed `color balance rgb' on GPU, blended on GPU
2246.077777 [dev_pixelpipe] took 0.002 secs (0.000 CPU) [full] processed `filmic rgb' on GPU, blended on GPU
image colorspace transform RGB-->Lab took 0.001 secs (0.000 GPU) [colorout ]
2246.080886 [dev_pixelpipe] took 0.003 secs (0.001 CPU) [full] processed `output color profile' on GPU, blended on GPU
2246.087558 [dev_pixelpipe] took 0.007 secs (0.016 CPU) [full] processed `display encoding' on CPU, blended on CPU
2246.087571 [opencl_profiling] profiling device 0 ('NVIDIA GeForce GTX 1060 6GB'):
2246.087573 [opencl_profiling] spent  0.0097 seconds in [Write Image (from host to device)]
2246.087575 [opencl_profiling] spent  0.0005 seconds in border_interpolate
2246.087576 [opencl_profiling] spent  0.0028 seconds in rcd_border_green
2246.087578 [opencl_profiling] spent  0.0061 seconds in rcd_border_redblue
2246.087579 [opencl_profiling] spent  0.0039 seconds in rcd_populate
2246.087580 [opencl_profiling] spent  0.0034 seconds in rcd_step_1_1
2246.087581 [opencl_profiling] spent  0.0022 seconds in rcd_step_1_2
2246.087583 [opencl_profiling] spent  0.0016 seconds in rcd_step_2_1
2246.087585 [opencl_profiling] spent  0.0038 seconds in rcd_step_3_1
2246.087586 [opencl_profiling] spent  0.0023 seconds in rcd_step_4_1
2246.087587 [opencl_profiling] spent  0.0012 seconds in rcd_step_4_2
2246.087588 [opencl_profiling] spent  0.0043 seconds in rcd_step_5_1
2246.087590 [opencl_profiling] spent  0.0073 seconds in rcd_step_5_2
2246.087591 [opencl_profiling] spent  0.0082 seconds in rcd_write_output
2246.087592 [opencl_profiling] spent  0.0202 seconds in interpolation_resample
2246.087593 [opencl_profiling] spent  0.0003 seconds in exposure
2246.087595 [opencl_profiling] spent  0.0003 seconds in colorin_unbound
2246.087596 [opencl_profiling] spent  0.0004 seconds in [Copy Image (on device)]
2246.087598 [opencl_profiling] spent  0.0002 seconds in colorspaces_transform_lab_to_rgb_matrix
2246.087599 [opencl_profiling] spent  0.0045 seconds in blur_2D_Bspline_horizontal
2246.087600 [opencl_profiling] spent  0.0068 seconds in blur_2D_Bspline_vertical
2246.087601 [opencl_profiling] spent  0.0064 seconds in wavelets_detail_level
2246.087603 [opencl_profiling] spent  0.0266 seconds in diffuse_pde
2246.087604 [opencl_profiling] spent  0.0144 seconds in [Read Image (from device to host)]
2246.087606 [opencl_profiling] spent  0.0004 seconds in colorbalancergb
2246.087607 [opencl_profiling] spent  0.0001 seconds in filmic_mask_clipped_pixels
2246.087608 [opencl_profiling] spent  0.0003 seconds in filmicrgb_chroma
2246.087609 [opencl_profiling] spent  0.0002 seconds in colorspaces_transform_rgb_matrix_to_lab
2246.087610 [opencl_profiling] spent  0.0004 seconds in colorout
2246.087612 [opencl_profiling] spent  0.1389 seconds totally in command queue (with 0 events missing)
2246.087886 [dev_process_image] pixel pipeline processing took 0.225 secs (0.213 CPU)
2246.113429 [histogram] took 0.002 secs (0.005 CPU) scope draw
2246.128578 [dev_pixelpipe] took 0.000 secs (0.000 CPU) initing base buffer [preview]
2246.129828 [dev_pixelpipe] took 0.001 secs (0.001 CPU) [preview] processed `raw black/white point' on GPU, blended on GPU
2246.130457 [dev_pixelpipe] took 0.001 secs (0.000 CPU) [preview] processed `white balance' on GPU, blended on GPU
2246.134592 [dev_pixelpipe] took 0.004 secs (0.016 CPU) [preview] processed `highlight reconstruction' on CPU, blended on CPU
2246.139789 [dev_pixelpipe] took 0.005 secs (0.001 CPU) [preview] processed `demosaic' on GPU, blended on GPU
2246.140581 [dev_pixelpipe] took 0.001 secs (0.000 CPU) [preview] processed `exposure' on GPU, blended on GPU
2246.141943 [dev_pixelpipe] took 0.001 secs (0.001 CPU) [preview] processed `input color profile' on GPU, blended on GPU
image colorspace transform Lab-->RGB took 0.001 secs (0.001 GPU) [diffuse ]
2246.156519 [dev_pixelpipe] took 0.015 secs (0.007 CPU) [preview] processed `diffuse or sharpen' on GPU, blended on GPU
2246.214564 [dev_pixelpipe] took 0.058 secs (0.046 CPU) [preview] processed `diffuse or sharpen 1' on GPU, blended on GPU
2246.218650 [dev_pixelpipe] took 0.004 secs (0.004 CPU) [preview] processed `color balance rgb' on GPU, blended on GPU
2246.220866 [dev_pixelpipe] took 0.002 secs (0.002 CPU) [preview] processed `filmic rgb' on GPU, blended on GPU
image colorspace transform RGB-->Lab took 0.001 secs (0.001 GPU) [colorout ]
2246.224093 [dev_pixelpipe] took 0.003 secs (0.003 CPU) [preview] processed `output color profile' on GPU, blended on GPU
2246.228642 [dev_pixelpipe] took 0.005 secs (0.020 CPU) [preview] processed `display encoding' on CPU, blended on CPU
image colorspace transform RGB-->RGB took 0.003 secs (0.026 CPU) [final histogram]
2246.237154 [histogram] took 0.009 secs (0.035 CPU) final rgb parade
2246.237168 [opencl_profiling] profiling device 0 ('NVIDIA GeForce GTX 1060 6GB'):
2246.237171 [opencl_profiling] spent  0.0006 seconds in [Write Image (from host to device)]
2246.237173 [opencl_profiling] spent  0.0001 seconds in rawprepare_1f
2246.237174 [opencl_profiling] spent  0.0001 seconds in whitebalance_1f
2246.237175 [opencl_profiling] spent  0.0068 seconds in [Read Image (from device to host)]
2246.237177 [opencl_profiling] spent  0.0001 seconds in border_interpolate
2246.237178 [opencl_profiling] spent  0.0001 seconds in rcd_border_green
2246.237179 [opencl_profiling] spent  0.0002 seconds in rcd_border_redblue
2246.237181 [opencl_profiling] spent  0.0001 seconds in rcd_populate
2246.237182 [opencl_profiling] spent  0.0001 seconds in rcd_step_1_1
2246.237184 [opencl_profiling] spent  0.0001 seconds in rcd_step_1_2
2246.237185 [opencl_profiling] spent  0.0001 seconds in rcd_step_2_1
2246.237186 [opencl_profiling] spent  0.0002 seconds in rcd_step_3_1
2246.237188 [opencl_profiling] spent  0.0001 seconds in rcd_step_4_1
2246.237189 [opencl_profiling] spent  0.0001 seconds in rcd_step_4_2
2246.237190 [opencl_profiling] spent  0.0001 seconds in rcd_step_5_1
2246.237191 [opencl_profiling] spent  0.0002 seconds in rcd_step_5_2
2246.237192 [opencl_profiling] spent  0.0002 seconds in rcd_write_output
2246.237193 [opencl_profiling] spent  0.0003 seconds in exposure
2246.237194 [opencl_profiling] spent  0.0003 seconds in colorin_unbound
2246.237195 [opencl_profiling] spent  0.0006 seconds in [Copy Image (on device)]
2246.237196 [opencl_profiling] spent  0.0003 seconds in colorspaces_transform_lab_to_rgb_matrix
2246.237198 [opencl_profiling] spent  0.0058 seconds in blur_2D_Bspline_horizontal
2246.237199 [opencl_profiling] spent  0.0091 seconds in blur_2D_Bspline_vertical
2246.237199 [opencl_profiling] spent  0.0081 seconds in wavelets_detail_level
2246.237201 [opencl_profiling] spent  0.0309 seconds in diffuse_pde
2246.237202 [opencl_profiling] spent  0.0005 seconds in colorbalancergb
2246.237203 [opencl_profiling] spent  0.0002 seconds in filmic_mask_clipped_pixels
2246.237205 [opencl_profiling] spent  0.0004 seconds in filmicrgb_chroma
2246.237206 [opencl_profiling] spent  0.0003 seconds in colorspaces_transform_rgb_matrix_to_lab
2246.237208 [opencl_profiling] spent  0.0005 seconds in colorout
2246.237209 [opencl_profiling] spent  0.0666 seconds totally in command queue (with 0 events missing)
2246.237720 [dev_process_preview] pixel pipeline processing took 0.137 secs (0.184 CPU)
2246.247594 [histogram] took 0.002 secs (0.002 CPU) scope draw
2247.913691 [histogram] took 0.002 secs (0.002 CPU) scope draw
2247.934520 [histogram] took 0.002 secs (0.002 CPU) scope draw
2247.950246 [histogram] took 0.003 secs (0.003 CPU) scope draw
2247.966070 [histogram] took 0.002 secs (0.002 CPU) scope draw
2247.986156 [histogram] took 0.003 secs (0.003 CPU) scope draw
2248.000026 [histogram] took 0.002 secs (0.002 CPU) scope draw
2248.016939 [histogram] took 0.002 secs (0.002 CPU) scope draw
2248.038371 [histogram] took 0.003 secs (0.003 CPU) scope draw
2248.054564 [histogram] took 0.003 secs (0.003 CPU) scope draw
2248.067630 [histogram] took 0.002 secs (0.002 CPU) scope draw
2248.083854 [histogram] took 0.002 secs (0.002 CPU) scope draw

g-man · December 11, 2022, 11:31am

Kofa, I can’t get it to crash either. Can you try with OpenCL tunning on?

kofa · December 11, 2022, 11:32am

Mine is set to

123sg · December 11, 2022, 8:39pm

On my system, setting it to memory transfer seemed the ‘best’ way to make it break.

kofa · December 11, 2022, 9:27pm

NVidia does not benefit from that, as far as I know – on the contrary.

123sg · December 11, 2022, 9:50pm

Yes, sorry, I had gathered that - it didn’t speed it up anyway and from reading this thread I actually thought that might be the cause of my ‘issue’. User error, in other words.
I only mentioned it, because as I said above (somewhere…) that seems to be the setting that reproduces the problem. In the weekly build thread I noticed that @Bernhard_Vogler has a similar issue - which might be tied in to the same thing?