Performance problem

Post any defects you find in the released or beta versions of the ImageMagick software here. Include the ImageMagick version, OS, and any command-line required to reproduce the problem. Got a patch for a bug? Post it here.
Post Reply
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Performance problem

Post by alexandre.boudreault »

I i've been testing Imagemagick 6.8.6 q8 with open mp on my laptop with 800ko jpg image

time convert 'TestByDaniel.jpg' -quiet -quality 80 -thumbnail 'x232' -gravity north -crop '232x232+0+0' -colorspace RGB jpg:TestSmall.jpg 2>&1

real 0m0.144s
user 0m0.308s
sys 0m0.040s

It gives me a 144ms convert time which I considere to be ok since i'm on my laptop and only doing test. My laptop is a Interl i5 quad core.

When i test the exact same convert, with the same image on my production server i got this

real 0m0.376s
user 0m0.356s
sys 0m0.016s

More then twice slower, my production server got an Intel Xeon X5670. I already tried to disable open mp on the production server but i get
the same range of time.

Anyone got an idea of what can cause this problem ?
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

Adding more info, i runned the command with some debug here's the output :
  • 2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: "Start Of Scan: 3 components"
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: " Component 1: dc=0 ac=0"
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: " Component 2: dc=1 ac=1"
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: " Component 3: dc=1 ac=1"
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: " Ss=0, Se=63, Ah=0, Al=0"
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/ReadJPEGImage/1221/Coder
    Interlace: nonprogressive
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/ReadJPEGImage/1223/Coder
    Data precision: 8
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/ReadJPEGImage/1225/Coder
    Geometry: 1024x768
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGSetImageQuality/821/Coder
    Quality: 99 (approximate)
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGSetImageSamplingFactor/911/Coder
    Colorspace: RGB
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Coder convert[13936]: jpeg.c/JPEGSetImageSamplingFactor/938/Coder
    Sampling Factors: 1x1,1x1,1x1
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Memory: 3.07KB/3KiB/1.9562GiB
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Area: 3.146MB/3.146MB/4.201GB
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Memory: 3.146MB/3.003MiB/1.9562GiB
    2013-10-11T10:23:59-04:00 0:00.000 0.000u 6.8.6 Cache convert[13936]: cache.c/OpenPixelCache/3571/Cache
    open TestByDaniel.jpg[0] (Heap Memory, 1024x768 3MiB)
    2013-10-11T10:23:59-04:00 0:00.070 0.060u 6.8.6 Coder convert[13936]: jpeg.c/JPEGWarningHandler/359/Coder
    [TestByDaniel.jpg] JPEG Trace: "End Of Image"
    2013-10-11T10:23:59-04:00 0:00.070 0.060u 6.8.6 Resource convert[13936]: resource.c/RelinquishMagickResource/851/Resource
    Memory: 3.07KB/3MiB/1.9562GiB
    2013-10-11T10:23:59-04:00 0:00.070 0.060u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Area: 7.169MB/7.169MB/4.201GB
    2013-10-11T10:23:59-04:00 0:00.070 0.060u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Memory: 7.169MB/9.837MiB/1.9562GiB
    2013-10-11T10:23:59-04:00 0:00.070 0.060u 6.8.6 Cache convert[13936]: cache.c/OpenPixelCache/3571/Cache
    open TestByDaniel.jpg[0] (Heap Memory, 1545x1160 6.837MiB)
    2013-10-11T10:23:59-04:00 0:00.080 0.070u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Area: 1.434MB/1.434MB/4.201GB
    2013-10-11T10:23:59-04:00 0:00.080 0.070u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Memory: 1.434MB/11.2MiB/1.9562GiB
    2013-10-11T10:23:59-04:00 0:00.080 0.070u 6.8.6 Cache convert[13936]: cache.c/OpenPixelCache/3571/Cache
    open TestByDaniel.jpg[0] (Heap Memory, 1545x232 1.367MiB)
    2013-10-11T10:23:59-04:00 0:00.300 0.300u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Area: 287KB/287KB/4.201GB
    2013-10-11T10:23:59-04:00 0:00.300 0.300u 6.8.6 Resource convert[13936]: resource.c/AcquireMagickResource/278/Resource
    Memory: 287KB/11.48MiB/1.9562GiB
There seems to be a huge delay when the script do his OpenPixelCache , from 70ms to 230ms, is it a normal behavior ?
Top
User avatar
dlemstra
Posts: 1570
Joined: 2013-05-04T15:28:54-07:00
Authentication code: 6789
Contact:
Contact dlemstra

Re: Performance problem

Post by dlemstra »

Could you also post the debug output from your development machine? And use -debug all? When you post the output please use a [ code ] block.
.NET + ImageMagick = Magick.NET https://github.com/dlemstra/Magick.NET, @MagickNET, Donate
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

I'm loosing a bit of speed on my laptop with the debug all option but it's still faster then on my the server without debug

