darktable-org / darktable

darktable is an open source photography workflow application and raw developer
https://www.darktable.org
GNU General Public License v3.0
9.66k stars 1.13k forks source link

darktable crashes after selecting 'orginal' in history stack #13535

Closed andabata closed 1 year ago

andabata commented 1 year ago

darktable 4.3.0+434~g8bcaea3-dirty

It crashes randomly whilst re-editing old shots, and selecting 'orginal' in the history stack. I can't trigger reliably but it happened about 4 a 5 times in a row. darktable didn't write anything to the crashlog in /tmp -rw------- 1 kg kg 0 Feb 5 13:57 darktable_bt_1RZEZ1.txt

@AxelG-DE was able to reproduce it and has output from running it -d all

AxelG-DE commented 1 year ago

yes, I can reproduse and here is my output. 20230205_crash_No1.txt 20230205_crash_No2.txt

As both crashes have something to do with tiling, I wonder if @jenshannoschwalm could have a smell about it? If not, sorry for the noise.

ralfbrown commented 1 year ago

Looks like the root cause is a ROI of zero by zero pixels.... Maybe some variable(s) not being properly reinitialized on resetting the history? Modules 'temperature' and 'highlights' have no problem with the empty buffer, but then 'demosaic' blows up.

jenshannoschwalm commented 1 year ago

It's not the tiling code running wild. The roi out dimension should never be 0x0

jenshannoschwalm commented 1 year ago

@TurboGit i just observed "something" that could trigger such a problem.

  1. I use rawprepare presets for my camera to extend the rawprepare area but have to set whitepoints depending on ISO
  2. thus i had defined right now two new presets here (not in auto mode), one for ISO <60 and one for above
  3. I selected images with ISO 50 and copy&pasted rawprepare (the source was used to define the new preset)
  4. select others and also copy&pasted rawprepare (again source was used for the new preset)

Then the interesting thing happened (i had the module expanded) and clicked the default module button & voila, i suddenly had the lower and right crop values as full width&height of the image. (the alternate way resetting to as-fresh-import worked fine)

Now - without any further intervention - works again as wanted. Does this trigger anything?

TurboGit commented 1 year ago

Now - without any further intervention - works again as wanted. Does this trigger anything?

Really strange. At least all goes well for the 1, 2, 3, & 4 steps above. So the preset is properly applied.

Maybe an issue with rawprepare reloaddefaults using crop{x,y,width,height}. Maybe there is some kind of race condition on this part?

wpferguson commented 1 year ago

I've had this occur once, but wasn't able to reproduce. I've also seen just a black screen instead of image data without the crash.

jenshannoschwalm commented 1 year ago

I've also seen just a black screen instead of image data without the crash.

Me too. Just couldn't reproduce

jenshannoschwalm commented 1 year ago

13521could basically be the same issue.

Maybe there is some kind of race condition on this part?

relies on proper image.h struct data available ?

andabata commented 1 year ago

I think found a way to reproduce this one. in darkroom, select original in the history stack, use space to go the next image, go back with backspace. wait a bit and it crashes.

log.txt

ptilopteri commented 1 year ago

confirmed, coredump @ http://wahoo.no-ip/org/~paka/core.darktable.1000.2928c7c465a14fcba40801555cafa625.19291.1675711407000000.zst

TurboGit commented 1 year ago

I think found a way to reproduce this one. in darkroom, select original in the history stack, use space to go the next image, go back with backspace. wait a bit and it crashes.

Did that at least 10 times, no crash. Is that with JPEG, RAW? Any context to share?

andabata commented 1 year ago

raws, canon 7d cr2's to be precise. I been re-editing old shots (2019)

andabata commented 1 year ago

https://shell.kees.nl/out.ogv as an example how i did it.

wpferguson commented 1 year ago

I got different symptoms (hang instead of crash).

My image was a fresh cr3, just imported. I edited it, went to lighttable, then reopened the image, selected original, and discarded the history.

This printed on the console

darktable:256526): GLib-ERROR **: 22:38:34.349: ../../../glib/gmem.c:167: failed to allocate 18446744073662794820 bytes

Seems a bit much for a 32mp image (EOS R7).

Modules I used (scene referred workflow)

Edited it again to make sure I had the correct list of modules, then for grins I went back to lighttable, then back to the image. I selected original and it crashed. Console showed the same memory allocation error and this time it dumped core. Unfortunately I don't have coredumps enabled (yet).

Another data point. Enabled core dumps. Started darktable and opened the same image, which still had the edits. Selected original which worked fine. Discarded history which worked fine. Went to lighttable. Reopened the image in darkroom. Selected original and got another crash with the same memory error. Tried to do a backtrace but it complained about not being able to read memory at a certain location in the coredump.

