淺析 - CocoaLumberjack 3.6 之 DatabaseLogger

阿新 • • 發佈：2020-06-24

這是 DDLog 原始碼閱讀的最後一篇。本篇重點介紹 DDLogger 對資料庫儲存的支援，原理應該和 FileLogger 一樣，log 磁碟儲存的頻率，過期 log 的淘汰策略，以及 log 儲存的快取策略等。

開始之前，建議大家回顧前兩篇文章，很多基本的概念本篇會直接忽略。

DDAbstractDatabaseLogger

作為抽象類，你可以自由的根據專案所使用的資料庫型別來提供具體的子類實現。DDLog 在 Demo 中提供了 FMDBLogger 和 CoreDataLogger 的實踐，會在後面稍微介紹。因此，dbLogger 主要是保證 log entify (message 對應的 SQL) 的讀寫策略。來看幾個暴露 property 的宣告，先來看第一組：

@property (assign,readwrite) NSUInteger saveThreshold; // 500
@property (assign,readwrite) NSTimeInterval saveInterval; // 60s
複製程式碼

這兩個是用於控制 entities 寫入磁碟的頻率。畢竟我們不能針對每一條 log 都執行 SQL 插入語句 (I/O 操作）。

saveThreshold：當前未處理 entities 數量的閾值，預設 500 條；
saveInterval：執行下一次寫入的時間間隔；

我們可以通過將這兩個的值歸零的方式來表示?️止對應的控制。當然，這裡不建議將兩個值都置零。

另外三個主要用於控制已儲存 entities 的清除頻率，畢竟我們可不願使用者發現磁碟被我們給寫滿了。

@property (assign,readwrite) NSTimeInterval maxAge; // 7 day
@property (assign,readwrite) NSTimeInterval deleteInterval; // 5 min
@property (assign,readwrite) BOOL deleteOnEverySave; // NO
複製程式碼

maxAge：日誌最多保留時長，預設為 7 天；
deleteInterval：過期日誌刪除的頻率，預設為 5 分鐘；

deleteOnEverySave：另外一個可選項，用於控制每次日誌寫入時，是否需要進行過期日誌的清除。

同樣，maxAge 和 deleteInterval 也可通過置零來 disable 其功能。

Timer 的生命週期

既然是跟蹤日誌的寫入和擦除，timer 是少不了的。dbLogger 分別針對 save 和 delete 操作都分配了一個 dispatch_source_t 作為 timer。對應的建立、更新、銷燬的方法如下：

Save	Delete
createSuspendedSaveTimer	createAndStartDeleteTimer
updateAndResumeSaveTimer	updateDeleteTimer
destroySaveTimer	destroyDeleteTimer

createSuspendedSaveTimer

SaveTimer 在執行 log 寫入操作的時候會先暫停，在寫入結束後重新恢復計時。這裡 DDLog 使用了 _saveTimerSuspended 作為標識 (為 NSInteger 型別) ，標記 timer 的狀態。

if ((_saveTimer == NULL) && (_saveInterval > 0.0)) {
    _saveTimer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER,0,self.loggerQueue);

    dispatch_source_set_event_handler(_saveTimer,^{ 
        @autoreleasepool { [self performSaveAndSuspendSaveTimer]; } 
    });
    _saveTimerSuspended = -1;
}
複製程式碼

_saveInterval > 0.0 表明開啟了 ⏲️ 檢查 log 寫入任務；
為 timer 設定了定時回撥 performSaveAndSuspendSaveTimer ；

_saveTimerSuspended 的值有三種型別，分別對應 dispatch_source_t 的三個狀態：

value	description
-1	建立時的初始狀態： inactivited
0	被啟用狀態：actived / resumed
1	被掛起狀態：suspended

所以 timer 被 create 時是處於未啟用的暫停狀態。

updateAndResumeSaveTimer

啟用或恢復 SaveTimer，恢復前會檢查 _unsavedTime 是否大於 0，_unsavedTime 為每次執行 logMessage 時所記錄的當前時間。_unsavedTime 也就是 timer 恢復的 startTime。

