Performance regression reading image files with large headers using stream API in 3.3.4

[konivo]

Hi,

I found a substantial slowdown in Animal Logic scene (https://animallogic.com/alab/) when accessing textures through OIIO infrastructure using OpenEXR 3.3.4 when compared to using 3.3.2 version.

Unfortunately I don't have a simple repro yet, but I've been able to trace the issue down to fix for #1984, and I've verified that disabling 1-byte read fixes the slowdown. The headers are quite large in alab textures and I wonder if they are not read by OIIO repeatedly.

A workaround could be to not use stream API (I am not sure that is possible as OIIO manages things), but we hope there could be a better fix, so that stream API is as fast as it used to be while behaving correctly for small files?

[lgritz]

It is also possible that OIIO is opening multiple times or reading the header multiple times, exacerbating the problem. Can you give a little more detail about which OIIO APIs are being used in this case? Is it something that can be reproduced simply by using the testtex harness with one of the Alab textures? (It's ok to transfer that part of the discussion to an OIIO issue.)

And, sorry, excuse my ignorance on the OpenEXR terminology, but what do you man by the "stream API" and what is the alternative?

[konivo]

Can you give a little more detail about which OIIO APIs are being used in this case?

When the texture is not yet in the cache, we call TextureSystem::imagespec() and in some cases we call that more than once. Furthermore we sometimes call OIIO::ImageInput::open(). And we call TextureSystem::get_texture_handle().

When the texture is in the cache we call just TextureSystem::texture()

The problem we observe happens when the cache is being populated.

Is it something that can be reproduced simply by using the testtex harness with one of the Alab textures?

I also tried igrep (grep on exr metadata from OIIO) on all files in Alab scene:

time find ./fragment -iname '*.exr' -exec <path_to_openimageio-2.6.3.0-fe137834>/bin/igrep black {} \;

with the following results:

slow - oiio with OpenEXR 3.3.4
real    0m18.802s
user    0m6.887s
sys     0m11.757s

fast - oiio with OpenEXR 3.3.4 with commit disabling 1-byte read on top
real    0m10.143s
user    0m3.191s
sys     0m6.924s

Then I repeated the same excerise for testtex --getimagespec:

slow
real    0m23.151s
user    0m8.636s
sys     0m17.926s


fast
real    0m14.511s
user    0m4.766s
sys     0m13.142s

Let me know if there is any other test you think could be useful.

And, sorry, excuse my ignorance on the OpenEXR terminology, but what do you man by the "stream API" and what is the alternative?

I am also not well versed in OpenEXR API, and I went with the explanation in #1984. I assumed OIIO is using the stream API because the 1-byte-read code-path was triggered (btw the OpenEXR commit introducing that is 55aa304)

[ThiagoIze]

I gave Ivo's a repro a try with the latest code from main (OIIO 3.1.3.0) and still saw the same slowdown: 20s with openexr 3.3.4 and 11s with 3.3.4 with the 1B reading commented out. So this is something we might need to optimize in OIIO.

[lgritz]

Proposed change on the OIIO side: AcademySoftwareFoundation/OpenImageIO#4832
But this only fixes the C++ version, I'm pretty sure OIIO should be using the C core library by default? I'm not sure what, if anything, to change on the C side.
@ThiagoIze are you doing something on your end to cause it to favor the C++ version of the OIIO's exr reader?

[ThiagoIze]

I tried your proposed change but it doesn't help my use case, which is where a bunch of threads are calling OIIO::ImageInput::open() nor the igrep example above. I guess that is to be expected if OIIO is not using the C++ code path?

Here's what the stack trace shows for where all the time is being spent in my case:

 * frame #0: 0x00007ffff724a407 libpthread.so.0`__pread64 + 87
    frame #1: 0x00007fffec49f1af libai.so`OpenImageIO_v2_6_3::Filesystem::IOFile::pread(this=<unavailable>, buf=0x00007fff801f9000, size=1, offset=733) at filesystem.cpp:1263:14
    frame #2: 0x00007fffec46abf6 libai.so`OpenImageIO_v2_6_3::oiio_exr_read_func(ctxt=0x00007fff927a9b00, userdata=<unavailable>, buffer=<unavailable>, sz=<unavailable>, offset=<unavailable>, error_cb=<unavailable>)(_priv_exr_context_t const*, int, char const*, ...)) at exrinput_c.cpp:83:33
    frame #3: 0x00007fffec6d766c libai.so`dispatch_read + 76
    frame #4: 0x00007fffec6e7e3a libai.so`scratch_seq_read + 282
    frame #5: 0x00007fffec6e883e libai.so`extract_attr_string + 46
    frame #6: 0x00007fffec6e7773 libai.so`internal_exr_parse_header + 8083
    frame #7: 0x00007fffec6d7a44 libai.so`exr_start_read + 548
    frame #8: 0x00007fffec46b2a4 libai.so`OpenImageIO_v2_6_3::OpenEXRCoreInput::open(this=0x00007fff7fef07e0, name="/tmp/alab-autotx//var/nas/scenes/AnimalLogic/ALab-2.0.2-beta/thelab02_with_remi/fragment/look/surfacing/structure_wall_fibro01/render_high/texture/look_surfacing_structure_wall_fibro01_render_high_texture/structure_wall_fibro01_BaseColor.1011_sRGB_ACEScg.exr.tx", newspec=0x00007fff8207cb20, config=<unavailable>) at exrinput_c.cpp:413:23
    frame #9: 0x00007fffec0e8f00 libai.so`OpenImageIO_v2_6_3::ImageInput::create(filename=(m_chars = "/tmp/alab-autotx//var/nas/scenes/AnimalLogic/ALab-2.0.2-beta/thelab02_with_remi/fragment/look/surfacing/structure_wall_fibro01/render_high/texture/look_surfacing_structure_wall_fibro01_render_high_texture/structure_wall_fibro01_BaseColor.1011_sRGB_ACEScg.exr.tx", m_len = 261), do_open=<unavailable>, config=<unavailable>, ioproxy=0x0000000000000000, plugin_searchpath=<unavailable>) at imageioplugin.cpp:752:27
    frame #10: 0x00007fffec1018bb libai.so`OpenImageIO_v2_6_3::ImageInput::open(filename=<unavailable>, config=<unavailable>, ioproxy=<unavailable>) at imageinput.cpp:160:16

[ThiagoIze]

Here's another example stack trace for where it seems most of the time is. I do see a "exr_uncompress_chunk", so I wonder if this is a 1B chunk and hence why it's so slow? It is being called from OIIO::OpenEXRCoreInput, so I assume this is C core code.

    frame #0: 0x00007fffec708d08 libai.so`deflate_decompress_bmi2 + 2312
    frame #1: 0x00007fffec709c25 libai.so`libdeflate_zlib_decompress_ex + 149
    frame #2: 0x00007fffec6edf65 libai.so`exr_uncompress_buffer + 117
    frame #3: 0x00007fffec70a714 libai.so`internal_exr_undo_zip + 148
    frame #4: 0x00007fffec6ee53c libai.so`exr_uncompress_chunk + 268
    frame #5: 0x00007fffec6ef272 libai.so`exr_decoding_run + 242
    frame #6: 0x00007fffec4719b3 libai.so`std::_Function_handler<void (long, long), OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1>::_M_invok
e(std::_Any_data const&, long&&, long&&) [inlined] OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(this=<unavailable>, tx=38, ty=0)::$_1::operator()(long, long) const at exrinput_c.cpp:1504:22
    frame #7: 0x00007fffec4716ce libai.so`std::_Function_handler<void (long, long), OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1>::_M_invok
e(std::_Any_data const&, long&&, long&&) [inlined] void std::__invoke_impl<void, OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1&, long, long>
((null)=<unavailable>, __f=<unavailable>, __args=<unavailable>, __args=<unavailable>)::$_1&, long&&, long&&) at invoke.h:61:14
    frame #8: 0x00007fffec4716c4 libai.so`std::_Function_handler<void (long, long), OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1>::_M_invok
e(std::_Any_data const&, long&&, long&&) [inlined] std::enable_if<is_invocable_r_v<void, OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1&, lon
g, long>, void>::type std::__invoke_r<void, OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(__fn=<unavailable>, __args=<unavailable>, __args=<unavailable>)::$_1&, long, long>(OpenImageIO_v2_6_3::OpenEXRCo
reInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1&, long&&, long&&) at invoke.h:111:2
    frame #9: 0x00007fffec4716c4 libai.so`std::_Function_handler<void (long, long), OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(int, int, int, int, int, int, int, int, int, int, void*)::$_1>::_M_invok
e(__functor=<unavailable>, __args=<unavailable>, __args=<unavailable>) at std_function.h:290:9
    frame #10: 0x00007fffec4c141e libai.so`std::_Function_handler<void (int, long, long, long, long), OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void (long, long)>&&, OpenImageIO_v2
_6_3::paropt)::$_2>::_M_invoke(std::_Any_data const&, int&&, long&&, long&&, long&&, long&&) [inlined] std::function<void (long, long)>::operator(this=<unavailable>, __args=38, __args=0)(long, long) const at std_
function.h:590:9
    frame #11: 0x00007fffec4c140e libai.so`std::_Function_handler<void (int, long, long, long, long), OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void (long, long)>&&, OpenImageIO_v2
