convert slow on new server because of FUTEX_WAIT_PRIVATE

[seaplusplus]

This may not be a bug so sorry if its the wrong forum.

I am testing one of our new servers, this machines has 48cores ( /proc/cpu shows 96 cpu's because of HT) we are using RHEL6.5 and are using ImageMagick-6.5.4.7-7. Although I compiled the latest from source and get the same problem.

Whenever I use more than 3 threads convert runs really slow with futex being the top system call. strace shows it wait on FUTEX_WAIT_PRIVATE.

On our older server running the same OS, kernel and IM we don't see this and can run any amount of threads we want, its far faster.

time strace -c convert -limit thread 3 00436248BE.tif -resize 10x10 aa.jpg

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
65.91 0.081988 11713 7 2 futex
31.69 0.039415 1516 26 munmap
1.98 0.002469 0 20707 read
0.25 0.000305 0 10368 lseek
0.14 0.000178 3 60 16 open
0.02 0.000021 0 69 write
0.01 0.000015 0 102 mmap
0.00 0.000000 0 44 close
0.00 0.000000 0 10 1 stat
0.00 0.000000 0 49 fstat
0.00 0.000000 0 37 mprotect
0.00 0.000000 0 15 brk
0.00 0.000000 0 10 rt_sigaction
0.00 0.000000 0 17 rt_sigprocmask
0.00 0.000000 0 6 1 access
0.00 0.000000 0 2 madvise
0.00 0.000000 0 2 clone
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 2 getdents
0.00 0.000000 0 2 getcwd
0.00 0.000000 0 1 readlink
0.00 0.000000 0 2 getrlimit
0.00 0.000000 0 12 times
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 1 sched_getaffinity
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.124391 31556 20 total

real 0m27.251s
user 0m6.755s
sys 0m18.573s

Anyone have any idea what might be going on here?

many thanks,

[magick]

What are the dimensions of 00436248BE.tif? We tried converting a 10000x6000 image under 6.5 with ImageMagick-6.5.4.7 and it ran in just a few seconds on a 12 core system. On our 48 cores system, with CentOS 7, we got the expected results-- lightening fast.

Try this command:

• time strace -c convert -limit thread 3 -limit map 0 00436248BE.tif -resize 10x10 aa.jpg

Now add '-debug cache' to your command line. Let's see if the slowdown is in the pixel cache.

What time to you get if you replace 'resize' with 'scale'? Is it any faster?

Perhaps a problem with libgomp? You could build from source and configure like this:

• ./configure --disable-openmp

It runs on only one core but it might let us know if the problem is OpenMP related.

[seaplusplus]

Hello,

This is the image: 00436248BE.tif TIFF 7760x10328 7760x10328+0+0 8-bit DirectClass 229.5mb

In an interesting turn of events it just started working perfectly, I didn't change anything. Very odd. I have spent days with it not working and now I can't get it not to work.

When it stops working again I will try your options, thanks for getting back to me.

Here we are working with 48 threads.

time strace -c convert -limit thread 48 00436248BE.tif -resize 10x10 aa.jpg
convert: 00436248BE.tif: wrong data type 7 for "RichTIFFIPTC"; tag ignored. `TIFFReadDirectory' @ tiff.c/TIFFWarnings/546.
convert: 00436248BE.tif: unknown field with tag 306 (0x132) encountered. `TIFFReadCustomDirectory' @ tiff.c/TIFFWarnings/546.
convert: 00436248BE.tif: unknown field with tag 42033 (0xa431) encountered. `TIFFReadCustomDirectory' @ tiff.c/TIFFWarnings/546.
convert: 00436248BE.tif: unknown field with tag 42034 (0xa432) encountered. `TIFFReadCustomDirectory' @ tiff.c/TIFFWarnings/546.
convert: 00436248BE.tif: unknown field with tag 42036 (0xa434) encountered. `TIFFReadCustomDirectory' @ tiff.c/TIFFWarnings/546.
convert: 00436248BE.tif: wrong data type 7 for "RichTIFFIPTC"; tag ignored. `TIFFReadDirectory' @ tiff.c/TIFFWarnings/546.
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
46.16 0.001948 81 24 munmap
37.13 0.001567 0 20707 read
5.62 0.000237 2 96 brk
5.28 0.000223 4 60 16 open
5.07 0.000214 0 10368 lseek
0.50 0.000021 0 69 write
0.24 0.000010 0 82 mprotect
0.00 0.000000 0 44 close
0.00 0.000000 0 10 1 stat
0.00 0.000000 0 49 fstat
0.00 0.000000 0 145 mmap
0.00 0.000000 0 10 rt_sigaction
0.00 0.000000 0 17 rt_sigprocmask
0.00 0.000000 0 6 1 access
0.00 0.000000 0 7 madvise
0.00 0.000000 0 47 clone
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 2 getdents
0.00 0.000000 0 2 getcwd
0.00 0.000000 0 1 readlink
0.00 0.000000 0 2 getrlimit
0.00 0.000000 0 12 times
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 5 1 futex
0.00 0.000000 0 1 sched_getaffinity
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.004220 31771 19 total

real 0m1.833s
user 0m12.707s
sys 0m0.857s

[seaplusplus]

Ok started being slow again.

I ran the commands with your options but it didn't make much difference.

Due to the random nature I started to think was a system issue and played with the vmdirty kernel setting. as noted here :
http://www.sysxperts.com/home/announce/ ... roundratio

This server has 512GB of ram. Since adjusting the setting I am no longer seeing any issues, it processing a large batch of images.

I will report back if I do see something but thanks for responding.