2009.02.17 10:26

DTrace 를 이용한 Ajax/자바 어플리케이션의 완벽한 추적

Amit Hurvitz, 2007년 7월

Ajax 와 DTrace 가 만나는 곳

Ajax 는 새롭게 급부상 하고 있는 신기술로 Google Map 같은 어플리케이션의 등장에 의해 크게 탄력을 받고 있습니다. Ajax 는 브라우저와 서버 간의 코드 수준의 상호작용을 높임으로써 Google Map 같은 웹 어플리케이션을 좀 더 상호작용적으로 만들어 줍니다. 서버와의 대단위 통신은 퍼포먼스 이슈를 이해 하기 어렵게 만들 수 있습니다. 종종 여러분은 호출 흐름을 이해하고 자바스크립트와 서버 메소드(아마도 자바로 쓰여진) 에서 소비되는 시간을 확인할 필요가 있습니다. 이러한 경우 DTrace 가 도움을 줄 수 있습니다.

DTrace 는 솔라리스 (10 혹은 그 이상)에서 스크립팅 능력을 가진 추적 설비로 시스템과 유저 활동 을 관찰 할 수 있도록 도와 줍니다. 거의 모든 시스템의 동작(I/O 네트워크, 스케줄링, 메모리) 을 관찰할 수 있고 유저 네이티브 혹은 자바 프로그래밍 언어 코드 또한 추적할 수 있습니다. 그리고 USDT 라고 불리는 구현하기 쉽고 직관적인 메카니즘을 가짐으로써 유저가 C 프로그램에 probe 를 추가시킬 수 있습니다. DTrace 에 대한 정보는 오픈솔라리스 커뮤니티 DTrace 페이지 에서 확인하시기 바랍니다.

오픈솔라리스의 모질라 DTrace 프로젝트 는 DTrace 를 이용한 자바스크립트 추적 기능을 제공 합니다. DTrace 를 이용해서 자바스크립트 함수를 추적하기 위해서는 DTrace 가 내장된 Firefox 가 있어야 합니다. 이러한 모질라 DTrace 기능을 사용하기 위해서는 또한 최신의 솔라리스 익스프레스 빌드 (63 혹은 그 이상) 가 있어야 합니다.

DTrace 를 이용한 자바 트레이스는 JVMPI/JVMTI 기반으로 이미 발표된 에이전트 를 통해서 자바 1.4.2, 5 버전에서 사용 가능합니다. 자바 6.0 에서 DTrace 설비는 솔라리스 JVM 에 빌트-인 되어 있습니다. 그러므로 DTrace probe 를 사용하기 위해 JVMPI/JVMTI 공유 라이브러리를 동적으로 링크할 필요가 전혀 없습니다. 자바 6.0 probe 는 Keith McGuigan 의 웹로그 를 참고하시기 바랍니다. 자바 probe 의 좋은 예제들은 Katya 의 예제 에서 찾으실 수 있습니다.

Ajax 어플리케이션 트레이스 예제

필자는 신상철 박사의 Ajax 소개 코스 증에서 Ajax 검증 예제를 사용했습니다. 예제를 실행하기 위해서는 페이지의 지시를 따르거나 혹은 아래의 간단히 따라하기 예제를 참고하시기 바랍니다.

필자의 간단한 환경에서 필자는 브라우저와 어플리케이션 서버(서블릿 엔진)을 동일한 머신에서 구동시켰습니다. 이렇게 함으로써 하나의 DTrace 스크립트로 둘다 추적을 할 수 있고 자바 스크립트와 자바 메소드의 하나의 결합된 순서를 쉽게 볼 수가 있었습니다. 백엔드의 서버 머신을 DTrace 로 추적하고 클라이언트 머신의 자바스크립트를 DTrace 로 추적한다고 했을때 서버의 경우(자바) 솔라리스(10 혹은 그 이상)을 운용해야 하고 클라이언트의 경우(브라우저) 솔라리스 익스프레스 빌드 63 혹은 그이상을 운용해야 합니다.

