munmap() doesn't return pages to system on macOS Sierra

Question

I have an application which operates with memory a lot. This app written in c# - it has mono runtime under the hood.

We identfied that on Sierra the app memory constantly grows when it does consuming memory operations. Same time the issue is not reproducible on El Captain.

It can even achive 8 or 10 GB if it works a long period of time (weeks).

I have verified that there is no memory leaks (significant, which can cause such a growth). I have verified that there is no retain cycles preventing objects from being collected - again the app works perfect on El Captain.

I found that:

Almost all app memory (excluding 150 mb of active) moves to compressed state and even swaped to disk then.

According to Xcode Instruments VM Tracker tool - VM_Allocation region holds almost all swapped memory

<---!!! - pay attention to

% of Res.   Type    # Regs  Path            Resident Size   Dirty Size  Swapped Size        Virtual Size    Res. %  
100%        *All*   17997   < multiple >    517.21 MiB      240.89 MiB  704.31 MiB <---!!!  2.07 GiB        24% 

% of Res.   Type        # Regs      Path    Resident Size   Dirty Size  Swapped Size        Virtual Size    Res. %  
18%         VM_ALLOCATE 15939       -       90.76 MiB       90.76 MiB   588.81 MiB <---!!!  696.29 MiB      13%

I dtrace-ed all occurences and stack traces of virtual memory allocation/ deallocations - mmap(), munmap(), vm_allocate(), vm_deallocate() and found that:

For each mmap() of currently swapped memory pages there was corresponding successfull munmap() For each vm_allocate() of currently swapped memory pages there was corresponding successfull vm_deallocate()

but

for some reason munmap() of some vm region returns "0" which means success but associated pages are still presented - they are not returned to system.

That's not expected - munmap() of private, ananymous memory should lead to page freeing. I verified that in my sample app. Any manipulations with mlock(), madvice() did not help to imitate this.

That causes an issues as that pages are abandoned by GC (they are not reused anymore) same time they are not free. As they are no longer in use they go thru compressing and then swapping to disk.

Moreover, abandoned pages are alive - access to them from lldb does not lead to BAD_ACCESS.

Has anyone met this?