Another data point. Opened an unedited image that was newly imported. Selected original and discarded the history stack. Went to lighttable, then reopened the image in darkroom. Selected original. Saw an error message flash about RCD area too small and then got what looks like a 9x12 pixel scaled to fit the screen

rcd size tool small

I've attached the image that gave the memory error along with the style and presets I used. The style adds a lot of turned off modules.

Oops file was too big. Here's a link to it, https://drive.google.com/file/d/1AKP9zOCZcRQVyyan0Ck8RFidhcNqKAu_/view?usp=share_link

Load the presets

Open the image

Apply the style

Turn on the modules I listed above

Go to lighttable

Reopen the image

Select original

System Info Intel 12900HX Nvidia 3070 driver 525.78 32GB RAM Ubuntu 22.04 OpenCL Yes 4k display

wpferguson commented 1 year ago

More data

@jenshannoschwalm

Tried the rcd_demosaic too small area (see above) while running -d all and got

   20.6112 [opencl memory] device 0: 352 bytes (0.0 MB) in use
    20.6112 [dev_pixelpipe] took 0.001 secs (0.000 CPU) [full] processed `highlight reconstruction' on GPU, blended on GPU
    20.6113 [dev_pixelpipe] module `highlight reconstruction' min: (0.012810) max: (0.141631) [full]
    20.6113 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    20.6116 [default_process_tiling_cl_roi] [full] **** tiling module 'demosaic' for image with input size 11x8 --> 2812x1875
    20.6116 [default_process_tiling_cl_roi] [full] aborted tiling for module 'demosaic'. too many tiles: 2812x1875
    20.6117 [opencl_pixelpipe] [full] could not run module `demosaic' on gpu. falling back to cpu path
    20.6117 [process TILE]               [full]         demosaic             (   0/   0)   11x   8 scale=1.0000 --> (   0/   0) 2812x1875 scale=234.3750 
    20.6117 [default_process_tiling_roi] [full] **** tiling module 'demosaic' for image input size 11x8 --> 2812x1875
    20.6117 [default_process_tiling_roi] [full] (1x1) tiles with max dimensions 2812x1875, good 2814x1876, overlap 12->2813
    20.6117 [default_process_tiling_roi] [full] process tile (0,0) size 11x8 at origin [0,0]
    20.6119 [demosaic] process CPU `RCD' did 0.00mpix, 0.0000 secs (0.0000 CPU), 4.63 pix/us
    20.6119 [clip_and_zoom_roi]          [full]         demosaic             (   0/   0)   11x   8 scale=1.0000 --> (   0/   0) 2812x1875 scale=234.3750 
    20.6393 [histogram] took 0.001 secs (0.003 CPU) scope draw
    20.9140 [resample_sse] plan 0.000 secs (0.000 CPU) resample 0.302 secs (4.658 CPU)
    20.9228 [dev_pixelpipe] took 0.311 secs (4.725 CPU) [full] processed `demosaic' on CPU with tiling, blended on CPU
    20.9708 [dev_pixelpipe] module `demosaic' min: (0.000000; 0.000000; 0.000000) max: (2202801869807110038669743882240.000000; 0.000000; 105362121255486862236271408840704.000000) [full]
wpferguson commented 1 year ago

