More detailed logging of memory consumption

Podfile

@@ -11,8 +11,8 @@ source 'https://cdn.cocoapods.org/'
 
 pod 'SwiftProtobuf', ">= 1.14.0"
 
-pod 'SignalCoreKit', git: 'git@github.com:signalapp/SignalCoreKit', testspecs: ["Tests"]
-# pod 'SignalCoreKit', path: '../SignalCoreKit', testspecs: ["Tests"]
+pod 'SignalCoreKit', git: 'git@github.com:signalapp/SignalCoreKit-Private', testspecs: ["Tests"], branch: 'mlin/PR/AggressiveFlushing'
+# pod 'SignalCoreKit', path: '../../SignalCoreKit', testspecs: ["Tests"]
 
 pod 'SignalClient', git: 'https://github.com/signalapp/libsignal-client.git', testspecs: ["Tests"]
 # pod 'SignalClient', path: '../libsignal-client', testspecs: ["Tests"]

Podfile.lock

@@ -226,8 +226,8 @@ DEPENDENCIES:
   - SignalArgon2/Tests (from `https://github.com/signalapp/Argon2.git`)
   - SignalClient (from `https://github.com/signalapp/libsignal-client.git`)
   - SignalClient/Tests (from `https://github.com/signalapp/libsignal-client.git`)
-  - "SignalCoreKit (from `git@github.com:signalapp/SignalCoreKit`)"
-  - "SignalCoreKit/Tests (from `git@github.com:signalapp/SignalCoreKit`)"
+  - "SignalCoreKit (from `git@github.com:signalapp/SignalCoreKit-Private`, branch `mlin/PR/AggressiveFlushing`)"
+  - "SignalCoreKit/Tests (from `git@github.com:signalapp/SignalCoreKit-Private`, branch `mlin/PR/AggressiveFlushing`)"
   - "SignalMetadataKit (from `ssh://git@github.com/signalapp/SignalMetadataKit`)"
   - "SignalMetadataKit/Tests (from `ssh://git@github.com/signalapp/SignalMetadataKit`)"
   - SignalRingRTC (from `ThirdParty/SignalRingRTC.podspec`)
@@ -304,7 +304,8 @@ EXTERNAL SOURCES:
   SignalClient:
     :git: https://github.com/signalapp/libsignal-client.git
   SignalCoreKit:
-    :git: "git@github.com:signalapp/SignalCoreKit"
+    :branch: mlin/PR/AggressiveFlushing
+    :git: "git@github.com:signalapp/SignalCoreKit-Private"
   SignalMetadataKit:
     :git: "ssh://git@github.com/signalapp/SignalMetadataKit"
   SignalRingRTC:
@@ -350,8 +351,8 @@ CHECKOUT OPTIONS:
     :commit: 3da7078ffe3f818b0b6c871f12cc4fd6d7c25fa8
     :git: https://github.com/signalapp/libsignal-client.git
   SignalCoreKit:
-    :commit: 517562ffa87cd18fe812d2abe50ff152e03e47e7
-    :git: "git@github.com:signalapp/SignalCoreKit"
+    :commit: 0cd0f6d7b04609e364878153a435318e1adf2dd8
+    :git: "git@github.com:signalapp/SignalCoreKit-Private"
   SignalMetadataKit:
     :commit: 90f1776e631e8e232360bbe11db620c77f078567
     :git: "ssh://git@github.com/signalapp/SignalMetadataKit"
@@ -411,6 +412,6 @@ SPEC CHECKSUMS:
   SwiftProtobuf: 3320217e9d8fb75f36b40282e78c482640fd75dd
   YYImage: f1ddd15ac032a58b78bbed1e012b50302d318331
 
-PODFILE CHECKSUM: 1e25c00efcbd52fb42b214c37129048ddbf653e4
+PODFILE CHECKSUM: 4e27145718a0c32abac6b974d5292b3800615093
 
 COCOAPODS: 1.10.1

Pods

@@ -1 +1 @@
-Subproject commit 1782e1973f3430ed4ef153c785f0c74f758c3927
+Subproject commit d78417dd6f7f3c7d1d405f633af8e53b7a065e20

Signal/src/ViewControllers/AppSettings/Internal/InternalSettingsViewController.swift

@@ -89,7 +89,7 @@ class InternalSettingsViewController: OWSTableViewController2 {
             }
         }
 