추적될 프로세스들은 파이어폭스의 자바스크립트 엔진과 넷빈즈 5.5에 내장된 자바 서블릿 엔진(Jakarta 톰캣), JRE 6.0 들입니다. 자바 추적 스크립트는 범용적이고 기동시에 JVM 플래그 -XX:+ExtendedDTraceProbes 을 주거나 혹은 JDK 6.0에서 플래그들을 활성화 비활성화 시킬 수 있는 jinfo 유틸리티(jinfo -flag +ExtendedDTraceProbes <자바-프로세스 ID>) 를 통해 ExtendedDTraceProbes 를 활성화 시켰을때 어떠한 자바 6.0 프로세스도 추적이 가능합니다. .

예제를 실행시키기는 방법:

설치 및 설정

  1. 솔라리스 익스프레스 빌드63 혹은 그이상의 오픈솔라리스를 사용해야 함. 필자는 빌드63에서 테스트해봤음.
  2. DTrace 가 설치된 Firefox 를 다운로드 및 설치.
  3. 자바 6.0이 설치 됐는지 확인하기(최신의 솔라리스 익스프레스 빌드에선 기본 제공).
  4. 넷빈즈 5.5 다운로드 및 설치.
  5. 신상철 박사의 코스 실습 자료 에서 4257_Ajaxbasics2.zip 를 다운로드 하고 압축해제시킴.
  6. 넷빈즈에서 파이어폭스를 기본 브라우저로 사용하도록 설정 (Tools/Options).
  7. 넷빈즈에서 Ajax 검증 프로젝트를 열기 <4257_Ajaxbasics2 압축을 풀어 놓은 디렉토리>/Ajaxbasics2/samples
  8. -XX:+ExtendedDTraceProbes” 플래그를 <netbeans-base-dir>/enterprise3/apache-tomcat-5.5.17/bin/catalina.sh 의 JAVA_OPTS 에 추가시킴. 이 단계를 그냥 넘어가고 다음장의 (4) 번에서 수행할 수도 있음.

실행

  1. 넷빈즈에서 여러분이 생성한 Ajax-validation 프로젝트를 우클릭하고 'Run Project' 를 선택.
  2. 자바스크립트 DTrace probe 가 활성화 되어 있는지 다음의 명령을 토앻서 확인:
# dtrace -P 'trace_mozilla*' -l

아래와 같은 probe 들이 떠있는지 확인:

ID PROVIDER MODULE FUNCTION NAME
73007 trace_mozilla9547 
libmozjs.so jsdtrace_execute_done js_execute-done 73008 trace_mozilla9547
libmozjs.so js_Execute js_execute-done 73009 trace_mozilla9547
libmozjs.so jsdtrace_execute_start js_execute-start 73010 trace_mozilla9547
libmozjs.so js_Execute js_execute-start 73011 trace_mozilla9547
libmozjs.so jsdtrace_function_entry js_function-entry 73012 trace_mozilla9547
libmozjs.so js_Interpret js_function-entry 73013 trace_mozilla9547
libmozjs.so jsdtrace_function_return js_function-return 73014 trace_mozilla9547
libmozjs.so js_Interpret js_function-return 73015 trace_mozilla9547
libmozjs.so jsdtrace_object_create js_object-create 73016 trace_mozilla9547
libmozjs.so js_NewObject js_object-create 73017 trace_mozilla9547
libmozjs.so jsdtrace_object_create_done js_object-create-done 73018 trace_mozilla9547
libmozjs.so js_NewObject js_object-create-done 73019 trace_mozilla9547
libmozjs.so jsdtrace_object_create_start js_object-create-start 73020 trace_mozilla9547
libmozjs.so js_NewObject js_object-create-start 73021 trace_mozilla9547
libmozjs.so jsdtrace_object_finalize js_object-finalize 73022 trace_mozilla9547
libmozjs.so js_FinalizeObject js_object-finalize
  1. 파이어폭스에서 어플리케이션 페이지가 나타난 다음에는 자바 서블릿 엔진(톰캣) 프로세스의 위치를 지정함 (다른 JVM 을 실행하고 있지 않다면 pgrep -n java 을 통해 확인, 혹은 'ptree NetBeans')
  1. 이전 단계에서 지정하지 않았다면 아래를 실행
