6.5.5 much slower than 6.3.6

[Arkadiy Kulev]

Nope, still the same, quality doesn't matter.


w11# convert -version
Version: ImageMagick 6.5.5-7 2009-09-23 Q16 http://www.imagemagick.org
Copyright: Copyright (C) 1999-2009 ImageMagick Studio LLC

w11# time convert t1.jpg -quality 75 t2.jpg
0.662u 0.121s 0:04.29 18.1% 4+1050k 0+73io 0pf+0w






w14# convert -version
Version: ImageMagick 6.3.6 04/03/08 Q16 http://www.imagemagick.org
Copyright: Copyright (C) 1999-2007 ImageMagick Studio LLC

w14# time convert t1.jpg -quality 75 t2.jpg
0.615u 0.052s 0:00.68 97.0% 5+1148k 0+73io 0pf+0w





Same slowdown I noticed in perlmagick. Seems like it's somewhere deep
inside the core.

convert t1.jpg -quality 75 t2.jpg
Is the runtime reduced? ImageMagick 6.5.5 has a higher default quality.

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[d***@imagemagick.org]

Here's our timing:

convert logo: -resize 5000x5000 logo.jpg

time ImageMagick-6.3.6/convert logo.jpg -quality 75 t2.jpg
0.709u 0.111s 0:00.82 98.7% 0+0k 0+720io 0pf+0w

time ImageMagick-6.5.6-4/convert logo.jpg -quality 75 t2.jpg
0.694u 0.079s 0:00.77 98.7% 0+0k 0+720io 0pf+0w

6.5.6 proves to be slightly faster. We are not sure why its slow on your
computer.

[Arkadiy Kulev]

Hello duc,

I've noticed, that the 6.5.5 trace contains alot of "getpid" calls,
where 6.3.6 almost doesn't have them at all.

I am willing to send you any dump needed if you will give me the correct
commands.

Let's track this problem down.

Post by d***@imagemagick.org
convert logo: -resize 5000x5000 logo.jpg
time ImageMagick-6.3.6/convert logo.jpg -quality 75 t2.jpg
0.709u 0.111s 0:00.82 98.7% 0+0k 0+720io 0pf+0w
time ImageMagick-6.5.6-4/convert logo.jpg -quality 75 t2.jpg
0.694u 0.079s 0:00.77 98.7% 0+0k 0+720io 0pf+0w
6.5.6 proves to be slightly faster. We are not sure why its slow on your
computer.

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[d***@imagemagick.org]

Post by Arkadiy Kulev
I've noticed, that the 6.5.5 trace contains alot of "getpid" calls,

As previously mentioned that should not be a problem. The getpid() method
has nearly zero overhead. We might be able to discern something from the
debugging log. Add -debug all to your command line and forward the logs
(6.3.6 and 6.5.5) to this e-mail address.

[Arkadiy Kulev]

Hello duc,

attached.

Post by d***@imagemagick.org

Post by Arkadiy Kulev
I've noticed, that the 6.5.5 trace contains alot of "getpid" calls,

As previously mentioned that should not be a problem. The getpid() method
has nearly zero overhead. We might be able to discern something from the
debugging log. Add -debug all to your command line and forward the logs
(6.3.6 and 6.5.5) to this e-mail address.

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[d***@imagemagick.org]

We ran this test 40 times on a quiet system:

convert /tmp/t1.jpg -quality 75 t2.jpg

The average time for version 6.3.6 was:

0.19s user 0.04s system 99% cpu 0.236 total

The average time for version 6.5.6 was:

0.22s user 0.03s system 99% cpu 0.244 total

[Arkadiy Kulev]

I am sorry, you were totally right. I installed 6.5.6-4 on the "good"
machine and it all worked well.

It seems to me, that the new freebsd 7.2 is having some issues with
my processor. Will take over the question to them from now on.

Thank you for your time.

