Darktable: pixelpipe fired twice when opening darkroom

Created on 4 Feb 2020 · 16Comments · Source: darktable-org/darktable

Describe the bug
When opening a new image in darkroom (while darktable runs with -d perf in a terminal), it shows that the pixelpipe is computed twice for no reason (full preview only).

This is similar to some debugging I did while developing the tone equalizer: for some images, the IOP commit_params() method is fired up to 16 times when opening the darkroom.

Platform :

Darktable Version: 3.1
OS: Fedora 31
OpenCL Nvidia + Intel
Nvidia 440.44, Intel Neo 20.04.15428

22,840833 [pixelpipe_process] [full] using device 0
22,857501 [dev_pixelpipe] took 0,016 secs (0,036 CPU) initing base buffer [full]
22,881662 [dev_pixelpipe] took 0,024 secs (0,032 CPU) processed `raw black/white point' on GPU, blended on GPU [full]
22,921965 [dev_pixelpipe] took 0,040 secs (0,060 CPU) processed `white balance' on GPU, blended on GPU [full]
22,953324 [dev_pixelpipe] took 0,031 secs (0,034 CPU) processed `highlight reconstruction' on GPU, blended on GPU [full]
23,061347 [dev_pixelpipe] took 0,108 secs (0,182 CPU) processed `demosaic' on GPU, blended on GPU [full]
23,187749 [dev_pixelpipe] took 0,126 secs (0,148 CPU) processed `exposure' on GPU, blended on GPU [full]
23,893583 [dev_pixelpipe] took 0,704 secs (0,702 CPU) processed `exposure 1' on GPU, blended on GPU [full]
24,136845 [dev_pixelpipe] took 0,242 secs (0,395 CPU) processed `lens correction' on GPU, blended on GPU [full]
24,257331 [dev_pixelpipe] took 0,119 secs (0,056 CPU) processed `orientation' on GPU, blended on GPU [full]
24,369267 [dev_pixelpipe] took 0,107 secs (0,047 CPU) processed `crop and rotate' on GPU, blended on GPU [full]
25,675875 [dev_pixelpipe] took 1,302 secs (8,598 CPU) processed `tone equalizer' on CPU, blended on CPU [full]
25,741823 [dev_pixelpipe] took 0,061 secs (0,056 CPU) processed `input color profile' on GPU, blended on GPU [full]
25,853092 [dev_pixelpipe] took 0,111 secs (0,059 CPU) processed `color balance' on GPU, blended on GPU [full]
26,068063 [dev_pixelpipe] took 0,215 secs (0,094 CPU) processed `local contrast' on GPU, blended on GPU [full]
image colorspace transform Lab-->RGB took 0,013 secs (0,004 GPU) [filmicrgb ]
26,143277 [dev_pixelpipe] took 0,075 secs (0,052 CPU) processed `filmic rgb' on GPU, blended on GPU [full]
image colorspace transform RGB-->Lab took 0,013 secs (0,004 GPU) [colorout ]
26,222091 [dev_pixelpipe] took 0,079 secs (0,052 CPU) processed `output color profile' on GPU, blended on GPU [full]
26,284059 [dev_pixelpipe] took 0,062 secs (0,251 CPU) processed `gamma' on CPU, blended on CPU [full]
26,284149 [opencl_profiling] profiling device 0 ('Quadro M2200'):
26,284157 [opencl_profiling] spent  0,0451 seconds in [Write Image (from host to device)]
26,284163 [opencl_profiling] spent  0,0015 seconds in rawprepare_1f
26,284170 [opencl_profiling] spent  0,9040 seconds in [Read Image (from device to host)]
26,284195 [opencl_profiling] spent  0,0013 seconds in whitebalance_1f
26,284199 [opencl_profiling] spent  0,0013 seconds in highlights_1f_clip
26,284203 [opencl_profiling] spent  0,0041 seconds in ppg_demosaic_green
26,284207 [opencl_profiling] spent  0,0052 seconds in ppg_demosaic_redblue
26,284210 [opencl_profiling] spent  0,0006 seconds in border_interpolate
26,284214 [opencl_profiling] spent  0,0537 seconds in interpolation_resample
26,284217 [opencl_profiling] spent  0,0105 seconds in exposure
26,284221 [opencl_profiling] spent  0,0013 seconds in blendop_mask_rgb
26,284239 [opencl_profiling] spent  0,0039 seconds in guided_filter_split_rgb_image
26,284244 [opencl_profiling] spent  0,3601 seconds in guided_filter_box_mean_x
26,284246 [opencl_profiling] spent  0,0324 seconds in guided_filter_box_mean_y
26,284269 [opencl_profiling] spent  0,0047 seconds in guided_filter_covariances
26,284273 [opencl_profiling] spent  0,0057 seconds in guided_filter_variances
26,284277 [opencl_profiling] spent  0,0187 seconds in guided_filter_update_covariance
26,284280 [opencl_profiling] spent  0,0142 seconds in guided_filter_solve
26,284284 [opencl_profiling] spent  0,0056 seconds in guided_filter_generate_result
26,284286 [opencl_profiling] spent  0,0247 seconds in [Copy Image (on device)]
26,284290 [opencl_profiling] spent  0,0094 seconds in blendop_rgb
26,284293 [opencl_profiling] spent  0,0372 seconds in [Write Buffer (from host to device)]
26,284296 [opencl_profiling] spent  0,0455 seconds in lens_distort_lanczos3
26,284299 [opencl_profiling] spent  0,0059 seconds in flip
26,284317 [opencl_profiling] spent  0,0051 seconds in colorin_unbound
26,284321 [opencl_profiling] spent  0,0057 seconds in colorbalance_cdl
26,284324 [opencl_profiling] spent  0,0048 seconds in pad_input
26,284347 [opencl_profiling] spent  0,0304 seconds in gauss_reduce
26,284351 [opencl_profiling] spent  0,0216 seconds in process_curve
26,284354 [opencl_profiling] spent  0,0269 seconds in laplacian_assemble
26,284358 [opencl_profiling] spent  0,0053 seconds in write_back
26,284360 [opencl_profiling] spent  0,0046 seconds in colorspaces_transform_lab_to_rgb_matrix
26,284364 [opencl_profiling] spent  0,0045 seconds in filmicrgb_chroma
26,284367 [opencl_profiling] spent  0,0046 seconds in colorspaces_transform_rgb_matrix_to_lab
26,284370 [opencl_profiling] spent  0,0128 seconds in colorout
26,284373 [opencl_profiling] spent  1,7230 seconds totally in command queue (with 0 events missing)
26,306373 [dev_process_image] pixel pipeline processing took 3,466 secs (10,869 CPU)
26,306448 [pixelpipe_process] [full] using device 0
26,310010 [dev_pixelpipe] took 0,003 secs (0,016 CPU) initing base buffer [full]
26,328939 [dev_pixelpipe] took 0,019 secs (0,017 CPU) processed `raw black/white point' on GPU, blended on GPU [full]
26,337658 [dev_pixelpipe] took 0,009 secs (0,006 CPU) processed `white balance' on GPU, blended on GPU [full]
26,357078 [dev_pixelpipe] took 0,019 secs (0,015 CPU) processed `highlight reconstruction' on GPU, blended on GPU [full]
26,432253 [dev_pixelpipe] took 0,075 secs (0,058 CPU) processed `demosaic' on GPU, blended on GPU [full]
26,494387 [dev_pixelpipe] took 0,062 secs (0,053 CPU) processed `exposure' on GPU, blended on GPU [full]
27,120049 [dev_pixelpipe] took 0,626 secs (0,600 CPU) processed `exposure 1' on GPU, blended on GPU [full]
27,292226 [dev_pixelpipe] took 0,172 secs (0,375 CPU) processed `lens correction' on GPU, blended on GPU [full]
27,341057 [dev_pixelpipe] took 0,049 secs (0,039 CPU) processed `orientation' on GPU, blended on GPU [full]
27,386298 [dev_pixelpipe] took 0,045 secs (0,037 CPU) processed `crop and rotate' on GPU, blended on GPU [full]
28,574495 [dev_pixelpipe] took 1,188 secs (8,336 CPU) processed `tone equalizer' on CPU, blended on CPU [full]
28,636117 [dev_pixelpipe] took 0,062 secs (0,058 CPU) processed `input color profile' on GPU, blended on GPU [full]
28,693119 [dev_pixelpipe] took 0,057 secs (0,051 CPU) processed `color balance' on GPU, blended on GPU [full]
28,909157 [dev_pixelpipe] took 0,216 secs (0,099 CPU) processed `local contrast' on GPU, blended on GPU [full]
image colorspace transform Lab-->RGB took 0,013 secs (0,004 GPU) [filmicrgb ]
28,979528 [dev_pixelpipe] took 0,070 secs (0,045 CPU) processed `filmic rgb' on GPU, blended on GPU [full]
image colorspace transform RGB-->Lab took 0,014 secs (0,003 GPU) [colorout ]
29,084148 [dev_pixelpipe] took 0,105 secs (0,077 CPU) processed `output color profile' on GPU, blended on GPU [full]
29,165150 [dev_pixelpipe] took 0,081 secs (0,273 CPU) processed `gamma' on CPU, blended on CPU [full]
29,165247 [opencl_profiling] profiling device 0 ('Quadro M2200'):
29,165251 [opencl_profiling] spent  0,0369 seconds in [Write Image (from host to device)]
29,165254 [opencl_profiling] spent  0,0013 seconds in rawprepare_1f
29,165257 [opencl_profiling] spent  0,4373 seconds in [Read Image (from device to host)]
29,165260 [opencl_profiling] spent  0,0012 seconds in whitebalance_1f
29,165263 [opencl_profiling] spent  0,0013 seconds in highlights_1f_clip
29,165266 [opencl_profiling] spent  0,0037 seconds in ppg_demosaic_green
29,165269 [opencl_profiling] spent  0,0051 seconds in ppg_demosaic_redblue
29,165271 [opencl_profiling] spent  0,0005 seconds in border_interpolate
29,165274 [opencl_profiling] spent  0,0469 seconds in interpolation_resample
29,165276 [opencl_profiling] spent  0,0115 seconds in exposure
29,165279 [opencl_profiling] spent  0,0013 seconds in blendop_mask_rgb
29,165282 [opencl_profiling] spent  0,0039 seconds in guided_filter_split_rgb_image
29,165284 [opencl_profiling] spent  0,3540 seconds in guided_filter_box_mean_x
29,165287 [opencl_profiling] spent  0,0322 seconds in guided_filter_box_mean_y
29,165289 [opencl_profiling] spent  0,0047 seconds in guided_filter_covariances
29,165291 [opencl_profiling] spent  0,0057 seconds in guided_filter_variances
29,165294 [opencl_profiling] spent  0,0186 seconds in guided_filter_update_covariance
29,165297 [opencl_profiling] spent  0,0144 seconds in guided_filter_solve
29,165299 [opencl_profiling] spent  0,0055 seconds in guided_filter_generate_result
29,165302 [opencl_profiling] spent  0,0251 seconds in [Copy Image (on device)]
29,165305 [opencl_profiling] spent  0,0093 seconds in blendop_rgb
29,165307 [opencl_profiling] spent  0,0277 seconds in [Write Buffer (from host to device)]
29,165310 [opencl_profiling] spent  0,0453 seconds in lens_distort_lanczos3
29,165312 [opencl_profiling] spent  0,0059 seconds in flip
29,165315 [opencl_profiling] spent  0,0051 seconds in colorin_unbound
29,165317 [opencl_profiling] spent  0,0056 seconds in colorbalance_cdl
29,165320 [opencl_profiling] spent  0,0048 seconds in pad_input
29,165322 [opencl_profiling] spent  0,0303 seconds in gauss_reduce
29,165325 [opencl_profiling] spent  0,0216 seconds in process_curve
29,165328 [opencl_profiling] spent  0,0269 seconds in laplacian_assemble
29,165330 [opencl_profiling] spent  0,0053 seconds in write_back
29,165333 [opencl_profiling] spent  0,0046 seconds in colorspaces_transform_lab_to_rgb_matrix
29,165335 [opencl_profiling] spent  0,0044 seconds in filmicrgb_chroma
29,165338 [opencl_profiling] spent  0,0046 seconds in colorspaces_transform_rgb_matrix_to_lab
29,165341 [opencl_profiling] spent  0,0128 seconds in colorout
29,165343 [opencl_profiling] spent  1,2254 seconds totally in command queue (with 0 events missing)
29,190170 [dev_process_image] pixel pipeline processing took 2,884 secs (10,174 CPU)
29,368506 [pixelpipe_process] [preview] using device 0
29,369463 [dev_pixelpipe] took 0,001 secs (0,001 CPU) initing base buffer [preview]
29,372028 [dev_pixelpipe] took 0,003 secs (0,003 CPU) processed `raw black/white point' on GPU, blended on GPU [preview]
29,375298 [dev_pixelpipe] took 0,003 secs (0,003 CPU) processed `white balance' on GPU, blended on GPU [preview]
29,378414 [dev_pixelpipe] took 0,003 secs (0,005 CPU) processed `highlight reconstruction' on GPU, blended on GPU [preview]
29,382836 [dev_pixelpipe] took 0,004 secs (0,006 CPU) processed `demosaic' on GPU, blended on GPU [preview]
29,397323 [dev_pixelpipe] took 0,014 secs (0,021 CPU) processed `exposure' on GPU, blended on GPU [preview]
29,465930 [dev_pixelpipe] took 0,068 secs (0,077 CPU) processed `exposure 1' on GPU, blended on GPU [preview]
29,492700 [dev_pixelpipe] took 0,027 secs (0,036 CPU) processed `lens correction' on GPU, blended on GPU [preview]
29,501240 [dev_pixelpipe] took 0,008 secs (0,002 CPU) processed `orientation' on GPU, blended on GPU [preview]
29,512253 [dev_pixelpipe] took 0,011 secs (0,010 CPU) processed `crop and rotate' on GPU, blended on GPU [preview]
29,559845 [dev_pixelpipe] took 0,048 secs (0,245 CPU) processed `tone equalizer' on CPU, blended on CPU [preview]
29,567709 [dev_pixelpipe] took 0,008 secs (0,006 CPU) processed `input color profile' on GPU, blended on GPU [preview]
29,570979 [dev_pixelpipe] took 0,003 secs (0,002 CPU) processed `color balance' on GPU, blended on GPU [preview]
29,593122 [dev_pixelpipe] took 0,022 secs (0,010 CPU) processed `local contrast' on GPU, blended on GPU [preview]
image colorspace transform Lab-->RGB took 0,003 secs (0,001 GPU) [filmicrgb ]
29,602437 [dev_pixelpipe] took 0,009 secs (0,002 CPU) processed `filmic rgb' on GPU, blended on GPU [preview]
image colorspace transform RGB-->Lab took 0,002 secs (0,002 GPU) [colorout ]
29,615794 [dev_pixelpipe] took 0,013 secs (0,009 CPU) processed `output color profile' on GPU, blended on GPU [preview]
29,623257 [dev_pixelpipe] took 0,007 secs (0,021 CPU) processed `gamma' on CPU, blended on CPU [preview]
image colorspace transform RGB-->RGB took 0,013 secs (0,059 CPU) [final histogram]
final histogram took 0,002 secs (0,010 CPU)
29,665210 [opencl_profiling] profiling device 0 ('Quadro M2200'):
29,665220 [opencl_profiling] spent  0,0042 seconds in [Write Image (from host to device)]
29,665243 [opencl_profiling] spent  0,0001 seconds in rawprepare_1f
29,665247 [opencl_profiling] spent  0,0580 seconds in [Read Image (from device to host)]
29,665250 [opencl_profiling] spent  0,0001 seconds in whitebalance_1f
29,665255 [opencl_profiling] spent  0,0001 seconds in highlights_1f_clip
29,665258 [opencl_profiling] spent  0,0003 seconds in ppg_demosaic_green
29,665261 [opencl_profiling] spent  0,0003 seconds in ppg_demosaic_redblue
29,665265 [opencl_profiling] spent  0,0001 seconds in border_interpolate
29,665268 [opencl_profiling] spent  0,0007 seconds in exposure
29,665272 [opencl_profiling] spent  0,0002 seconds in blendop_mask_rgb
29,665275 [opencl_profiling] spent  0,0003 seconds in guided_filter_split_rgb_image
29,665278 [opencl_profiling] spent  0,0253 seconds in guided_filter_box_mean_x
29,665282 [opencl_profiling] spent  0,0055 seconds in guided_filter_box_mean_y
29,665285 [opencl_profiling] spent  0,0003 seconds in guided_filter_covariances
29,665289 [opencl_profiling] spent  0,0004 seconds in guided_filter_variances
29,665292 [opencl_profiling] spent  0,0013 seconds in guided_filter_update_covariance
29,665295 [opencl_profiling] spent  0,0007 seconds in guided_filter_solve
29,665299 [opencl_profiling] spent  0,0003 seconds in guided_filter_generate_result
29,665304 [opencl_profiling] spent  0,0016 seconds in [Copy Image (on device)]
29,665308 [opencl_profiling] spent  0,0005 seconds in blendop_rgb
29,665312 [opencl_profiling] spent  0,0052 seconds in [Write Buffer (from host to device)]
29,665316 [opencl_profiling] spent  0,0032 seconds in lens_distort_lanczos3
29,665319 [opencl_profiling] spent  0,0003 seconds in flip
29,665323 [opencl_profiling] spent  0,0004 seconds in colorin_unbound
29,665326 [opencl_profiling] spent  0,0003 seconds in colorbalance_cdl
29,665329 [opencl_profiling] spent  0,0003 seconds in pad_input
29,665332 [opencl_profiling] spent  0,0027 seconds in gauss_reduce
29,665336 [opencl_profiling] spent  0,0017 seconds in process_curve
29,665339 [opencl_profiling] spent  0,0021 seconds in laplacian_assemble
29,665343 [opencl_profiling] spent  0,0004 seconds in write_back
29,665346 [opencl_profiling] spent  0,0003 seconds in colorspaces_transform_lab_to_rgb_matrix
29,665349 [opencl_profiling] spent  0,0003 seconds in filmicrgb_chroma
29,665353 [opencl_profiling] spent  0,0003 seconds in colorspaces_transform_rgb_matrix_to_lab
29,665357 [opencl_profiling] spent  0,0008 seconds in colorout
29,665361 [opencl_profiling] spent  0,1187 seconds totally in command queue (with 0 events missing)
29,667471 [dev_process_preview] pixel pipeline processing took 0,312 secs (0,576 CPU)

