在分布式微服務的架構中，不同業務的項目之間通過RPC服務相互調用，方便了可擴展性，如下圖
假如在某個時間節點某個接口請求出現了請求比較慢的問題，而整個接口的流程可能涉及到多個RPC服務之間的調用，那么該如何排查問題呢？
先說一下一體化架構的一貫方法
最簡單的思路是：打印下單操作的每一個步驟的耗時情況，然后通過比較這些耗時的數據，找到延遲最高的一步，然后再來看看這個步驟要如何的優化。如果有必要的話，你還需要針對步驟中的子步驟，再增加日志來繼續排查，打印出日志后，我們可以登錄到機器上，搜索關鍵詞來查看每個步驟的耗時情況。
雖然這個方式比較簡單，但可能很快就會遇到問題：由於同時會有多個下單請求並行處理，所以，這些下單請求的每個步驟的耗時日志，是相互穿插打印的。你無法知道這些日志，哪些是來自於同一個請求，也就不能很直觀地看到，某一次請求耗時最多的步驟是哪一步了。那么，你要如何把單次請求，每個步驟的耗時情況串起來呢？
一個簡單的思路是：給同一個請求的每一行日志，增加一個相同的標記。這樣，只要拿到這個標記就可以查詢到這個請求鏈路上，所有步驟的耗時了，我們把這個標記叫做requestId，我們可以在程序的入口處生成一個requestId，然后把它放在線程的上下文中，這樣就可以在需要時，隨時從線程上下文中獲取到requestId了。簡單的代碼實現就像下面這樣：
String requestId = UUID.randomUUID().toString();
ThreadLocal<String> tl = new ThreadLocal<String>(){
@Override
protected String initialValue() {
return requestId;
}
}; //requestId存儲在線程上下文中
long start = System.currentTimeMillis();
processA();
Logs.info("rid : " + tl.get() + ", process A cost " + (System.currentTimeMillis() - start)); // 日志中增加requestId
start = System.currentTimeMillis();
processB();
Logs.info("rid : " + tl.get() + ", process B cost " + (System.currentTimeMillis() - start));
start = System.currentTimeMillis();
processC();
Logs.info("rid : " + tl.get() + ", process C cost " + (System.currentTimeMillis() - start));
有了requestId，你就可以清晰地了解一個調用鏈路上的耗時分布情況了。於是，你給你的代碼增加了大量的日志，來排查下單操作緩慢的問題。
但是假如每次有新的問題，你需要每次給代碼增加日志然后重啟服務，這樣的方式不是最好的辦法，然后考慮一下有沒有別的辦法。
思路
一個接口響應時間慢，一般是出在跨網絡的調用上，比如說請求數據庫、緩存或者依賴的第三方服務。所以，只需要針對這些調用的客戶端類，通過插入一些代碼打印每個耗時就好了。
這樣，你就在你的系統的每個接口中，打印出了所有訪問數據庫、緩存、外部接口的耗時情況，一次請求可能要打印十幾條日志，如果你的電商系統的QPS是10000的話，就是每秒鍾會產生十幾萬條日志，對於磁盤I/O的負載是巨大的，那么這時，你就要考慮如何減少日志的數量。
你可以考慮對請求做采樣，采樣的方式也簡單，比如你想采樣10%的日志，那么你可以只打印“requestId%10==0”的請求。
有了這些日志之后，當給你一個requestId的時候，你發現自己並不能確定這個請求到了哪一台服務器上，所以你不得不登陸所有的服務器，去搜索這個requestId才能定位請求。這樣無疑會增加問題排查的時間。
你可以考慮的解決思路是：把日志不打印到本地文件中，而是發送到消息隊列里，再由消息處理程序寫入到集中存儲中，比如Elasticsearch。這樣，你在排查問題的時候，只需要拿着requestId到Elasticsearch中查找相關的記錄就好了。在加入消息隊列和Elasticsearch之后，這個排查程序的架構圖也會有所改變：
總結一下，為了排查單次請求響應時間長的原因，主要做了哪些事情：
- 1.在記錄打點日志時，我們使用requestId將日志串起來，這樣方便比較一次請求中的多個步驟的耗時情況；
- 2.增加了日志采樣率，避免全量日志的打印；
- 3.最后為了避免在排查問題時，需要到多台服務器上搜索日志，我們使用消息隊列，將日志集中起來放在了Elasticsearch中。
再來說一下分布式trace
在一體化架構中，單次請求的所有的耗時日志，都被記錄在一台服務器上，而在微服務的場景下，單次請求可能跨越多個RPC服務，這就造成了，單次的請求的日志會分布在多個服務器上。
當然，你也可以通過requestId將多個服務器上的日志串起來，但是僅僅依靠requestId很難表達清楚服務之間的調用關系，所以從日志中，就無法了解服務之間是誰在調用誰。因此，我們采用traceId + spanId這兩個數據維度來記錄服務之間的調用關系（這里traceId就是requestId），也就是使用traceId串起單次請求，用spanId記錄每一次RPC調用。
比如：你的請求從用戶端過來，先到達A服務，A服務會分別調用B和C服務，B服務又會調用D和E服務。
- 用戶到A服務之后會初始化一個traceId為100，spanId為1；
- A服務調用B服務時，traceId不變，而spanId用1.1標識，代表上一級的spanId是1，這一級的調用次序是1；
- A調用C服務時，traceId依然不變，spanId則變為了1.2，代表上一級的spanId還是1，而調用次序則變成了2，以此類推。
通過這種方式，我們可以在日志中，清晰地看出服務的調用關系是如何的，方便在后續計算中調整日志順序，打印出完整的調用鏈路。
那么spanId是何時生成的，又是如何傳遞的呢？這部分內容可以算作一個延伸點，能夠幫你了解分布式trace中間件的實現原理。
首先，A服務在發起RPC請求服務B前，先從線程上下文中獲取當前的traceId和spanId，然后，依據上面的邏輯生成本次RPC調用的spanId，再將spanId和traceId序列化后，裝配到請求體中，發送給服務方B。
服務方B獲取請求后，從請求體中反序列化出spanId和traceId，同時設置到線程上下文中，以便給下次RPC調用使用。在服務B調用完成返回響應前，計算出服務B的執行時間發送給消息隊列。
當然，在服務B中，你依然可以使用切面編程的方式，得到所有調用的數據庫、緩存、HTTP服務的響應時間，只是在發送給消息隊列的時候，要加上當前線程上下文中的spanId和traceId。
這樣，無論是數據庫等資源的響應時間，還是RPC服務的響應時間就都匯總到了消息隊列中，在經過一些處理之后，最終被寫入到Elasticsearch中以便給開發和運維同學查詢使用。
而在這里，你大概率會遇到的問題還是性能的問題，也就是因為引入了分布式追蹤中間件，導致對於磁盤I/O和網絡I/O的影響，“避坑”指南就是：如果你是自研的分布式trace中間件，那么一定要提供一個開關，方便在線上隨時將日志打印關閉；如果使用開源的組件，可以開始設置一個較低的日志采樣率，觀察系統性能情況再調整到一個合適的數值。