ASP.NET에서 Trace를 이용한 웹페이지 속도 및 성능 측정

출처 : http://shkblog.tistory.com/5

유독 특정 웹페이지가 굉장히 느린 경우가 있죠. 다른 웹페이지는 괜찮은데 왜 이 웹페이지만 느린 걸까? 그럼 일단 그 웹페이지 조사 한번 들어가 봅니다.

그런데, 소스를 까봐도 정확히 어느 부분이 원인인지 진단을 내리기가 어려운 경우가 있습니다. 짐작이 가는 부분은 있는데, 그 부분을 파헤쳐 보자니  괜히 헛짚으면 시간만 낭비하는 것 같고, 그렇다고 전체를 모두 까볼려니 엄두가  나지 않고 이래저래 고민만 하고 있죠.

소스의 각 요소의 소요 시간을 측정할 수 있다면 최소한 어느 녀석 때문에 페이지가 느린지 알 수 있는 방법은 없을까?
예를 들어서 로드 이벤트에 다음과 같은 간단한 코드가 있다고 한다면,
    protected void Page_Load(object sender, EventArgs e)
    {
         TestMethod(); //나 정말 간단한 함수 
         DbConnectAndFillDataSet();//DB에 연결하고 데이터 셋에 데이터를 채우는 로직
    }

이 두 함수의 걸리는 시간을 알 수 있다면, 많이 소요되는 함수를 집중적으로 조사해서 원인을 찾을 수 있을 겁니다.

이렇게 코드의 부분들의 소요 시간을 측정하는 방법으로 Trace를 이용해 볼 수 있습니다.
먼저 다음과 같이 aspx페이지의 @page 지시자에 Trace=true를 추가합니다.
<%@ Page Trace="true"  Language="C#" …….>

먼저 측정 시간을 간단히 이해하기 위해서 Trace="true" 상태에서 코드가 없는 빈 웹페이지를 웹브라우저에서 보면 다음과 같습니다.

위 웹페이지를 보면 PreInit, Init,…Load,….. 등 페이지의 이벤트 순서로 오른 쪽에 초 단위로 From First(s)과 From Last(s) 가 표시되는 것을 볼 수 있습니다. From First(s)는 페이지가 처음 시작된 후 메시지가 찍혔을 때의 시각을 나타냅니다. 

그리고 From Last(s)가 중요한데, 이것은 소요된 시간을 나타냅니다. 이 소요 시간은 바로 앞의 직전의 메시지가 일어난 후 소요된 시간을 나타냅니다.

예를 들어서 End Load 이벤트의 소요시간은 0.000182 초인데, 이것은 직전의 이벤트인 Begin Load 이벤트가 시작된 후 소요된 시간을 말합니다. 즉, Begin Load와 End Load 사이의 소요시간을 나타냅니다.(이 소요시간 0.000182초는 "End Load"에서 찍힌 From First(0.000411504814159341초)에서 "Begin Load" 에서 찍힌 From First(0.000229638124398492초)를 뺀 시간입니다. 즉, 해당 메시지 시각(From First)에서 바로 직전의 메시지 시각(From First)을 뺀 값입니다.)

하나 더 예를 들면, Begin Load의 소요시간은 0.000025초인데, 이것은 그 위의 End PreLoad와 Begin Load 사이의 소요 시간입니다.

 자 그러면, 이런 순서 속에 특정한 로직 함수가 들어가면 이 로직의 소요시간을 어떤 식으로 표현할 수 있을까요?
위의 Load이벤트에서 나온 함수들을 다시 한번 보면,
    protected void Page_Load(object sender, EventArgs e)
    {
         TestMethod(); //나 정말 간단한 함수일까?
         DbConnectAndFillDataSet();//DB에 연결하고 데이터 셋에 데이터를 채우는 로직
    }

이 두 함수 중에 어떤 녀석이 굉장히 많은 시간을 잡아 먹고 있습니다. 그래서 이것의 소요시간을 Trace에서 보고 싶다면 다음과 같이 Trace.Warn함수로 구분을 해줍니다.
    protected void Page_Load(object sender, EventArgs e)
    {
       Trace.Warn("TestMethod", "Before TestMethod");
       TestMethod();
       Trace.Warn("TestMethod", "After  TestMethod");

       Trace.Warn("DbConnectAndFillDataSet", "Before DbConnectAndFillDataSet");
       DbConnectAndFillDataSet();       
       Trace.Warn("DbConnectAndFillDataSet", "After DbConnectAndFillDataSet");
    }