And here's the output from the memory allocation crash, taken from after the image loaded


    51.8302 [opencl_profiling] spent  0.0001 seconds in colorout
    51.8302 [opencl_profiling] spent  0.1887 seconds totally in command queue (with 0 events missing)
    51.8304 [cache report]               [preview]                            12 lines (important=4, used=12). Used 186MB, limit=0MB. Hitrate=0.00
    51.8304 [modify roi OUT]             [full]         rawprepare           (   0/   0) 7128x4732 scale=1.0000 --> (   0/   0) 6960x4640 scale=1.0000 
    51.8304 [modify roi OUT]             [full]         ashift               (   0/   0) 6960x4640 scale=1.0000 --> (   0/   0) 6431x4288 scale=1.0000 
    51.8304 [modify roi OUT]             [full]         flip                 (   0/   0) 6431x4288 scale=1.0000 --> (   0/   0) 4288x6431 scale=1.0000 
    51.8305 [dev_process_preview] pixel pipeline processing took 0.504 secs (0.869 CPU)
    51.8305 [run_job-] 01 385136974.975176     51.8305 develop process preview | queue: 0 | priority: 0    51.8305 
    51.8425 [histogram] took 0.001 secs (0.001 CPU) scope draw
    51.8635 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8637 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8638 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8638 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8638 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8639 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8639 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8639 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8639 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8640 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8640 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8640 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8641 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        OR op_params IS NULL)   AND blendop_params = ?3"
    51.8641 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8641 [sql] /home/bill/src/darktable/darktable/src/common/presets.c:345, function dt_presets_get_name(): prepare "SELECT name FROM data.presets WHERE operation = ?1   AND (op_params = ?2        )   AND blendop_params = ?3"
    51.8767 [histogram] took 0.001 secs (0.000 CPU) scope draw
    51.9355 [sql] /home/bill/src/darktable/darktable/src/common/film.c:527, function dt_film_set_folder_status(): prepare "DELETE FROM memory.film_folder"
    51.9355 [sql] /home/bill/src/darktable/darktable/src/common/film.c:533, function dt_film_set_folder_status(): prepare "SELECT id, folder FROM main.film_rolls"
    51.9355 [sql] /home/bill/src/darktable/darktable/src/common/film.c:538, function dt_film_set_folder_status(): prepare "INSERT INTO memory.film_folder (id, status) VALUES (?1, ?2)"
    51.9360 [sql] /home/bill/src/darktable/darktable/src/libs/collect.c:2000, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count, status FROM main.images AS mi JOIN (SELECT fr.id AS film_rolls_id, folder, status       FROM main.film_rolls AS fr        JOIN memory.film_folder AS ff        ON ff.id = fr.id)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
    51.9484 [sql] /home/bill/src/darktable/darktable/src/common/film.c:527, function dt_film_set_folder_status(): prepare "DELETE FROM memory.film_folder"
    51.9485 [sql] /home/bill/src/darktable/darktable/src/common/film.c:533, function dt_film_set_folder_status(): prepare "SELECT id, folder FROM main.film_rolls"
    51.9485 [sql] /home/bill/src/darktable/darktable/src/common/film.c:538, function dt_film_set_folder_status(): prepare "INSERT INTO memory.film_folder (id, status) VALUES (?1, ?2)"
    51.9487 [sql] /home/bill/src/darktable/darktable/src/libs/collect.c:2000, function list_view(): prepare "SELECT folder, film_rolls_id, COUNT(*) AS count, status FROM main.images AS mi JOIN (SELECT fr.id AS film_rolls_id, folder, status       FROM main.film_rolls AS fr        JOIN memory.film_folder AS ff        ON ff.id = fr.id)   ON film_id = film_rolls_id  WHERE (1=1) GROUP BY folder ORDER BY film_rolls_id DESC"
    57.3051 [sql] /home/bill/src/darktable/darktable/src/common/image_cache.c:253, function dt_image_cache_write_release(): prepare "UPDATE main.images SET width = ?1, height = ?2, filename = ?3, maker = ?4, model = ?5,     lens = ?6, exposure = ?7, aperture = ?8, iso = ?9, focal_length = ?10,     focus_distance = ?11, film_id = ?12, datetime_taken = ?13, flags = ?14,     crop = ?15, orientation = ?16, raw_parameters = ?17, group_id = ?18,     longitude = ?19, latitude = ?20, altitude = ?21, color_matrix = ?22,     colorspace = ?23, raw_black = ?24, raw_maximum = ?25,     aspect_ratio = ROUND(?26,1), exposure_bias = ?27,     import_timestamp = ?28, change_timestamp = ?29, export_timestamp = ?30,     print_timestamp = ?31, output_width = ?32, output_height = ?33 WHERE id = ?34"
    57.3058 [noiseprofile] looking for maker `Canon', model `EOS R7'
    57.3058 [noiseprofile] found 18 makers
    57.3058 [noiseprofile] found `Canon' as `Canon'
    57.3058 [noiseprofile] found 85 models
    57.3059 [noiseprofile] found EOS R7
    57.3059 [noiseprofile] found 27 profiles
    57.3105 [modify roi OUT]             [full]         rawprepare           (   0/   0) 7128x4732 scale=1.0000 --> (   0/   0) 6960x4640 scale=1.0000 
    57.3105 [modify roi OUT]             [full]         ashift               (   0/   0) 6960x4640 scale=1.0000 --> (   0/   0) 6431x4288 scale=1.0000 
    57.3105 [modify roi OUT]             [full]         flip                 (   0/   0) 6431x4288 scale=1.0000 --> (   0/   0) 4288x6431 scale=1.0000 
    57.3105 [sql] /home/bill/src/darktable/darktable/src/libs/ioporder.c:87, function update(): prepare "SELECT op_params, name FROM data.presets WHERE operation='ioporder' ORDER BY writeprotect DESC"
    57.3159 [undo] record for type 2 (length 1)
    57.3213 [lib_modulegroups_update_iop_visibility] modulegroups
    57.3213           rawprepare 1    57.3213          temperature 3    57.3213           highlights 4    57.3213             demosaic 8    57.3213                 flip 19    57.3214              colorin 33    57.3214             colorout 102    57.3214           finalscale 104, hidden    57.3214          overexposed 105, hidden    57.3214       rawoverexposed 106, hidden    57.3214                gamma 110, hidden    57.3329 [histogram] took 0.001 secs (0.001 CPU) scope draw
    57.3402 [add_job_res] 0 |     57.3402 develop process image | queue: 0 | priority: 0    57.3402 
    57.3402 [add_job_res] 1 |     57.3402 develop process preview | queue: 0 | priority: 0    57.3402 
    57.3403 [run_job+] 01 385136980.485014     57.3403 develop process preview | queue: 0 | priority: 0    57.3403 
    57.3403 [run_job+] 00 385136980.485017     57.3404 develop process image | queue: 0 | priority: 0    57.3404 
    57.3404 [pixelpipe] [preview] pipeline state changing, flag 2
    57.3404 [dt_dev_process_image_job] loading image. took 0.000 secs (0.000 CPU)
    57.3427 [pixelpipe] [preview] synch all modules with defaults_params
    57.3427 [sql] /home/bill/src/darktable/darktable/src/common/image_cache.c:253, function dt_image_cache_write_release(): prepare "UPDATE main.images SET width = ?1, height = ?2, filename = ?3, maker = ?4, model = ?5,     lens = ?6, exposure = ?7, aperture = ?8, iso = ?9, focal_length = ?10,     focus_distance = ?11, film_id = ?12, datetime_taken = ?13, flags = ?14,     crop = ?15, orientation = ?16, raw_parameters = ?17, group_id = ?18,     longitude = ?19, latitude = ?20, altitude = ?21, color_matrix = ?22,     colorspace = ?23, raw_black = ?24, raw_maximum = ?25,     aspect_ratio = ROUND(?26,1), exposure_bias = ?27,     import_timestamp = ?28, change_timestamp = ?29, export_timestamp = ?30,     print_timestamp = ?31, output_width = ?32, output_height = ?33 WHERE id = ?34"
    57.3429 [dt_iop_commit_params] [preview] committed for rawprepare with hash 11529353175976843138
    57.3429 validation check failed in _iop_validate_params for type "float", field: g2
    57.3429 validation check failed in _iop_validate_params for type "dt_iop_temperature_params_t"
    57.3429 [dt_iop_commit_params] [preview] committed for temperature with hash 1915786779934438022
    57.3429 [dt_iop_commit_params] [preview] committed for highlights with hash 3307084630505009048
    57.3437 [dt_iop_commit_params] [preview] committed for demosaic with hash 12713709861679059410
    57.3437 [noiseprofile] looking for maker `Canon', model `EOS R7'
    57.3437 [noiseprofile] found 18 makers
    57.3437 [noiseprofile] found `Canon' as `Canon'
    57.3437 [noiseprofile] found 85 models
    57.3438 [noiseprofile] found EOS R7
    57.3438 [noiseprofile] found 27 profiles
    57.3445 [dt_iop_commit_params] [preview] committed for flip with hash 6381475781
    57.3470 [dt_iop_commit_params] [preview] committed for colorin with hash 8458784419482823018
    57.3584 [sql] /home/bill/src/darktable/darktable/src/common/image.c:285, function dt_image_film_roll(): prepare "SELECT folder FROM main.film_rolls WHERE id = ?1"
    57.3585 [sql] /home/bill/src/darktable/darktable/src/common/image.c:356, function dt_image_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id and i.id = ?1"
    57.3587 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/metadata.c:487, function dt_metadata_get(): prepare "SELECT value FROM main.meta_data WHERE id = ?1 AND key = ?2 ORDER BY value"
    57.3588 [sql] /home/bill/src/darktable/darktable/src/common/tags.c:635, function dt_tag_get_attached(): prepare "SELECT DISTINCT I.tagid, T.name, T.flags, T.synonyms, COUNT(DISTINCT I.imgid) AS inb FROM main.tagged_images AS I JOIN data.tags AS T ON T.id = I.tagid WHERE I.imgid IN (125515) AND T.id NOT IN memory.darktable_tags GROUP BY I.tagid  ORDER by T.name"
    57.3589 [sql] /home/bill/src/darktable/darktable/src/common/tags.c:635, function dt_tag_get_attached(): prepare "SELECT DISTINCT I.tagid, T.name, T.flags, T.synonyms, COUNT(DISTINCT I.imgid) AS inb FROM main.tagged_images AS I JOIN data.tags AS T ON T.id = I.tagid WHERE I.imgid IN (125515) AND T.id NOT IN memory.darktable_tags GROUP BY I.tagid  ORDER by T.name"
    57.3611 [dt_iop_commit_params] [preview] committed for colorout with hash 10257528088492143908
    57.3611 validation check failed in _iop_validate_params for type "float", field: aspect
    57.3611 validation check failed in _iop_validate_params for type "dt_iop_borders_params_t"
    57.3611 [dt_iop_commit_params] [preview] committed for gamma with hash 7567884774754821
    57.3650 [pixelpipe] [preview] synch all modules with history
    57.3650 [modify roi OUT]             [preview]      rawprepare           (   0/   0) 1355x 900 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3650 [modify roi OUT]             [preview]      flip                 (   0/   0)  510x-338 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3650 [pixelpipe] [full] pipeline state changing, flag 2
    57.3650 [pixelpipe_cache_checkmem]   [preview]                            12 lines (important=4, used=12). Cache: freed=0MB (bad=0 low=0 high=0). Now using 186MB, limit=0MB
    57.3650 [memory] before pixelpipe process
    57.3651 [memory] max address space (vmpeak):    13109336 kB