if ((_saveTimer != NULL) && (_saveInterval > 0.0) && (_unsavedTime > 0)) {
    uint64_t interval = (uint64_t)(_saveInterval * (NSTimeInterval) NSEC_PER_SEC);
    dispatch_time_t startTime = dispatch_time(_unsavedTime,(int64_t)interval);

    dispatch_source_set_timer(_saveTimer,startTime,interval,1ull * NSEC_PER_SEC);
    //... 啟用 timer
}
複製程式碼

啟用計時器會重置 timer 的 startTime 和 interval。

恢復 timer 的邏輯，這裡對不同版本的 GCD API 做了相容性的適配。在 macOS 10.12,iOS 10.0 之後，新出了 dispatch_activate API 區別於原有的 dispatch_resume。這裡面有一個坑需要注意一下，先來看看這兩個方法的檔案描述：

dispatch_activate

Suspends the invocation of blocks on a dispatch object.

新生成的 queue 或 source 預設為 inactive 狀態，它們必須設定為 active 後其關聯的 event handler 才可能被invoke。

對於未啟用的 dispatch objc 我們可以通過 dispatch_set_target_queue() 來更新初始化時繫結的 queue，一旦為 active 話，這麼做就可能導致 crash，坑點 1。另外，dispatch_activate 對已啟用的 dispatch objc 是沒有副作用的。

dispatch_resume

Resumes the invocation of blocks on a dispatch object.

dispatch source 通過 dispatch_suspend() 時，會增加內部的 suspension count，resume 則是相反操作。當 suspension count 清空後，註冊的 event handler 才能被再次觸發。

為了向後相容，對於 inactive 的 source 呼叫 dispatch_resume 的效果與 dispatch_active 一致。對於 inactive 的 source 建議使用 dispatch_activate 來啟用。

如果對 suspension count 為 0 且為 inactive 狀態的 source 執行 dispatch_resume，則會觸發斷言被強制退出。

啟用 Timer 實現如下，所以下面這段程式碼對不同版本的 timer 的不同狀態做了區分。

if (@available(macOS 10.12,iOS 10.0,tvOS 10.0,watchOS 3.0,*)) {
    if (_saveTimerSuspended < 0) { /// inactive
        dispatch_activate(_saveTimer);
        _saveTimerSuspended = 0;
    } else if (_saveTimerSuspended > 0) { /// active
        dispatch_resume(_saveTimer);
        _saveTimerSuspended = 0;
    }
} else {
    if (_saveTimerSuspended != 0) { /// inactive
        dispatch_resume(_saveTimer);
        _saveTimerSuspended = 0;
    }
}
複製程式碼

destroySaveTimer

銷燬 timer。首先執行 dispatch_source_cancel 將 timer 標記為 cacneled 以取消之後的 event handler 的執行。之後將 timer 狀態標記為 actived，否則在 release inactive 的 source 會導致 crash。

if (@available(macOS 10.12,*)) {
    if (_saveTimerSuspended < 0) {
        dispatch_activate(_saveTimer);
    } else if (_saveTimerSuspended > 0) {
        dispatch_resume(_saveTimer);
    }
} else {
    if (_saveTimerSuspended != 0) {
        dispatch_resume(_saveTimer);
    }
}
複製程式碼

最後釋放：

#if !OS_OBJECT_USE_OBJC
dispatch_release(_saveTimer);
#endif
_saveTimer = NULL;
_saveTimerSuspended = 0;
複製程式碼

createAndStartDeleteTimer

Delete Timer 的邏輯就比較簡單一些。由於 log 清除的邏輯不需要像寫入一樣，在每次 logMessage 的時候都重新更新 startTime 並恢復為 active 狀態。同時 Delete Timer 在初始化的時候就保證了其為 active 狀態。所以 Delete Timer 在 update 的時候，也不需要再確保狀態為 active。

if ((_deleteTimer == NULL) && (_deleteInterval > 0.0) && (_maxAge > 0.0)) {
    _deleteTimer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER,self.loggerQueue);

    if (_deleteTimer != NULL) {
        dispatch_source_set_event_handler(_deleteTimer,^{ 
           @autoreleasepool { [self performDelete]; } 
        });

        [self updateDeleteTimer];

        if (@available(macOS 10.12,*))
            dispatch_activate(_deleteTimer);
        else
            dispatch_resume(_deleteTimer);
    }
}
複製程式碼

