search

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

4.2.1 crashes when importing and building thumbnails for negadoctor-processed pictures #14325

Closed redmoon1945 closed 1 year ago

redmoon1945 commented 1 year ago

Describe the bug

4.2.1 started to crash when I import images all processed with negadoctor, more precisely at thumbnail creation it appears. Running Linux Mint 21.1 (32 GB of RAM). Using flatpak DT 4.2.1 as of 24 apr 2023, but same problem with 4.3 master branch darktable_4.3.0~git1954.80bfae38-1+9840.1_amd64.deb. I tried importing these images from a brand new Linux Kubuntu 23.04, with empty DT database and brand new install of DT 4.2.1 flatpak. The crash occurs the same, but not for the same images set… I tried many times by deleting the data and library db. So lets say I have set A,B,C of photos. If I change the order of importing (one set at a time), the crash does not occur for the same set.

I provide console output for "darktable -d all". Systematically, the last lines are about nlmean.

I have been able to reproduce the problem with only 4 files, that can be found here : https://drive.proton.me/urls/J43P4NC69W#XYma9ZxaheyR

It is random, so I had to play for 10 minutes doing this → erase library.db, data.db → darktable -d all → loop

load one or many of these 4 images -> always switch to Lighttable -> while loading , resizing thumbnail size (the crash still occur if I dont do that) -> remove all of them (without deleting the files) → rinse and repeat until segmentation fault. Takes usually 5 to 10 minutes) All files causing the problem have been processed with negadoctor.

Note :

Steps to reproduce

→ erase library.db, data.db → darktable -d all → loop

load one or many of these 4 images -> always switch to Lighttable -> while loading , resizing thumbnail size (the crash still occur if I dont do that) -> remove all of them (without deleting the files) → rinse and repeat until segmentation fault. Takes usually 5 to 10 minutes)

Expected behavior

DT should not crash

Logfile | Screenshot | Screencast