Post by d***@imagemagick.org
convert /tmp/t1.jpg -quality 75 t2.jpg
0.19s user 0.04s system 99% cpu 0.236 total
0.22s user 0.03s system 99% cpu 0.244 total

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[Arkadiy Kulev]

Hello duc,

Unfortunately, I couldn't investigate any further. Switching the freebsd
scheduling back to 4BSD didn't help.

I don't even know where to look anymore. Only you can help me.

The only way to find out what is happening is to understand why am I
having so many "getpid()" in my strace.

Even in just "strace convert" (without any parameters).
I have attached the strace from it.

Can you please check it out? Abnormal getpid()-s start near the
middle and to the bottom.

Post by d***@imagemagick.org
convert /tmp/t1.jpg -quality 75 t2.jpg
0.19s user 0.04s system 99% cpu 0.236 total
0.22s user 0.03s system 99% cpu 0.244 total

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[Arkadiy Kulev]

Hello duc,

Here are test results from both systems - slow and fast.

slow system:

w11# time ./a.out
489654080
0.110u 0.132s 0:00.24 100.0% 17+199k 0+0io 0pf+0w

fast system:

w14# time ./a.out
1867392448
0.157u 0.105s 0:00.26 96.1% 5+184k 0+0io 0pf+0w



Since, the timing is almost identical, I think, that getpid here is
really not the problem.

What I am trying to figure out, is why I have many getpid lines in the strace
of the simple "strace convert" command (which is identical to --help)
on the slow system and not on the fast one?

In ImageMagick, getpid() is called once when getting the execution
path and call multiple times when gathering entropy for random number
generation and when logging. Even so, getpid() is lightweight. How long
#include <stdio.h>
main()
{
int i,j = 0;
for (i=0; i < 1000000; i++)
j+=getpid();
printf("%d\n",j);
}
cc gif.c
time a.out
-989967296
0.004u 0.001s 0:00.01 0.0% 0+0k 8+0io 0pf+0w
On our system, 1 million calls to getpid() consumes less than 0.01 seconds
of elapsed time suggesting getpid() is not the cause of any apparent slowdown
of ImageMagick.

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[Arkadiy Kulev]

Hello duc,


Here is the line I get from the freebsd 7.0 system (ps aux | grep http):
web 8140 11.2 0.6 28876 20540 ?? RN 1:08AM 0:35.20 /home/storage/node/img_node_err.pl (httpd)

(Version: ImageMagick 6.3.6 04/03/08 Q16 http://www.imagemagick.org)


And here is the line I get from the freebsd 7.2 system (ps aux | grep http):
web 86711 20.0 0.6 92040 20736 ?? RN 1:12AM 0:07.61 /home/storage/node/img_node_err.pl (httpd)

(Version: ImageMagick 6.5.5-7 2009-10-01 Q16 http://www.imagemagick.org)

Please notice the difference in memory usage. Somehow, the 7.0
(6.3.6) manages to perform the ImagetoBlob-gif function without heavy
overload on the memory.

What can this be?

print $image->ImageToBlob(magick => 'gif');

GIF forces a colormap and the color reduction algorithm is memory intensive.
See http://www.imagemagick.org/script/quantize.php. Also, don't forget that
images stay in memory in perl unless they go out of scope or are explicitedly
undef'ed, see
http://www.imagemagick.org/script/perl-magick.php#overview.

Arkadiy Kulev mailto:***@ethaniel.com
[phone]
Moscow, Russia

[d***@imagemagick.org]

Post by Arkadiy Kulev
web 86711 20.0 0.6 92040 20736 ?? RN

Memory usage under Linux depends on which dynamic libraries are loaded when
the memory snapshot is taken. Can you be sure that both snapshots were taken
under identical conditions. The only way we can properly debug the problem
is if its reproducible in our environment. Send us a script or command line
and a URL to your input images and a description of the problem. If we can
reproduce the problem we generally will have a fix within a day or two.