[memory] cur address space (vmsize):     9690320 kB
[memory] max used memory   (vmhwm ):     2102808 kB
[memory] cur used memory   (vmrss ):     1321272 kB
    57.3651 [modify roi IN]              [preview]      flip                 (   0/   0)  510x-338 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3651 [modify roi IN]              [preview]      rawprepare           (   0/   0) 1355x 900 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3651 [dev_pixelpipe] took 0.000 secs (0.000 CPU) initing base buffer [preview]
    57.3657 [opencl memory] device 0: 2439000 bytes (2.3 MB) in use
    57.3662 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3662 [opencl memory] device 0: 2439000 bytes (2.3 MB) in use
    57.3662 [opencl_pixelpipe] [preview] couldn't allocate output buffer for module `rawprepare'
    57.3665 [opencl_pixelpipe] [preview] could not run module `rawprepare' on gpu. falling back to cpu path
    57.3669 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3669 [pixelpipe_process_on_CPU]   [preview]      rawprepare           (   0/   0) 1355x 900 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3670 [dev_pixelpipe] took 0.001 secs (0.003 CPU) [preview] processed `raw black/white point' on CPU, blended on CPU
    57.3670 [dev_pixelpipe] module `raw black/white point' min: (340282346638528859811704183484516925440.000000) max: (0.000000) [preview]
    57.3679 [default_process_tiling_cl_ptp] [preview] **** tiling module 'temperature' for image with size 510x-338 --> 510x-338
    57.3679 [default_process_tiling_cl_ptp] [preview] (1x1) tiles with max dimensions 510x-338, pinned=OFF, good 510x1 and overlap 0
    57.3679 [default_process_tiling_cl_ptp] [preview] tile (0,0) size 510x18446744073709551278 at origin [0,0]
    57.3679 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3679 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3679 [default_process_tiling_opencl_ptp] [preview] couldn't run process_cl() for module 'temperature' in tiling mode: DT_OPENCL_DEFAULT_ERROR
    57.3679 [opencl_pixelpipe] [preview] could not run module `temperature' on gpu. falling back to cpu path
    57.3679 [pixelpipe_process_on_CPU]   [preview]      temperature          (   0/   0)  510x-338 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3679 [dev_pixelpipe] took 0.000 secs (0.000 CPU) [preview] processed `white balance' on CPU, blended on CPU
    57.3679 [dev_pixelpipe] module `white balance' min: (340282346638528859811704183484516925440.000000) max: (0.000000) [preview]
    57.3683 [default_process_tiling_cl_ptp] [preview] **** tiling module 'highlights' for image with size 510x-338 --> 510x-338
    57.3683 [default_process_tiling_cl_ptp] [preview] (1x1) tiles with max dimensions 510x-338, pinned=OFF, good 510x1 and overlap 0
    57.3683 [default_process_tiling_cl_ptp] [preview] tile (0,0) size 510x18446744073709551278 at origin [0,0]
    57.3683 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3683 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3683 [default_process_tiling_opencl_ptp] [preview] couldn't run process_cl() for module 'highlights' in tiling mode: DT_OPENCL_DEFAULT_ERROR
    57.3683 [opencl_pixelpipe] [preview] could not run module `highlights' on gpu. falling back to cpu path
    57.3683 [pixelpipe_process_on_CPU]   [preview]      highlights           (   0/   0)  510x-338 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3684 [dev_pixelpipe] took 0.000 secs (0.002 CPU) [preview] processed `highlight reconstruction' on CPU, blended on CPU
    57.3684 [dev_pixelpipe] module `highlight reconstruction' min: (340282346638528859811704183484516925440.000000) max: (0.000000) [preview]
    57.3687 [default_process_tiling_cl_ptp] [preview] **** tiling module 'demosaic' for image with size 510x-338 --> 510x-338
    57.3687 [default_process_tiling_cl_ptp] [preview] (1x1) tiles with max dimensions 510x-338, pinned=OFF, good 490x1 and overlap 10
    57.3687 [default_process_tiling_cl_ptp] [preview] tile (0,0) size 510x18446744073709551278 at origin [0,0]
    57.3687 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3687 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3687 [default_process_tiling_opencl_ptp] [preview] couldn't run process_cl() for module 'demosaic' in tiling mode: DT_OPENCL_DEFAULT_ERROR
    57.3687 [opencl_pixelpipe] [preview] could not run module `demosaic' on gpu. falling back to cpu path
    57.3687 [pixelpipe_process_on_CPU]   [preview]      demosaic             (   0/   0)  510x-338 scale=1.0000 --> (   0/   0)  510x-338 scale=1.0000 
    57.3687 [dev_pixelpipe] took 0.000 secs (0.000 CPU) [preview] processed `demosaic' on CPU, blended on CPU
    57.3687 [dev_pixelpipe] module `demosaic' min: (340282346638528859811704183484516925440.000000; 0.000000; 0.000000) max: (0.000000; 0.000000; 0.000000) [preview]
    57.3687 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3687 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3687 [opencl_pixelpipe] [preview] couldn't generate input buffer for module `flip'
    57.3688 [pixelpipe] [full] synch all modules with defaults_params
    57.3688 [dt_iop_commit_params] [full] committed for rawprepare with hash 11529353175976843138
    57.3688 validation check failed in _iop_validate_params for type "float", field: g2
    57.3688 validation check failed in _iop_validate_params for type "dt_iop_temperature_params_t"
    57.3688 [dt_iop_commit_params] [full] committed for temperature with hash 1915786779934438022
    57.3688 [dt_iop_commit_params] [full] committed for highlights with hash 3307084630505009048
    57.3690 [opencl_pixelpipe] [preview] could not run module `flip' on gpu. falling back to cpu path
    57.3690 [pixelpipe_process_on_CPU]   [preview]      flip                 (   0/   0)  510x-338 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3690 [dev_pixelpipe] took 0.000 secs (0.001 CPU) [preview] processed `orientation autodetect' on CPU, blended on CPU
    57.3690 [dev_pixelpipe] module `orientation autodetect' min: (340282346638528859811704183484516925440.000000; 0.000000; 0.000000) max: (0.000000; 0.000000; 0.000000) [preview]
    57.3693 [default_process_tiling_cl_ptp] [preview] **** tiling module 'colorin' for image with size -338x510 --> -338x510
    57.3693 [default_process_tiling_cl_ptp] [preview] (1x1) tiles with max dimensions -338x510, pinned=OFF, good 1x510 and overlap 0
    57.3693 [default_process_tiling_cl_ptp] [preview] tile (0,0) size 18446744073709551278x510 at origin [0,0]
    57.3693 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3693 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3693 [dt_iop_commit_params] [full] committed for demosaic with hash 12713709861679059410
    57.3693 [default_process_tiling_opencl_ptp] [preview] couldn't run process_cl() for module 'colorin' in tiling mode: DT_OPENCL_DEFAULT_ERROR
    57.3693 [opencl_pixelpipe] [preview] could not run module `colorin' on gpu. falling back to cpu path
    57.3693 [noiseprofile] looking for maker `Canon', model `EOS R7'
    57.3693 [pixelpipe_process_on_CPU]   [preview]      colorin              (   0/   0) -338x 510 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3694 [dev_pixelpipe] took 0.000 secs (0.001 CPU) [preview] processed `input color profile' on CPU, blended on CPU
    57.3694 [noiseprofile] found 18 makers
    57.3694 [dev_pixelpipe] module `input color profile' min: (340282346638528859811704183484516925440.000000; 0.000000; 0.000000) max: (0.000000; 0.000000; 0.000000) [preview]
    57.3694 [noiseprofile] found `Canon' as `Canon'
    57.3694 [noiseprofile] found 85 models
    57.3694 [noiseprofile] found EOS R7
    57.3694 [noiseprofile] found 27 profiles
    57.3697 [default_process_tiling_cl_ptp] [preview] **** tiling module 'colorout' for image with size -338x510 --> -338x510
    57.3697 [default_process_tiling_cl_ptp] [preview] (1x1) tiles with max dimensions -338x510, pinned=OFF, good 1x510 and overlap 0
    57.3697 [default_process_tiling_cl_ptp] [preview] tile (0,0) size 18446744073709551278x510 at origin [0,0]
    57.3697 [opencl alloc_device] could not alloc img buffer on device 0: CL_INVALID_IMAGE_SIZE
    57.3697 [opencl memory] device 0: 0 bytes (0.0 MB) in use
    57.3697 [default_process_tiling_opencl_ptp] [preview] couldn't run process_cl() for module 'colorout' in tiling mode: DT_OPENCL_DEFAULT_ERROR
    57.3697 [opencl_pixelpipe] [preview] could not run module `colorout' on gpu. falling back to cpu path
    57.3697 [pixelpipe_process_on_CPU]   [preview]      colorout             (   0/   0) -338x 510 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3697 [dev_pixelpipe] took 0.000 secs (0.001 CPU) [preview] processed `output color profile' on CPU, blended on CPU
    57.3697 [dev_pixelpipe] module `output color profile' min: (340282346638528859811704183484516925440.000000; 0.000000; 0.000000) max: (0.000000; 0.000000; 0.000000) [preview]
    57.3697 [pixelpipe_process_on_CPU]   [preview]      gamma                (   0/   0) -338x 510 scale=1.0000 --> (   0/   0) -338x 510 scale=1.0000 
    57.3697 [dev_pixelpipe] took 0.000 secs (0.000 CPU) [preview] processed `display encoding' on CPU, blended on CPU
    57.3697 [opencl_profiling] profiling device 0 ('NVIDIA GeForce RTX 3070 Ti Laptop GPU'):
    57.3697 [opencl_profiling] spent  0.0002 seconds in [Write Image (from host to device)]
    57.3697 [opencl_profiling] spent  0.0002 seconds in [Read Image (from device to host)]
    57.3697 [opencl_profiling] spent  0.0004 seconds totally in command queue (with 0 events missing)

