2 Replies
      Latest reply: Dec 20, 2016 12:32 AM by botov RSS
      botov Level 1 Level 1 (0 points)

        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