15天玩轉redis —— 第七篇 同事的一次快取操作引起對慢查詢的認識

      上個星期同事做一個業務模組，需要將一個80M的資料存入到redis快取中，想法總是好的，真操作的時候遇到了HSet超時，我們使用的是C#的

StackExchange.Redis驅動。

  <redisCacheClient allowAdmin="true" ssl="false" connectTimeout="5000" abortConnect="false" database="0">
    <hosts>
      <add host="192.168.202.129" cachePort="6379"/>
    </hosts>
  </redisCacheClient>

 

      由於封裝程式碼啥的都是網上下載的，第一反應就是把上面的“connectTimeout”設為5000 * 60 =3min，但是絲毫沒有用處，也就是3min沒有起

到作用，碼蛋的，這可怎麼辦？？？只能硬著頭皮去看StackExchange的原始碼，終於在1個小時的地毯式搜尋中找到了兩處凶殺現場，如下所示：

　　 

 

接著我發現其中的 timeoutMilliseconds 和  this.multiplexer.RawConfig.ResponseTimeout的取值決定著是否會拋異常，感謝感謝，接下來我繼續

順藤摸瓜，找到了兩個屬性的賦值處。

當我看到了上面的syncTimeout.GetValueOrDefault(1000)的時候一顆懸著的心也就放下了，也懶得改了，直接將這裡的1000改成1000*60*5

就好啦，commit程式碼後讓同事再執行下看看效果。。。終於撥開迷霧見青天，資料出來啦，遺憾的是，讀寫操作需要耗時3s，雖然問題表面上看似

解決了，但是問題來了，3s延時真的不是什麼好事情，我們都知道redis是單執行緒的，那就意味著什麼？？？ 意味著這3s的時間內其他redis客戶端

是阻塞的。。。雖然心裡是這麼想的，但是還是存有一點僥倖心理覺得不是這樣的，不過還是決定做一個實驗看一看。

 

一：阻塞演示

　　我決定開一個執行緒將一個txt中140M的資料插入到redis的hashset中，同時我開另一個執行緒1秒鐘一次的從string中獲取資料,同時記錄下獲

取時間，如果獲取string的時間間隔太大，說明阻塞產生了，想法就是這樣，說幹就幹。。。

 System.Threading.Tasks.Task.Factory.StartNew(() =>
                    {
                        try
                        {
                            var content = File.ReadAllText(@"D:\20151120-13\20151120-13.log", Encoding.Default);

                            Console.WriteLine("主執行緒 讀取txt內容完畢，準備插入redis {0}", DateTime.Now);
                            var result = CacheUtil.CacheClient.HashSet("myredis", "mykey", content);

                            Console.WriteLine("主執行緒 插入Redis 成功:{0} , {1}", result, DateTime.Now);

                            var r = CacheUtil.CacheClient.HashGet<string>("myredis", "mykey");

                            Console.WriteLine("主執行緒,讀取Redis成功，總長度{0}, {1}", r.Length, DateTime.Now);
                        }
                        catch (Exception ex)
                        {
                            Console.WriteLine(ex.Message);
                        }
                    });

                    System.Threading.Tasks.Task.Factory.StartNew(() =>
                    {
                        try
                        {
                            var result = CacheUtil.CacheClient.Add<string>("myfruits", "asdfasdfasdfasdfasd");

                            for (int i = 0; i < 10; i++)
                            {
                                var content = CacheUtil.CacheClient.Get<string>("myfruits");

                                Console.WriteLine("第 {0} 次讀取 {1} ,{2}", i, content, DateTime.Now);

                                Thread.Sleep(1000);
                            }
                        }
                        catch (Exception ex)
                        {
                            Console.WriteLine(ex.Message);
                        }
                    });

讀取string的執行緒被Hashset阻塞了6s之多，很恐怖，這個就屬於典型的慢查詢，它的慢果然阻塞了其他client，接下來就拿著問題找同事，第一個想

法就是問同事為什麼要存這麼大的資料，得知為了避免海量運算必須要存這麼大資料之後，沒撤只能從假定80M的資料量做優化，第二個想法就是拆，

既然是80M的資料，我可以拆成8份10M的資料，這樣有兩個好處，第一個不會太拖長Hset的時間，第二個盡最大努力不阻塞其他client，但是呢，同

事不想改動程式碼，還要問我還有其他解決方案不？？？然後我就提了一個下下策，隔離你的快取業務，既然你都是儲存大資料，那我專門給你開一個

redis去儲存快取，幾秒鐘就幾秒鐘吧，估計對他業務還能夠承受，我可不能讓我的主redis因為這個吊毛業務掛了。。。

 

二：慢查詢日誌

　　自從發生這個事情之後，我就有一個想法了，我是不是也需要記錄一下主redis中那些“慢操作”的命令，然後找到相關的業務方，不然的話，阻塞

就不好玩了。然後就直接在redis手冊中就找到了相關的命令。

SLOWLOG subcommand [argument]

什麼是 SLOWLOG

Slow log 是 Redis 用來記錄查詢執行時間的日誌系統。

查詢執行時間指的是不包括像客戶端響應(talking)、傳送回覆等 IO 操作，而單單是執行一個查詢命令所耗費的時間。

另外，slow log 儲存在記憶體裡面，讀寫速度非常快，因此你可以放心地使用它，不必擔心因為開啟 slow log 而損害 Redis 的速度。

設定 SLOWLOG

Slow log 的行為由兩個配置引數(configuration parameter)指定，可以通過改寫 redis.conf 檔案或者用 CONFIG GET 和 CONFIG SET 命令對它們動態地進行修改。

第一個選項是 slowlog-log-slower-than ，它決定要對執行時間大於多少微秒(microsecond，1秒 = 1,000,000 微秒)的查詢進行記錄。

比如執行以下命令將讓 slow log 記錄所有查詢時間大於等於 100 微秒的查詢：

CONFIG SET slowlog-log-slower-than 100

而以下命令記錄所有查詢時間大於 1000 微秒的查詢：

CONFIG SET slowlog-log-slower-than 1000

另一個選項是 slowlog-max-len ，它決定 slow log 最多能儲存多少條日誌， slow log 本身是一個 FIFO 佇列，當佇列大小超過 slowlog-max-len 時，最舊的一條日誌將被刪除，而最新的一條日誌加入到 slow log ，以此類推。

以下命令讓 slow log 最多儲存 1000 條日誌：

CONFIG SET slowlog-max-len 1000

從上面這段話中，大概看出了兩個屬性：  slowlog-log-slower-than  和 slowlog-max-len，為了測試方便，我就不config set了，直接改掉

redis.conf檔案即可。。。

# The following time is expressed in microseconds, so 1000000 is equivalent
# to one second. Note that a negative number disables the slow log, while
# a value of zero forces the logging of every command.
slowlog-log-slower-than 0

# There is no limit to this length. Just be aware that it will consume memory.
# You can reclaim memory used by the slow log with SLOWLOG RESET.
slowlog-max-len 10

 

然後我簡單測試一下，所有command都會被記錄到slowlog裡面去了，下圖中的紅色框框就是comand的執行時間。

 

有了這個，我現在是不是可以找到所有生產線上哪些慢的command命令呢？？？這樣大家就不會扯皮了。。。最後我們簡單看下他們的原始碼，從原始碼

中你可以看到其實slowlog是用List實現的，而我們也知道在Redis中List是用“雙向連結串列”實現的。