(darktable:313589): GLib-ERROR **: 23:43:00.514: ../../../glib/gmem.c:167: failed to allocate 18446744073708862096 bytes
/home/bill/bin/darktable43: line 1: 313589 Trace/breakpoint trap   (core dumped) /opt/darktable43/bin/darktable -d lua --cachedir $HOME/.cache/darktable43 --configdir $HOME/.config/darktable43 $@
jenshannoschwalm commented 1 year ago

Again this hints to a problem in rawprepare. I am already working on this :-)

wpferguson commented 1 year ago

Just tried with #13557

This was the unedited image, select oroginal, discard, lighttable, reopen image, select original - resulted in crash with huge memory allocation

    29.0186 [rawprepare] got wrong crop parameters left=156, right=4640, top=84, bottom=6960 for size=7128x4732
    29.0187 Trouble: [raw black/white point] invalid crop parameters (105EOSR7_2R4A4324.cr3 125518)
    29.0434 LUA caught pixelpipe-processing-complete
    29.0747 [rawprepare] got wrong crop parameters left=156, right=4640, top=84, bottom=6960 for size=7128x4732
    29.0748 Trouble: [raw black/white point] invalid crop parameters (105EOSR7_2R4A4324.cr3 125518)
    31.3018 [rawprepare] got wrong crop parameters left=156, right=4640, top=84, bottom=6960 for size=7128x4732
    31.3019 Trouble: [raw black/white point] invalid crop parameters (105EOSR7_2R4A4324.cr3 125518)
    31.3198 [rawprepare] got wrong crop parameters left=156, right=4640, top=84, bottom=6960 for size=7128x4732
    31.3199 Trouble: [raw black/white point] invalid crop parameters (105EOSR7_2R4A4324.cr3 125518)
