emmalloc failing to allocate memory whereas dlmalloc can successfully allocate

[emelalkim]

Version of emscripten/emsdk:
emcc (Emscripten gcc/clang-like replacement + linker emulating GNU ld) 3.1.46 (1960782)
clang version 18.0.0 (https://github.com/llvm/llvm-project 75501f53624de92aafce2f1da698b249a7293dc7)
Target: wasm32-unknown-emscripten
Thread model: posix
InstalledDir: /emsdk/upstream/bin

Full link command and output with -v appended:
We are using emscripten to compile openjpeg library to create codecs for DICOM files.
configure: cmake .. -DCMAKE_TOOLCHAIN_FILE=/emsdk/upstream/emscripten/cmake/Modules/Platform/Emscripten.cmake -DCMAKE_CROSSCOMPILING_EMULATOR=/emsdk/node/16.20.0_64bit/bin/node

Two different js files are created:
openjpegjs.js
/emsdk/upstream/emscripten/em++ -O3 --bind -s MODULARIZE=1 -s EXPORT_NAME=OpenJPEGJS -s WASM=0 -s DISABLE_EXCEPTION_CATCHING=1 -s ASSERTIONS=2 -s NO_EXIT_RUNTIME=1 -s MALLOC=emmalloc -s ALLOW_MEMORY_GROWTH=1 -s INITIAL_MEMORY=50mb -s FILESYSTEM=0 -s EXPORTED_FUNCTIONS=[] -s EXPORTED_RUNTIME_METHODS=[ccall] @CMakeFiles/openjpegjs.dir/objects1.rsp -o ../extern/openjpeg/bin/openjpegjs.js @CMakeFiles/openjpegjs.dir/linklibs.rsp
openjpegjs_decode.js
/emsdk/upstream/emscripten/em++ -O3 --bind -s MODULARIZE=1 -s EXPORT_NAME=OpenJPEGJS -s WASM=0 -s DISABLE_EXCEPTION_CATCHING=1 -s ASSERTIONS=2 -s NO_EXIT_RUNTIME=1 -s MALLOC=emmalloc -s ALLOW_MEMORY_GROWTH=1 -s INITIAL_MEMORY=50mb -s FILESYSTEM=0 -s EXPORTED_FUNCTIONS=[] -s EXPORTED_RUNTIME_METHODS=[ccall] @CMakeFiles/openjpegjs_decode.dir/objects1.rsp -o ../extern/openjpeg/bin/openjpegjs_decode.js @CMakeFiles/openjpegjs_decode.dir/linklibs.rsp

When we try to decode some files using openjpegjs.js, memory allocation crashes while trying to allocate 595*4 bytes of memory in this line. It increases the heap size till it exceeds 2GB and cannot allocate memory which results in not being able to decompress the data.
Here are the assertion logs.

encodedBitStream.length= 1960356
[INFO] Header of tile 1 / 1 has been read.
Heap resize call from 52428800 to 62914560 took 2.5182799994945526 msecs. Success: true
Heap resize call from 62914560 to 75497472 took 4.030688002705574 msecs. Success: true
Heap resize call from 75497472 to 90636288 took 0.11062300205230713 msecs. Success: true
Heap resize call from 90636288 to 108789760 took 4.0902139991521835 msecs. Success: true
Heap resize call from 108789760 to 130547712 took 0.43175700306892395 msecs. Success: true
Heap resize call from 130547712 to 156696576 took 0.20280899107456207 msecs. Success: true
Heap resize call from 156696576 to 188088320 took 2.495059996843338 msecs. Success: true
Heap resize call from 188088320 to 225705984 took 0.8876210004091263 msecs. Success: true
Heap resize call from 225705984 to 270860288 took 0.14028400182724 msecs. Success: true
Heap resize call from 270860288 to 325058560 took 1.9511590003967285 msecs. Success: true
Heap resize call from 325058560 to 390070272 took 0.7931340038776398 msecs. Success: true
Heap resize call from 390070272 to 468123648 took 0.15468500554561615 msecs. Success: true
Heap resize call from 468123648 to 561774592 took 1.5468769967556 msecs. Success: true
Heap resize call from 561774592 to 662503424 took 0.49696899950504303 msecs. Success: true
Heap resize call from 662503424 to 763232256 took 0.1452219933271408 msecs. Success: true
Heap resize call from 763232256 to 863961088 took 1.945467010140419 msecs. Success: true
Heap resize call from 863961088 to 964689920 took 0.6675080060958862 msecs. Success: true
Heap resize call from 964689920 to 1065418752 took 1.5788139998912811 msecs. Success: true
Heap resize call from 1065418752 to 1166147584 took 3.2779290080070496 msecs. Success: true
Heap resize call from 1166147584 to 1266876416 took 2.6842510104179382 msecs. Success: true
Heap resize call from 1266876416 to 1367605248 took 3.610280990600586 msecs. Success: true
Heap resize call from 1367605248 to 1468334080 took 3.7163310050964355 msecs. Success: true
Heap resize call from 1468334080 to 1569062912 took 2.760885000228882 msecs. Success: true
Heap resize call from 1569062912 to 1669791744 took 3.910877004265785 msecs. Success: true
Heap resize call from 1669791744 to 1770520576 took 3.2484830021858215 msecs. Success: true
Heap resize call from 1770520576 to 1871249408 took 3.4929400086402893 msecs. Success: true
Heap resize call from 1871249408 to 1971978240 took 4.082751989364624 msecs. Success: true
Heap resize call from 1971978240 to 2072707072 took 3.2575770020484924 msecs. Success: true
Heap resize call from 2072707072 to 2147483648 took 3.5487619936466217 msecs. Success: true
Cannot enlarge memory, requested 2147484432 bytes, but the limit is 2147483648 bytes!
[ERROR] Failed to decode.
[ERROR] Failed to decode tile 1/1
[ERROR] opj_decompress: failed to decode tile!

If we use openjpegjs_decode.js instead, it can successfully decompress

encodedBitStream.length= 1960356
[INFO] Start to read j2k main header (0).
[INFO] Main header has been correctly decoded.
[INFO] Header of tile 1 / 1 has been read.
Decode of ./../fixtures/j2k/EE60E32E_dat.j2k took 392.496375 ms
  frameInfo =  {
  width: 1030,
  height: 1870,
  bitsPerSample: 14,
  componentCount: 1,
  isSigned: false
}
 imageOffset =  { x: 0, y: 0 }
  decoded length =  3852200

If we use dlmalloc instead of emmalloc, it can decompress without any issues with both js files.
For further information about the issue and solution see the issue and PR
We wanted to report this as we couldn't understand the root cause of why emmalloc had this problem and it is not documented as a shortcoming.

[kripken]

Possibly the issue here arises because emmalloc is less efficient than dlmalloc. As a result emmalloc may need more memory to achieve the same amount of allocations, due to fragmentation etc. - emmalloc trades off size versus efficiency basically. So I'd guess that dlmalloc needs a little less total memory, and manages to not error on that limit.

Note that you can raise the limit above 2GB (the default), for example to 4GB: -sMAXIMUM_MEMORY=4GB.

[emelalkim]

@kripken the amount of memory it tries to allocate is 595*4 bytes. Does it make sense that it needs more than 2GB?

[kripken]

Oh, maybe I misunderstood. I thought that the last allocation was 595*4, but that there were other allocations before? The 2GB figure is the limit on the total amount of memory in use.

[sbc100]

Decoding that jpeg should not require anything like that much memory.. something must be going very wrong. Can you do some debugging to find out why its trying allocate so much memory? Perhaps capturing the backtrace on memory growth would help see where its coming from.

[chafey]

I am the original author of this OpenJPEG WASM build and I agree that 2GB is way more than should be needed to decompress this. I know that it allocates some fairly large buffers on the heap possibly intermixed with smaller allocations. Is there a chance that the heap is getting so big due to memory fragmentation with emmalloc? It seems unlikely that OpenJPEG is allocating all that memory and I don't think the wrapper code is leaking (I will double check)

[chafey]

Just double checked the code and didn't notice any obvious leaks. I am not sure what you mean by capturing a backtrace on memory growth - can you point me to more info on that (google didn't reveal anything)? I hate leaving things like this unresolved so would like to track down the root cause. OpenJPEG is a huge library and checking it for leaks may take considerable time.