_6_3::paropt)::$_2>::_M_invoke(std::_Any_data const&, int&&, long&&, long&&, long&&, long&&) at thread.cpp:851:21
    frame #12: 0x00007fffec4c13b9 libai.so`std::_Function_handler<void (int, long, long, long, long), OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void (long, long)>&&, OpenImageIO_v2
_6_3::paropt)::$_2>::_M_invoke(std::_Any_data const&, int&&, long&&, long&&, long&&, long&&) [inlined] void std::__invoke_impl<void, OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void
(long, long)>&&, OpenImageIO_v2_6_3::paropt)::$_2&, int, long, long, long, long>((null)=<unavailable>, __f=<unavailable>, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>, __
args=<unavailable>)>&&, OpenImageIO_v2_6_3::paropt)::$_2&, int&&, long&&, long&&, long&&, long&&) at invoke.h:61:14
    frame #13: 0x00007fffec4c13a0 libai.so`std::_Function_handler<void (int, long, long, long, long), OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void (long, long)>&&, OpenImageIO_v2
_6_3::paropt)::$_2>::_M_invoke(std::_Any_data const&, int&&, long&&, long&&, long&&, long&&) [inlined] std::enable_if<is_invocable_r_v<void, OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::functi
on<void (long, long)>&&, OpenImageIO_v2_6_3::paropt)::$_2&, int, long, long, long, long>, void>::type std::__invoke_r<void, OpenImageIO_v2_6_3::parallel_for_2D(__fn=<unavailable>, __args=<unavailable>, __args=<un
available>, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>)>&&, OpenImageIO_v2_6_3::paropt)::$_2&, int, long, long, long, long>(OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::f
unction<void (long, long)>&&, OpenImageIO_v2_6_3::paropt)::$_2&, int&&, long&&, long&&, long&&, long&&) at invoke.h:111:2
    frame #14: 0x00007fffec4c13a0 libai.so`std::_Function_handler<void (int, long, long, long, long), OpenImageIO_v2_6_3::parallel_for_2D(long, long, long, long, std::function<void (long, long)>&&, OpenImageIO_v2