jenshannoschwalm commented 1 year ago

That gets interesting. At least we now know there is something strange happening while presenting the sensor data to rawprepare.

  1. What happens if you disable lua?
  2. Can you confirm at least the correctness of the sensor size?

@kmilos any idea about something specific to CR3 ?

kmilos commented 1 year ago

any idea about something specific to CR3 ?

Don't know, we get crop parameters straight from LibRaw...

Looks to be portrait/landscape mixup somehow?

Perhaps we should be using different fields: https://www.libraw.org/docs/API-datastruct-eng.html#libraw_image_sizes_t

Although @andabata mentioned it happens with CR2s (and therefore rawspeed) as well, no?

TurboGit commented 1 year ago

@kmilos :

img->crop_width = raw->rawdata.sizes.raw_width - ric->cwidth - ric->cleft;

The LibRaw doc is not clear but is cwidth the width of the cropped image or the number of right pixels cropped?

wpferguson commented 1 year ago

What happens if you disable lua?

No difference, still crashes with same errors

Can you confirm at least the correctness of the sensor size?

Published resolution is 6960 x 4640

kmilos commented 1 year ago

The LibRaw doc is not clear but is cwidth the width of the cropped image or the number of right pixels cropped?

This was (I think?) copied/transferred from very ancient imageio_libraw code somehow... I haven't checked LibRaw implementation details, so there is a possibility something is wrong here.