[emelalkim]

Hi, this is the line it fails. I added some logs above and below it to debug it like this.

printf("Trying to allocate %d,%zu \n",
                                   flagssize, sizeof(opj_flag_t));
t1->flags = (opj_flag_t*) opj_aligned_malloc(flagssize * sizeof(
                            opj_flag_t));
printf("Successfully allocated %p \n",
                                   t1->flags);

Here is the log and assertions with openjpegjs.js

[INFO] Header of tile 1 / 1 has been read.
Trying to allocate 595,4 
Heap resize call from 52428800 to 62914560 took 9.15191999077797 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 52428800,62914560
Heap resize call from 62914560 to 75497472 took 18.244430005550385 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 62914560,75497472
Heap resize call from 75497472 to 90636288 took 15.389878004789352 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 75497472,90636288
Heap resize call from 90636288 to 108789760 took 34.179903998970985 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 90636288,108789760
Heap resize call from 108789760 to 130547712 took 23.30315700173378 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 108789760,130547712
Heap resize call from 130547712 to 156696576 took 26.621210992336273 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 130547712,156696576
Heap resize call from 156696576 to 188088320 took 59.25681500136852 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 156696576,188088320
Heap resize call from 188088320 to 225705984 took 37.7863489985466 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 188088320,225705984
Heap resize call from 225705984 to 270860288 took 38.673955008387566 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 225705984,270860288
Heap resize call from 270860288 to 325058560 took 52.473206996917725 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 270860288,325058560
Heap resize call from 325058560 to 390070272 took 74.66965200006962 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 325058560,390070272
Heap resize call from 390070272 to 468123648 took 67.89711600542068 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 390070272,468123648
Heap resize call from 468123648 to 561774592 took 146.05747298896313 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 468123648,561774592
Heap resize call from 561774592 to 662503424 took 97.38967099785805 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 561774592,662503424
Heap resize call from 662503424 to 763232256 took 141.96113599836826 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 662503424,763232256
Heap resize call from 763232256 to 863961088 took 139.8098829984665 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 763232256,863961088
Heap resize call from 863961088 to 964689920 took 352.7677489966154 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 863961088,964689920
Heap resize call from 964689920 to 1065418752 took 175.03405199944973 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 964689920,1065418752
Heap resize call from 1065418752 to 1166147584 took 222.02861399948597 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1065418752,1166147584
Heap resize call from 1166147584 to 1266876416 took 220.9680499881506 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1166147584,1266876416
Heap resize call from 1266876416 to 1367605248 took 259.4167490005493 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1266876416,1367605248
Heap resize call from 1367605248 to 1468334080 took 223.19872099161148 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1367605248,1468334080
Heap resize call from 1468334080 to 1569062912 took 285.17606899142265 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1468334080,1569062912
Heap resize call from 1569062912 to 1669791744 took 259.60784301161766 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1569062912,1669791744
Heap resize call from 1669791744 to 1770520576 took 304.19291900098324 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1669791744,1770520576
Heap resize call from 1770520576 to 1871249408 took 339.73202300071716 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1770520576,1871249408
Heap resize call from 1871249408 to 1971978240 took 371.1722670048475 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1871249408,1971978240
Heap resize call from 1971978240 to 2072707072 took 306.3399900048971 msecs. Success: true
Warning: Enlarging memory arrays, this is not fast! 1971978240,2072707072
growMemory: Attempted to grow heap from 2072707072 bytes to 2147483648 bytes, but got error: RangeError: Invalid array buffer length
Heap resize call from 2072707072 to 2147483648 took 0.25585100054740906 msecs. Success: false
growMemory: Attempted to grow heap from 2072707072 bytes to 2147483648 bytes, but got error: RangeError: Invalid array buffer length
Heap resize call from 2072707072 to 2147483648 took 0.0766340047121048 msecs. Success: false
growMemory: Attempted to grow heap from 2072707072 bytes to 2147483648 bytes, but got error: RangeError: Invalid array buffer length
Heap resize call from 2072707072 to 2147483648 took 0.07394599914550781 msecs. Success: false
Failed to grow the heap from 2072707072 bytes to 2147483648 bytes, not enough memory!
[ERROR] Failed to decode.
[ERROR] Failed to decode tile 1/1
[ERROR] opj_decompress: failed to decode tile!

