And to answer the question about mtrace.
root@host:~# MALLOC_TRACE=mtrace.log ./threadarena Zoom140.png
1685735077
VSZ RSS USER COMMAND
2312024 8124 root ./threadarena Zoom140.png
33
1685735078
VSZ RSS USER COMMAND
4605784 9684 root ./threadarena Zoom140.png
67
1685735079
VSZ RSS USER COMMAND
6899544 11232 root ./threadarena Zoom140.png
101
1685735080
VSZ RSS USER COMMAND
9193304 12796 root ./threadarena Zoom140.png
135
1685735081
VSZ RSS USER COMMAND
11487064 14328 root ./threadarena Zoom140.png
169
1685735082
VSZ RSS USER COMMAND
13780824 15924 root ./threadarena Zoom140.png
203
1685735084
VSZ RSS USER COMMAND
16074584 17424 root ./threadarena Zoom140.png
237
1685735085
VSZ RSS USER COMMAND
18368344 19004 root ./threadarena Zoom140.png
271
1685735086
VSZ RSS USER COMMAND
20662104 20536 root ./threadarena Zoom140.png
305
1685735087
VSZ RSS USER COMMAND
20989784 21948 root ./threadarena Zoom140.png
309
root@host:~# mtrace ./threadarena mtrace.log
- 0x00007f31380008d0 Free 365 was never alloc'd 0x7f315afcc4d4
- 0x00007f3150008a70 Free 367 was never alloc'd 0x7f315afcc4bb
- 0x00007f3150006ed0 Free 369 was never alloc'd 0x7f315afcc4bb
- 0x00007f3150008300 Free 370 was never alloc'd 0x7f315afcc4bb
- 0x00007f3150008a90 Free 371 was never alloc'd 0x7f315afcc4bb
- 0x00007f315000b350 Free 372 was never alloc'd 0x7f315afcc4bb
- 0x00007f315000b150 Free 373 was never alloc'd 0x7f315afcc4bb
- 0x00007f315000b050 Free 374 was never alloc'd 0x7f315afcc4bb
- 0x00007f315000af50 Free 375 was never alloc'd 0x7f315afcc4bb
...
- 0x00007f2c5000a610 Free 3839 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c50002d90 Free 3840 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c50007df0 Free 3842 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c50011940 Free 3843 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c50011ad0 Free 3844 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c5000a740 Free 3846 was never alloc'd 0x7f315afcc4bb
- 0x00007f2c500008d0 Free 3847 was never alloc'd 0x7f315afcc4d4
Memory not freed:
-----------------
Address Size Caller
0x0000555b1d8652d0 0xd0 at 0x7f315a4a90f9
There's a total of 514 "Free xxx was never alloc'd" messages, which doesn't
match the thread arena leaks. It might match the total number of threads OpenMP
might use, but it seems a bit off.
As an extra data point, restricting the number of OpenMP threads doesn't fix
the problem:
root@host:~# OMP_NUM_THREADS=8 ./threadarena Zoom140.png
1685735486
VSZ RSS USER COMMAND
345944 8324 root ./threadarena Zoom140.png
4
1685735487
VSZ RSS USER COMMAND
608088 9724 root ./threadarena Zoom140.png
7
1685735488
VSZ RSS USER COMMAND
870232 11156 root ./threadarena Zoom140.png
10
1685735489
VSZ RSS USER COMMAND
1132376 12556 root ./threadarena Zoom140.png
13
1685735490
VSZ RSS USER COMMAND
1394520 13988 root ./threadarena Zoom140.png
16
1685735491
VSZ RSS USER COMMAND
1656664 15388 root ./threadarena Zoom140.png
19
1685735492
VSZ RSS USER COMMAND
1918808 16820 root ./threadarena Zoom140.png
22
1685735493
VSZ RSS USER COMMAND
2180952 18220 root ./threadarena Zoom140.png
25
1685735494
VSZ RSS USER COMMAND
2443096 19652 root ./threadarena Zoom140.png
28
1685735495
VSZ RSS USER COMMAND
2705240 21052 root ./threadarena Zoom140.png
31
________________________________
From: Beauregard,Christophe (ECCC) <christophe.beaureg...@ec.gc.ca>
Sent: Friday, June 2, 2023 15:32
To: Bob Friesenhahn <bfrie...@simple.dallas.tx.us>; 1037...@bugs.debian.org
<1037...@bugs.debian.org>
Subject: Re: Bug#1037042: graphicsmagick: GetImageDepth has a thread arena and
memory leak
I'm kind of stuck with this version of GM; my organization is currently
tracking Debian LTS.
I suppose I should have added some more points... while digging into this I did
run diagnostics under gdb on my "real" application.
The threads themselves are terminating correctly; there aren't any
lingering/unjoined threads, and the internal pthreads cleanup routines are all
being hit. No sign of any red flags.
Running with MAGICK_DEBUG=resource:
root@host:~# MAGICK_DEBUG=resource ./threadarena Zoom140.png
18:46:16 0:0.000223 0.000u 2666849
resource.c/InitializeMagickResources/447/Resource:
Total physical memory 128776 MB (32966668 pages and 4096 bytes per page)
18:46:16 0:0.000279 0.000u 2666849
resource.c/InitializeMagickResources/615/Resource:
40 CPU cores are available
18:46:16 0:0.000294 0.000u 2666849
resource.c/InitializeMagickResources/644/Resource:
System file open limits are 1024 soft, 1048576 hard
18:46:16 0:0.000306 0.000u 2666849
resource.c/SetMagickResourceLimit/964/Resource:
Set files resource limit to 256
18:46:16 0:0.000321 0.000u 2666849
resource.c/SetMagickResourceLimit/964/Resource:
Set map resource limit to 251.5GiB
18:46:16 0:0.000332 0.000u 2666849
resource.c/SetMagickResourceLimit/964/Resource:
Set memory resource limit to 125.8GiB
18:46:16 0:0.000343 0.000u 2666849
resource.c/SetMagickResourceLimit/964/Resource:
Set threads resource limit to 40
18:46:16 0:0.001345 0.000u 2666849
resource.c/AcquireMagickResource/235/Resource:
width +414P/----/256.0MiP
18:46:16 0:0.001372 0.000u 2666849
resource.c/AcquireMagickResource/235/Resource:
height +377P/----/256.0MiP
18:46:16 0:0.001383 0.000u 2666849
resource.c/AcquireMagickResource/235/Resource:
pixels +152.4KiP/----/Unlimited
18:46:16 0:0.001394 0.000u 2666849
resource.c/AcquireMagickResource/235/Resource:
memory +1.5MiB/1.5MiB/125.8GiB
18:46:16 0:0.019786 0.010u 2666849
resource.c/LiberateMagickResource/811/Resource:
memory -1.5MiB/0B/125.8GiB
1685731577
VSZ RSS USER COMMAND
2443096 8280 root ./threadarena Zoom140.png
35
18:46:17 0:1.054500 0.100u 2666849
resource.c/AcquireMagickResource/235/Resource:
width +414P/----/256.0MiP
18:46:17 0:1.054537 0.100u 2666849
resource.c/AcquireMagickResource/235/Resource:
height +377P/----/256.0MiP
18:46:17 0:1.054554 0.100u 2666849
resource.c/AcquireMagickResource/235/Resource:
pixels +152.4KiP/----/Unlimited
18:46:17 0:1.054574 0.100u 2666849
resource.c/AcquireMagickResource/235/Resource:
memory +1.5MiB/1.5MiB/125.8GiB
18:46:17 0:1.073180 0.170u 2666849
resource.c/LiberateMagickResource/811/Resource:
memory -1.5MiB/0B/125.8GiB
1685731578
VSZ RSS USER COMMAND
4802392 9848 root ./threadarena Zoom140.png
70
...
20989784 31940 root ./threadarena Zoom140.png
302
18:46:34 0:17.922374 2.080u 2666849
resource.c/AcquireMagickResource/235/Resource:
width +414P/----/256.0MiP
18:46:34 0:17.922409 2.080u 2666849
resource.c/AcquireMagickResource/235/Resource:
height +377P/----/256.0MiP
18:46:34 0:17.922426 2.080u 2666849
resource.c/AcquireMagickResource/235/Resource:
pixels +152.4KiP/----/Unlimited
18:46:34 0:17.922448 2.080u 2666849
resource.c/AcquireMagickResource/235/Resource:
memory +1.5MiB/1.5MiB/125.8GiB
18:46:34 0:17.943440 2.180u 2666849
resource.c/LiberateMagickResource/811/Resource:
memory -1.5MiB/0B/125.8GiB
0B, which backs up what I saw with valgrind/memcheck. It leaks, but it's not a
resource leak that GM seems to be able to track.
Unfortunately/interestingly, this test application doesn't quite show the same
behaviour under valgrind. That is, if I modify it to only run 10 cycles:
root@host:~# valgrind --tool=memcheck --leak-check=full --show-leak-kinds=all
./threadarena Zoom140.png
==2674090== Memcheck, a memory error detector
==2674090== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==2674090== Using Valgrind-3.16.1 and LibVEX; rerun with -h for copyright info
==2674090== Command: ./threadarena Zoom140.png
==2674090==
1685732666
VSZ RSS USER COMMAND
224116 115612 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732677
VSZ RSS USER COMMAND
224196 116692 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732689
VSZ RSS USER COMMAND
228388 118252 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732701
VSZ RSS USER COMMAND
228452 119784 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732711
VSZ RSS USER COMMAND
232644 121336 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732721
VSZ RSS USER COMMAND
232724 122880 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732732
VSZ RSS USER COMMAND
236916 124440 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732743
VSZ RSS USER COMMAND
236980 125972 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732755
VSZ RSS USER COMMAND
241172 127532 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
1685732765
VSZ RSS USER COMMAND
241252 129068 root /usr/bin/valgrind.bin --tool=memcheck --leak-check=full --
0
==2674090==
==2674090== HEAP SUMMARY:
==2674090== in use at exit: 216 bytes in 2 blocks
==2674090== total heap usage: 1,703 allocs, 1,701 frees, 17,954,690 bytes
allocated
==2674090==
==2674090== 8 bytes in 1 blocks are still reachable in loss record 1 of 2
==2674090== at 0x483877F: malloc (in
/usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==2674090== by 0x57B10F8: ??? (in /usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x57C1076: ??? (in /usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x57AF599: ??? (in /usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x400FFE1: call_init.part.0 (dl-init.c:72)
==2674090== by 0x40100E8: call_init (dl-init.c:30)
==2674090== by 0x40100E8: _dl_init (dl-init.c:119)
==2674090== by 0x40010C9: ??? (in /usr/lib/x86_64-linux-gnu/ld-2.31.so)
==2674090== by 0x1: ???
==2674090== by 0x1FFF000786: ???
==2674090== by 0x1FFF000794: ???
==2674090==
==2674090== 208 bytes in 1 blocks are still reachable in loss record 2 of 2
==2674090== at 0x483877F: malloc (in
/usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==2674090== by 0x57B10F8: ??? (in /usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x57C063A: ??? (in /usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x57B1584: omp_set_num_threads (in
/usr/lib/x86_64-linux-gnu/libgomp.so.1.0.0)
==2674090== by 0x49437BB: InitializeMagickResources (in
/usr/lib/libGraphicsMagick-Q16.so.3.22.0)
==2674090== by 0x491117A: InitializeMagickEx (in
/usr/lib/libGraphicsMagick-Q16.so.3.22.0)
==2674090== by 0x4911451: InitializeMagick (in
/usr/lib/libGraphicsMagick-Q16.so.3.22.0)
==2674090== by 0x1093A6: main (in /root/threadarena)
==2674090==
==2674090== LEAK SUMMARY:
==2674090== definitely lost: 0 bytes in 0 blocks
==2674090== indirectly lost: 0 bytes in 0 blocks
==2674090== possibly lost: 0 bytes in 0 blocks
==2674090== still reachable: 216 bytes in 2 blocks
==2674090== suppressed: 0 bytes in 0 blocks
==2674090==
==2674090== For lists of detected and suppressed errors, rerun with: -s
==2674090== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
So, that's... great. There are trivial increases in process heap use, but you
have to expect that with valgrind. There are no thread arena leaks at all, and
only a smattering of memory lost in initialization code.
Granted, the leaking thread arenas are memory mapped areas, so memcheck might
not trigger on them. I might have a go at the valgrind-mmt fork unless someone
has a better idea.
I was hoping another set of eyes could spot something trivial and obvious in
how GetImageDepth() invokes/manages OpenMP, because the more I look at this bug
the less I trust my sanity.
________________________________
From: Bob Friesenhahn <bfrie...@simple.dallas.tx.us>
Sent: Friday, June 2, 2023 14:38
To: Beauregard,Christophe (ECCC) <christophe.beaureg...@ec.gc.ca>;
1037...@bugs.debian.org <1037...@bugs.debian.org>
Subject: Re: Bug#1037042: graphicsmagick: GetImageDepth has a thread arena and
memory leak
[You don't often get email from bfrie...@simple.dallas.tx.us. Learn why this is
important at https://aka.ms/LearnAboutSenderIdentification ]
Christophe,
It would be good to test a modern GM version which supports "resource
limited memory". Probably Debian's 1.4 version supports that.
For a version which supports the resource limited memory allocator,
you can set 'MAGICK_DEBUG=resource' in the environment prior to
running the program. This will cause very verbose output with a tally
similar to:
13:27:40 0:0.007952 0.050u 173194 resource.c/unknown/236/Resource:
memory +65.2MiB/81.0MiB/39.0GiB
13:27:40 0:0.027664 0.190u 173194 resource.c/unknown/818/Resource:
memory -3.3KiB/81.0MiB/39.0GiB
13:27:40 0:0.027692 0.190u 173194 resource.c/unknown/818/Resource:
.
.
.
13:27:40 0:0.033629 0.220u 173194 resource.c/unknown/818/Resource:
memory -65.2MiB/0B/39.0GiB
The "0B" at the end means that at least as related to memory allocated
by the resource limited memory allocator (used only for non-public
allocations), there are no leaks.
The type of leak you seem to be finding is a thread-specific memory
allocation leak where a destructor did not fire to free the memory
when the thread quit. I don't believe that GetImageDepth() uses
thread-specific memory but the "thread arena"s that you are talking
about likely do.
For allocations which specifically use a memory allocator, I have had
some good luck using Glibc's mtrace.
Bob
--
Bob Friesenhahn
bfrie...@simple.dallas.tx.us,
https://can01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.simplesystems.org%2Fusers%2Fbfriesen%2F&data=05%7C01%7CChristophe.Beauregard%40ec.gc.ca%7C2f494c13d0c849d2fb9f08db6398a2da%7C740c5fd36e8b41769cc9454dbe4e62c4%7C0%7C0%7C638213279445113847%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=uT3H4GWUpf8JufGwlVlPOs9YPxIUrqyvpbq96FHs1t4%3D&reserved=0<http://www.simplesystems.org/users/bfriesen/>
GraphicsMagick Maintainer,
https://can01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.graphicsmagick.org%2F&data=05%7C01%7CChristophe.Beauregard%40ec.gc.ca%7C2f494c13d0c849d2fb9f08db6398a2da%7C740c5fd36e8b41769cc9454dbe4e62c4%7C0%7C0%7C638213279445113847%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=J7E%2FKlCYduo41V1X8FOcHboGfXrrhujL1%2B4ig0BE%2F94%3D&reserved=0<http://www.graphicsmagick.org/>
Public Key,
https://can01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.simplesystems.org%2Fusers%2Fbfriesen%2Fpublic-key.txt&data=05%7C01%7CChristophe.Beauregard%40ec.gc.ca%7C2f494c13d0c849d2fb9f08db6398a2da%7C740c5fd36e8b41769cc9454dbe4e62c4%7C0%7C0%7C638213279445113847%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=E9oFKN%2FiDPH8D3hMeAvfbP%2FroGWyTDUqZs9U8BUNebc%3D&reserved=0<http://www.simplesystems.org/users/bfriesen/public-key.txt>
