GraphicsMagick / Bugs / #634 Slow to read JPEG with big APP1 profile

On Fri, 21 Aug 2020, Mattias Wadman wrote:

I've run into a JPEG file that decodes quite slowly and the source
of the slowness seems to be that the JPEG has a APP1 profile divied
into 2624 parts. I guess it's using extended XMP?

What version of GraphicsMagick are you using?

If you can do

gm convert -debug coder infile.jpg null:

and capture the log output , then that may be helpful.

Also, the output of

gm identify -verbose infile.jpg would be helpful.

Unfortently I can't share the image because of legal reasons but I
could try to find another one or generate a file with the same
characteristics.

File size if 176106391 bytes and the APP1 xmp profile is 171821220 bytes long dividi into 2624 parts.

That is a quite huge profile!

If you can get me a file which behaves the same way, then that would
be helpful.

I would guess one reason for slowness could be the allocation and
copying in magick/profile.c:AppendImageProfile for each part?

This would be a reasonable assumption. For some reason, JPEG is only
able to produce 64k chunks and these need to be collected and
concatenated to produce the full profile. I don't think that there is
a way to know the total size without reading the content. The current
algorithm allocates new storage for the updated size, copies the
existing content, and then appends the new content.

I am quite certain that the implementation can be made much more
efficient. It has not been an issue (as far as I know) until now.

Bob

Bob Friesenhahn
bfriesen@simple.dallas.tx.us, http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer, http://www.GraphicsMagick.org/
Public Key, http://www.simplesystems.org/users/bfriesen/public-key.txt

On Fri, Aug 21, 2020 at 6:07 PM Bob Friesenhahn bfriesen@users.sourceforge.net wrote:

On Fri, 21 Aug 2020, Mattias Wadman wrote:

I've run into a JPEG file that decodes quite slowly and the source
of the slowness seems to be that the JPEG has a APP1 profile divied
into 2624 parts. I guess it's using extended XMP?

What version of GraphicsMagick are you using?

Sorry, I should have included that of course.

It's 1.3.35 with some patches built on linux and musl as libc.

Patches are:
Change default MinimumCoderClass to PrimaryCoderClass
Use png_set_chunk_malloc_max to set bigger chunk size
Uses a patched version of libpng to fix a invalid chunk reading bug.

GraphicsMagick 1.3.35 2020-02-23 Q16 http://www.GraphicsMagick.org/
Copyright (C) 2002-2020 GraphicsMagick Group.
Additional copyrights and licenses apply to this software.
See http://www.GraphicsMagick.org/www/Copyright.html for details.

Feature Support:
Native Thread Safe yes
Large Files (> 32 bit) yes
Large Memory (> 32 bit) yes
BZIP no
DPS no
FlashPix no
FreeType no
Ghostscript (Library) no
JBIG no
JPEG-2000 yes
JPEG yes
Little CMS no
Loadable Modules no
Solaris mtmalloc no
Google perftools tcmalloc no
OpenMP yes (201511 "4.5")
PNG yes
TIFF yes
TRIO no
Solaris umem no
WebP yes
WMF no
X11 no
XML no
ZLIB yes

Host type: x86_64-pc-linux-musl

Configured using the command:
./configure '--enable-static' '--disable-shared'
'--disable-dependency-tracking' '--with-quantum-depth=16' 'CFLAGS=-O3
-fno-strict-overflow -fstack-protector-all -fPIE' 'LDFLAGS=-Wl,-z,relro
-Wl,-z,now -fPIE -pie' 'CXXFLAGS=-O3 -fno-strict-overflow
-fstack-protector-all -fPIE'

Final Build Parameters:
CC = gcc
CFLAGS = -fopenmp -O3 -fno-strict-overflow -fstack-protector-all -fPIE
-Wall
CPPFLAGS =
CXX = g++
CXXFLAGS = -O3 -fno-strict-overflow -fstack-protector-all -fPIE
LDFLAGS = -Wl,-z,relro -Wl,-z,now -fPIE -pie
LIBS = -lwebp -lwebpmux -ltiff -ljasper -ljpeg -lpng16 -lz -lm
-lpthread

