請求方報超時的比例大概有4%

他們設定的超時時間是500ms

但是我們統計日誌，服務時間超過500ms的日誌很少

原因是什麼呢？

超時原因分析：

1、請求內容太長

根據請求方超時日誌， 大多數query的長度都是1w以上，這些query我手動請求，響應時間的確大於500ms， 在服務端還沒有處理完的時候，客戶端已經超時斷開了

2、等待時間太長

客戶端報超時的query，其中有部分日誌中記錄響應時間其實只有100多毫秒

客戶端的整個請求時間包括多個部分： 請求網路延遲、等待被處理、被處理、序列化返回、返回網路延遲

目前“被處理”的時間其實很短，但是客戶端還是超時，而因為都是內網訪問，那麼網路延遲的時間是很短的，那麼主要的原因應該是在等待被處理或者序列化返回的時候耗時了

如果要驗證是等待被處理耗時太長：只能對時間戳了，看傳送請求的時間和開始處理（接收到請求）的時間之間的關係， 但是如果客戶端和服務端不是一個機器，那麼兩個機器的時間本身就不同步的話就不好弄了

日誌記錄丟失的問題：

發現報超時的這些query，日誌中部分query查不到日誌

網上資料說：是因為logging不是執行緒安全的，  當多個程序往同一個日誌檔案裡面寫日誌的時候可能會出現問題：

每一次往disk寫入的IO操作，是以1個block的大小為原子單位的。現在的系統中，一個block一般是4K。也就是說當一次寫入的log資訊大小不超過4k，那麼這條log的紀錄就是原子的。如果這條log大小超過了4k，那麼這條log紀錄就有可能被別的程序所中斷。

在這裡，原子性是由系統本身提供的。在client層面，並不需要任何的加鎖操作。也就是說，當我們列印的log不會超過4k時，我們是可以忽略多程序競爭寫一個檔案的問題的。

這也許就解釋了，為什麼有些query日誌裡面沒有列印了： 因為請求方給我傳送的超時query的長度基本都在1w個字以上，這很顯然超過了4k， 所以在寫日誌的過程中因為執行緒不安全的問題而發生了寫日誌失敗

日誌丟失問題壓測驗證：

於是，我手動對這個服務進行了壓力測試， 單機壓測：

當query內容很短的時候， 無論是1個併發、10個還是20個併發，日誌記錄一條都沒有丟失

當query內容很長，長達1w個字的時候，1個併發情況下，日誌沒有丟失，10個併發的情況下丟失了一條日誌，20個併發的情況下丟失了10條日誌

參考地址：

https://www.jianshu.com/p/8fe3ff57b5c6