Again, doesn't explain failures w/ CR2s though...

wpferguson commented 1 year ago

It also has something to do with leaving the image after resetting the history. If I select an image, I can keep resetting the history without a problem. When I go to the next image and then come back and select original I get a crash.

Is something not getting saved properly (or cleaned up) when I leave the image?

kmilos commented 1 year ago

It also has something to do with leaving the image after resetting the history.

Cf. again the apparent portrait/landscape mixup?

wpferguson commented 1 year ago

The image is in portrait mode, so the numbers are correct with respect to the orientation. I'll try with landscape oriented pictures.

wpferguson commented 1 year ago

Doesn't happen with landscape orientation

TurboGit commented 1 year ago

@wpferguson : Definitely a good hint that there is a mixing width/height missing an orientation adjustment probably.

andabata commented 1 year ago

It's still crashing for me.

(landscape) [rawspeed_open] extensions list to ignore: `cr3' 14.1372 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 14.1372 Trouble: [raw black/white point] invalid crop parameters (IMG_7460.CR2 58) 15.0228 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 15.0228 Trouble: [raw black/white point] invalid crop parameters (IMG_7460.CR2 58) 15.2131 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 15.2132 Trouble: [raw black/white point] invalid crop parameters (IMG_7460.CR2 58) 15.3565 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 15.3565 Trouble: [raw black/white point] invalid crop parameters (IMG_7461.CR2 59) 16.7416 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 16.7416 Trouble: [raw black/white point] invalid crop parameters (IMG_7460.CR2 58) 16.7695 [rawprepare] got wrong crop parameters left=158, right=5202, top=52, bottom=3464 for size=5360x3516 16.7695 Trouble: [raw black/white point] invalid crop parameters (IMG_7460.CR2 58) Segmentation fault

(portrait) [rawspeed_open] extensions list to ignore: `cr3' 14.3450 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 14.3450 Trouble: [raw black/white point] invalid crop parameters (IMG_7437.CR2 35) 15.2189 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 15.2189 Trouble: [raw black/white point] invalid crop parameters (IMG_7437.CR2 35) 15.3469 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 15.3469 Trouble: [raw black/white point] invalid crop parameters (IMG_7437.CR2 35) 15.4324 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 15.4324 Trouble: [raw black/white point] invalid crop parameters (IMG_7438.CR2 36) 17.0714 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 17.0715 Trouble: [raw black/white point] invalid crop parameters (IMG_7437.CR2 35) 17.0994 [rawprepare] got wrong crop parameters left=158, right=3464, top=52, bottom=5202 for size=5360x3516 17.0994 Trouble: [raw black/white point] invalid crop parameters (IMG_7437.CR2 35)