# jinfo -flag + ExtendedDTraceProbes <JVM-PID>
  1. 실행:
# <dtrace script name> <JavaScript-engine-PID> <JVM-PID>. 

이것은 루트 유저 혹은 DTrace 가 사용가능한 유저에 의해 실행되어야 함.

주의:
모질라 DTrace 제공자에서는 몇가지 이름의 변경이 필요로 합니다:

    trace_mozilla* 가 자바스크립트로 변경될 것임
    probe 이름들이 js_X 에서 X 로 변경될 것임(i.e., js_function-entry 이 function-entry)
예제:
현재: trace_mozilla*:::js_function-entry
앞으로는: javascript*:::function-entry

Ajax 와 자바 호출 흐름 추적하기

이 예제에서 우리는 Ajax 호출에 관련된 자바스크립트 함수들과 자바 서블릿 메소드의 호출 흐름을 추적할 것입니다. 이것을 위해 아래의 스크립트를 사용할 것입니다 (javax_java_call_flow.d).

#!/usr/sbin/dtrace -Zs

#pragma D option quiet
#pragma D option switchrate=10

dtrace:::BEGIN
{
        jsIndent = 0;
        jsFile = "ajax-validation";
        javaMethodBoundary= "doGet";
        startTimestamp = timestamp;
}