If you can do

gm convert -debug coder infile.jpg null:

08:04:01 0:0.007513 0.000u 1 constitute.c/ReadImage/1601/Coder:
Invoking "JPEG" decoder (Joint Photographic Experts Group JFIF format)
subimage=0 subrange=0
08:04:01 0:0.010911 0.000u 1 jpeg.c/ReadJPEGImage/1225/Coder:
Memory capped to 1671010713 bytes
08:04:01 0:0.010971 0.000u 1 jpeg.c/ReadJPEGImage/1241/Coder:
Reading JPEG header...
08:04:01 0:0.011048 0.000u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Start of Image"
08:04:01 0:0.011084 0.000u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "JFIF APP0 marker:
version 1.01, density 72x72 1"
08:04:01 0:0.011915 0.000u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: EXIF, header 0 bytes, data 8542 bytes
08:04:01 0:0.011990 0.000u 1 jpeg.c/ReadIPTCProfile/775/Coder:
Profile: IPTC, 15278 bytes
08:04:01 0:0.012073 0.000u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: XMP, header 29 bytes, data 2457 bytes
08:04:01 0:0.012992 0.000u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: APP1, header 0 bytes, data 65475 bytes
08:04:01 0:0.015375 0.000u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: APP1, header 0 bytes, data 65475 bytes
08:04:01 0:0.015842 0.000u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: APP1, header 0 bytes, data 65475 bytes

... 2000 of the same ...

