現象：

生產中心進行拷機任務下了300個任務，過了一陣時間后發現任務不再被調度起來，查看后臺日志發現日志輸出停在某個時間點。

分析：

1、首先確認進程存在并沒有dead。

2、然后用strace ?p看了一下進程，發現進程卡在futex調用上面，應該是在鎖操作上面出問題了。

3、用gdb attach進程ID，用py-bt查看一下堆棧，發現堆棧的信息大致為：sig_handler(某個信號處理函數)->auroralogger(自定義的日志函數)->logging(python的logging模塊)->threading.acquire(獲取鎖)。從gdb的bt信息基本驗證了上面的猜想，應該是出現了死鎖。

4、Python的logging模塊本身肯定不會有死鎖的這種bug有可能出問題的就是我們的使用方式，看python中logging模塊的doc，發現有一個有一個Thread Safety的章節，內容很簡單但是也一下就解釋了我遇到的這個問題，內容如下：

The logging module is intended to be thread-safe without any special work needing to be done by its clients. It achieves this though using threading locks; there is one lock to serialize access to the module’s shared data, and each handler also creates a lock to serialize access to its underlying I/O.

If you are implementing asynchronous signal handlers using the signal module, you may not be able to use logging from within such handlers. This is because lock implementations in the threading module are not always re-entrant, and so cannot be invoked from such signal handlers.

第一部分是說logging是線程安全的，通過threading的lock對公用的數據進行了加鎖。

第二部分特意提到了在異步的信號處理函數中不能使用logging模塊，因為threading的lock機制是不支持重入的。

這樣就解釋了上面我遇到的死鎖問題，因為我在信號處理函數中調用了不可以重入的logging模塊。

線程安全和可重入：

從上面的logging模塊來看線程安全和可重入不是等價的，那么這兩個概念之間有什么聯系、區別呢？

1、可重入函數：從字面意思來理解就是這個函數可以重復調用，函數被多個線程亂序執行甚至交錯執行都能保證函數的輸出和函數單獨被執行一次的輸出一致。也就是說函數的輸出只決定于輸入。

線程安全函數：函數可以被多個線程調用，并且保證不會引用到錯誤的或者臟的數據。線程安全的函數輸出不僅僅依賴于輸入還可能依賴于被調用時的順序。

2、可重入函數和線程安全函數之間有一個最大的差異是：是否是異步信號安全。可重入函數在異步信號處理函數中可以被安全調用，而線程安全函數不保證可以在異步信號處理函數中被安全調用。

上面我們遇到的loggin模塊就是非異步信號安全的，在主線程中我們正在使用log函數而log函數調用了threading.lock來獲取到了鎖，此時一個異步信號產生程序跳轉到信號處理函數中，信號處理函數又正好調用了log函數，因為前一個被調用的log函數還未釋放鎖，最后就形成了一個死鎖。

1、可重入函數必然是線程安全函數和異步信號安全函數，線程安全函數不一定是可重入函數。

總結：

異步信號處理函數中一定要盡可能的功能簡單并且不能調用不可重入的函數。

Python loggin模塊是線程安全但是是不可重入的。

補充：Python—logging模塊使用教程

簡單用法日志等級級別 何時使用 DEBUG 細節信息，僅當診斷問題時適用。 INFO 確認程序按預期運行 WARNING 表明有已經或即將發生的意外（例如：磁盤空間不足）。程序仍按預期進行 ERROR 由于嚴重的問題，程序的某些功能已經不能正常執行 CRITICAL 嚴重的錯誤，表明程序已不能繼續執行 控制臺輸出日志

import logginglogging.warning(’Watch out!’) logging.info(’I told you so’) 將日志保存到文件并且設置時間和輸出格式

import logging# 保存文件為example.log，記錄等級為DEBUG，即只記錄DENBUG及以上的日志# 輸出格式為 2019-19-06 18:47:06 - WARNING - And this, toologging.basicConfig( filename=’example.log’, filemode=’w’, level=logging.DEBUG, format=’%(asctime)s - %(levelname)s - %(message)s’, datefmt=’%Y-%d-%d %H:%M:%S’)logging.debug(’This message should go to the log file’)logging.info(’So shoul this’)logging.warning(’And this, too’)參數解釋

filename日志文件路徑

filemode記錄日志文件的模式，w為每次啟動程序都創建一個全新的文件記錄, a表示追加到文件末尾, 默認為a

level記錄日志的等級

format日志輸出的格式

datefmt日志輸出時間的格式

使用配置文件配置日志

[loggers]# 配置日志對象名, 默認為rootkeys=root, poj[handlers]# 日志配置名對象名keys=writeFileHandlers[formatters]# 日志輸出格式對象名keys=writeFileFormatters[logger_root]level=DEBUGhandlers=writeFileHandlers[logger_poj]level=DEBUGhandlers=writeFileHandlersqualname=writeFileFormatterspropagate=0[logger_leetcode]level=DEBUGhandlers=writeFileHandlersqualname=writeFileFormatterspropagate=0[handler_writeFileHandlers]# 設置writeFileHandlers對象的配置class=FileHandlerlevel=DEBUGformatter=writeFileFormatters# 記錄在文件中，以追加的形式args=('demo.log', 'a')[formatter_writeFileFormatters]設置writeFileHandlers對象的輸出配置format=%(asctime)s - %(name)s - %(levelname)s - %(message)sdatefmt=%Y-%d-%m %H:%M:%S使用配置文件

import logging.config# 加載配置文件logging.config.fileConfig(’logging.conf’)# 獲取日志對象名為poj的logger = logging.getLogger('poj')logger.debug(’This message should go to the log file’)logger.info(’So shoul this’)logger.warning(’And this, too’)

以上為個人經驗，希望能給大家一個參考，也希望大家多多支持好吧啦網。如有錯誤或未考慮完全的地方，望不吝賜教。