Code: Select all

  [TestByDaniel.jpg] JPEG Trace: "          4   8   4   5   2   3   2  15"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "Start Of Scan: 3 components"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "    Component 1: dc=0 ac=0"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "    Component 2: dc=1 ac=1"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "    Component 3: dc=1 ac=1"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "  Ss=0, Se=63, Ah=0, Al=0"
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/ReadJPEGImage/1221/Coder
  Interlace: nonprogressive
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/ReadJPEGImage/1223/Coder
  Data precision: 8
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/ReadJPEGImage/1225/Coder
  Geometry: 1024x768
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGSetImageQuality/821/Coder
  Quality: 99 (approximate)
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGSetImageSamplingFactor/911/Coder
  Colorspace: RGB
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Coder convert[6010]: jpeg.c/JPEGSetImageSamplingFactor/938/Coder
  Sampling Factors: 1x1,1x1,1x1
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Memory: 3.07KB/3KiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Area: 3.146MB/3.146MB/4.2011GB
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Memory: 3.146MB/3.003MiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.000 0.000u 6.8.6 Cache convert[6010]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1024x768 3MiB)
2013-10-11T10:45:21-04:00 0:00.020 0.020u 6.8.6 Coder convert[6010]: jpeg.c/JPEGWarningHandler/359/Coder
  [TestByDaniel.jpg] JPEG Trace: "End Of Image"
2013-10-11T10:45:21-04:00 0:00.020 0.020u 6.8.6 Resource convert[6010]: resource.c/RelinquishMagickResource/851/Resource
  Memory: 3.07KB/3MiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.020 0.020u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Area: 7.169MB/7.169MB/4.2011GB
2013-10-11T10:45:21-04:00 0:00.020 0.020u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Memory: 7.169MB/9.837MiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.020 0.020u 6.8.6 Cache convert[6010]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x1160 6.837MiB)
2013-10-11T10:45:21-04:00 0:00.030 0.020u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Area: 1.434MB/1.434MB/4.2011GB
2013-10-11T10:45:21-04:00 0:00.030 0.020u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Memory: 1.434MB/11.2MiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.030 0.020u 6.8.6 Cache convert[6010]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x232 1.367MiB)
2013-10-11T10:45:21-04:00 0:00.160 0.160u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Area: 287KB/287KB/4.2011GB
2013-10-11T10:45:21-04:00 0:00.160 0.160u 6.8.6 Resource convert[6010]: resource.c/AcquireMagickResource/278/Resource
  Memory: 287KB/11.48MiB/1.9563GiB
2013-10-11T10:45:21-04:00 0:00.160 0.160u 6.8.6 Cache convert[6010]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 309x232 280KiB)
2013-10-11T10:45:21-04:00 0:00.160 0.160u 6.8.6 Cache convert[6010]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][18x232+0+0]
at 160ms is start the Read/write cycle in pixel cache and finish the processing at 210 ms.

He does the same number of open open TestByDaniel.jpg[0] (Heap Memory), two take 0 ms one 20ms the last one is 140ms.
On my server it's two take 0ms one 60ms and one 230ms.
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

Another thing i just noticed, my cpu on the server is spiking a nearly 100% on the convert command, while on my laptop
I hit between 10-15% usage.
Top
User avatar
magick
Site Admin
Posts: 11064
Joined: 2003-05-31T11:32:55-07:00

Re: Performance problem

Post by magick »

Add -debug cache. Its likely the pixel cache is served in memory on one host and on disk on the other. Also check you JPEG library. Libjpeg0turbo is generally faster than libjpeg.
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

I switched my jpeg library for the turbo one, recompiled/installed imagemagick but i still have the same result, here's a debug cache for both environment

Server XEON (production)

Code: Select all

2013-10-11T12:03:30-04:00 0:00.010 0.000u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy
2013-10-11T12:03:30-04:00 0:00.010 0.000u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1024x768 3MiB)
2013-10-11T12:03:30-04:00 0:00.050 0.040u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x1160 6.837MiB)
2013-10-11T12:03:30-04:00 0:00.060 0.040u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x232 1.367MiB)
2013-10-11T12:03:30-04:00 0:00.280 0.260u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 309x232 280KiB)
2013-10-11T12:03:30-04:00 0:00.280 0.260u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][18x232+0+0]
2013-10-11T12:03:30-04:00 0:00.280 0.260u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+0+0]
2013-10-11T12:03:30-04:00 0:00.280 0.260u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache

...

2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+297+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1478+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+298+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1483+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+299+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1488+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+300+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1493+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+301+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1498+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+302+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1503+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+303+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1508+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+304+0]
2013-10-11T12:03:30-04:00 0:00.340 0.320u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1513+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+305+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][27x232+1518+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+306+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][22x232+1523+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+307+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][17x232+1528+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+308+0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 232x232 210KiB)
2013-10-11T12:03:30-04:00 0:00.340 0.330u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:03:31-04:00 0:00.360 0.340u 6.8.6 Cache convert[16072]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 232x232 210KiB)
2013-10-11T12:03:31-04:00 0:00.370 0.350u 6.8.6 Cache convert[16072]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
0.35user 0.00system 0:00.36elapsed 98%CPU (0avgtext+0avgdata 61296maxresident)k
0inputs+208outputs (0major+4136minor)pagefaults 0swaps
My Laptop I5

