Race condition in verbose output

[mistydemeo]

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

[andrews05]

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)

[ace-dent]

@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...

[andrews05]

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.