oxipng icon indicating copy to clipboard operation
oxipng copied to clipboard

Race condition in verbose output

Open mistydemeo opened this issue 1 year ago • 3 comments

In 9.0.0, with verbose output enabled, if I process multiple files at once the verbose logs are chaotically intermixed in a way that makes it difficult to tell which logs have to do with which input image. Here's a sample:

Processing: gn00015.png
Processing: gn00002.png
Processing: gn00006.png
Processing: gn00005.png
Processing: gn00007.png
Processing: gn00017.png
Processing: gn00000.png
Processing: gn00010.png
    512x343 pixels, PNG format
    8-bit RGB, non-interlaced
    IDAT size = 227717 bytes
    File size = 230974 bytes
Trying: 10 filters
    512x343 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 20235 bytes
    File size = 23527 bytes
    512x343 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 26606 bytes
    File size = 29898 bytes
Reducing image to 8-bit RGB, non-interlaced
Trying: 10 filters
    512x343 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 210150 bytes
    File size = 213514 bytes
    512x343 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 251942 bytes
    File size = 255318 bytes

By comparison, here's the same command run in 8.0.0:

Processing: gn00000.png
    512x343 pixels, PNG format
    3x8 bits/pixel, RGB (non-interlaced)
    IDAT size = 227717 bytes
    File size = 230974 bytes
Trying: 10 filters
    zc = 12  f = Average  >227726 bytes
    zc = 12  f = Paeth    >227726 bytes
    zc = 12  f = Up       >227726 bytes
    zc = 12  f = Sub      >227726 bytes
    zc = 12  f = Entropy  >227726 bytes
    zc = 12  f = None     >227726 bytes
    zc = 12  f = MinSum   >227726 bytes
    zc = 12  f = Bigrams  >227726 bytes
    zc = 12  f = BigEnt   >227726 bytes
    zc = 12  f = Brute    >227726 bytes
    IDAT size = 227717 bytes (0 bytes decrease)
    file size = 230974 bytes (0 bytes = 0.00% decrease)
File already optimized
Processing: gn00001.png
    512x343 pixels, PNG format
    3x8 bits/pixel, RGB (non-interlaced)
    IDAT size = 20307 bytes
    File size = 23564 bytes
Trying: 10 filters
    zc = 12  f = None      20302 bytes
    zc = 12  f = MinSum   >20316 bytes
    zc = 12  f = Bigrams  >20316 bytes
    zc = 12  f = Up       >20316 bytes
    zc = 12  f = BigEnt   >20316 bytes
    zc = 12  f = Entropy  >20316 bytes
    zc = 12  f = Sub      >20316 bytes
    zc = 12  f = Paeth    >20316 bytes
    zc = 12  f = Average  >20311 bytes
    zc = 12  f = Brute    >20311 bytes
Found better combination:
    zc = 12  f = None      20302 bytes
    IDAT size = 20302 bytes (5 bytes decrease)
    file size = 23559 bytes (5 bytes = 0.02% decrease)
Output: gn00001.png

The input command is oxipng -omax --verbose --alpha $files

mistydemeo avatar Nov 07 '23 07:11 mistydemeo

Yes, this is true 😂 Is it a problem? I don’t think there are any good options for resolving it. Like, maybe we could prefix each line with the filename, but that could also look pretty messy.

(This isn’t a “race condition” as such, it’s just printing output as it occurs across multiple threads)

andrews05 avatar Nov 07 '23 07:11 andrews05

@andrews05 - I presume limiting the threads is a temporary 'fix' ...? --threads 1 ...?

Edit: Perhaps this could also be covered by documentation, as discussed before.

  • Maximum threads used on a single image is 10, if evaluating all filters. (Still true?)
  • For higher thread utilisation, multiple images may be processed simultaneously, although verbose output can be intermixed.

As I personally feed oxipng one image at a time (via a script), I had never observed this behaviour. It does seem kinda broken to me...

ace-dent avatar Nov 07 '23 08:11 ace-dent

Yeah, -t1 would certainly avoid it, it would just take longer. What we're seeing is just a natural consequence of processing multiple files in parallel. Maybe we could prefix each line with an index number of the current file? That would be a lot tidier than the file name.

andrews05 avatar Nov 08 '23 21:11 andrews05