일단은 웹페이지를 실행해서 Trace된 화면을 웹브라우저에서 보면 다음과 같습니다.

보시는 바와 같이 Trace.Warn 함수의 첫번째 인수는 범주를 나타내고, 두번째 인수는 메시지를 나타냅니다.
그래서 범주를 구분하고, 특정 메시지로 의미를 알 수 있게 하고자 한다면 위와 같이 인수 값을 지정해줍니다.

자, 그러면 두 함수의 소요시간을 볼까요.
메시지 "After TestMethod"의 소요 시간은 0.000149초입니다. 이것은 "Befor TestMethod"와 "After TestMethod" 사이의 소요 시간입니다. 따라서 이 사이에 TestMethd() 함수가 있기 때문에 이 함수의 소요 시간은 약 0.000149초입니다. 위 패턴과 마찬 가지로  DbConnectAndFillDataSet() 함수의 소요 시간은 약 0.012541초라는 것을 알 수 있겠죠.
그래서 범인(?)이 DbConnectAndFillDataSet()함수라는 것을 알 수 있습니다.

DbConnectAndFillDataSet()함수를 여기서 그치지 않고 그 내부의 소요시간도 좀더 상세하게 파헤쳐 보고 싶다면, 역시 같은 방법으로 조사해볼 수 있습니다. DbConnectAndFillDataSet()함수가 다음과 같이 DataSet에 Fill하고, GridView에 바인딩한다고 한다면,

            OracleDataAdapter productsAdapter = new OracleDataAdapter();
            productsAdapter.SelectCommand = new OracleCommand("SELECT **** ", conn);
            DataSet productsDataSet = new DataSet("productsDataSet");
            productsAdapter.Fill(productsDataSet, "Products");
            gridView.DataSource = productsDataSet;
            gridView.DataMember = "Products";
            gridView.DataBind();

Fill할때의 소요시간과 GridView의 바인딩할 때의 시간을 알고 싶다면, 역시 위와 같은 방법으로 다음과 같이 Trace.Warn 함수를 이용합니다.

            OracleDataAdapter productsAdapter = new OracleDataAdapter();
            productsAdapter.SelectCommand = new OracleCommand("SELECT **** ", conn);
            DataSet productsDataSet = new DataSet("productsDataSet");

            Trace.Warn(" Fill DataSet", "Before Fill DataSet");
            productsAdapter.Fill(productsDataSet, "Products");
            Trace.Warn(" Fill DataSet", "After Fill DataSet");

            gridView.DataSource = productsDataSet;
            gridView.DataMember = "Products";

            Trace.Warn("GridView Binding", "Before GridView Binding");
            gridView.DataBind();
            Trace.Warn("GridView Binding", "After GridView Binding");

이 상태에서 웹페이지를 보면 다음과 같습니다.

DbConnectAndFillDataSet()함수가 "DbConnectAndFillDataSet"범주 안에 있기 때문에 "Fill DataSet"범주와 "GridView Binding"범주도 역시 "DbConnectAndFillDataSet"범주 사이에서 보여지는 것을 알 수 있고, Fill할 때의 소요시간은 약 0.11653초, GridView를 바인딩할 때의 소요시간은 약 0.000509초가 걸린다는 것을 알 수 있습니다.

이런 식으로 특정 부분을  Trace.Warn함수로 Before와 After로 지정해서 소요시간과, 그 결과로 어느 부분이 많은 시간이 소요되는지 파악할 수 있습니다.

** 그리고 주의할 점은, Trace.Warn함수를 다음과 같이 쓰레드와 같이 사용한다면,
Trace.Warn("Thread","Before Thread");
Thread t = new Thread(어떤함수);
t.Start();
Trace.Warn("Thread","After Thread");

이때 "After Thread" 메시지의 소요시간은 [어떤 함수]의 정확한 소요시간을 나타내지 않습니다. 쓰레드와 같이 사용하면, 코드는 코드대로 그대로 진행되고 쓰레드는 쓰레드대로 코드에서 툭 튀어나오듯이 따로 진행이 되기 때문입니다. 이때에는 [어떤함수] 안에서 Trace.Warn함수를 사용해야 합니다.....