updateDeleteTimer

更新 Delete Timer 時，會檢查是否執行過一次清除操作。如果有，會以上次清楚的時間戳作為 startTime。

if ((_deleteTimer != NULL) && (_deleteInterval > 0.0) && (_maxAge > 0.0)) {
    int64_t interval = (int64_t)(_deleteInterval * (NSTimeInterval) NSEC_PER_SEC);
    dispatch_time_t startTime;

    if (_lastDeleteTime > 0) {
        startTime = dispatch_time(_lastDeleteTime,interval);
    } else {
        startTime = dispatch_time(DISPATCH_TIME_NOW,interval);
    }

    dispatch_source_set_timer(_deleteTimer,(uint64_t)interval,1ull * NSEC_PER_SEC);
}
複製程式碼

destroyDeleteTimer

if (_deleteTimer != NULL) {
    dispatch_source_cancel(_deleteTimer);
    #if !OS_OBJECT_USE_OBJC
    dispatch_release(_deleteTimer);
    #endif
    _deleteTimer = NULL;
}
複製程式碼

Configuration

dbLogger 對寫入和清除操作控制策略的屬性進行了過載。這幾個 Access 方法的 getter 和 setter 都是執行緒安全的，它們都是在 loggingQueue 和 loggerQueue 中來執行操作的，具體可以看 DDLog 上篇。getter 只是取值，因此這裡主要聊聊，其值更新時有哪些操作。

setSaveThreshold

更新 saveThreshold 後，需要檢查當前未寫入的 entities 數是否超過新賦值的閾值。如果超出需要主動執行寫入操作並更新 SaveTimer：

if ((self->_unsavedCount >= self->_saveThreshold) && (self->_saveThreshold > 0)) {
    [self performSaveAndSuspendSaveTimer];
}
複製程式碼

setSaveInterval

更新下一次執行 log entries 的時間間隔。又出現新知識點了，這裡作者使用了 islessgreater 巨集來判斷 saveInterval 是否有變化。這個 islessgreater 是 C99 標準中推薦的浮點數比較的巨集:

The built-in operator< and operator> for floating-point numbers may raise FE_INVALID if one or both of the arguments is NaN. This function is a "quiet" version of the expression x < y || x > y. The macro does not evaluate x and y twice.

使用它能避免因為值為 NaN 而出現的異常。關於浮點數的對比，這裡有一篇不錯的文章：comparison。

由於 saveInterval 是否為 0 是用於控制定時寫入功能，因此，更新後有三種情況需要處理：

if (self->_saveInterval > 0.0) {
    if (self->_saveTimer == NULL) {

        [self createSuspendedSaveTimer];
        [self updateAndResumeSaveTimer];
    } else {

        [self updateAndResumeSaveTimer];
    }
} else if (self->_saveTimer) {

    [self destroySaveTimer];
}
複製程式碼

需要開啟定時寫入且 timer 為 NULL；需要建立 SaveTimer 並啟用它；
需要開啟定時寫入且 timer 存在；啟用並恢復 SaveTimer；
無需定時寫入：銷燬 Timer；

setMaxAge

maxAge 的情況更多一些，有四種 case。在更新 maxAge 前，保留了舊值用於對比，同樣用到了 islessgreater。

BOOL shouldDeleteNow = NO;

if (oldMaxAge > 0.0) {
    if (newMaxAge <= 0.0) { /// 1
        [self destroyDeleteTimer];
       
    } else if (oldMaxAge > newMaxAge) {
        shouldDeleteNow = YES; /// 4
    }
} else if (newMaxAge > 0.0) {
    shouldDeleteNow = YES; /// 2
}

if (shouldDeleteNow) {
    [self performDelete];

    if (self->_deleteTimer) {
        [self updateDeleteTimer];
    } else {
        [self createAndStartDeleteTimer];
    }
}
複製程式碼