Code: Select all

2013-10-11T12:37:27-04:00 0:00.010 0.010u 6.8.6 Cache convert[6497]: cache.c/DestroyPixelCache/956/Cache
  destroy
2013-10-11T12:37:27-04:00 0:00.010 0.010u 6.8.6 Cache convert[6497]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1024x768 3MiB)
2013-10-11T12:37:27-04:00 0:00.040 0.030u 6.8.6 Cache convert[6497]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x1160 6.837MiB)
2013-10-11T12:37:27-04:00 0:00.040 0.040u 6.8.6 Cache convert[6497]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 1545x232 1.367MiB)
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 309x232 280KiB)
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][18x232+0+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+0+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][23x232+0+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+1+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][28x232+0+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+2+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+3+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+3+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+8+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+4+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+13+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+5+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+18+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+6+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+23+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+7+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+28+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+8+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+33+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+9+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+38+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+10+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+43+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+11+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+48+0]
2013-10-11T12:37:27-04:00 0:00.180 0.180u 6.8.6 Cache convert[6497]: cache.c/WritePixelCachePixels/5435/Cache

....

2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+297+0]
2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1478+0]
2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+298+0]
2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1483+0]
2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+299+0]
2013-10-11T12:05:24-04:00 0:00.210 0.210u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1488+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+300+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1493+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+301+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1498+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+302+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1503+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+303+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1508+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+304+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][30x232+1513+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+305+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][27x232+1518+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+306+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][22x232+1523+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+307+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/ReadPixelCachePixels/4466/Cache
  TestByDaniel.jpg[0][17x232+1528+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/WritePixelCachePixels/5435/Cache
  TestByDaniel.jpg[0][1x232+308+0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 232x232 210KiB)
2013-10-11T12:05:24-04:00 0:00.210 0.220u 6.8.6 Cache convert[6432]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
2013-10-11T12:05:24-04:00 0:00.220 0.220u 6.8.6 Cache convert[6432]: cache.c/OpenPixelCache/3571/Cache
  open TestByDaniel.jpg[0] (Heap Memory, 232x232 210KiB)
2013-10-11T12:05:24-04:00 0:00.220 0.230u 6.8.6 Cache convert[6432]: cache.c/DestroyPixelCache/956/Cache
  destroy TestByDaniel.jpg[0]
0.21user 0.03system 0:00.25elapsed 98%CPU (0avgtext+0avgdata 73216maxresident)k
0inputs+208outputs (0major+4944minor)pagefaults 0swaps
[edit] forgot the begging of the log (the part where it allow memory)
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

Hmm think i found a big part of the problem : the thumbnail option

Code: Select all

time convert 'TestByDaniel.jpg' -quality 80 -thumbnail 'x232'  -gravity north -crop '232x232+0+0'  -colorspace RGB jpg:TestSmall_thumbnail.jpg 2>&1

Average 377ms

time convert 'TestByDaniel.jpg' -quality 80 -resize 'x232'  -gravity north -crop '232x232+0+0'  -strip -colorspace RGB jpg:TestSmall_thumbnail.jpg 2>&1

Average 200ms
A bit closer to the performance i was expecting.
Top
User avatar
magick
Site Admin
Posts: 11064
Joined: 2003-05-31T11:32:55-07:00

Re: Performance problem

Post by magick »

There is another speed up for thumbnails. Assume the largest thumbnail is 256x256. Try
  • convert -define jpeg:size=256x256 image.jpg -resize 256x256 thumbnail.jpg
Top
User avatar
dlemstra
Posts: 1570
Joined: 2013-05-04T15:28:54-07:00
Authentication code: 6789
Contact:
Contact dlemstra

Re: Performance problem

Post by dlemstra »

Are you sure you build ImageMagick with OpenMP support on your production server? It looks like the resize operation is not using multiple cores.
.NET + ImageMagick = Magick.NET https://github.com/dlemstra/Magick.NET, @MagickNET, Donate
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

It's build with OpenMP but i only have 1 core assigned to my VM. But when i run the command
on my laptop to compare i user -limit thread 1.
Top
alexandre.boudreault
Posts: 8
Joined: 2013-10-10T13:16:40-07:00
Authentication code: 6789

Re: Performance problem

Post by alexandre.boudreault »

Performance are better but still, i would have tought that on the Xeon i would get much much better performance than on my laptop.
I tested on a dev server which is pretty similar to my production environement. This dev environment got an AMD Opteron 2376 and I
still get slightly better performance then on the Xeon.

Start to think that the VM configuration is a bit messed up on that Xeon.
Top
Post Reply

Return to “Bugs”