_6_3::paropt)::$_2>::_M_invoke(__functor=0x00007fff912941b0, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>, __args=<unavailable>) at std_function.h:290:9
    frame #15: 0x00007fffec4c0e4f libai.so`OpenImageIO_v2_6_3::parallel_for_chunked_2D_id(long, long, long, long, long, long, std::function<void (int, long, long, long, long)>&&, OpenImageIO_v2_6_3::paropt) [inli
ned] std::function<void (int, long, long, long, long)>::operator(this=<unavailable>, __args=-1, __args=0, __args=64, __args=0, __args=1)(int, long, long, long, long) const at std_function.h:590:9
    frame #16: 0x00007fffec4c0e28 libai.so`OpenImageIO_v2_6_3::parallel_for_chunked_2D_id(xbegin=<unavailable>, xend=64, xchunksize=0, ybegin=0, yend=1, ychunksize=0, task=0x00007fff912941b0, opt=paropt @ 0x00007
fff91294188)>&&, OpenImageIO_v2_6_3::paropt) at thread.cpp:803:9
    frame #17: 0x00007fffec4c125b libai.so`OpenImageIO_v2_6_3::parallel_for_2D(xbegin=<unavailable>, xend=<unavailable>, ybegin=<unavailable>, yend=<unavailable>, task=0x00007fff91294270, opt=paropt @ 0x00007fff9
12941e0)>&&, OpenImageIO_v2_6_3::paropt) at thread.cpp:846:5
    frame #18: 0x00007fffec46f57f libai.so`OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(this=0x00007fff77f6c480, subimage=0, miplevel=0, xbegin=0, xend=<unavailable>, ybegin=<unavailable>, yend=3456, z