no-issue-activity

Source

aurelienpierre

All 16 comments

Not sure if this is related but several recent builds seem to be very slow moving from image to image in darkroom. If I hit spacebar my screen now goes gray for several seconds and displays the working message. The same if I now go back using backspace. Nothing seems cached and it seems to be running something each time. In lighttable I can move quickly image to image and back. This happens with only one or two modules added . I will perhaps try a systematic approach but I tested it with a fresh empty library and database so I don't think any issues there. I just imported a folder of about 60 images and noticed this seems to be the behaviour. Any suggestions for a strategy to troubleshoot this would be welcome....

todd-prior on 6 Feb 2020

Tracing other points I've found this (nb = imgid) EDIT: each time I open an image in darkroom:

dt_view_manager_switch_by_view (enter)
enter 7949
dt_dev_load_image 7949
dt_dev_read_history_ext 7949

_lib_duplicate_init_callback (dt_image_get_final_size)
dt_image_get_final_size 7949
dt_dev_load_image 7949
dt_dev_read_history_ext 7949

I think that the second thread should be avoided in some way.

phweyland on 20 Feb 2020

@phweyland You may be on to something....

todd-prior on 20 Feb 2020

yes, I've seen that...
...and already fixed it in my lighttable rewrite (lib duplicate has needed some cleanup during the process)
if you prefer, we can fix it in master and I'll take care of the rebasing in my branch...

