From 2133f600e3af0fe43145a9199735e37166bf554c Mon Sep 17 00:00:00 2001 From: Michelle Linington Date: Tue, 4 Jan 2022 01:14:07 -0800 Subject: [PATCH] More detailed logging of memory consumption --- Podfile | 4 +- Podfile.lock | 13 +-- Pods | 2 +- .../InternalSettingsViewController.swift | 2 +- SignalNSE/NSEContext.swift | 64 +++++------ SignalNSE/NotificationService.swift | 12 +-- .../src/Messages/MessageProcessor.swift | 4 +- .../src/Messages/OWSOutgoingReceiptManager.m | 4 +- SignalServiceKit/src/Util/Atomics.swift | 4 + SignalServiceKit/src/Util/LocalDevice.swift | 100 +++++++++++++----- SignalServiceKit/src/Util/PendingTasks.swift | 4 +- 11 files changed, 134 insertions(+), 79 deletions(-) diff --git a/Podfile b/Podfile index 2a8c30c09b..27229dba17 100644 --- a/Podfile +++ b/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"] diff --git a/Podfile.lock b/Podfile.lock index 087f271fa8..49abfcc857 100644 --- a/Podfile.lock +++ b/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 diff --git a/Pods b/Pods index 1782e1973f..d78417dd6f 160000 --- a/Pods +++ b/Pods @@ -1 +1 @@ -Subproject commit 1782e1973f3430ed4ef153c785f0c74f758c3927 +Subproject commit d78417dd6f7f3c7d1d405f633af8e53b7a065e20 diff --git a/Signal/src/ViewControllers/AppSettings/Internal/InternalSettingsViewController.swift b/Signal/src/ViewControllers/AppSettings/Internal/InternalSettingsViewController.swift index 05299a949c..7aae1fda52 100644 --- a/Signal/src/ViewControllers/AppSettings/Internal/InternalSettingsViewController.swift +++ b/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 ( diff --git a/SignalNSE/NSEContext.swift b/SignalNSE/NSEContext.swift index 3be659f862..8d098f737f 100644 --- a/SignalNSE/NSEContext.swift +++ b/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)" + } + } +} diff --git a/SignalNSE/NotificationService.swift b/SignalNSE/NotificationService.swift index d11fca6f42..742a8762fd 100644 --- a/SignalNSE/NotificationService.swift +++ b/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() } diff --git a/SignalServiceKit/src/Messages/MessageProcessor.swift b/SignalServiceKit/src/Messages/MessageProcessor.swift index 552598fb57..64f6c832bf 100644 --- a/SignalServiceKit/src/Messages/MessageProcessor.swift +++ b/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 diff --git a/SignalServiceKit/src/Messages/OWSOutgoingReceiptManager.m b/SignalServiceKit/src/Messages/OWSOutgoingReceiptManager.m index f65a3f1d99..79ec1b8683 100644 --- a/SignalServiceKit/src/Messages/OWSOutgoingReceiptManager.m +++ b/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); } } diff --git a/SignalServiceKit/src/Util/Atomics.swift b/SignalServiceKit/src/Util/Atomics.swift index 7da83a968e..80c103d6ce 100644 --- a/SignalServiceKit/src/Util/Atomics.swift +++ b/SignalServiceKit/src/Util/Atomics.swift @@ -254,6 +254,10 @@ public final class AtomicOptional { 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 { diff --git a/SignalServiceKit/src/Util/LocalDevice.swift b/SignalServiceKit/src/Util/LocalDevice.swift index 300c77d65b..3bf0401514 100644 --- a/SignalServiceKit/src/Util/LocalDevice.swift +++ b/SignalServiceKit/src/Util/LocalDevice.swift @@ -19,40 +19,92 @@ public class LocalDevice: NSObject { ProcessInfo.processInfo.activeProcessorCount } - public static var memoryUsageUInt64: UInt64? { - let vmInfoExpectedSize = MemoryLayout.size / MemoryLayout.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.size / MemoryLayout.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(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 (..