maxAge 檢查從開啟變為關閉狀態，此時只需要銷燬 Delete Timer；
maxAge 檢查從關閉變為開啟狀態，需要立即清理過期日誌，並初始化 Delete Timer
日誌保留時長增加，do nothing；
日誌保留時長減少，需要立即清理；

setDeleteInterval

deleteInterval 同 saveInterval 對 timer 的操作邏輯相同，就不展開了。

Save & Delete

既然做為抽象類，肯定需要有幾個方法暴露給子類去實現，要不就是通過 protocol 讓 delegate 去實現。這裡 ddLogger 預留了四個虛方法：

- (BOOL)db_log:(__unused DDLogMessage *)logMessage {
	// Return YES if an item was added to the buffer.
	// Return NO if the logMessage was ignored.
	return NO;
}
- (void)db_save {}
- (void)db_delete {}
- (void)db_saveAndDelete {}
複製程式碼

Public API

dbLogger 為使用者主動執行寫入和清除提供了兩個方法 savePendingLogEntries 和 deleteOldLogEntries。

作為 logger 的公共方法，其執行必須在 loggerQueue 中，以 savePendingLogEntries 為例：

dispatch_block_t block = ^{
     @autoreleasepool {
         [self performSaveAndSuspendSaveTimer];
     }
 };

 if ([self isOnInternalLoggerQueue]) {
     block();
 } else {
     dispatch_async(self.loggerQueue,block);
 }
複製程式碼

performSaveAndSuspendSaveTimer 則是其對應的 private method，同樣的 deleteOldLogEntries 對應的 private method 為 performDelete 。

performSaveAndSuspendSaveTimer

從方法名可知這裡做了兩件事：執行日誌寫入和掛起 SaveTimer。

寫入前確儲存在未寫入日誌，然後依據 _deleteOnEverySave 區分是否需要在每次寫入的同時進行清楚操作：

if (_unsavedCount > 0) {
    if (_deleteOnEverySave) {
        [self db_saveAndDelete];
    } else {
        [self db_save];
    }
}
/// 寫入結束重置狀態；
_unsavedCount = 0;
_unsavedTime = 0;
複製程式碼

接著將 timer 掛起，等待下一次的 logMessage 以重新整理 timer：

if (_saveTimer != NULL && _saveTimerSuspended == 0) {
    dispatch_suspend(_saveTimer);
    _saveTimerSuspended = 1;
}
複製程式碼

需要注意，這裡使用 _saveTimerSuspended 作為標記，防止多次執行 dispatch_suspend 操作，同時也保證了 source 是處於 active 狀態。前面在 dispatch source 的狀態變更中提到，source 內部維護一個 suspension count，多次執行會導致 count 增大。這裡算是一魚多吃了，?。

performDelete

if (_maxAge > 0.0) {
    [self db_delete];

    _lastDeleteTime = dispatch_time(DISPATCH_TIME_NOW,0);
}
複製程式碼

開啟清楚操作的話就執行 delete，結束後更新 _lastDeleteTime。

DDLogger

在遵循 DDLogger 的方法中基本也是維護 timer 的狀態，觸發 save 操作。

didAddLogger

[self createSuspendedSaveTimer];
[self createAndStartDeleteTimer];
複製程式碼

willRemoveLogger

[self performSaveAndSuspendSaveTimer];

[self destroySaveTimer];
[self destroyDeleteTimer];
複製程式碼

logMessage

if ([self db_log:logMessage]) { /* 更新 save timer */  }
複製程式碼

logMessage 方法是使用者產生 new log 所觸發的，包含了關鍵的 log message。在 FileLogger 中時將 message 轉換為 NSData 呼叫 lt_logData 來寫入檔案，而這裡則會將 message 轉換為 log entity 以期寫入 DB 中。db_log 所做的真是和 lt_logData 一致的。

不過這裡留了一個開關，就是 db_log 的返回值。如果返回 NO 則意味著改條 log 被丟棄，我們也不需要更新 timer 的 startTime 或者觸發 save 操作。

更新邏輯如下：