*mozilla$1:::js_function-entry
/basename(copyinstr(arg0)) == jsFile/
{
        jsIndent += 2;
        printf("%*s -> %s:%s (JavaScript)(elapsed ms: %d)\n", jsIndent, "",
            jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
}

*mozilla$1:::js_function-return
/basename(copyinstr(arg0)) == jsFile/
{
        printf("%*s <- %s:%s (JavaScript)(elapsed ms: %d)\n", jsIndent, "",
            jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
        jsIndent -= 2;
}


hotspot$2:::method-entry
{
        self->strPtr = (char *)copyin(arg1, args[2]+1);
        self->strPtr[(int)args[2]] = '\0';
        self->classStr = (string)self->strPtr;
        self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
        self->strPtr[(int)args[4]] = '\0';
        self->methodStr = (string)self->strPtr;
}

hotspot$2:::method-entry
/javaMethodBoundary == self->methodStr/
{
        self->interested = 1;
        self->indent = 0;
}

hotspot$2:::method-entry
/self->interested/
{
        self->indent += 2;
        printf("%*s -> %s:%s (Java)(elapsed ms: %d)\n", self->indent, "",
     self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
}

hotspot$2:::method-return
{
        self->strPtr = (char *)copyin(arg1, args[2]+1);
        self->strPtr[(int)args[2]] = '\0';
        self->classStr = (string)self->strPtr;
        self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
        self->strPtr[(int)args[4]] = '\0';
        self->methodStr = (string)self->strPtr;
}

hotspot$2:::method-return
/self->interested/
{
        printf("%*s <- %s:%s (Java)(elapsed ms: %d)\n", self->indent, "",
  self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
        self->indent -= 2;
}

hotspot$2:::method-return
/javaMethodBoundary == self->methodStr/
{
        self->interested = 0;
        /* exit(0); */
}

아래의 방법으로 스크립트를 실행하시기 바랍니다 (루트 혹은 DTrace 권한을 가지고 있는 유저를 통해):

# ajax_java_call_flow.d <JavaScript-engine-PID> <JVM-PID>

  1. 자바스크립트-엔진-PID 는 "dtrace -P 'trace_mozilla*' -l" 을 실행한 결과에서 provider 이름을 통해 얻을 수 있음. 예를 들어:

    73007 trace_mozilla9547 libmozjs.so jsdtrace_execute_done js_execute-done (9547 이 pid 임).

  2. JVM-PID 는 어플리케이션을 실행한 후 "ptree `pgrep -n netbeans`" 을 실행해서 제일 아래의 자바 프로세스를 통해 확인이 가능함

  3. 어플리케이션 폼에 문자를 입력하고, 2초를 기다린 다음 <Ctrl-C> 를 눌러서 스크립트를 중지 시킴. 스크립트 결과를 확인.

JavaScript probe 는 BEGIN{} 블럭 바로 뒤에서 멈췄습니다:

  • *mozilla*:::js_function-entry 이 자바스크립트 함수가 호출될때 마다 기동됨. 조건절에서 ajax-validation 과 관계된 호출만을 필터링 하게 됨 (arg0 는 자바스크립트 함수가 위치한 URL 을 가르킴) 이 probe 는 함수 이름과 마지막 호출 및 리턴에서 전달된 시간들을 적절한 들여쓰기를 이용해서 출력함.
  • *mozilla*:::js_function-return 은 모든 'ajax-validation' 함수의 리턴에 동일한 작업을 함.

자바 probe들

  • hotspot$target:::method-entry 는 자바 메소드들이 호출 될때 마다 작동 됨. doGet() 서블리세 메소드의 바운더리 안에 포함되어 있지 않는 호출들을 필터링 하기 위해 동일한 probe 에 몇개의 액션 블럭이 존재함. 오직 이러한 바운더리 안에서 probe 는 클래스의 이름과 메소드 이름 그리고 마지막 클래스에서 전달되어진 시간등을 적절한 띄어쓰기를 이용해서 출력해 줄 것임.
  • hotspot$target:::method-return 은 바운더리 내의 모든 메소드 리턴 타임에 동일한 동작을 함.

출력은 아래와 같을 것입니다 (훨씬 더 길 것임...):

 
    -> ajax-validation:validateUserId (JavaScript)(elapsed ms: 4288375)
     -> ajax-validation:escape (JavaScript)(elapsed ms: 4288497)
     <- ajax-validation:escape (JavaScript)(elapsed ms: 4288514)
     -> ajax-validation:initRequest (JavaScript)(elapsed ms: 4288529)
     <- ajax-validation:initRequest (JavaScript)(elapsed ms: 4288588)
     -> ajax-validation:open (JavaScript)(elapsed ms: 4288642)
     <- ajax-validation:open (JavaScript)(elapsed ms: 4288955)
     -> ajax-validation:send (JavaScript)(elapsed ms: 4288969)
     <- ajax-validation:send (JavaScript)(elapsed ms: 4289758)
   <- ajax-validation:validateUserId (JavaScript)(elapsed ms: 4289769)
   -> com/sun/j2ee/blueprints/bpcatalog/ajax/ValidationServlet:doGet 
(Java)(elapsed ms: 4721275) -> org/netbeans/modules/web/monitor/server/
MonitorRequestWrapper:getParameter (Java)(elapsed ms: 4721289) -> org/apache/catalina/connector/RequestFacade:getParameter
(Java)(elapsed ms: 4721300) -> java/lang/System:getSecurityManager
(Java)(elapsed ms: 4721309) <- java/lang/System:getSecurityManager
(Java)(elapsed ms: 4721319) -> org/apache/catalina/connector/Request:getParameter
(Java)(elapsed ms: 4721330) -> org/apache/catalina/connector/Request:parseParameters
(Java)(elapsed ms: 4721341) ... ... ... <- org/apache/tomcat/util/buf/CharChunk:min
(Java)(elapsed ms: 4729143) -> java/lang/String:getChars (Java)(elapsed ms: 4729156) -> java/lang/System:arraycopy (Java)(elapsed ms: 4729166) <- java/lang/System:arraycopy (Java)(elapsed ms: 4729176) <- java/lang/String:getChars (Java)(elapsed ms: 4729185) <- org/apache/tomcat/util/buf/CharChunk:append
(Java)(elapsed ms: 4729196) <- org/apache/catalina/connector/OutputBuffer:write
(Java)(elapsed ms: 4729207) <- org/apache/catalina/connector/CoyoteWriter:write
(Java)(elapsed ms: 4729218) <- org/apache/catalina/connector/CoyoteWriter:write (
Java)(elapsed ms: 4729228) <- com/sun/j2ee/blueprints/bpcatalog/ajax/ValidationServlet:doGet
(Java)(elapsed ms: 4729242) -> ajax-validation:getElementsByTagName
(JavaScript)(elapsed ms: 4922548) <- ajax-validation:getElementsByTagName
(JavaScript)(elapsed ms: 4922644) -> ajax-validation:setMessageUsingDOM (JavaScript)(elapsed ms: 4922782) -> ajax-validation:getElementById (JavaScript)(elapsed ms: 4922812) <- ajax-validation:getElementById (JavaScript)(elapsed ms: 4922866) -> ajax-validation:createTextNode (JavaScript)(elapsed ms: 4923003) <- ajax-validation:createTextNode (JavaScript)(elapsed ms: 4923040) -> ajax-validation:replaceChild (JavaScript)(elapsed ms: 4923142) <- ajax-validation:replaceChild (JavaScript)(elapsed ms: 4923437) <- ajax-validation:setMessageUsingDOM (JavaScript)(elapsed ms: 4923449) -> ajax-validation:getElementById (JavaScript)(elapsed ms: 4923471) <- ajax-validation:getElementById (JavaScript)(elapsed ms: 4923523)

각 호출 (->) 혹은 리턴 (<-) 함수/메소드는 마지막 호출/리턴 으로 부터 얼마의 시간이 흘렀는지를 나타냅니다.

이 스크립트를 사용할때는 조심해야 합니다: 동시간의 Ajax 요청 및 다수의 서블릿 쓰레드는 출력을 얼망으로 만들 것입니다. 이 예제는 오직 하나의 자바 쓰레드 만을 보여 줬습니다. 좀더 복잡한 환경에서 특히 오직 흐름만을 이해하고자 한다면 오직 하나의 CPU 만을 사용하도록 어플리케이션 쓰레드를 직렬화 하는 것이 맞습니다(만약 멀티 코어/CPU 머신을 운용하고 있다면) 솔라리스의 pbindpsrset 멘 페이지에서 어플리케이션이 특정 CPU(들) 에 제한적으로 실행될 수 있는 방법에 대해 알아보시기 바랍니다.

Ajx 와 자바 함수/메소드 호출 횟수 프로파일링

이전의 스크립트(ajax_java_functions.d) 를 수정함으로써 내부 함수 호출 시간을 볼 수 있습니다.

#!/usr/sbin/dtrace -Zs

#pragma D option quiet
#pragma D option switchrate=10

dtrace:::BEGIN
{
        jsFile = "ajax-validation";
        JavaMethodBoundary = "doGet";
}

*mozilla$1:::js_function-entry
/basename(copyinstr(arg0)) == jsFile/
{
        depth++;
        jsFEntry[copyinstr(arg2), depth] = vtimestamp;
}

*mozilla$1:::js_function-return
/basename(copyinstr(arg0)) == jsFile/
{
        @jsFTimes[copyinstr(arg2)] = sum(vtimestamp
- jsFEntry[copyinstr(arg2), depth]); depth--; } hotspot$2:::method-entry { self->strPtr = (char *)copyin(arg1, args[2]+1); self->strPtr[(int)args[2]] = '\0'; self->classStr = (string)self->strPtr; self->strPtr = (char *)copyin(arg3, (int)args[4]+1); self->strPtr[(int)args[4]] = '\0'; self->methodStr = (string)self->strPtr; } hotspot$2:::method-entry /JavaMethodBoundary == self->methodStr/ { self->interested = 1; } hotspot$2:::method-entry /self->interested/ { self->depth++; javaFEntry[self->classStr, self->methodStr, self->depth]
= vtimestamp; } hotspot$2:::method-return { self->strPtr = (char *)copyin(arg1, args[2]+1); self->strPtr[(int)args[2]] = '\0'; self->classStr = (string)self->strPtr; self->strPtr = (char *)copyin(arg3, (int)args[4]+1); self->strPtr[(int)args[4]] = '\0'; self->methodStr = (string)self->strPtr; } hotspot$2:::method-return /self->interested/ { @javaFTimes[self->classStr, self->methodStr]
= sum(vtimestamp - javaFEntry[self->classStr, self->methodStr, self->depth]); self->depth--; } hotspot$2:::method-return /JavaMethodBoundary == self->methodStr/ { self->interested = 0; } END { normalize(@jsFTimes, 1000); normalize(@javaFTimes, 1000); printf("JavaScript Functions\n"); printf("--------------------\n"); printf("%-10s %-25s\n", "inc. time", "Function"); printa("%@-10u %-25s\n", @jsFTimes); printf("\n\n\n"); printf("Java Methods\n"); printf("------------\n"); printf("%-10s %-50s %s\n", "inc. time", "Class", "Method"); printa("%@-10u %-50s %s\n", @javaFTimes); }

스크립트를 아래와 같은 방법으로 실행하시기 바랍니다(root 혹은 DTrace 권한이 있는 유저로):

# ajax_java_functions.d <JavaScript-engine-PID> <JVM-PID>

  1. JavaScript-engine-PID 는 dtrace -P 'trace_mozilla*' -l 출력의 provider 이름을 통해 알아낼 수 있습니다. 예를 들어:

    73007 trace_mozilla9547 libmozjs.so jsdtrace_execute_done js_execute-done (9547 is the pid).

  2. JVM-PID 는 어플리케이션을 실행한 후 &quot;<i>ptree `pgrep -n netbeans`</i>&quot; 을 실행해서 제일 아래의 자바 프로세스를 통해 확인이 가능함

  3. 추적을 멈추고자 할때 <Ctrl-C> 를 누르면 표준 출력에서 결과를 볼 수 있음

위의 스크립트는 필자의 머신에서 아래와 같은 결과를 생성하였습니다. 첫번째 컬럼은 inclusive 실행 시간 (밀리세컨 단위, 몇몇 자바 메소드는 나노세컨드가 밀리세컨으로 올림 되면서 0을 리턴할 것임) inclusive 실행 시간이란 특정 함수/메소드에서 실행하는 모든 함수/메소드 호출에 의해 소비된 총 시간을 포함하는 것을 의미 합니다. 함수/메소드 호출 시간을 포함하지 않은 것은 exclusive 시간이라고 부릅니다.

아래 결과의 제일 하단의 processParameters() 메소드를 보면 doGet() 메소드(실제로 이 메소드가 포함된) 보다 inclusive 시간이 더 큼을 볼 수 있습니다. 이것은 rocessParameters() 가 재귀호출이기 때문입니다. 우리는 inclusive 시간을 고려했기 때문에 재귀 호출 함수는 이러한 시간을 초과 하게 됩니다. 왜냐하면 여러번 계산되기 떄문입니다.

JavaScript Functions
--------------------
inc. time  Function                 
5          escape                   
29         createTextNode           
59         initRequest              
84         getElementsByTagName     
89         getElementById           
295        replaceChild             
318        open                     
465        send                     
569        setMessageUsingDOM       
1048       validateUserId           



Java Methods
------------
inc. time  Class                                              
Method 0 org/apache/tomcat/util/buf/CharChunk
min 0 org/apache/tomcat/util/http/ContentType
getCharsetFromContentType 0 org/apache/tomcat/util/buf/MessageBytes
toString ... ... ... 94 org/apache/catalina/connector/ResponseFacade
setHeader 100 javax/servlet/http/HttpServletResponseWrapper
setHeader 191 java/lang/StringCoding$StringDecoder
decode 372 java/lang/StringCoding
decode 384 java/lang/String
<init> 388 org/apache/tomcat/util/buf/ByteChunk
toStringInternal 455 org/apache/tomcat/util/buf/StringCache
toString 459 org/apache/tomcat/util/buf/ByteChunk
toString 492 org/apache/tomcat/util/http/Parameters
urlDecode 585 org/apache/tomcat/util/http/Parameters
handleQueryParameters 664 org/apache/catalina/connector/Request
parseParameters 680 org/apache/catalina/connector/Request
getParameter 688 org/apache/catalina/connector/RequestFacade
getParameter 691 org/netbeans/modules/web/monitor/server/
MonitorRequestWrapper getParameter 927 com/sun/j2ee/blueprints/bpcatalog/ajax/
ValidationServlet doGet 1082 org/apache/tomcat/util/http/Parameters
processParameters

대부분의 경우 우리는 exclusive 함수 시간에 더 관심이 있습니다. 이것은 어플리케이션의 핫스팟(hotspot)을 빠르게 알려주기 때문입니다. 필자는 이전의 스크립트 호출 결과를 이용 파일로 리다이렉트 해서 이것을 펄 스크립트로 처리하였습니다(ajax_java_time_from_callflow.pl):

실행:

# ajax_java_call_flow.d <JavaScript-engine-PID> <JVM-PID> > 
<output-file>
# perl ajax_java_time_from_callflow.txt <output-file>

이 스크립트는 모든 함수/메소드(자바스크립트와 자바를 포함) 의 목록과 각각의 exclusive, inclusive 시간을 생성해 줄 것입니다. 이 리스트는 exclusive 시간의 아랫차순으로 정렬됩니다.

Method/Function                          Exc. time  Inc. time 
ajax-validation:send                     789        789       
ajax-validation:open                     313        313       
ajax-validation:replaceChild             295        295       
ajax-validation:setMessageUsingDOM       281        667       
java/lang/StringCoding$StringDecoder:decode 252        1944      
sun/nio/cs/UTF_8$Decoder:decodeArrayLoop    244        429       
ajax-validation:validateUserId              216        1394      
org/apache/tomcat/util/buf/MessageBytes:equalsIgnoreCase     
213 314

아래의 probe 를 추가함으로써 시스템 호출 시간을 좀 더 추적해 볼 수 있습니다
(아래의 추적은 doGet() 함수 바운더리에 제한되지 않음)

syscall:::entry
/pid == $2/
{
        scEntry[probefunc] = vtimestamp;
}

syscall:::return
/pid = $2/
{
        @scTimes[probefunc] 
= sum(vtimestamp - scEntry[probefunc]); } and adding these lines to the END clause to do the printing: END { ... normalize(@scTimes, 1000); printf("System Calls\n"); printf("------------\n"); printf("%-10s %-50s\n", "inc. time", "Syscall"); printa("%@-10u %-50s\n", @scTimes); }

우리들은 DTrace 를 이용해서 시스템의 모든 분야(네트워크, I/O, 프로세스들 등) 를 추적할 수 있습니다. 기본적인 DTrace 유틸리티는 거의 모든 시스템의 분야를 커버 합니다. the DTrace toolkit 을 참고하시기 바랍니다.

결론

우리는 어떻게 DTrace 를 이용해서 자바스크립트와 자바간 호출 흐름을 추적하는지 살펴 보았습니다. 각 추적 작업은 전문 프로파일링 툴들을 이용할 수도 있을 것입니다. DTrace 단하나의 툴로 이 모든 툴들을 대체할 수 있습니다. 유저 함수가 실행되는 동안 여러분의 어플리케이션이 자바 메소드든지 자바 스크립트의 함수든지 어느 부분에서 시간의 대부분을 소비하는지 찾아낼 수 있습니다. 다양한 툴을 다룰 필요도 없고 각각의 부분작업들을 전부 할 수 있어야 되는것도 아닙니다. DTrace 기술은 시스템상의 모든 부분을 추적할 수 있도록 도와줄 것입니다.

추가 정보


이 컨텐츠의 원본 영문 컨텐츠 보기
http://developers.sun.com/solaris/articles/dtrace_ajax.html


출처 : http://www.sdnkorea.com/blog/418?cid=921141


Trackback 0 Comment 0