日志系統實戰(三)-分布式跟蹤的Net實現

介紹

在大型系統開發調試中，跨系統之間聯調開始變得不好使了。莫名其妙一個錯誤爆出來了，日志雖然有記錄，但到底是哪里出問題了呢？  

是Ios端參數傳的不對？還是A系統或B系統提供的接口導致？相信有不少人遇到這種情況，大多數問題往往不大，但排查起來比較費勁。

下面介紹下怎么通過上下文跟蹤的方法，最快定位到其問題。

閱讀目錄：

1. 概述
2. web環境
3. 多線程環境
4. 異步環境
5. 性能，大數據量，隱私安全
6. 總結

概述

簡單介紹就是，通過一個TraceId把整個業務請求邏輯相關聯起來，根據時間順序形成一個完整的調用鏈。

這樣無論任何地方報錯，只要拿TraceId去日志系統簡查下，根據上下文的順序就知道是哪一步、哪個函數、哪個參數出錯了，能以最快速度定位處理BUG。

 

如圖以博客園為例。當博客園收到一個請求后，自動為生產個唯一ID 1000，之后所有處理工作都是用這個1000。

每個處理模塊都維持一個上下文ID自增，rpcid++。

其處理模塊可以是函數級，邏輯層級，服務器級等都可以。

一旦發現有異常后，自動將TraceId發給博客園。這樣程序員們，就能根據TraceId最快定位問題了。

 

關於各種環境下具體的代碼實現：

web環境

定義跟蹤日志需要的參數，進行上下文傳遞。

   public class LogBody
    {
        /// <summary>
        /// 跟蹤ID
        /// </summary>
        public string TraceId { get; set; }
        /// <summary>
        /// 上下文ID
        /// </summary>
        public int RpcId { get; set; }
        /// <summary>
        /// 處理時間
        /// </summary>
        public DateTime LastTime { get; set; }
    }

在global.asax全局Application_BeginRequest函數中，使用HttpContext.Current上下文，開始進行埋點(跟蹤)，設置rpc 0。

   void Application_BeginRequest(object sender, EventArgs e)
        {
            var lb = new LogBody();
            lb.TraceId = Guid.NewGuid().ToString("N");
            lb.RpcId=0;
            lb.LastTime = DateTime.Now;
            HttpContext.Current.Response.AppendHeader("traceID", lb.TraceId);
            HttpContext.Current.Items.Add(lb.TraceId, lb);
            //記錄日志，例：用戶請求參數，userAgent等。
        }

在default頁開始業務邏輯，設置rpc 1。

 protected void Page_Load(object sender, EventArgs e)
        {
            var traceID = HttpContext.Current.Response.Headers["traceID"];
            LogBody logbody = HttpContext.Current.Items[traceID] as LogBody;
            logbody.RpcId++;
            logbody.LastTime = DateTime.Now;
            //業務邏輯。
            //記錄日志。。。
        }

如上就完成上下文的傳遞。

Application_BeginRequest  中在實際使用中，只需要對有用的頁面(例:aspx，ashx)進行埋點。

日志記錄的時候，可以把logbody都存儲起來。

存儲到Headers可以讓前端通過JS也能拿到TraceId，方便去排查問題。

LastTime這個字段，可以與上一次的相減，這樣就得出中間邏輯處理所花費的時間了。

多線程環境

在web程序中可以用httpcontext的上下文傳遞。

在單線程的程序中,按照線性順序即可。

多線程中利用用threadlocal傳遞。

  public static ThreadLocal<LogBody> Body = new ThreadLocal<LogBody>();
        static void Main(string[] args)
        {
            var t1 = new Thread(() =>
            {
                Body.Value = new LogBody()
                {
                    LastTime = DateTime.Now,
                    RpcId = 0,
                    TraceId = Guid.NewGuid().ToString("N")
                };
                //業務1
                Console.WriteLine("Thread1 log record:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);

                Thread.Sleep(5000);

                Body.Value.RpcId++;
                Body.Value.LastTime = DateTime.Now;
                //業務2
                Console.WriteLine("Thread1 log record:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);
            });
            t1.Start();

            var t2 = new Thread(() =>
            {
                Body.Value = new LogBody()
                {
                    LastTime = DateTime.Now,
                    RpcId = 0,
                    TraceId = Guid.NewGuid().ToString("N")
                };
                //業務1
                Console.WriteLine("Thread2 log record:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);

                Thread.Sleep(5000);
                Body.Value.RpcId++;
                Body.Value.LastTime = DateTime.Now;
                //業務2
                Console.WriteLine("Thread2 log record:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);
            });
            t2.Start();
        }

運行如下：

 

異步環境

往往在生產環境中，會有大量的異步操作。如果有異步行為的話，打亂上下文怎么辦？這時候需要引入另外一個概念，父節點Id。

這樣異步操作的行為就父節點之下，最終在日志后台展示的是一個倒着的樹形結構。

如圖可以看到業務2異步派生出來的子節點。

 把上下文rpcid修改成double類型。

 static void Main(string[] args)
        {
            var t2 = new Thread(() =>
            {
                Body.Value = new LogBody()
                {
                    LastTime = DateTime.Now,
                    RpcId = 1,
                    TraceId = Guid.NewGuid().ToString("N")
                };
                var t1 = new Thread((lb) =>
                {
                    var temp = lb as LogBody;
                    Body.Value = new LogBody()
                    {
                        LastTime = DateTime.Now,
                        RpcId = temp.RpcId,
                        TraceId = temp.TraceId
                    };
                    Body.Value.RpcId += 0.1;
                    //業務x
                    Console.WriteLine("async Thread:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime );

                    Thread.Sleep(5000);

                    Body.Value.RpcId+=0.1;
                    Body.Value.LastTime = DateTime.Now;
                    //業務y
                    Console.WriteLine("async Thread:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);
                });
                t1.Start(Body.Value);


                //業務1
                Console.WriteLine("sync Thread:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);

                Thread.Sleep(2000);
                Body.Value.RpcId+=1;
                Body.Value.LastTime = DateTime.Now;
                //業務2
                Console.WriteLine("sync Thread:" + Body.Value.TraceId + "-" + Body.Value.RpcId + "-" + Body.Value.LastTime);
            });
            t2.Start();
        }

代碼中用參數傳遞給了異步線程中，運行如下：

性能，大數據量，隱私安全

關於性能

從代碼中可以看出，這種方式對程序性能影響可以忽略不計。

需要注意是：如果在生產環境跑的話，不論是寫文件，還是數據庫，或寫統一日志平台。都會導致大量IO讀寫，網絡資源消耗。

如果服務器都消耗這上面，就得不償失了。

可以用內存隊列+隊列+批量push或pull的方式，並且注意設置閥值。

關於大數據量

大量的請求，其實多數是無效的。這里引入采樣率的概念。 例如按求余取，或者按地區，時間等。也可以單獨寫采樣規則。

日志可以只記錄error以上的級別，只有在排查生產環境的時候才開啟debug，info級別信息。   

存儲這塊，可以根據實際需要選擇sql server，mongodb，hbase hdfs。

關於隱私安全

如果有敏感數據，可根據安全級別進行加密。

總結

本文是基於Google dapper論文的思路展開，基於此進行很多擴展。

示例中采用的是手動記錄，在實際使用中，可以簡化調用，封裝成自動構建的，有興趣的可以看前2篇自動注入的相關介紹。

參考資源

Google dapper論文

淘寶EagleEye系統