-        infoSection.add(.label(withText: "Memory Usage: \(LocalDevice.memoryUsage)"))
+        infoSection.add(.label(withText: "Memory Usage: \(LocalDevice.memoryUsageString)"))
 
         let (threadCount, messageCount, attachmentCount, subscriberID) = databaseStorage.read { transaction in
             return (

SignalNSE/NSEContext.swift

@@ -59,42 +59,27 @@ class NSEContext: NSObject, AppContext {
         return userDefaults
     }
 
+
+
+    let memoryPressureSource = DispatchSource.makeMemoryPressureSource(
+        eventMask: .all,
+        queue: .global()
+    )
+
     override init() {
         super.init()
 
-        NotificationCenter.default.addObserver(self,
-                                               selector: #selector(applicationWillResignActive),
-                                               name: UIApplication.willResignActiveNotification,
-                                               object: nil)
-        NotificationCenter.default.addObserver(self,
-                                               selector: #selector(applicationWillTerminate),
-                                               name: UIApplication.willTerminateNotification,
-                                               object: nil)
-        NotificationCenter.default.addObserver(self,
-                                               selector: #selector(applicationDidReceiveMemoryWarning),
-                                               name: UIApplication.didReceiveMemoryWarningNotification,
-                                               object: nil)
-    }
+        memoryPressureSource.setEventHandler { [weak self] in
+            if let self = self {
+                Logger.warn("Memory pressure event: \(self.memoryPressureSource.memoryEventDescription)")
+            } else {
+                Logger.warn("Memory pressure event.")
+            }
+            Logger.warn("Current memory usage: \(LocalDevice.memoryUsageString)")
+            Logger.flush()
+        }
+        memoryPressureSource.resume()
 
-    @objc
-    private func applicationWillResignActive(_ notification: NSNotification) {
-        AssertIsOnMainThread()
-
-        Logger.info("memoryUsage: \(LocalDevice.memoryUsage)")
-    }
-
-    @objc
-    private func applicationWillTerminate(_ notification: NSNotification) {
-        AssertIsOnMainThread()
-
-        Logger.info("memoryUsage: \(LocalDevice.memoryUsage)")
-    }
-
-    @objc
-    private func applicationDidReceiveMemoryWarning(_ notification: NSNotification) {
-        AssertIsOnMainThread()
-
-        Logger.info("memoryUsage: \(LocalDevice.memoryUsage)")
     }
 
     // MARK: - Unused in this extension
@@ -136,3 +121,18 @@ class NSEContext: NSObject, AppContext {
         DebugLogger.nseDebugLogsDirPath
     }
 }
+
+fileprivate extension DispatchSourceMemoryPressure {
+    var memoryEvent: DispatchSource.MemoryPressureEvent {
+        DispatchSource.MemoryPressureEvent(rawValue: data)
+    }
+
+    var memoryEventDescription: String {
+        switch memoryEvent {
+        case .normal: return "Normal"
+        case .warning: return "Warning!"
+        case .critical: return "Critical!!"
+        default: return "Unknown value: \(memoryEvent.rawValue)"
+        }
+    }
+}

SignalNSE/NotificationService.swift

@@ -47,7 +47,7 @@ class NotificationService: UNNotificationServiceExtension {
             if DebugFlags.internalLogging,
                _logTimer == nil {
                 _logTimer = OffMainThreadTimer(timeInterval: 1.0, repeats: true) { _ in
-                    Logger.info("... memoryUsage: \(LocalDevice.memoryUsage)")
+                    Logger.info("... memoryUsage: \(LocalDevice.memoryUsageString)")
                 }
             }
 
@@ -77,7 +77,7 @@ class NotificationService: UNNotificationServiceExtension {
 
         guard let contentHandler = contentHandler.swap(nil) else {
             if DebugFlags.internalLogging {
-                Logger.warn("No contentHandler, memoryUsage: \(LocalDevice.memoryUsage), nseCount: \(nseCount).")
+                Logger.warn("No contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
             }
             Logger.flush()
             return
@@ -105,7 +105,7 @@ class NotificationService: UNNotificationServiceExtension {
         content.badge = updatedBadgeCount
 
         if DebugFlags.internalLogging {
-            Logger.info("Invoking contentHandler, memoryUsage: \(LocalDevice.memoryUsage), nseCount: \(nseCount).")
+            Logger.info("Invoking contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
         }
         Logger.flush()
 
@@ -151,17 +151,17 @@ class NotificationService: UNNotificationServiceExtension {
 
         let nseCount = Self.nseDidStart()
 
-        Logger.info("Received notification in class: \(self), thread: \(Thread.current), pid: \(ProcessInfo.processInfo.processIdentifier), memoryUsage: \(LocalDevice.memoryUsage), nseCount: \(nseCount)")
+        Logger.info("Received notification in class: \(self), thread: \(Thread.current), pid: \(ProcessInfo.processInfo.processIdentifier), memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount)")
 
         AppReadiness.runNowOrWhenAppDidBecomeReadySync {
             environment.askMainAppToHandleReceipt { [weak self] mainAppHandledReceipt in
                 guard !mainAppHandledReceipt else {
-                    Logger.info("Received notification handled by main application, memoryUsage: \(LocalDevice.memoryUsage).")
+                    Logger.info("Received notification handled by main application, memoryUsage: \(LocalDevice.memoryUsageString).")
                     self?.completeSilenty()
                     return
                 }
 
-                Logger.info("Processing received notification, memoryUsage: \(LocalDevice.memoryUsage).")
+                Logger.info("Processing received notification, memoryUsage: \(LocalDevice.memoryUsageString).")
 
                 self?.fetchAndProcessMessages()
             }

SignalServiceKit/src/Messages/MessageProcessor.swift

@@ -266,12 +266,12 @@ public class MessageProcessor: NSObject {
 
             guard !batchEnvelopes.isEmpty, messagePipelineSupervisor.isMessageProcessingPermitted else {
                 if DebugFlags.internalLogging {
-                    Logger.info("Processing complete: \(self.queuedContentCount) (memoryUsage: \(LocalDevice.memoryUsage).")
+                    Logger.info("Processing complete: \(self.queuedContentCount) (memoryUsage: \(LocalDevice.memoryUsageString).")
                 }
                 return false
             }
 
-            Logger.info("Processing batch of \(batchEnvelopes.count)/\(pendingEnvelopesCount) received envelope(s). (memoryUsage: \(LocalDevice.memoryUsage)")
+            Logger.info("Processing batch of \(batchEnvelopes.count)/\(pendingEnvelopesCount) received envelope(s). (memoryUsage: \(LocalDevice.memoryUsageString)")
 
             var processedEnvelopes: [PendingEnvelope] = []
             SDSDatabaseStorage.shared.write { transaction in

SignalServiceKit/src/Messages/OWSOutgoingReceiptManager.m

@@ -186,9 +186,7 @@ NSString *NSStringForOWSReceiptType(OWSReceiptType receiptType)
 
 - (void)logMemoryUsage {
     if (SSKDebugFlags.internalLogging) {
-        dispatch_async(self.serialQueue, ^{
-            OWSLogVerbose(@"memoryUsage: %@", LocalDevice.memoryUsage);
-        });
+        OWSLogInfo(@"memoryUsage: %@", LocalDevice.memoryUsageString);
     }
 }
 

SignalServiceKit/src/Util/Atomics.swift

@@ -254,6 +254,10 @@ public final class AtomicOptional<T> {
     public func swap(_ value: T?) -> T? {
         self.value.swap(value)
     }
+
+    public func map(_ block: @escaping (T?) -> T?) -> T? {
+        value.map(block)
+    }
 }
 
 extension AtomicOptional: Codable where T: Codable {

SignalServiceKit/src/Util/LocalDevice.swift

@@ -19,40 +19,92 @@ public class LocalDevice: NSObject {
         ProcessInfo.processInfo.activeProcessorCount
     }
 
-    public static var memoryUsageUInt64: UInt64? {
-        let vmInfoExpectedSize = MemoryLayout<task_vm_info_data_t>.size / MemoryLayout<natural_t>.size
-        var vmInfo = task_vm_info_data_t()
-        var vmInfoSize = mach_msg_type_number_t(vmInfoExpectedSize)
+    public struct MemoryStatus {
+        public let fetchDate: Date
+        public let footprint: UInt64
+        public let peakFootprint: Int64
+        public let bytesRemaining: UInt64
 
-        let kern: kern_return_t = withUnsafeMutablePointer(to: &vmInfo) {
-            $0.withMemoryRebound(to: integer_t.self, capacity: 1) {
-                task_info(mach_task_self_,
-                          task_flavor_t(TASK_VM_INFO),
-                          $0,
-                          &vmInfoSize)
+        let mallocSize: UInt64
+        let mallocAllocations: UInt64
+
+        fileprivate static func fetchCurrentStatus() -> MemoryStatus? {
+            let vmInfoExpectedSize = MemoryLayout<task_vm_info_data_t>.size / MemoryLayout<natural_t>.size
+            var vmInfo = task_vm_info_data_t()
+            var vmInfoSize = mach_msg_type_number_t(vmInfoExpectedSize)
+
+            let kern: kern_return_t = withUnsafeMutablePointer(to: &vmInfo) {
+                $0.withMemoryRebound(to: integer_t.self, capacity: 1) {
+                    task_info(mach_task_self_,
+                              task_flavor_t(TASK_VM_INFO),
+                              $0,
+                              &vmInfoSize)
+                }
             }
+
+            guard kern == KERN_SUCCESS else {
+                let errorString = String(cString: mach_error_string(kern), encoding: .ascii) ?? "Unknown error"
+                owsFailDebug(errorString)
+                return nil
+            }
+
+            let mallocZone = malloc_default_zone()
+            var statistics = malloc_statistics_t()
+            malloc_zone_statistics(mallocZone, &statistics)
+
+            if DebugFlags.internalLogging, CurrentAppContext().isNSE {
+                // Losing log messages is painful when trying to track down memory usage bugs
+                OWSLogger.aggressiveFlushing = (vmInfo.limit_bytes_remaining < 1024 * 1024)
+            }
+
+            return MemoryStatus(
+                fetchDate: Date(),
+                footprint: vmInfo.phys_footprint,
+                peakFootprint: vmInfo.ledger_phys_footprint_peak,
+                bytesRemaining: vmInfo.limit_bytes_remaining,
+                mallocSize: UInt64(statistics.size_in_use),
+                mallocAllocations: UInt64(statistics.size_allocated)
+            )
+        }
+    }
+
+    private static var _memoryStatus = AtomicOptional<MemoryStatus>(nil)
+    public static func currentMemoryStatus(forceUpdate: Bool = false) -> MemoryStatus? {
+        // If we don't have a cached status, we must fetch
+        guard let currentStatus = _memoryStatus.get() else {
+            return _memoryStatus.map { _ in MemoryStatus.fetchCurrentStatus() }
         }
 
-        guard kern == KERN_SUCCESS else {
-            let errorString = String(cString: mach_error_string(kern), encoding: .ascii) ?? "Unknown error"
-            owsFailDebug(errorString)
-            return nil
+        let cacheValidityPeriod: TimeInterval = 1.0
+        if forceUpdate || currentStatus.fetchDate.addingTimeInterval(cacheValidityPeriod).isBeforeNow {
+            return _memoryStatus.map { _ in MemoryStatus.fetchCurrentStatus() }
+        } else {
+            return currentStatus
         }
-
-        return vmInfo.phys_footprint
     }
 
     @objc
-    public static var memoryUsage: String {
-        guard let memoryUsageUInt64 = self.memoryUsageUInt64 else {
+    public static var memoryUsageString: String {
+        // Since this string is intended to be logged, we should fetch a fresh status
+        guard let currentMemoryStatus = currentMemoryStatus(forceUpdate: true) else {
             return "Unknown"
         }
-        let nseMemoryUsageWarn: UInt64 = 24 * 1000 * 1000
-        if CurrentAppContext().isNSE,
-           memoryUsageUInt64 > nseMemoryUsageWarn {
-            return "\(memoryUsageUInt64) ⚠️⚠️⚠️"
-        } else {
-            return "\(memoryUsageUInt64)"
+
+        let currentFootprint = currentMemoryStatus.footprint
+        let freeBytes = currentMemoryStatus.bytesRemaining
+        let mallocUsage = currentMemoryStatus.mallocSize
+        let mallocAllocations = currentMemoryStatus.mallocAllocations
+
+        let warnThreshold: UInt64 = 5 * 1024 * 1024
+        let criticalThreshold = UInt64(1.5 * 1024 * 1024)
+
+        switch (freeBytes, CurrentAppContext().isNSE) {
+        case (..<criticalThreshold, true):
+            return "\(currentFootprint) ⚠️⚠️⚠️ \(freeBytes) remaining — mallocUsage: \(mallocUsage) / \(mallocAllocations)"
+        case (..<warnThreshold, _):
+            return "\(currentFootprint) — \(freeBytes) remaining — mallocUsage: \(mallocUsage) / \(mallocAllocations)"
+        default:
+            return "\(currentFootprint)"
         }
     }
 }

SignalServiceKit/src/Util/PendingTasks.swift

@@ -30,7 +30,7 @@ public class PendingTasks: NSObject {
             Promise.when(resolved: promises).asVoid()
         }.map(on: .global()) {
             if DebugFlags.internalLogging {
-                Logger.info("Complete \(label) (memoryUsage: \(LocalDevice.memoryUsage)).")
+                Logger.info("Complete \(label) (memoryUsage: \(LocalDevice.memoryUsageString)).")
             }
         }
     }
@@ -49,7 +49,7 @@ public class PendingTasks: NSObject {
         let wasRemoved = nil != pendingTasks.removeValue(forKey: pendingTask.id)
         owsAssertDebug(wasRemoved)
         if DebugFlags.internalLogging {
-            Logger.info("Completed: \(self.label).\(pendingTask.label) (memoryUsage: \(LocalDevice.memoryUsage))")
+            Logger.info("Completed: \(self.label).\(pendingTask.label) (memoryUsage: \(LocalDevice.memoryUsageString))")
         }
         pendingTask.future.resolve(())
     }