Python 100 Days Day46 Log and Debug tool

author: jackfrued

日志和調試工具欄

配置日志

項目開發階段，顯示足夠的調試信息以輔助開發人員調試代碼還是非常必要的；項目上線以後，將系統運行時出現的警告、錯誤等信息記錄下來以備相關人員了解系統運行狀況並維護代碼也是很有必要的。與此同時，采集日志數據也是為網站做數字化運營奠定一個基礎，通過對系統運行日志的分析，我們可以監測網站的流量以及流量分布，同時還可以挖掘出用戶的使用習慣和行為模式。

接下來，我們先看看如何通過Django的配置文件來配置日志。Django的日志配置基本可以參照官方文檔再結合項目實際需求來進行，這些內容基本上可以從官方文檔上覆制下來，然後進行局部的調整即可，下面給出一些參考配置。

LOGGING = {
    'version': 1,
    # 是否禁用已經存在的日志器
    'disable_existing_loggers': False,
    # 日志格式化器
    'formatters': {
        'simple': {
            'format': '%(asctime)s %(module)s.%(funcName)s: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S',
        },
        'verbose': {
            'format': '%(asctime)s %(levelname)s [%(process)d-%(threadName)s] '
                      '%(module)s.%(funcName)s line %(lineno)d: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S',
        }
    },
    # 日志過濾器
    'filters': {
        # 只有在Django配置文件中DEBUG值為True時才起作用
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    # 日志處理器
    'handlers': {
        # 輸出到控制台
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'DEBUG',
            'filters': ['require_debug_true'],
            'formatter': 'simple',
        },
        # 輸出到文件(每周切割一次)
        'file1': {
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': 'access.log',
            'when': 'W0',
            'backupCount': 12,
            'formatter': 'simple',
            'level': 'INFO',
        },
        # 輸出到文件(每天切割一次)
        'file2': {
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': 'error.log',
            'when': 'D',
            'backupCount': 31,
            'formatter': 'verbose',
            'level': 'WARNING',
        },
    },
    # 日志器記錄器
    'loggers': {
        'django': {
            # 需要使用的日志處理器
            'handlers': ['console', 'file1', 'file2'],
            # 是否向上傳播日志信息
            'propagate': True,
            # 日志級別(不一定是最終的日志級別)
            'level': 'DEBUG',
        },
    }
}

大家可能已經注意到了，上面日志配置中的formatters是日志格式化器，它代表了如何格式化輸出日志，其中格式占位符分別表示：

1. %(name)s - 記錄器的名稱
2. %(levelno)s - 數字形式的日志記錄級別
3. %(levelname)s - 日志記錄級別的文本名稱
4. %(filename)s - 執行日志記錄調用的源文件的文件名稱
5. %(pathname)s - 執行日志記錄調用的源文件的路徑名稱
6. %(funcName)s - 執行日志記錄調用的函數名稱
7. %(module)s - 執行日志記錄調用的模塊名稱
8. %(lineno)s - 執行日志記錄調用的行號
9. %(created)s - 執行日志記錄的時間
10. %(asctime)s - 日期和時間
11. %(msecs)s - 毫秒部分
12. %(thread)d - 線程ID（整數）
13. %(threadName)s - 線程名稱
14. %(process)d - 進程ID （整數）

日志配置中的handlers用來指定日志處理器，簡單的說就是指定將日志輸出到控制台還是文件又或者是網絡上的服務器，可用的處理器包括：

1. logging.StreamHandler(stream=None) - 可以向類似與sys.stdout或者sys.stderr的任何文件對象輸出信息
2. logging.FileHandler(filename, mode='a', encoding=None, delay=False) - 將日志消息寫入文件
3. logging.handlers.DatagramHandler(host, port) - 使用UDP協議，將日志信息發送到指定主機和端口的網絡主機上
4. logging.handlers.HTTPHandler(host, url) - 使用HTTP的GET或POST方法將日志消息上傳到一台HTTP 服務器
5. logging.handlers.RotatingFileHandler(filename, mode='a', maxBytes=0, backupCount=0, encoding=None, delay=False) - 將日志消息寫入文件，如果文件的大小超出maxBytes指定的值，那麽將重新生成一個文件來記錄日志
6. logging.handlers.SocketHandler(host, port) - 使用TCP協議，將日志信息發送到指定主機和端口的網絡主機上
7. logging.handlers.SMTPHandler(mailhost, fromaddr, toaddrs, subject, credentials=None, secure=None, timeout=1.0) - 將日志輸出到指定的郵件地址
8. logging.MemoryHandler(capacity, flushLevel=ERROR, target=None, flushOnClose=True) - 將日志輸出到內存指定的緩沖區中

上面每個日志處理器都指定了一個名為level的屬性，它代表了日志的級別，不同的日志級別反映出日志中記錄信息的嚴重性。Python中定義了六個級別的日志，按照從低到高的順序依次是：NOTSET、DEBUG、INFO、WARNING、ERROR、CRITICAL。

最後配置的日志記錄器是用來真正輸出日志的，Django框架提供了如下所示的內置記錄器：

1. django - 在Django層次結構中的所有消息記錄器
2. django.request - 與請求處理相關的日志消息。5xx響應被視為錯誤消息；4xx響應被視為為警告消息
3. django.server - 與通過runserver調用的服務器所接收的請求相關的日志消息。5xx響應被視為錯誤消息；4xx響應被記錄為警告消息；其他一切都被記錄為INFO
4. django.template - 與模板渲染相關的日志消息
5. django.db.backends - 有與數據庫交互產生的日志消息，如果希望顯示ORM框架執行的SQL語句，就可以使用該日志記錄器。