With the same test file, when I use the openjpegjs_decode.js, it is able to decode successfully without resizing the heap

[INFO] Header of tile 1 / 1 has been read.
Trying to allocate 595,4 
Successfully allocated 0xc6d6a0 
Trying to allocate 595,4 
Successfully allocated 0xc6d6a0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1056,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 858,4 
Successfully allocated 0xc72be0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 858,4 
Successfully allocated 0xc72be0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 858,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 462,4 
Successfully allocated 0xc6d6a0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 462,4 
Successfully allocated 0xc6d6a0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 462,4 
Successfully allocated 0xc6d6a0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 792,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 792,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 1188,4 
Successfully allocated 0xc6b7e0 
Trying to allocate 792,4 
Successfully allocated 0xc6b7e0 
Decode of ./../fixtures/j2k/EE60E32E_dat.j2k took 16001.020072 ms

[kripken]

Perhaps use mallinfo() to find out how much memory is in use?

https://github.com/emscripten-core/emscripten/blob/main/test/core/test_mallinfo.c

Printing the used memory right before and right after that call would be interesting I think. That would include allocations in other places as well and not just here, and by comparing dlmalloc to emmalloc we can confirm exactly how much dlmalloc uses.

[chafey]

@emelalkim Am I reading this correctly - the heap gets expanded from 50MB to 2GB just trying to allocate 2380 bytes?