08:16:06 12:5.626283 719.930u 1 jpeg.c/ReadGenericProfile/601/Coder:
Profile: APP1, header 0 bytes, data 14820 bytes
08:16:06 12:5.626426 719.930u 1 jpeg.c/ReadICCProfile/666/Coder:
ICC profile chunk: 3144 bytes
08:16:06 12:5.626980 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Quantization
Table 0 precision 0"
08:16:06 12:5.628551 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Quantization
Table 1 precision 0"
08:16:06 12:5.628610 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Start Of Frame 0xc0:
width=4000, height=4000, components=3"
08:16:06 12:5.629320 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 1:
2hx2v q=0"
08:16:06 12:5.629494 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 2:
1hx1v q=1"
08:16:06 12:5.629696 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 3:
1hx1v q=1"
08:16:06 12:5.630120 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Huffman Table
0x00"
08:16:06 12:5.632483 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 0 1 5
1 1 1 1 1"
08:16:06 12:5.632842 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 1 0 0
0 0 0 0 0"
08:16:06 12:5.633742 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Huffman Table
0x10"
08:16:06 12:5.633812 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 0 2 1
3 3 2 4 3"
08:16:06 12:5.634919 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 5 5 4
4 0 0 1 125"
08:16:06 12:5.635306 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Huffman Table
0x01"
08:16:06 12:5.635359 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 0 3 1
1 1 1 1 1"
08:16:06 12:5.636241 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 1 1 1
0 0 0 0 0"
08:16:06 12:5.636782 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Define Huffman Table
0x11"
08:16:06 12:5.637130 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 0 2 1
2 4 4 3 4"
08:16:06 12:5.637443 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " 7 5 4
4 0 1 2 119"
08:16:06 12:5.637599 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "Start Of Scan: 3
components"
08:16:06 12:5.638049 719.930u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 1: dc=0
ac=0"
08:16:06 12:5.638492 719.940u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 2: dc=1
ac=1"
08:16:06 12:5.639888 719.940u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Component 3: dc=1
ac=1"
08:16:06 12:5.640074 719.940u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: " Ss=0, Se=63, Ah=0,
Al=0"
08:16:06 12:5.640134 719.940u 1 jpeg.c/ReadJPEGImage/1245/Coder:
Done with reading JPEG header
08:16:06 12:5.640190 719.940u 1 jpeg.c/ReadJPEGImage/1276/Coder:
Image resolution set to 72x72 PixelsPerInch
08:16:06 12:5.640248 719.940u 1 jpeg.c/ReadJPEGImage/1425/Coder:
Interlace: nonprogressive
08:16:06 12:5.640811 719.940u 1 jpeg.c/ReadJPEGImage/1427/Coder:
Data precision: 8
08:16:06 12:5.641874 719.940u 1 jpeg.c/ReadJPEGImage/1429/Coder:
Components: 3
08:16:06 12:5.642708 719.940u 1 jpeg.c/ReadJPEGImage/1431/Coder:
Geometry: 4000x4000
08:16:06 12:5.647236 719.940u 1 jpeg.c/ReadJPEGImage/1434/Coder:
DCT Method: 0
08:16:06 12:5.647321 719.940u 1 jpeg.c/ReadJPEGImage/1436/Coder:
Fancy Upsampling: true
08:16:06 12:5.647773 719.940u 1 jpeg.c/ReadJPEGImage/1438/Coder:
Block Smoothing: true
08:16:06 12:5.648248 719.940u 1 jpeg.c/ReadJPEGImage/1449/Coder:
Starting JPEG decompression...
08:16:06 12:5.649290 719.940u 1 jpeg.c/EstimateJPEGQuality/932/Coder:
Quality: 94
08:16:06 12:5.649483 719.940u 1 jpeg.c/ReadJPEGImage/1470/Coder:
Colorspace: RGB (2)
08:16:06 12:5.649535 719.940u 1 jpeg.c/ReadJPEGImage/1477/Coder:
Sampling Factors: 2x2,1x1,1x1
08:16:06 12:6.107309 720.390u 1 jpeg.c/JPEGDecodeMessageHandler/304/Coder:
[9c927fc8-7ed1-4776-a637-4b2118d18770] JPEG Trace: "End Of Image"
08:16:06 12:6.108831 720.390u 1 jpeg.c/ReadJPEGImage/1746/Coder:
return
08:16:06 12:6.108904 720.390u 1 constitute.c/ReadImage/1613/Coder:
Returned from "JPEG" decoder: frames=1 cache=present monochrome=False
grayscale=False class=DirectClass colorspace=RGB
08:16:06 12:6.114093 720.390u 1 constitute.c/WriteImage/2232/Coder:
Invoking "NULL" encoder (Constant image of uniform color): cache=present
adjoin=True type=Undefined monochrome=False grayscale=False
class=DirectClass colorspace=RGB
08:16:06 12:6.114161 720.390u 1 constitute.c/WriteImage/2247/Coder:
Returned from "NULL" encoder, Succeeded

and capture the log output , then that may be helpful.

Also, the output of

gm identify -verbose infile.jpg would be helpful.

