【案例需求】

使用者反應近來某些網頁程式"執行時間好像變久了"。OP希望由IIS Log中取得相關數字證實,釐清是程式效能變差需要調校,還是使用者需要一本金剛經培養耐性?

【分析程序】

  1. 取得網頁所在IIS近三個月的IIS Log,ex1002*.log, ex1003*.log, ex1004*.log
  2. 使用Visual Log Parser(好物! 可參考保哥的介紹文)進行查詢,語法為:
    排版顯示純文字
    select 
           to_string(date, 'yyyyMMdd') as logDate, 
           to_string(time, 'HH') as hour, 
           cs-uri-stem as page, 
           avg(time-taken) as duration, 
           count(time-taken) as count
    from x:\temp\LogTemp\ex100*.log
    where cs-uri-query like 'blahParam=%'
          and cs-method='POST' and sc-status='200'
    group by to_string(date, 'yyyyMMdd'), 
          to_string(time, 'HH'), cs-uri-stem
    以上查詢以日期、小時(主要是想區分尖/離峰)、特定網頁(有用到blahParam參數者)做GROUP BY,並限定成功POST執行者做統計,計算被呼叫次數及平均執行時間。
    注意: time-taken並非預設會記載的欄位,必須額外設定。 (參考下圖)
  3. 由於每天的Log檔大小超過500M,上述查詢耗費的時間超出我的耐性極限(謎之聲: 你才是真正需要金剛經的人吧?),且其中夾雜了js, jpg, css下載、其他網頁存取、HTTP 401認證過程... 真正對我們有用的資料量很少。因此,打算做個過濾,只保留我們感興趣的部分。
  4. 有UNIX經驗的人都知道誰該上場了---grep! 而好東西不寂寞,在Windows上當然也有grep可以用,配合DOS Batch的迴圈技巧,可以寫成:
    for /f %%a IN ('dir /b ex*.log') do call grep -E "#Field| blahParam=" %%a > c%%a
    如此,就只會留下有" blahParam="字眼出現的Log(前方加空白是為了確定它出現在cs-uri-query,而不是cs(Referer)裡以*.aspx?blahMode=...形式出現)。另外,Log Parser需要#Fields:那一列宣告以確知欄位定義,因此也要在保留之列。
  5. 經過grep轉換後,cex*.log均小於1MB,縮小500倍以上,查詢速度快多了。
  6. 查看結果,發現的確某幾天執行時間有變長的趨勢,而且是不分時段都明顯變慢,於是再將查詢再改成每日平均一次:

    由結果的確可看出3/15-3/19平均時間拉長到正常狀態的6倍以上!
  7. 下一步是將查詢結果做成報告呈報長官,Excel是首選!
    Visual Log Parser提供兩種匯出方式 ,結果複製到剪貼簿或存成CSV檔(見上圖),我個人偏好剪貼簿法,理由是比存檔後再開檔簡便,而且可將資料放在工作表任意位置,應用時較靈活。
  8. 貼在Excel的資料由於是用";"分隔,所以不會自動展開成多儲存格,此時可以用資料剖析功能將其解析成多欄資料:

接著,善用Excel 2007的格式化條件功能,將偏長的時間突顯出來,漂亮的報表就完成囉!


Comments

# by 路過的貓

那...請問...為什麼會變慢呀?

# by chiyuan

是阿 黑大 我也很想知道 原因是啥 造成變慢?? ^^

Post a comment