[sbc100]

I am the original author of this OpenJPEG WASM build and I agree that 2GB is way more than should be needed to decompress this. I know that it allocates some fairly large buffers on the heap possibly intermixed with smaller allocations. Is there a chance that the heap is getting so big due to memory fragmentation with emmalloc? It seems unlikely that OpenJPEG is allocating all that memory and I don't think the wrapper code is leaking (I will double check)

The input files is 1.9 mb right? How can you you/they explain needing 2GB of memory to decompress a small image? Clearly something fundamental is going wrong here, no?

[sbc100]

Perhaps the clue is in the use of alignment in opj_aligned_malloc .. perhaps emmalloc is less test tested on aligned alloc. What does opj_aligned_malloc do exactly?

[chafey]

I am the original author of this OpenJPEG WASM build and I agree that 2GB is way more than should be needed to decompress this. I know that it allocates some fairly large buffers on the heap possibly intermixed with smaller allocations. Is there a chance that the heap is getting so big due to memory fragmentation with emmalloc? It seems unlikely that OpenJPEG is allocating all that memory and I don't think the wrapper code is leaking (I will double check)

The input files is 1.9 mb right? How can you you/they explain needing 2GB of memory to decompress a small image? Clearly something fundamental is going wrong here, no?

I can't explain it and I suspect OpenJPEG can't either - hence my question about whether some kind of memory fragmentation is happening.

[chafey]

Perhaps the clue is in the use of alignment in opj_aligned_malloc .. perhaps emmalloc is less test tested on aligned alloc. What does opj_aligned_malloc do exactly?

yes just noticed that too - it appears to be trying to allocate memory on a 16 byte boundary

[kripken]

@chafey I had the same question, yeah - mallinfo as I suggested would be a way to confirm that (we'd know exactly how much was used before the attempted allocation).

@sbc100

The input files is 1.9 mb right? How can you you/they explain needing 2GB of memory to decompress a small image? Clearly something fundamental is going wrong here, no?

I agree it seems very odd, but it could be the result of many tiny allocations - where the overhead per allocation is much larger than the allocations themselves - plus fragmentation which can lead to "lost" memory. dlmalloc does much better than emmalloc on both tiny allocations and on fragmentation, and for those reasons emmalloc would not be recommended in such a situation. But, yes, a bug in emmalloc is also very possible here.

Aligned allocation could also be an issue as you suggested @sbc100 . We recently fixed some issues there, like #20704 - which I see landed after 3.1.46 which is what was mentioned by @emelalkim in the top comment. So I would recommend trying a recent emsdk to see if it's better.