BOOL firstUnsavedEntry = (++_unsavedCount == 1);
if ((_unsavedCount >= _saveThreshold) && (_saveThreshold > 0)) {
    [self performSaveAndSuspendSaveTimer];
} else if (firstUnsavedEntry) {
    _unsavedTime = dispatch_time(DISPATCH_TIME_NOW,0);
    [self updateAndResumeSaveTimer];
}
複製程式碼

flush

[self performSaveAndSuspendSaveTimer];
複製程式碼

該方法是當應用退出或崩潰時主動呼叫，以及時儲存還在 pendding 狀態的 log entities。

FMDBLogger

簡單介紹一下 FMDBLogger，它是通過 FMDB 提供的 API 將 log message 寫入資料庫。

這裡每條 DDLogMessage 對應為 FMDBLogEntry，它簡單儲存了 context、flag、message、timestamp。資料庫建表和校驗就不說了，主要圍繞過載的幾個方法。

db_log

FMDBLogEntry *logEntry = [[FMDBLogEntry alloc] initWithLogMessage:logMessage];
[pendingLogEntries addObject:logEntry];
複製程式碼

這裡並沒有直接將 logEntry 插入 db，而是新增到緩衝列表中。我們真的需要這個緩衝區嗎？

來看 SQLite 作者的回答：(19) INSERT is really slow - I can only do few dozen INSERTs per second

Actually,SQLite will easily do 50,000 or more INSERT statements per second on an average desktop computer. But it will only do a few dozen transactions per second. Transaction speed is limited by the rotational speed of your disk drive. A transaction normally requires two complete rotations of the disk platter,which on a 7200RPM disk drive limits you to about 60 transactions per second.

Transaction speed is limited by disk drive speed because (by default) SQLite actually waits until the data really is safely stored on the disk surface before the transaction is complete. That way,if you suddenly lose power or if your OS crashes,your data is still safe. For details,read about atomic commit in SQLite..

By default,each INSERT statement is its own transaction. But if you surround multiple INSERT statements with BEGIN...COMMIT then all the inserts are grouped into a single transaction. The time needed to commit the transaction is amortized over all the enclosed insert statements and so the time per insert statement is greatly reduced.

也就是說，我們可以通過將多條插入語句用 BEGIN ... COMMIT 的方法包裹起來作為單獨的事務來提交，效率將會有巨大的提升。

db_save

最終嘗試將 pendingLogEntries 作為事務執行的方法。會先檢查 pendingLogEntries count 以及 database 是否正在執行事務，來判斷是否需要使用 BEGIN ... COMMIT 。

BOOL saveOnlyTransaction = ![database inTransaction];

if (saveOnlyTransaction) {
    [database beginTransaction];
}

/* INSERT INTO logs & remove pendingLogEntries  */ 

if (saveOnlyTransaction) {
    [database commit];

    if ([database hadError]) {
        NSLog(@"%@: Error inserting log entries: code(%d): %@",[self class],[database lastErrorCode],[database lastErrorMessage]);
    }
}
複製程式碼

可以看到這裡的事務並非強制執行的，因此還是有優化空間的。比如通過序列佇列來保證每次 save 都能在 transaction 中完成。

db_delete 與 db_saveAndDelete 就不展開了。

The End

DDLog 所提供的 Demo 中還有 CoreDataLogger、WebSocketLogger 等自定義 logger 的擴充套件。比如，通過 WebSocketLogger 我們可以將日誌直接輸出到瀏覽器上來時時預覽和校驗日誌或檢查埋點資料等等。

通過這些 Demo 我們對 DDLog 的需求完全可以通過 Logger 的擴充套件來實現。比如，通過 mmap 來儲存日誌。這方面 Xlog 和 logan 目前就是這麼實現的。而基於微信現有提供的 MMKV，我們用 Logger 簡單擴充套件就能實現高效儲存。

DDLog 中可以看到其對 dispatch source 的安全使用，包括 queue 和 timer 和多執行緒的處理；對 NSProxy 的巧妙使用來為 fileHandler 新增 buffer 支援；對系統的 log system 的瞭解，以及程式碼的健壯性，日誌更新儲存策略等等。非常值得一看。