I have an application which operates with memory a lot. This app is 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