Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
redmoon1945 opened this issue Apr 25, 2023 · 13 comments · Fixed by #14395
Closed

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

redmoon1945 opened this issue Apr 25, 2023 · 13 comments · Fixed by #14395

Comments

@redmoon1945
Copy link

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 :

  • all files can be repetitively opened without problems in Rawtherapee  5.9 (obviously not applying DT processing), so the files are not corrupted

  • it was working some weeks ago. There has been some “updates” recently of the DT 4.2.1 flatpak (strange because the version number did not change).

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)
@redmoon1945 redmoon1945 changed the title 4.2.1 crashes when importing and building thumbnail for negadoctor-processed pictures 4.2.1 crashes when importing and building thumbnails for negadoctor-processed pictures Apr 25, 2023
@jenshannoschwalm
Copy link
Collaborator

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 :-)

@gi-man
Copy link
Contributor

gi-man commented Apr 26, 2023

@jenshannoschwalm he said that he tested master too.

@jenshannoschwalm
Copy link
Collaborator

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
Copy link
Author

redmoon1945 commented Apr 26, 2023 •
edited

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 !!

@gi-man
Copy link
Contributor

gi-man commented Apr 26, 2023

It took some effort but I was able to reproduce once on master (4.3.0~git1979.0c3b3fbc). Fedora 37 KDE, Nvidia 3060 12gb Vram. I set the Resources to small and turned off opencl. I've tried again but I cant get it repeat.

                #0  0x00007f05023596b3 init_column_sums (libdarktable.so + 0x1596b3)
                #1  0x00007f0502360191 nlmeans_denoise._omp_fn.0.avx2 (libdarktable.so + 0x160191)
                #2  0x00007f0501ff661e gomp_thread_start (libgomp.so.1 + 0x1d61e)
                #3  0x00007f05020ae12d start_thread (libc.so.6 + 0x8b12d)
                #4  0x00007f050212fbc0 __clone3 (libc.so.6 + 0x10cbc0)
                
                Stack trace of thread 194966:
                #0  0x00007f0502360899 nlmeans_denoise._omp_fn.0.avx2 (libdarktable.so + 0x160899)
                #1  0x00007f0501fed766 GOMP_parallel (libgomp.so.1 + 0x14766)
                #2  0x00007f0502364fb3 nlmeans_denoise.avx2 (libdarktable.so + 0x164fb3)
                #3  0x00007f039a0194ed process (libnlmeans.so + 0x34ed)
                #4  0x00007f0502454899 _pixelpipe_process_on_CPU (libdarktable.so + 0x254899)
                #5  0x00007f050245616f _dev_pixelpipe_process_rec (libdarktable.so + 0x25616f)
                #6  0x00007f050245524c _dev_pixelpipe_process_rec (libdarktable.so + 0x25524c)
                #7  0x00007f050245524c _dev_pixelpipe_process_rec (libdarktable.so + 0x25524c)

@redmoon1945
Copy link
Author

redmoon1945 commented Apr 27, 2023 •
edited

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.

@gi-man
Copy link
Contributor

gi-man commented Apr 27, 2023 •
edited

My reports means that it looks we still have an issue with nlmeans in the current version of code.

Can you rename the issue to something like: segfaults from nlmeans with negadoctor on current master.

@apostel338
Copy link

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.

@gi-man
Copy link
Contributor

gi-man commented Apr 28, 2023

I managed to get to to segfault under gdb (openCL off). This is darktable 4.3.0~git2027.2b3d5ec0

(gdb) bt
#0  nlmeans_denoise._omp_fn.0 () at /usr/lib/gcc/x86_64-redhat-linux/12/include/xmmintrin.h:894
#1  0x00007ffff746f61e in gomp_thread_start () at /lib64/libgomp.so.1
#2  0x00007ffff259c12d in start_thread () at /lib64/libc.so.6
#3  0x00007ffff261dbc0 in clone3 () at /lib64/libc.so.6
(gdb)

@jenshannoschwalm
Copy link
Collaborator

@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
Copy link
Collaborator

@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
Copy link
Collaborator

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

@gi-man
Copy link
Contributor

gi-man commented May 1, 2023

I tested with master first and it took a while to get it to crash. I turned off OpenCL, set resources to small and zoomed in to 400% while playing with exposure. I managed to get it to crash twice.

I did the edit you suggested and could not get it to crash.

@ralfbrown ralfbrown mentioned this issue May 1, 2023
Merged
@apostel338 apostel338 mentioned this issue May 15, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

nlmeans_core: fix crash due to unaligned memory access ralfbrown/darktable
5 participants
@ralfbrown @jenshannoschwalm @apostel338 @gi-man @redmoon1945