begin=0, zend=<unavailable>, chbegin=0, chend=<unavailable>, data=0x00007fff8b6f6000) at exrinput_c.cpp:1464:5
    frame #19: 0x00007fffec46f1bd libai.so`OpenImageIO_v2_6_3::OpenEXRCoreInput::read_native_tiles(this=0x00007fff77f6c480, subimage=0, miplevel=0, xbegin=0, xend=4096, ybegin=3392, yend=<unavailable>, zbegin=<un
available>, zend=<unavailable>, data=<unavailable>) at exrinput_c.cpp:1408:12
    frame #20: 0x00007fffec103b16 libai.so`OpenImageIO_v2_6_3::ImageInput::read_tiles(this=<unavailable>, subimage=<unavailable>, miplevel=<unavailable>, xbegin=<unavailable>, xend=<unavailable>, ybegin=<unavaila
ble>, yend=<unavailable>, zbegin=<unavailable>, zend=<unavailable>, chbegin=<unavailable>, chend=3, format=(basetype = '\0', aggregate = '\0', vecsemantics = '\0', reserved = '\0', arraylen = 0), data=<unavailabl
e>, xstride=<unavailable>, ystride=<unavailable>, zstride=<unavailable>) at imageinput.cpp:644:20
    frame #21: 0x00007fffec10533e libai.so`OpenImageIO_v2_6_3::ImageInput::read_image(this=0x00007fff77f6c480, subimage=<unavailable>, miplevel=<unavailable>, chbegin=<unavailable>, chend=<unavailable>, format=(b
asetype = '\0', aggregate = '\0', vecsemantics = '\0', reserved = '\0', arraylen = 0), data=<unavailable>, xstride=<unavailable>, ystride=<unavailable>, zstride=<unavailable>, progress_callback=<unavailable>, pro
gress_callback_data=<unavailable>)(void*, float), void*) at imageinput.cpp:970:23
    frame #22: 0x00007fffec10a356 libai.so`OpenImageIO_v2_6_3::ImageBufImpl::read(this=0x00007fff923c1400, subimage=0, miplevel=<unavailable>, chbegin=<unavailable>, chend=<unavailable>, force=<unavailable>, conv
ert=(basetype = '\0', aggregate = '\0', vecsemantics = '\0', reserved = '\0', arraylen = 0), progress_callback=<unavailable>, progress_callback_data=<unavailable>, do_lock=<unavailable>)(void*, float), void*, Ope
nImageIO_v2_6_3::DoLock) at imagebuf.cpp:1191:27
    frame #23: 0x00007fffec1076af libai.so`OpenImageIO_v2_6_3::ImageBufImpl::reset(this=0x00007fff923c1400, filename=(m_chars = "/var/nas/scenes/AnimalLogic/ALab-2.0.2-beta/thelab02_with_remi/fragment/look/surfac
ing/structure_wall_fibro02/render_high/texture/look_surfacing_structure_wall_fibro02_render_high_texture/structure_wall_fibro02_Normal.1012.exr", m_len = 226), subimage=0, miplevel=0, imagecache=0x000000000000000
0, config=0x00007fff91295ff8, ioproxy=0x0000000000000000) at imagebuf.cpp:764:9
    frame #24: 0x00007fffec107367 libai.so`OpenImageIO_v2_6_3::ImageBufImpl::ImageBufImpl(this=0x00007fff923c1400, filename=(m_chars = "/var/nas/scenes/AnimalLogic/ALab-2.0.2-beta/thelab02_with_remi/fragment/look
/surfacing/structure_wall_fibro02/render_high/texture/look_surfacing_structure_wall_fibro02_render_high_texture/structure_wall_fibro02_Normal.1012.exr", m_len = 226), subimage=0, miplevel=0, imagecache=0x00000000
00000000, spec=0x0000000000000000, buffer=0x0000000000000000, config=0x00007fff91295ff8, ioproxy=0x0000000000000000, xstride=-9223372036854775808, ystride=-9223372036854775808, zstride=-9223372036854775808) at im
agebuf.cpp:406:9
    frame #25: 0x00007fffec1088bd libai.so`OpenImageIO_v2_6_3::ImageBuf::ImageBuf(this=0x00007fff91f4c2c0, filename=(m_chars = "/var/nas/scenes/AnimalLogic/ALab-2.0.2-beta/thelab02_with_remi/fragment/look/surfaci
ng/structure_wall_fibro02/render_high/texture/look_surfacing_structure_wall_fibro02_render_high_texture/structure_wall_fibro02_Normal.1012.exr", m_len = 226), subimage=0, miplevel=0, imagecache=0x0000000000000000
, config=<unavailable>, ioproxy=<unavailable>) at imagebuf.cpp:510:18