日志記錄器中配置的日志級別有可能不是最終的日志級別，因為還要參考日志處理器中配置的日志級別，取二者中級別較高者作為最終的日志級別。

配置Django-Debug-Toolbar

如果想調試你的Django項目，你一定不能不過名為Django-Debug-Toolbar的神器，它是項目開發階段輔助調試和優化的必備工具，只要配置了它，就可以很方便的查看到如下表所示的項目運行信息，這些信息對調試項目和優化Web應用性能都是至關重要的。

1. 安裝Django-Debug-Toolbar。

   pip install django-debug-toolbar
   

2. 配置 - 修改settings.py。

   INSTALLED_APPS = [
       'debug_toolbar',
   ]
      
   MIDDLEWARE = [
       'debug_toolbar.middleware.DebugToolbarMiddleware',
   ]
      
   DEBUG_TOOLBAR_CONFIG = {
       # 引入jQuery庫
       'JQUERY_URL': 'https://cdn.bootcss.com/jquery/3.3.1/jquery.min.js',
       # 工具欄是否折疊
       'SHOW_COLLAPSED': True,
       # 是否顯示工具欄
       'SHOW_TOOLBAR_CALLBACK': lambda x: True,
   }
   

3. 配置 - 修改urls.py。

   if settings.DEBUG:
      
       import debug_toolbar
      
       urlpatterns.insert(0, path('__debug__/', include(debug_toolbar.urls)))
   

4. 在配置好Django-Debug-Toolbar之後，頁面右側會看到一個調試工具欄，如下圖所示，上面包括了如前所述的各種調試信息，包括執行時間、項目設置、請求頭、SQL、靜態資源、模板、緩存、信號等，查看起來非常的方便。

   

優化ORM代碼

在配置了日志或Django-Debug-Toolbar之後，我們可以查看一下之前將老師數據導出成Excel報表的視圖函數執行情況，這里我們關注的是ORM框架生成的SQL查詢到底是什麽樣子的，相信這里的結果會讓你感到有一些意外。執行Teacher.objects.all()之後我們可以注意到，在控制台看到的或者通過Django-Debug-Toolbar輸出的SQL是下面這樣的：

SELECT `tb_teacher`.`no`, `tb_teacher`.`name`, `tb_teacher`.`detail`, `tb_teacher`.`photo`, `tb_teacher`.`good_count`, `tb_teacher`.`bad_count`, `tb_teacher`.`sno` FROM `tb_teacher`; args=()
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 101; args=(101,)
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 101; args=(101,)
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 101; args=(101,)
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 101; args=(101,)
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 103; args=(103,)
SELECT `tb_subject`.`no`, `tb_subject`.`name`, `tb_subject`.`intro`, `tb_subject`.`create_date`, `tb_subject`.`is_hot` FROM `tb_subject` WHERE `tb_subject`.`no` = 103; args=(103,)

這里的問題通常被稱為“1+N查詢”（有的地方也將其稱之為“N+1查詢”），原本獲取老師的數據只需要一條SQL，但是由於老師關聯了學科，當我們查詢到N條老師的數據時，Django的ORM框架又向數據庫發出了N條SQL去查詢老師所屬學科的信息。每條SQL執行都會有較大的開銷而且會給數據庫服務器帶來壓力，如果能夠在一條SQL中完成老師和學科的查詢肯定是更好的做法，這一點也很容易做到，相信大家已經想到怎麽做了。是的，我們可以使用連接查詢，但是在使用Django的ORM框架時如何做到這一點呢？對於多對一關聯（如投票應用中的老師和學科），我們可以使用QuerySet的用select_related()方法來加載關聯對象；而對於多對多關聯（如電商網站中的訂單和商品），我們可以使用prefetch_related()方法來加載關聯對象。

在導出老師Excel報表的視圖函數中，我們可以按照下面的方式優化代碼。

queryset = Teacher.objects.all().select_related('subject')

事實上，用ECharts生成前端報表的視圖函數中，查詢老師好評和差評數據的操作也能夠優化，因為在這個例子中，我們只需要獲取老師的姓名、好評數和差評數這三項數據，但是在默認的情況生成的SQL會查詢老師表的所有字段。可以用QuerySet的only()方法來指定需要查詢的屬性，也可以用QuerySet的defer()方法來指定暫時不需要查詢的屬性，這樣生成的SQL會通過投影操作來指定需要查詢的列，從而改善查詢性能，代碼如下所示：

queryset = Teacher.objects.all().only('name', 'good_count', 'bad_count')

當然，如果要統計出每個學科的老師好評和差評的平均數，利用Django的ORM框架也能夠做到，代碼如下所示：

queryset = Teacher.objects.values('subject').annotate(good=Avg('good_count'), bad=Avg('bad_count'))

這里獲得的QuerySet中的元素是字典對象，每個字典中有三組鍵值對，分別是代表學科編號的subject、代表好評數的good和代表差評數的bad。如果想要獲得學科的名稱而不是編號，可以按照如下所示的方式調整代碼：

queryset = Teacher.objects.values('subject__name').annotate(good=Avg('good_count'), bad=Avg('bad_count'))

可見，Django的ORM框架允許我們用面向對象的方式完成關系數據庫中的分組和聚合查詢。