Image: 9c927fc8-7ed1-4776-a637-4b2118d18770
Format: JPEG (Joint Photographic Experts Group JFIF format)
Geometry: 4000x4000
Class: DirectClass
Type: true color
Depth: 8 bits-per-pixel component
Channel Depths:
Red: 8 bits
Green: 8 bits
Blue: 8 bits
Channel Statistics:
Red:
Minimum: 0.00 (0.0000)
Maximum: 65535.00 (1.0000)
Mean: 20646.96 (0.3151)
Standard Deviation: 20776.40 (0.3170)
Green:
Minimum: 0.00 (0.0000)
Maximum: 65535.00 (1.0000)
Mean: 14820.24 (0.2261)
Standard Deviation: 17410.00 (0.2657)
Blue:
Minimum: 0.00 (0.0000)
Maximum: 63222.00 (0.9647)
Mean: 16881.68 (0.2576)
Standard Deviation: 10121.82 (0.1544)
Resolution: 72x72 pixels/inch
Filesize: 167.9Mi
Interlace: No
Orientation: TopLeft
Background Color: white
Border Color: #DFDFDF
Matte Color: #BDBDBD
Page geometry: 4000x4000+0+0
Compose: Over
Dispose: Undefined
Iterations: 0
Compression: JPEG
JPEG-Quality: 94
JPEG-Colorspace: 2
JPEG-Colorspace-Name: RGB
JPEG-Sampling-factors: 2x2,1x1,1x1
Signature:
a283ccced05b3c915e7b4e4d93c38f49846fd4f81da38b91671386ba78fae927
Profile-color: 3144 bytes
Profile-iptc: 15278 bytes
unknown:
0x00000000: ff18ffff ff6affff ff112cff ffffffff 68ff0cff
------j----,-----h--
0x00000014: ff697134 ffff43ff ffff4aff 7cffffff ff6e663d
--iq4--C---J-|----nf
0x00000028: 0fffffff 33ff6174 ffff753f ffffff45 6bffffff
=----3-at--u?---Ek--
0x0000003c: ff0b32ff ff4036ff ff3dff77 ff747d2a ffff00 ---2--@6--
Profile-EXIF: 8542 bytes
Orientation: 1
X Resolution: 720000/10000
Y Resolution: 720000/10000
Resolution Unit: 2
Software: Adobe Photoshop 21.0 (Windows)
Date Time: 2020:07:31 17:17:07
Exif Offset: 166
Color Space: 1
Exif Image Width: 4000
Exif Image Length: 4000
Profile-XMP: 2457 bytes
Profile-APP1: 171821220 bytes
Tainted: False
User Time: 702.870u
Elapsed Time: 11m:47.950829s
Pixels Per Second: 22.1Ki

Unfortently I can't share the image because of legal reasons but I
could try to find another one or generate a file with the same
characteristics.

File size if 176106391 bytes and the APP1 xmp profile is 171821220 bytes
long dividi into 2624 parts.

That is a quite huge profile!

If you can get me a file which behaves the same way, then that would
be helpful.

Yeap I have no idea why something would produce a file like this. Will try
to extract the profile and see what it is.

I would guess one reason for slowness could be the allocation and
copying in magick/profile.c:AppendImageProfile for each part?

This would be a reasonable assumption. For some reason, JPEG is only
able to produce 64k chunks and these need to be collected and
concatenated to produce the full profile. I don't think that there is
a way to know the total size without reading the content. The current
algorithm allocates new storage for the updated size, copies the
existing content, and then appends the new content.

I am quite certain that the implementation can be made much more
efficient. It has not been an issue (as far as I know) until now.

Collect and join at the end i guess or some kind of double size strategy?

But yes I have no idea if this is some kind of pathological file or not yet.

-Mattias

Bob

Bob Friesenhahn
bfriesen@simple.dallas.tx.us, http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer, http://www.GraphicsMagick.org/
Public Key, http://www.simplesystems.org/users/bfriesen/public-key.txt

[bugs:#634] https://sourceforge.net/p/graphicsmagick/bugs/634/ Slow to
read JPEG with big APP1 profile*

Status: open
Group: v1.0_(example)
Created: Fri Aug 21, 2020 03:19 PM UTC by Mattias Wadman
Last Updated: Fri Aug 21, 2020 03:19 PM UTC
Owner: nobody

Hello!

I've run into a JPEG file that decodes quite slowly and the source of the
slowness seems to be that the JPEG has a APP1 profile divied into 2624
parts. I guess it's using extended XMP?

Unfortently I can't share the image because of legal reasons but I could
try to find another one or generate a file with the same characteristics.

File size if 176106391 bytes and the APP1 xmp profile is 171821220 bytes
long dividi into 2624 parts.

I would guess one reason for slowness could be the allocation and copying
in magick/profile.c:AppendImageProfile for each part?

-Mattias

Sent from sourceforge.net because you indicated interest in
https://sourceforge.net/p/graphicsmagick/bugs/634/

To unsubscribe from further messages, please visit
https://sourceforge.net/auth/subscriptions/

Bugs: ~~#634~~

alternate

Slow to read JPEG with big APP1 profile

Swiss army knife of image processing

Group

Searches

Help

#634 Slow to read JPEG with big APP1 profile

Related

Discussion

Bob

-Mattias

Related

Bob