Just to be clear, I've move the final size computation in the button_press routine, and so avoid some unnecessary pipe firing.

AlicVB on 20 Feb 2020

if you prefer, we can fix it in master and I'll take care of the rebasing in my branch...

Just to be clear, I've move the final size computation in the button_press routine, and so avoid some unnecessary pipe firing.

Sounds good for me.
I was wondering if we could maintain in the dev environment the sizes available but I don't master this enough. If I've understood correctly the duplicate part, the size computation is called (always) for the current dev image...
But limiting this when the user presses the button that's great.

phweyland on 20 Feb 2020

The issue described here is affecting the darkroom, and it has been on for quite at least 6 months.

aurelienpierre on 20 Feb 2020

👍1

Yes I know :)
In fact, during the lighttable rewrite, I've changed things inside the duplicate lib (which is in darkroom). Originally, that was just a matter of using the new code for the thumbnails, but at the end, I've been "forced" to fix other things around...

Now maybe that'll not fix completely your issue, but at least that reduce unneeded full pipe computation.

That said, ideally (and maybe it's already the case) dt_image_get_final_size should fire a "size only" pipe with just ROI computation, and not the process_*

AlicVB on 21 Feb 2020

👍1

if you prefer, we can fix it in master and I'll take care of the rebasing in my branch...

Do you plan to do it ?
If not which branch should I look at in your repository to reproduce it ?

phweyland on 24 Feb 2020

it's here : https://github.com/AlicVB/darktable/tree/filemanager2 but beware that the branch (lighttable rewrite) is still WIP and you may face other bugs when testing...
The specific commit is a444f836277ee30f51ab4ab6535b553c9d2e990d if you want to have a look at the code

AlicVB on 24 Feb 2020

👍1

it's here : https://github.com/AlicVB/darktable/tree/filemanager2 but beware that the branch (lighttable rewrite) is still WIP and you may face other bugs when testing...
The specific commit is a444f83 if you want to have a look at the code

Excellent ! I'll try a git cherry-pick !

phweyland on 25 Feb 2020

Thanks for sharing...

Sent from
Mail for Windows 10

From: Philippe
Sent: February 25, 2020 7:56 AM
To: darktable-org/darktable
Cc: Prior,Todd;
Comment
Subject: Re: [darktable-org/darktable] pixelpipe fired twice when opening darkroom (#4232)

Excellent ! I'll try a git cherry-pick !
—
You are receiving this because you commented.
Reply to this email directly,
view it on GitHub, or
unsubscribe.

todd-prior on 25 Feb 2020

I've tried the cherry-pick but it brings more code than your changes shown in the specified commit.
Then I'll try to understand your changes and mimic them as far as possible.

phweyland on 26 Feb 2020

I'm not sure of what you want to achieve : is that just for testing or do you want to incorporate the fix in a PR ?

I'm not sure that second option is good, as we'll end with 2 times the same change in different branch, with merge conflict in the 2 cases... maybe better try directly PR #4370
Now if it's just for testing, the idea of the change is to only call dt_image_get_final_size in_lib_duplicate_thumb_press_callback if d->cur_final_width <= 0. And to force recomputation (in case of image change, ...) we just have to set d->cur_final_width to 0

AlicVB on 26 Feb 2020

My intention was to fix this in a PR. I've just pushed it to my repository (https://github.com/phweyland/darktable/tree/double-fire) but not yet issued the PR.

I have really copied the minimum of lines from your code to make it work. As far as I can see that actually avoids double fire when opening an image in darkroom.

As this is a strict copy of your code, this should not be a problem to rebase your PR as you have suggested earlier.

At the end I don't want to difficult your work, especially if your PR is merged soon :)
Just let me know. I can issue the PR though and let the team decide what to do with it.

phweyland on 26 Feb 2020

ok, no pb, it's just a very simple commit with only my changes, so rebasing shouldn't be hard anyway !
(and if you plan to PR this commit alone, it should land in master before mine, considering the amount of change)

AlicVB on 26 Feb 2020

👍1

This issue did not get any activity in the past 30 days and will be closed in 365 days if no update occurs. Please check if the master branch has fixed it and report again or close the issue.