output of darktable -d all, look at the end to see the potential culprit (nlmean)

   137.0552 [add_job] found job already in queue:    137.0552 load image 19 mip 2 | queue: 1 | priority: 4   137.0552
   137.0564 [add_job] 6 |    137.0564 load image 20 mip 2 | queue: 1 | priority: 0   137.0564
   137.0564 [add_job] found job already in queue:    137.0564 load image 20 mip 2 | queue: 1 | priority: 4   137.0564
   137.1296 [clip_and_zoom_roi]          [thumbnail]    demosaic             (1332/1080) 6204x3629 scale=1.0000 -> ( 158/ 128)  735x 430 scale=0.1185
   137.1955 [dev_pixelpipe] module `white balance' min: (0.002717) max: (0.283483) [thumbnail]
   137.1956 [pixelpipe_process_on_CPU]   [thumbnail]    demosaic             ( 244/ 554) 7993x4884 scale=1.0000 -> (  22/  50)  720x 440 scale=0.0901
   137.2173 [dev_pixelpipe] took 0.022 secs (0.366 CPU) [thumbnail] processed `demosaic' on CPU, blended on CPU
   137.2241 [dev_pixelpipe] module `demosaic' min: (0.009797; 0.000000; 0.000000) max: (0.236657; 0.121130; 0.099334) [thumbnail]
   137.2242 [pixelpipe_process_on_CPU]   [thumbnail]    clipping             (  22/  50)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2298 [dev_pixelpipe] took 0.006 secs (0.109 CPU) [thumbnail] processed `crop and rotate' on CPU, blended on CPU
   137.2358 [dev_pixelpipe] module `crop and rotate' min: (0.009797; 0.000000; 0.000000) max: (0.236657; 0.121130; 0.099334) [thumbnail]
   137.2359 [pixelpipe_process_on_CPU]   [thumbnail]    exposure             (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2460 [dev_pixelpipe] took 0.010 secs (0.120 CPU) [thumbnail] processed `exposure' on CPU, blended on CPU
   137.2500 [dev_pixelpipe] module `exposure' min: (0.032644; 0.000000; 0.000000) max: (0.770150; 0.394580; 0.323723) [thumbnail]
   137.2501 [pixelpipe_process_on_CPU]   [thumbnail]    colorin              (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2501 [matrix conversion on CPU]   [thumbnail]    colorin              (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901 `enhanced color matrix'
   137.2508 [lighttable] expose took 0.0000 sec
   137.2512 [dev_pixelpipe] took 0.001 secs (0.007 CPU) [thumbnail] processed `input color profile' on CPU, blended on CPU
   137.2513 [add_job] 6 |    137.2513 load image 11 mip 2 | queue: 1 | priority: 0   137.2513
   137.2513 [add_job] found job already in scheduled:    137.2513 load image 11 mip 2 | queue: 1 | priority: 4   137.2513
   137.2553 [dev_pixelpipe] module `input color profile' min: (14.886395; -16.110241; -25.529457) max: (75.349243; 47.496765; 39.186771) [thumbnail]
   137.2553 [transform colorspace CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901 IOP_CS_LAB -> IOP_CS_RGB
   137.2561 [dt_ioppr_transform_image_colorspace] IOP_CS_LAB-->IOP_CS_RGB took 0.001 secs (0.003 CPU) [negadoctor ]
   137.2561 [pixelpipe_process_on_CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2595 [dev_pixelpipe] took 0.004 secs (0.041 CPU) [thumbnail] processed `negadoctor' on CPU, blended on CPU
   137.2631 [dev_pixelpipe] module `negadoctor' min: (0.000000; 0.000000; 0.000000) max: (2.000000; 2.000000; 2.000000) [thumbnail]
   137.2631 [transform colorspace CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901 IOP_CS_RGB -> IOP_CS_LAB
   137.2635 [lighttable] expose took 0.0000 sec
   137.2638 [add_job] 6 |    137.2638 load image 12 mip 2 | queue: 1 | priority: 0   137.2638
   137.2638 [add_job] found job already in scheduled:    137.2638 load image 12 mip 2 | queue: 1 | priority: 4   137.2638
   137.2638 [dt_ioppr_transform_image_colorspace] IOP_CS_RGB-->IOP_CS_LAB took 0.001 secs (0.004 CPU) [nlmeans ]
   137.2638 [pixelpipe_process_on_CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2647 [resample_plain] plan 0.000 secs (0.000 CPU) resample 0.135 secs (1.854 CPU)
   137.2687 [dev_pixelpipe] took 0.006 secs (0.035 CPU) [thumbnail] processed `astrophoto denoise' on CPU, blended on CPU
   137.2724 [dev_pixelpipe] module `astrophoto denoise' min: (0.000000; -46.608448; -53.654217) max: (130.153000; 82.817703; 107.285431) [thumbnail]
   137.2724 [pixelpipe_process_on_CPU]   [thumbnail]    sharpen              (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2729 [dev_pixelpipe] took 0.001 secs (0.012 CPU) [thumbnail] processed `sharpen' on CPU, blended on CPU
   137.2765 [dev_pixelpipe] module `sharpen' min: (0.000000; -46.608448; -53.654217) max: (130.153000; 82.817703; 107.285431) [thumbnail]
   137.2765 [pixelpipe_process_on_CPU]   [thumbnail]    colorout             (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2777 [dev_pixelpipe] took 0.001 secs (0.010 CPU) [thumbnail] processed `output color profile' on CPU, blended on CPU
   137.2811 [dev_pixelpipe] module `white balance' min: (0.004122) max: (0.333586) [thumbnail]
   137.2812 [pixelpipe_process_on_CPU]   [thumbnail]    demosaic             ( 254/ 144) 7763x5305 scale=1.0000 -> (  23/  13)  698x 477 scale=0.0899
   137.2814 [dev_pixelpipe] module `output color profile' min: (0.000000; 0.000000; 0.000000) max: (1.420178; 1.373194; 1.370532) [thumbnail]
   137.2814 [pixelpipe_process_on_CPU]   [thumbnail]    gamma                (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2822 [dev_pixelpipe] took 0.001 secs (0.004 CPU) [thumbnail] processed `display encoding' on CPU, blended on CPU
   137.2822 [cache report]               [thumbnail]                          2 lines (important=0, used=0). Used 1396MB, limit=0MB. Hitrate=0.00
   137.2822 [pixelpipe finished]         [thumbnail]                         (   0/   0)  720x 440 scale=0.0901 -> (   0/   0)  720x 440 scale=0.0901
   137.2822 [dev_process_thumbnail] pixel pipeline processing took 0.653 secs (5.412 CPU)
   137.2822 [dev_pixelpipe] took 0.278 secs (3.344 CPU) [thumbnail] processed `demosaic' on CPU, blended on CPU
   137.2885 [dev_pixelpipe] module `demosaic' min: (0.032316; 0.000000; 0.000000) max: (0.272142; 0.157277; 0.138477) [thumbnail]
   137.2886 [pixelpipe_process_on_CPU]   [thumbnail]    clipping             ( 158/ 128)  735x 430 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.2908 [dev_pixelpipe] module `white balance' min: (0.001405) max: (0.291164) [thumbnail]
   137.2908 [pixelpipe_process_on_CPU]   [thumbnail]    demosaic             ( 108/ 988) 7917x4442 scale=1.0000 -> (  10/  90)  720x 404 scale=0.0909
   137.2976 [dev_pixelpipe] took 0.009 secs (0.110 CPU) [thumbnail] processed `crop and rotate' on CPU, blended on CPU
   137.2984 [lighttable] expose took 0.0000 sec
   137.2988 [add_job] 6 |    137.2988 load image 13 mip 2 | queue: 1 | priority: 0   137.2988
   137.2988 [add_job] found job already in scheduled:    137.2988 load image 13 mip 2 | queue: 1 | priority: 4   137.2988
   137.2989 [mipmap_cache] generate mip 2 for image 11 from scratch
   137.2989 [sql] ./src/common/image_cache.c:268, 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"
   137.2993 [run_job-] 03 391822019.394328    137.2993 load image 11 mip 2 | queue: 1 | priority: 4   137.2993
   137.2993 [run_job+] 03 391822019.394344    137.2993 load image 20 mip 2 | queue: 1 | priority: 4   137.2993
   137.2993 [sql] ./src/common/image.c:393, 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"
   137.2994 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.2994 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 20"
   137.2995 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 11"
   137.2996 [sql] ./src/common/history.c:996, function dt_history_get_items_as_string(): prepare "SELECT operation, enabled, multi_name FROM main.history WHERE imgid=?1 ORDER BY num DESC"
   137.3005 [dev_pixelpipe] took 0.010 secs (0.114 CPU) [thumbnail] processed `demosaic' on CPU, blended on CPU
   137.3012 [dev_pixelpipe] module `crop and rotate' min: (0.032681; 0.000000; 0.000000) max: (0.275341; 0.155420; 0.134860) [thumbnail]
   137.3012 [pixelpipe_process_on_CPU]   [thumbnail]    exposure             (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3018 [dev_pixelpipe] took 0.001 secs (0.006 CPU) [thumbnail] processed `exposure' on CPU, blended on CPU
   137.3036 [sql] ./src/common/image.c:393, 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"
   137.3037 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.3042 [dev_pixelpipe] module `demosaic' min: (0.011611; 0.000000; 0.000000) max: (0.265149; 0.147217; 0.130107) [thumbnail]
   137.3042 [pixelpipe_process_on_CPU]   [thumbnail]    clipping             (  10/  90)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3048 [dev_pixelpipe] took 0.001 secs (0.000 CPU) [thumbnail] processed `crop and rotate' on CPU, blended on CPU
   137.3055 [dev_pixelpipe] module `exposure' min: (0.046548; 0.000000; 0.000000) max: (0.389602; 0.220066; 0.191001) [thumbnail]
   137.3055 [pixelpipe_process_on_CPU]   [thumbnail]    colorin              (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3055 [matrix conversion on CPU]   [thumbnail]    colorin              (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185 `enhanced color matrix'
   137.3064 [dev_pixelpipe] took 0.001 secs (0.003 CPU) [thumbnail] processed `input color profile' on CPU, blended on CPU
   137.3087 [dev_pixelpipe] module `crop and rotate' min: (0.011611; 0.000000; 0.000000) max: (0.265149; 0.147217; 0.130107) [thumbnail]
   137.3087 [pixelpipe_process_on_CPU]   [thumbnail]    exposure             (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3100 [dev_pixelpipe] module `input color profile' min: (19.835064; -15.804291; -19.083982) max: (56.165482; 31.460793; 26.625591) [thumbnail]
   137.3101 [transform colorspace CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185 IOP_CS_LAB -> IOP_CS_RGB
   137.3156 [dt_ioppr_transform_image_colorspace] IOP_CS_LAB-->IOP_CS_RGB took 0.005 secs (0.027 CPU) [negadoctor ]
   137.3156 [pixelpipe_process_on_CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3157 [dev_pixelpipe] took 0.007 secs (0.045 CPU) [thumbnail] processed `exposure' on CPU, blended on CPU
   137.3174 [lighttable] expose took 0.0000 sec
   137.3177 [dev_pixelpipe] took 0.008 secs (0.070 CPU) [thumbnail] processed `negadoctor' on CPU, blended on CPU
   137.3216 [dev_pixelpipe] module `exposure' min: (0.035370; 0.000000; 0.000000) max: (0.791770; 0.439933; 0.388886) [thumbnail]
   137.3217 [pixelpipe_process_on_CPU]   [thumbnail]    colorin              (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3218 [matrix conversion on CPU]   [thumbnail]    colorin              (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909 `enhanced color matrix'
   137.3241 [dev_pixelpipe] module `negadoctor' min: (0.000193; 0.000000; 0.000000) max: (2.000000; 0.866619; 0.775784) [thumbnail]
   137.3244 [transform colorspace CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185 IOP_CS_RGB -> IOP_CS_LAB
   137.3260 [dt_ioppr_transform_image_colorspace] IOP_CS_RGB-->IOP_CS_LAB took 0.002 secs (0.043 CPU) [nlmeans ]
   137.3260 [dev_pixelpipe] took 0.004 secs (0.067 CPU) [thumbnail] processed `input color profile' on CPU, blended on CPU
   137.3260 [pixelpipe_process_on_CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3301 [dev_pixelpipe] took 0.006 secs (0.086 CPU) [thumbnail] processed `astrophoto denoise' on CPU, blended on CPU
   137.3319 [dev_pixelpipe] module `input color profile' min: (16.126728; -21.033525; -27.230953) max: (75.572868; 46.966434; 45.337521) [thumbnail]
   137.3321 [transform colorspace CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909 IOP_CS_LAB -> IOP_CS_RGB
   137.3332 [dt_ioppr_transform_image_colorspace] IOP_CS_LAB-->IOP_CS_RGB took 0.001 secs (0.010 CPU) [negadoctor ]
   137.3332 [pixelpipe_process_on_CPU]   [thumbnail]    negadoctor           (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3352 [dev_pixelpipe] took 0.003 secs (0.034 CPU) [thumbnail] processed `negadoctor' on CPU, blended on CPU
   137.3358 [dev_pixelpipe] module `astrophoto denoise' min: (0.370640; -23.568272; -28.221851) max: (105.766754; 88.056625; 101.517509) [thumbnail]
   137.3358 [pixelpipe_process_on_CPU]   [thumbnail]    sharpen              (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3369 [dev_pixelpipe] took 0.001 secs (0.010 CPU) [thumbnail] processed `sharpen' on CPU, blended on CPU
   137.3386 [dt_view_image_get_surface]  id 11, dots 297x295, mip 720x440, surf 297x182 created in 0.0130 sec
   137.3389 [add_job] 5 |    137.3389 load image 12 mip 2 | queue: 1 | priority: 0   137.3389
   137.3389 [add_job] found job already in scheduled:    137.3389 load image 12 mip 2 | queue: 1 | priority: 4   137.3389
   137.3395 [add_job] 5 |    137.3395 load image 13 mip 2 | queue: 1 | priority: 0   137.3395
   137.3396 [add_job] found job already in scheduled:    137.3396 load image 13 mip 2 | queue: 1 | priority: 4   137.3396
   137.3409 [dev_pixelpipe] module `negadoctor' min: (0.000000; 0.000000; 0.000000) max: (2.000000; 2.000000; 2.000000) [thumbnail]
   137.3410 [transform colorspace CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909 IOP_CS_RGB -> IOP_CS_LAB
   137.3427 [dev_pixelpipe] module `sharpen' min: (0.370640; -23.568272; -28.221851) max: (105.766754; 88.056625; 101.517509) [thumbnail]
   137.3428 [pixelpipe_process_on_CPU]   [thumbnail]    bilat                (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.3433 [dt_ioppr_transform_image_colorspace] IOP_CS_RGB-->IOP_CS_LAB took 0.002 secs (0.030 CPU) [nlmeans ]
   137.3434 [pixelpipe_process_on_CPU]   [thumbnail]    nlmeans              (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3461 [dev_pixelpipe] took 0.005 secs (0.067 CPU) [thumbnail] processed `astrophoto denoise' on CPU, blended on CPU
   137.3477 [add_job] 5 |    137.3477 load image 14 mip 2 | queue: 1 | priority: 0   137.3478
   137.3478 [add_job] found job already in scheduled:    137.3478 load image 14 mip 2 | queue: 1 | priority: 4   137.3478
   137.3484 [add_job] 5 |    137.3484 load image 15 mip 2 | queue: 1 | priority: 0   137.3484
   137.3484 [add_job] found job already in queue:    137.3484 load image 15 mip 2 | queue: 1 | priority: 4   137.3484
   137.3488 [add_job] 5 |    137.3488 load image 16 mip 2 | queue: 1 | priority: 0   137.3488
   137.3488 [add_job] found job already in queue:    137.3488 load image 16 mip 2 | queue: 1 | priority: 4   137.3488
   137.3495 [add_job] 5 |    137.3495 load image 17 mip 2 | queue: 1 | priority: 0   137.3495
   137.3495 [add_job] found job already in queue:    137.3495 load image 17 mip 2 | queue: 1 | priority: 4   137.3495
   137.3499 [add_job] 5 |    137.3499 load image 18 mip 2 | queue: 1 | priority: 0   137.3499
   137.3500 [add_job] found job already in queue:    137.3500 load image 18 mip 2 | queue: 1 | priority: 4   137.3500
   137.3504 [add_job] 5 |    137.3504 load image 19 mip 2 | queue: 1 | priority: 0   137.3504
   137.3504 [add_job] found job already in queue:    137.3504 load image 19 mip 2 | queue: 1 | priority: 4   137.3504
   137.3508 [add_job] 5 |    137.3508 load image 20 mip 2 | queue: 1 | priority: 0   137.3508
   137.3508 [add_job] found job already in scheduled:    137.3508 load image 20 mip 2 | queue: 1 | priority: 4   137.3509
   137.3516 [dev_pixelpipe] module `astrophoto denoise' min: (0.000000; -49.248158; -68.049118) max: (130.153000; 87.991508; 108.719162) [thumbnail]
   137.3517 [pixelpipe_process_on_CPU]   [thumbnail]    sharpen              (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3525 [dev_pixelpipe] took 0.001 secs (0.008 CPU) [thumbnail] processed `sharpen' on CPU, blended on CPU
   137.3558 [lighttable] expose took 0.0000 sec
   137.3562 [dev_pixelpipe] module `sharpen' min: (0.000000; -49.248158; -68.049118) max: (130.153000; 87.991508; 108.719162) [thumbnail]
   137.3562 [pixelpipe_process_on_CPU]   [thumbnail]    colorout             (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3629 [dev_pixelpipe] took 0.007 secs (0.071 CPU) [thumbnail] processed `output color profile' on CPU, blended on CPU
   137.3664 [add_job] 5 |    137.3665 load image 12 mip 2 | queue: 1 | priority: 0   137.3665
   137.3665 [add_job] found job already in scheduled:    137.3665 load image 12 mip 2 | queue: 1 | priority: 4   137.3665
   137.3673 [add_job] 5 |    137.3674 load image 13 mip 2 | queue: 1 | priority: 0   137.3674
   137.3674 [add_job] found job already in scheduled:    137.3674 load image 13 mip 2 | queue: 1 | priority: 4   137.3674
   137.3697 [dev_pixelpipe] module `output color profile' min: (0.000000; 0.000000; 0.000000) max: (1.419584; 1.373238; 1.386226) [thumbnail]
   137.3698 [pixelpipe_process_on_CPU]   [thumbnail]    gamma                (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3712 [dev_pixelpipe] took 0.001 secs (0.015 CPU) [thumbnail] processed `display encoding' on CPU, blended on CPU
   137.3712 [cache report]               [thumbnail]                          2 lines (important=0, used=0). Used 1396MB, limit=0MB. Hitrate=0.00
   137.3712 [pixelpipe finished]         [thumbnail]                         (   0/   0)  720x 404 scale=0.0909 -> (   0/   0)  720x 404 scale=0.0909
   137.3712 [dev_process_thumbnail] pixel pipeline processing took 0.611 secs (5.563 CPU)
   137.3743 [add_job] 5 |    137.3743 load image 14 mip 2 | queue: 1 | priority: 0   137.3744
   137.3744 [add_job] found job already in scheduled:    137.3744 load image 14 mip 2 | queue: 1 | priority: 4   137.3744
   137.3751 [add_job] 5 |    137.3751 load image 15 mip 2 | queue: 1 | priority: 0   137.3751
   137.3751 [add_job] found job already in queue:    137.3751 load image 15 mip 2 | queue: 1 | priority: 4   137.3751
   137.3757 [add_job] 5 |    137.3757 load image 16 mip 2 | queue: 1 | priority: 0   137.3757
   137.3758 [add_job] found job already in queue:    137.3758 load image 16 mip 2 | queue: 1 | priority: 4   137.3758
   137.3763 [add_job] 5 |    137.3763 load image 17 mip 2 | queue: 1 | priority: 0   137.3763
   137.3763 [add_job] found job already in queue:    137.3763 load image 17 mip 2 | queue: 1 | priority: 4   137.3763
   137.3768 [add_job] 5 |    137.3768 load image 18 mip 2 | queue: 1 | priority: 0   137.3768
   137.3768 [add_job] found job already in queue:    137.3768 load image 18 mip 2 | queue: 1 | priority: 4   137.3768
   137.3773 [add_job] 5 |    137.3773 load image 19 mip 2 | queue: 1 | priority: 0   137.3773
   137.3773 [add_job] found job already in queue:    137.3773 load image 19 mip 2 | queue: 1 | priority: 4   137.3773
   137.3777 [add_job] 5 |    137.3777 load image 20 mip 2 | queue: 1 | priority: 0   137.3777
   137.3777 [add_job] found job already in scheduled:    137.3777 load image 20 mip 2 | queue: 1 | priority: 4   137.3778
   137.3913 [mipmap_cache] generate mip 2 for image 14 from scratch
   137.3914 [sql] ./src/common/image_cache.c:268, 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"
   137.3917 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 14"
   137.3923 [run_job-] 05 391822019.487373    137.3923 load image 14 mip 2 | queue: 1 | priority: 4   137.3923
   137.3924 [run_job+] 05 391822019.487396    137.3924 load image 19 mip 2 | queue: 1 | priority: 4   137.3924
   137.3925 [sql] ./src/common/image.c:393, 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"
   137.3925 [sql] ./src/common/history.c:996, function dt_history_get_items_as_string(): prepare "SELECT operation, enabled, multi_name FROM main.history WHERE imgid=?1 ORDER BY num DESC"
   137.3926 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.3927 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 19"
   137.3956 [sql] ./src/common/image.c:393, 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"
   137.3957 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.3957 [lighttable] expose took 0.0000 sec
   137.4051 [add_job] 4 |    137.4051 load image 12 mip 2 | queue: 1 | priority: 0   137.4051
   137.4051 [add_job] found job already in scheduled:    137.4051 load image 12 mip 2 | queue: 1 | priority: 4   137.4051
   137.4055 [add_job] 4 |    137.4055 load image 13 mip 2 | queue: 1 | priority: 0   137.4055
   137.4055 [add_job] found job already in scheduled:    137.4055 load image 13 mip 2 | queue: 1 | priority: 4   137.4055
   137.4061 [dev_pixelpipe] took 0.063 secs (0.519 CPU) [thumbnail] processed `local contrast' on CPU, blended on CPU
   137.4123 [dev_pixelpipe] module `local contrast' min: (-3.936523; -23.568272; -28.221851) max: (111.904121; 88.056625; 101.517509) [thumbnail]
   137.4125 [pixelpipe_process_on_CPU]   [thumbnail]    colorout             (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.4146 [dev_pixelpipe] took 0.002 secs (0.058 CPU) [thumbnail] processed `output color profile' on CPU, blended on CPU
   137.4204 [dev_pixelpipe] module `output color profile' min: (0.000000; 0.000000; 0.000000) max: (1.517197; 0.964108; 0.921133) [thumbnail]
   137.4204 [pixelpipe_process_on_CPU]   [thumbnail]    gamma                (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.4219 [dev_pixelpipe] took 0.001 secs (0.011 CPU) [thumbnail] processed `display encoding' on CPU, blended on CPU
   137.4221 [cache report]               [thumbnail]                          2 lines (important=0, used=0). Used 1396MB, limit=0MB. Hitrate=0.00
   137.4222 [pixelpipe finished]         [thumbnail]                         (   0/   0)  720x 405 scale=0.1185 -> (   0/   0)  720x 405 scale=0.1185
   137.4222 [dev_process_thumbnail] pixel pipeline processing took 0.732 secs (6.354 CPU)
   137.4243 [rawspeed_open] extensions list to ignore: `cr3'
   137.4253 [dt_view_image_get_surface]  id 14, dots 297x295, mip 720x404, surf 297x167 created in 0.0129 sec
   137.4259 [add_job] 4 |    137.4259 load image 15 mip 2 | queue: 1 | priority: 0   137.4259
   137.4259 [add_job] found job already in queue:    137.4259 load image 15 mip 2 | queue: 1 | priority: 4   137.4259
   137.4268 [add_job] 4 |    137.4268 load image 16 mip 2 | queue: 1 | priority: 0   137.4268
   137.4268 [add_job] found job already in queue:    137.4268 load image 16 mip 2 | queue: 1 | priority: 4   137.4268
   137.4274 [add_job] 4 |    137.4274 load image 17 mip 2 | queue: 1 | priority: 0   137.4274
   137.4274 [add_job] found job already in queue:    137.4274 load image 17 mip 2 | queue: 1 | priority: 4   137.4274
   137.4279 [add_job] 4 |    137.4279 load image 18 mip 2 | queue: 1 | priority: 0   137.4279
   137.4279 [add_job] found job already in queue:    137.4279 load image 18 mip 2 | queue: 1 | priority: 4   137.4279
   137.4284 [add_job] 4 |    137.4284 load image 19 mip 2 | queue: 1 | priority: 0   137.4284
   137.4284 [add_job] found job already in scheduled:    137.4284 load image 19 mip 2 | queue: 1 | priority: 4   137.4284
   137.4291 [add_job] 4 |    137.4291 load image 20 mip 2 | queue: 1 | priority: 0   137.4291
   137.4291 [add_job] found job already in scheduled:    137.4291 load image 20 mip 2 | queue: 1 | priority: 4   137.4291
   137.4386 [lighttable] expose took 0.0000 sec
   137.4401 [mipmap_cache] generate mip 2 for image 12 from scratch
   137.4402 [sql] ./src/common/image_cache.c:268, 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"
   137.4412 [run_job-] 06 391822019.536281    137.4413 load image 12 mip 2 | queue: 1 | priority: 4   137.4413
   137.4413 [run_job+] 06 391822019.536330    137.4413 load image 18 mip 2 | queue: 1 | priority: 4   137.4413
   137.4414 [sql] ./src/common/image.c:393, 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"
   137.4415 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.4416 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 18"
   137.4481 [sql] ./src/common/image.c:393, 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"
   137.4482 [sql] ./src/common/image.c:449, function _image_local_copy_full_path(): prepare "SELECT folder || '/' || filename FROM main.images i, main.film_rolls f WHERE i.film_id = f.id AND i.id = ?1"
   137.4561 [dt_view_image_get_surface]  id 12, dots 297x295, mip 720x405, surf 297x167 created in 0.0085 sec
   137.4567 [add_job] 3 |    137.4567 load image 13 mip 2 | queue: 1 | priority: 0   137.4567
   137.4567 [add_job] found job already in scheduled:    137.4567 load image 13 mip 2 | queue: 1 | priority: 4   137.4567
   137.4576 [add_job] 3 |    137.4576 load image 15 mip 2 | queue: 1 | priority: 0   137.4576
   137.4576 [add_job] found job already in queue:    137.4576 load image 15 mip 2 | queue: 1 | priority: 4   137.4576
   137.4663 [add_job] 3 |    137.4663 load image 16 mip 2 | queue: 1 | priority: 0   137.4663
   137.4663 [add_job] found job already in queue:    137.4663 load image 16 mip 2 | queue: 1 | priority: 4   137.4663
   137.4667 [add_job] 3 |    137.4667 load image 17 mip 2 | queue: 1 | priority: 0   137.4667
   137.4667 [add_job] found job already in queue:    137.4667 load image 17 mip 2 | queue: 1 | priority: 4   137.4667
   137.4670 [add_job] 3 |    137.4670 load image 18 mip 2 | queue: 1 | priority: 0   137.4670
   137.4670 [add_job] found job already in scheduled:    137.4670 load image 18 mip 2 | queue: 1 | priority: 4   137.4670
   137.4673 [add_job] 3 |    137.4673 load image 19 mip 2 | queue: 1 | priority: 0   137.4673
   137.4674 [add_job] found job already in scheduled:    137.4674 load image 19 mip 2 | queue: 1 | priority: 4   137.4674
   137.4677 [add_job] 3 |    137.4677 load image 20 mip 2 | queue: 1 | priority: 0   137.4677
   137.4677 [add_job] found job already in scheduled:    137.4677 load image 20 mip 2 | queue: 1 | priority: 4   137.4677
   137.4809 [lighttable] expose took 0.0000 sec
   137.5067 [add_job] 3 |    137.5067 load image 13 mip 2 | queue: 1 | priority: 0   137.5067
   137.5067 [add_job] found job already in scheduled:    137.5067 load image 13 mip 2 | queue: 1 | priority: 4   137.5068
   137.5221 [add_job] 3 |    137.5222 load image 15 mip 2 | queue: 1 | priority: 0   137.5222
   137.5222 [add_job] found job already in queue:    137.5223 load image 15 mip 2 | queue: 1 | priority: 4   137.5223
   137.5263 [add_job] 3 |    137.5263 load image 16 mip 2 | queue: 1 | priority: 0   137.5263
   137.5263 [add_job] found job already in queue:    137.5264 load image 16 mip 2 | queue: 1 | priority: 4   137.5264
   137.5296 [add_job] 3 |    137.5296 load image 17 mip 2 | queue: 1 | priority: 0   137.5296
   137.5296 [add_job] found job already in queue:    137.5296 load image 17 mip 2 | queue: 1 | priority: 4   137.5296
   137.5324 [add_job] 3 |    137.5325 load image 18 mip 2 | queue: 1 | priority: 0   137.5325
   137.5325 [add_job] found job already in scheduled:    137.5325 load image 18 mip 2 | queue: 1 | priority: 4   137.5325
   137.5340 [rawspeed_open] extensions list to ignore: `cr3'
   137.5348 [add_job] 3 |    137.5348 load image 19 mip 2 | queue: 1 | priority: 0   137.5348
   137.5348 [add_job] found job already in scheduled:    137.5348 load image 19 mip 2 | queue: 1 | priority: 4   137.5348
   137.5372 [add_job] 3 |    137.5373 load image 20 mip 2 | queue: 1 | priority: 0   137.5373
   137.5373 [add_job] found job already in scheduled:    137.5373 load image 20 mip 2 | queue: 1 | priority: 4   137.5373
   137.5421 [lighttable] expose took 0.0000 sec
   137.5445 [sql] ./src/common/history.c:1755, function dt_history_hash_get_status(): prepare "SELECT CASE  WHEN basic_hash == current_hash THEN 1  WHEN auto_hash == current_hash THEN 2  WHEN (basic_hash IS NULL OR current_hash != basic_hash) AND       (auto_hash IS NULL OR current_hash != auto_hash) THEN 4  ELSE 1 END AS status FROM main.history_hash WHERE imgid = 12"
   137.5448 [sql] ./src/common/history.c:996, function dt_history_get_items_as_string(): prepare "SELECT operation, enabled, multi_name FROM main.history WHERE imgid=?1 ORDER BY num DESC"
   137.5608 [lighttable] expose took 0.0000 sec
   137.5688 [rawspeed_open] extensions list to ignore: `cr3'
   137.5712 [clip_and_zoom_roi]          [thumbnail]    demosaic             ( 254/ 144) 7763x5305 scale=1.0000 -> (  23/  13)  698x 477 scale=0.0899
   137.5715 [dt_view_image_get_surface]  id 12, dots 297x295, mip 720x405, surf 297x167 created in 0.0042 sec
   137.5718 [add_job] 3 |    137.5718 load image 13 mip 2 | queue: 1 | priority: 0   137.5718
   137.5718 [add_job] found job already in scheduled:    137.5718 load image 13 mip 2 | queue: 1 | priority: 4   137.5718
   137.5809 [add_job] 3 |    137.5810 load image 15 mip 2 | queue: 1 | priority: 0   137.5810
   137.5810 [add_job] found job already in queue:    137.5810 load image 15 mip 2 | queue: 1 | priority: 4   137.5810
   137.5831 [add_job] 3 |    137.5831 load image 16 mip 2 | queue: 1 | priority: 0   137.5831
   137.5831 [add_job] found job already in queue:    137.5832 load image 16 mip 2 | queue: 1 | priority: 4   137.5832
   137.5850 [add_job] 3 |    137.5850 load image 17 mip 2 | queue: 1 | priority: 0   137.5850
   137.5850 [add_job] found job already in queue:    137.5850 load image 17 mip 2 | queue: 1 | priority: 4   137.5850
   137.5868 [add_job] 3 |    137.5868 load image 18 mip 2 | queue: 1 | priority: 0   137.5868
   137.5868 [add_job] found job already in scheduled:    137.5868 load image 18 mip 2 | queue: 1 | priority: 4   137.5868
   137.5885 [add_job] 3 |    137.5886 load image 19 mip 2 | queue: 1 | priority: 0   137.5886
   137.5886 [add_job] found job already in scheduled:    137.5886 load image 19 mip 2 | queue: 1 | priority: 4   137.5886
   137.5903 [add_job] 3 |    137.5904 load image 20 mip 2 | queue: 1 | priority: 0   137.5904
   137.5904 [add_job] found job already in scheduled:    137.5904 load image 20 mip 2 | queue: 1 | priority: 4   137.5904
   137.6005 [lighttable] expose took 0.0000 sec
   137.6015 [add_job] 3 |    137.6015 load image 15 mip 2 | queue: 1 | priority: 0   137.6015
   137.6016 [add_job] found job already in queue:    137.6016 load image 15 mip 2 | queue: 1 | priority: 4   137.6016
   137.6044 [add_job] 3 |    137.6045 load image 16 mip 2 | queue: 1 | priority: 0   137.6045
   137.6045 [add_job] found job already in queue:    137.6045 load image 16 mip 2 | queue: 1 | priority: 4   137.6045
   137.6326 [lighttable] expose took 0.0000 sec
   137.6354 [add_job] 3 |    137.6354 load image 17 mip 2 | queue: 1 | priority: 0   137.6354
   137.6354 [add_job] found job already in queue:    137.6354 load image 17 mip 2 | queue: 1 | priority: 4   137.6354
   137.6361 [add_job] 3 |    137.6362 load image 18 mip 2 | queue: 1 | priority: 0   137.6362
   137.6362 [add_job] found job already in scheduled:    137.6362 load image 18 mip 2 | queue: 1 | priority: 4   137.6362
   137.6367 [add_job] 3 |    137.6367 load image 19 mip 2 | queue: 1 | priority: 0   137.6367
   137.6367 [add_job] found job already in scheduled:    137.6367 load image 19 mip 2 | queue: 1 | priority: 4   137.6367
   137.6416 [add_job] 3 |    137.6417 load image 20 mip 2 | queue: 1 | priority: 0   137.6417
   137.6417 [add_job] found job already in scheduled:    137.6417 load image 20 mip 2 | queue: 1 | priority: 4   137.6417
   137.7947 [resample_plain] plan 0.000 secs (0.006 CPU) resample 0.223 secs (2.931 CPU)
   137.8168 [dev_pixelpipe] took 0.536 secs (5.648 CPU) [thumbnail] processed `demosaic' on CPU, blended on CPU
   137.8207 [dev_pixelpipe] module `demosaic' min: (0.011215; 0.000000; 0.000000) max: (0.290344; 0.149555; 0.129971) [thumbnail]
   137.8207 [pixelpipe_process_on_CPU]   [thumbnail]    clipping             (  23/  13)  698x 477 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899
   137.8234 [dev_pixelpipe] took 0.003 secs (0.018 CPU) [thumbnail] processed `crop and rotate' on CPU, blended on CPU
   137.8243 [lighttable] expose took 0.0000 sec
   137.8245 [add_job] 3 |    137.8245 load image 13 mip 2 | queue: 1 | priority: 0   137.8245
   137.8245 [add_job] found job already in scheduled:    137.8245 load image 13 mip 2 | queue: 1 | priority: 4   137.8245
   137.8270 [dev_pixelpipe] module `crop and rotate' min: (0.023899; 0.000000; 0.000000) max: (0.287283; 0.148788; 0.131462) [thumbnail]
   137.8270 [pixelpipe_process_on_CPU]   [thumbnail]    exposure             (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899
   137.8279 [dev_pixelpipe] took 0.001 secs (0.008 CPU) [thumbnail] processed `exposure' on CPU, blended on CPU
   137.8314 [dev_pixelpipe] module `exposure' min: (0.034132; 0.000000; 0.000000) max: (0.406484; 0.210690; 0.186197) [thumbnail]
   137.8315 [pixelpipe_process_on_CPU]   [thumbnail]    colorin              (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899
   137.8315 [matrix conversion on CPU]   [thumbnail]    colorin              (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899 `enhanced color matrix'
   137.8321 [dev_pixelpipe] took 0.001 secs (0.005 CPU) [thumbnail] processed `input color profile' on CPU, blended on CPU
   137.8356 [dev_pixelpipe] module `input color profile' min: (16.109821; -16.700298; -15.958971) max: (57.425919; 36.716877; 36.444229) [thumbnail]
   137.8357 [transform colorspace CPU]   [thumbnail]    negadoctor           (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899 IOP_CS_LAB -> IOP_CS_RGB
   137.8361 [dt_ioppr_transform_image_colorspace] IOP_CS_LAB-->IOP_CS_RGB took 0.000 secs (0.003 CPU) [negadoctor ]
   137.8361 [pixelpipe_process_on_CPU]   [thumbnail]    negadoctor           (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899
   137.8380 [dev_pixelpipe] took 0.002 secs (0.031 CPU) [thumbnail] processed `negadoctor' on CPU, blended on CPU
   137.8415 [dev_pixelpipe] module `negadoctor' min: (0.000000; 0.000000; 0.000000) max: (2.000000; 0.922874; 0.852433) [thumbnail]
   137.8415 [transform colorspace CPU]   [thumbnail]    nlmeans              (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899 IOP_CS_RGB -> IOP_CS_LAB
   137.8420 [dt_ioppr_transform_image_colorspace] IOP_CS_RGB-->IOP_CS_LAB took 0.000 secs (0.004 CPU) [nlmeans ]
   137.8420 [pixelpipe_process_on_CPU]   [thumbnail]    nlmeans              (   0/   0)  680x 450 scale=0.0899 -> (   0/   0)  680x 450 scale=0.0899
Segmentation fault (core dumped)

Commit

?

Where did you install darktable from?

flatpak

darktable version

4.2.1

What OS are you using?

Linux

What is the version of your OS?

Mint 21.1, with all the latest patches and updates

Describe your system?

System: Kernel: 5.15.0-70-generic x86_64 bits: 64 compiler: gcc v: 11.3.0 parameters: BOOT_IMAGE=/vmlinuz-5.15.0-70-generic root=/dev/mapper/vgmint-root ro quiet splash Desktop: Cinnamon 5.6.8 tk: GTK 3.24.33 wm: muffin vt: 7 dm: LightDM 1.30.0 Distro: Linux Mint 21.1 Vera base: Ubuntu 22.04 jammy Machine: Type: Laptop System: LENOVO product: 21CQ000GUS v: ThinkPad T14s Gen 3 serial: Chassis: type: 10 serial: Mobo: LENOVO model: 21CQ000GUS v: SDK0T76530 WIN serial: UEFI: LENOVO v: R22ET61W (1.31 ) date: 03/21/2023 Battery: ID-1: BAT0 charge: 50.6 Wh (89.6%) condition: 56.5/57.0 Wh (99.1%) volts: 16.6 min: 15.4 model: Sunwoda LNV-5B10W51876�� type: Li-poly serial: status: Not charging cycles: 37 CPU: Info: model: AMD Ryzen 7 PRO 6850U with Radeon Graphics bits: 64 type: MT MCP arch: Zen 3 family: 0x19 (25) model-id: 0x44 (68) stepping: 1 microcode: 0xA404102 Topology: cpus: 1x cores: 8 tpc: 2 threads: 16 smt: enabled cache: L1: 512 KiB desc: d-8x32 KiB; i-8x32 KiB L2: 4 MiB desc: 8x512 KiB L3: 16 MiB desc: 1x16 MiB Speed (MHz): avg: 1404 high: 1555 min/max: 1600/4767 boost: enabled scaling: driver: acpi-cpufreq governor: schedutil cores: 1: 1396 2: 1397 3: 1471 4: 1456 5: 1365 6: 1389 7: 1375 8: 1365 9: 1555 10: 1379 11: 1397 12: 1396 13: 1396 14: 1397 15: 1362 16: 1372 bogomips: 86230 Flags: avx avx2 ht lm nx pae sse sse2 sse3 sse4_1 sse4_2 sse4a ssse3 svm Vulnerabilities: Type: itlb_multihit status: Not affected Type: l1tf status: Not affected Type: mds status: Not affected Type: meltdown status: Not affected Type: mmio_stale_data status: Not affected Type: retbleed status: Not affected Type: spec_store_bypass mitigation: Speculative Store Bypass disabled via prctl and seccomp Type: spectre_v1 mitigation: usercopy/swapgs barriers and __user pointer sanitization Type: spectre_v2 mitigation: Retpolines, IBPB: conditional, IBRS_FW, STIBP: always-on, RSB filling, PBRSB-eIBRS: Not affected Type: srbds status: Not affected Type: tsx_async_abort status: Not affected Graphics: Device-1: AMD Rembrandt vendor: Lenovo driver: amdgpu v: kernel pcie: gen: 4 speed: 16 GT/s lanes: 16 ports: active: DP-2,eDP-1 empty: DP-1, DP-3, DP-4, DP-5, DP-6, HDMI-A-1 bus-ID: 33:00.0 chip-ID: 1002:1681 class-ID: 0300 Device-2: Acer Integrated Camera type: USB driver: uvcvideo bus-ID: 5-1:2 chip-ID: 5986:1177 class-ID: fe01 serial: Display: x11 server: X.Org v: 1.21.1.4 driver: X: loaded: amdgpu,ati unloaded: fbdev,modesetting,vesa gpu: amdgpu display-ID: :0 screens: 1 Screen-1: 0 s-res: 4096x4224 s-dpi: 120 s-size: 867x894mm (34.1x35.2") s-diag: 1245mm (49") Monitor-1: DisplayPort-1 mapped: DP-2 pos: primary,top-left model: Dell S2719DC serial: built: 2020 res: 4096x2304 hz: 60 dpi: 174 gamma: 1.2 size: 597x336mm (23.5x13.2") diag: 685mm (27") ratio: 16:9 modes: max: 2560x1440 min: 720x400 Monitor-2: eDP pos: primary,bottom-r res: 3072x1920 hz: 60 dpi: 258 size: 302x189mm (11.9x7.4") diag: 356mm (14") OpenGL: renderer: REMBRANDT (rembrandt LLVM 15.0.6 DRM 3.42 5.15.0-70-generic) v: 4.6 Mesa 22.2.5 direct render: Yes Audio: Device-1: AMD vendor: Lenovo driver: snd_hda_intel v: kernel pcie: gen: 4 speed: 16 GT/s lanes: 16 bus-ID: 33:00.1 chip-ID: 1002:1640 class-ID: 0403 Device-2: AMD Raven/Raven2/FireFlight/Renoir Audio Processor vendor: Lenovo driver: snd_pci_acp6x v: kernel alternate: snd_pci_acp3x,snd_rn_pci_acp3x,snd_pci_acp5x pcie: gen: 4 speed: 16 GT/s lanes: 16 bus-ID: 33:00.5 chip-ID: 1022:15e2 class-ID: 0480 Device-3: AMD Family 17h HD Audio vendor: Lenovo driver: snd_hda_intel v: kernel pcie: gen: 4 speed: 16 GT/s lanes: 16 bus-ID: 33:00.6 chip-ID: 1022:15e3 class-ID: 0403 Sound Server-1: ALSA v: k5.15.0-70-generic running: yes Sound Server-2: PulseAudio v: 15.99.1 running: yes Sound Server-3: PipeWire v: 0.3.48 running: yes Network: Device-1: Qualcomm Atheros QCNFA765 vendor: Lenovo driver: ath11k_pci v: kernel pcie: gen: 2 speed: 5 GT/s lanes: 1 link-max: gen: 3 speed: 8 GT/s port: N/A bus-ID: 01:00.0 chip-ID: 17cb:1103 class-ID: 0280 IF: wlp1s0 state: down mac: Device-2: Lenovo Thinkpad LAN type: USB driver: r8152 bus-ID: 10-1.1:3 chip-ID: 17ef:7205 class-ID: 0000 serial: IF: enx3c18a01e39cf state: up speed: 1000 Mbps duplex: full mac: IF-ID-1: ipv6leakintrf0 state: unknown speed: N/A duplex: N/A mac: IF-ID-2: proton0 state: unknown speed: 10 Mbps duplex: full mac: N/A

Are you using OpenCL GPU in darktable?

No

If yes, what is the GPU card and driver?

No response

Please provide additional context if applicable. You can attach files too, but might need to rename to .txt or .zip

It was working with 3.8.1 for sure. I think it was also working with 4.2.1 some time ago (cannot confirm that)

jenshannoschwalm commented 1 year ago

As already mentioned on pixls this is related to a bug in the denoiser, that has been fixed already on master, so for 4.4

In the meantime, you should use another module that does the denoising for you :-)

jenshannoschwalm commented 1 year ago

he said that he tested master too

Sorry, missed that. Nevertheless i couldn't reproduce here.

@redmoon1945 two questions

  1. if you reproduce this on master it would be nice to post -d pipe output, far less noise to check :-)
  2. Is it an issue if opencl is switched off? If so, we might need the initial lines in the log from -d opencl
redmoon1945 commented 1 year ago

Hi, as a matter of fact, master 4.3.0 produces the same problem. But 4.0.0 flatpak works fine (just tried it on Kubuntu 23.04). Yes, opencl is definitely OFF. Sure, I will try -d pipe and post the result here. Problem is random, in the sense that it is not a specific image that produce the crash (so I cannot identify a deterministic path that lead to the problem). In the 4 I have put on my proton drive, I have to play 5-10 min as I describe earlier to get the segmentation fault. Thx for your help !!

redmoon1945 commented 1 year ago

congrat gl-man ! You got it !! In my case, the resource were set to Large. Yes, not easily reproductable, although with my 2000 negadoctor-processed files (no problem when negadoctor is not involved), it crashes quite rapidly, all the time, but not at the same image.

apostel338 commented 1 year ago

I can get this crash very (very) reliable, so far only without open cl. And it's enough to have Astro Denoise on and Negadoctor can be off. If I can offer any information or testing, I'm happy to copy&paste your commands into my CLI.

jenshannoschwalm commented 1 year ago

@ralfbrown the issue title is misleading, this is again an nlmeans cpu code issue.

I tried pretty hard and could not trigger any crashes, do you have an idea on this?

Could it be a __DT_CLONE_TARGETS__ problem? Wrong code for the platform?

ralfbrown commented 1 year ago

@gi-man Does the code still segfault if you change the two occurrences of _mm_load_ps in common/nlmeans_core.c to _mm_loadu_ps? That fixed things back when we still had a separate SSE code path, but we never did figure out why there were unaligned accesses at all.

jenshannoschwalm commented 1 year ago

Something I noticed was i have artefacts while zooming...