Here are extractions from the logs which show the problem.

   This is VM state evolution in 0x11c5XXXXX range of 1 MB:

   I. allocation, deallocation object in Large objects space

   Type Address Range   Dirty Size  Swapped Size    Resident Size   Virtual Size    Resident %  Protections Path
   VM_ALLOCATE  0x11c500000 - 0x11c600000   1.00 MiB    0 Bytes 1.00 MiB    1.00 MiB    100%    rw-/rwx 

     3    551                      mmap:return [240760570406181]:mmap:  [0x11c500000, 2097152] flags: 4098
                 libsystem_kernel.dylib`__mmap+0xa
                 Drive`mono_valloc+0x69
                 Drive`mono_valloc_aligned+0x22
                 Drive`sgen_alloc_os_memory_aligned+0x23
                 Drive`sgen_los_alloc_large_inner+0x274
                 Drive`sgen_alloc_obj_nolock+0x69
                 Drive`mono_gc_alloc_vector+0x7b
                 0x1063cb0e6
                 0x117429a4a
                 0x1174296d2
                 0x11742881c
                 0x1174286ca
                 0x117428530
                 0x1173a77cd
                 0x11739a81a
                 0x11739a2e1
                 0x11739a213
                 0x116ad373b
                 0x111a2f199
                 0x10df54fc9

     3    303                    munmap:return [240983284059591]:munmap: 0   0x11c500000, 1048576
                 libsystem_kernel.dylib`__munmap+0xa
                 Drive`mono_valloc_aligned+0xd0
                 Drive`sgen_alloc_os_memory_aligned+0x23
                 Drive`sgen_los_alloc_large_inner+0x274
                 Drive`sgen_alloc_obj_nolock+0x69
                 Drive`mono_gc_alloc_vector+0x7b
                 0x1063cb0e6
                 0x117429a4a
                 0x1174296d2
                 0x11742881c
                 0x1174286ca
                 0x117428530
                 0x1173a77cd
                 0x11739a81a
                 0x11739a2e1
                 0x11739a213
                 0x116ad373b
                 0x111a2f199
                 0x10df54fc9
                 Drive`mono_jit_runtime_invoke+0x8e0

   II. SQLITE page cache allocation / deallocation 

   Type Address Range   Dirty Size  Swapped Size    Resident Size   Virtual Size    Resident %  Protections Path
   SQLite page cache    0x11c50f000 - 0x11c51f000   64.00 KiB   0 Bytes 64.00 KiB   64.00 KiB   100%    rw-/rwx 
   SQLite page cache    0x11c51f000 - 0x11c52f000   64.00 KiB   0 Bytes 64.00 KiB   64.00 KiB   100%    rw-/rwx 

   [241059759675635]:vm_allocate:   0x11c50f000, 0x10000

                 libsystem_kernel.dylib`vm_allocate+0x26
                 libsqlite3.dylib`purgeableCacheFetch+0x32a
                 libsqlite3.dylib`sqlite3PagerGet+0x18d
                 libsqlite3.dylib`getAndInitPage+0x47
                 libsqlite3.dylib`sqlite3BtreeMovetoUnpacked+0x52d
                 libsqlite3.dylib`handleDeferredMoveto+0x1e
                 libsqlite3.dylib`sqlite3VdbeExec+0x9b72
                 libsqlite3.dylib`sqlite3_step+0x3cf
                 0x11188e240

   [241097285460026]:vm_deallocate: 0x11c50f000

                 libsystem_kernel.dylib`vm_deallocate
                 libsqlite3.dylib`purgeableCacheDestroy+0x464
                 libsqlite3.dylib`sqlite3PagerClose+0x279
                 libsqlite3.dylib`sqlite3BtreeClose+0x142
                 libsqlite3.dylib`sqlite3LeaveMutexAndCloseZombie+0x192
                 libsqlite3.dylib`sqlite3Close+0x409
                 0x112caf100
                 0x112caee8d
                 0x11188ec28
                 0x112fee6d5
                 Drive`mono_gc_run_finalize+0x3fc
                 Drive`sgen_gc_invoke_finalizers+0x114
                 Drive`finalizer_thread+0x252
                 Drive`start_wrapper+0x22e
                 Drive`inner_start_thread+0x196
                 libsystem_pthread.dylib`_pthread_body+0xb4
                 libsystem_pthread.dylib`_pthread_body
                 libsystem_pthread.dylib`thread_start+0xd


   III. SQLITE page cache deallocation. These three guys are unknown... That's strange - my assumption that the reason that I don't have allocation stack trace for them is dtrace failure - it reports errors a little from time to time

   Type Address Range   Dirty Size  Swapped Size    Resident Size   Virtual Size    Resident %  Protections Path
   VM_ALLOCATE  0x11c5ef000 - 0x11c5f1000   8.00 KiB    0 Bytes 8.00 KiB    8.00 KiB    100%    rw-/rwx 
   VM_ALLOCATE  0x11c5f1000 - 0x11c5f2000   4.00 KiB    0 Bytes 4.00 KiB    4.00 KiB    100%    rw-/rwx 
   VM_ALLOCATE  0x11c5f5000 - 0x11c5fa000   20.00 KiB   0 Bytes 20.00 KiB   20.00 KiB   100%    rw-/rwx 


   IV. FIRST REPRODUCTION <---!!! 0x11c51e000 - mmapped() then munmapped() but still be presented.
   Type Address Range   Dirty Size  Swapped Size    Resident Size   Virtual Size    Resident %  Protections Path
   SQLite page cache    0x11c50e000 - 0x11c51e000   0 Bytes 0 Bytes 0 Bytes 64.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c51e000 - 0x11c529000   44.00 KiB   0 Bytes 44.00 KiB   44.00 KiB   100%    rw-/rwx 
   VM_ALLOCATE  0x11c5ef000 - 0x11c5f1000   8.00 KiB    0 Bytes 8.00 KiB    8.00 KiB    100%    rw-/rwx 
   VM_ALLOCATE  0x11c5f1000 - 0x11c5f2000   4.00 KiB    0 Bytes 4.00 KiB    4.00 KiB    100%    rw-/rwx 
   VM_ALLOCATE  0x11c5f5000 - 0x11c5fa000   20.00 KiB   0 Bytes 20.00 KiB   20.00 KiB   100%    rw-/rwx 


   0    551                      mmap:return [241237210309703]:mmap:   [0x11c51e000, 4096] flags: 4098
                 libsystem_kernel.dylib`__mmap+0xa
                 Drive`mono_valloc+0x69
                 Drive`mono_lock_free_alloc+0x335
                 Drive`sgen_alloc_internal+0x3b
                 Drive`sgen_gray_object_enqueue+0x5c
                 Drive`mono_g_hash_mark+0x11a
                 Drive`job_scan_from_registered_roots+0x18c
                 Drive`sgen_workers_enqueue_job+0x23
                 Drive`enqueue_scan_from_roots_jobs+0x7d
                 Drive`major_copy_or_mark_from_roots+0x36a
                 Drive`major_start_collection+0x155
                 Drive`major_do_collection+0x4e
                 Drive`sgen_perform_collection+0x2a6
                 Drive`sgen_los_alloc_large_inner+0x5d
                 Drive`sgen_alloc_obj_nolock+0x69
                 Drive`mono_gc_alloc_vector+0x7b
                 0x1063cb0e6
                 0x10bd2a7b3
                 0x10bd293d1
                 0x1173a6db6



     2    303                    munmap:return [241257343803100]:munmap: 0    <---!!!    0x11c51e000, 4096
                 libsystem_kernel.dylib`__munmap+0xa
                 Drive`mono_vfree+0x32
                 Drive`desc_retire+0x43
                 Drive`mono_lock_free_free+0x1a9
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x17
                 Drive`pin_stats_tree_free+0x17
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x17
                 Drive`pin_stats_tree_free+0x17
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`pin_stats_tree_free+0x20
                 Drive`sgen_pin_stats_reset+0x10
                 Drive`collect_nursery+0x414
                 Drive`sgen_perform_collection+0x1b1


   V. Done - all the memory in the range is abandoned

   Type Address Range   Dirty Size  Swapped Size    Resident Size   Virtual Size    Resident %  Protections Path
   VM_ALLOCATE  0x11c51c000 - 0x11c51e000   0 Bytes 8.00 KiB    0 Bytes 8.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c51e000 - 0x11c53c000   0 Bytes 120.00 KiB  0 Bytes 120.00 KiB  0%  rw-/rwx 
   VM_ALLOCATE  0x11c53c000 - 0x11c550000   0 Bytes 80.00 KiB   0 Bytes 80.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c550000 - 0x11c568000   0 Bytes 96.00 KiB   0 Bytes 96.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c568000 - 0x11c569000   0 Bytes 4.00 KiB    0 Bytes 4.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c569000 - 0x11c57d000   0 Bytes 80.00 KiB   0 Bytes 80.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c57d000 - 0x11c589000   0 Bytes 48.00 KiB   0 Bytes 48.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c589000 - 0x11c58b000   0 Bytes 8.00 KiB    0 Bytes 8.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c58b000 - 0x11c58c000   0 Bytes 4.00 KiB    0 Bytes 4.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c58c000 - 0x11c594000   0 Bytes 32.00 KiB   0 Bytes 32.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c594000 - 0x11c5b3000   0 Bytes 124.00 KiB  0 Bytes 124.00 KiB  0%  rw-/rwx 
   VM_ALLOCATE  0x11c5b3000 - 0x11c5b5000   0 Bytes 8.00 KiB    0 Bytes 8.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c5b5000 - 0x11c5c9000   0 Bytes 80.00 KiB   0 Bytes 80.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5c9000 - 0x11c5cd000   0 Bytes 16.00 KiB   0 Bytes 16.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5cd000 - 0x11c5d1000   0 Bytes 16.00 KiB   0 Bytes 16.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5d1000 - 0x11c5df000   0 Bytes 56.00 KiB   0 Bytes 56.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5df000 - 0x11c5ee000   0 Bytes 60.00 KiB   0 Bytes 60.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5ee000 - 0x11c5ef000   0 Bytes 4.00 KiB    0 Bytes 4.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c5ef000 - 0x11c5f1000   0 Bytes 8.00 KiB    0 Bytes 8.00 KiB    0%  rw-/rwx 
   VM_ALLOCATE  0x11c5f1000 - 0x11c5f5000   0 Bytes 16.00 KiB   0 Bytes 16.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5f5000 - 0x11c5fa000   0 Bytes 20.00 KiB   0 Bytes 20.00 KiB   0%  rw-/rwx 
   VM_ALLOCATE  0x11c5fa000 - 0x11c619000   0 Bytes 124.00 KiB  0 Bytes 124.00 KiB  0%  rw-/rwx

Have you tried the managed profiler? https://www.xamarin.com/profiler It sounds like you might have a managed leak somewhere. — Chris Hamons, Dec 12 '16 at 21:59
Yep, the first thing I tried was Xamarin Profiler. I didn't identify any kind of managed objects that alive and number of which is growing. All numbers seem reasonable. If it makes sense I can share screenshots with Xamarin Profiler's results. — Igor B., Dec 13 '16 at 07:43

munmap() doesn't return pages to system on macOS Sierra

0 Answers0