(darktable:30072): GLib-ERROR **: 10:16:41.276: ../../../glib/gmem.c:169: failed to allocate 18446744073708757736 bytes Trace/breakpoint trap

TurboGit commented 1 year ago

@jenshannoschwalm : Thinking more about this, isn't this just a corner case that we cannot support anyway. If "original" is selected, the rawprepare module is not yet activated and so properly gets some garbled data... I'm not even sure how this is supposed to work actually. I have been able to reproduce the same issue with a NEF BTW. So when clicking on "original" and still on the same image it's ok as probably rawprepare has been initialized with some proper values, but if changing image and going back there is no way this can be working to me.

If my analysis is correct, one solution is to ensure that when changing image and if "original" is selected we at least select the rawpreapre (just one step above) module. I have tested and when rawprepare is selected all is fine.

AxelG-DE commented 1 year ago

For me it crashed already (sometimes) by merely clicking on "original", which should be an allowed user action ;)

jenshannoschwalm commented 1 year ago

I'm not even sure how this is supposed to work actually. I have been able to reproduce the same issue with a NEF BTW. So when clicking on "original" and still on the same image it's ok as probably rawprepare has been initialized with some proper values,

Hmm, shouldn't we have data available here from the image loader?

But yes, for raws selecting radprepare is fine - and for non-raws?

TurboGit commented 1 year ago

Hmm, shouldn't we have data available here from the image loader?

You're right.

But it seems there is a bug in fact as sometime we get the right,bottom crop and sometimes we get the actual width,height from the cache. Something fishy to track down.

jenshannoschwalm commented 1 year ago

Yes, the naming in raw prepare didn't make things easier.

TurboGit commented 1 year ago

Found the culprit: f83e9efaf2c87c61855197ec1d8e437824516b08

jenshannoschwalm commented 1 year ago

Hurray!

TurboGit commented 1 year ago

The fix is there #13571, only reverting part of https://github.com/darktable-org/darktable/commit/f83e9efaf2c87c61855197ec1d8e437824516b08

wpferguson commented 1 year ago

Just tested, works for me. Thanks @TurboGit

andabata commented 1 year ago

It's fixed for me now. Thanks all

paolobenve commented 1 year ago

Found the culprit: f83e9ef

What about assigning imgtmp->crop_right/bottom only if ww/hh != 0?

I'm experimenting with that, and it seems that it works

I prepare a PR