TCP Write 부분에 대해서는 오류가 있어서 소스에서 삭제했습니다. 따라서, 아래 그림에 있는 TCP Write와 같은 부분은 더 이상 출력되지 않습니다. 추후 별도로 TCP status를 하는 스크립트를 소개해보겠습니다.
---
곧 출시를 앞두고 있는 솔라리스 11의 프리젠테이션 자료를 보니, LatencyTop 라는 스크립트를 언급하고 있더군요. 검색을 해보니 리눅스 시스템에서 지연 부분을 찾기 위해서 인텔이 만들었던 LatencyTop이라는 유틸리티를 흉내내기 위하여 솔라리스 커널 엔지니어인 브라이언 칸트릴(Bryan Cantrill)이 만들어 놓은 스크립트인 듯 하더군요.
---
곧 출시를 앞두고 있는 솔라리스 11의 프리젠테이션 자료를 보니, LatencyTop 라는 스크립트를 언급하고 있더군요. 검색을 해보니 리눅스 시스템에서 지연 부분을 찾기 위해서 인텔이 만들었던 LatencyTop이라는 유틸리티를 흉내내기 위하여 솔라리스 커널 엔지니어인 브라이언 칸트릴(Bryan Cantrill)이 만들어 놓은 스크립트인 듯 하더군요.
인텔 만들어서 오픈한 LatencyTop의 자료는 http://www.latencytop.org/ 에서 참고할 수 있으며, 관련 소스도 다운 받을 수 있습니다. 처음에는 여기의 소스도 다운받아서 솔라리스에서 컴파일 해보려 했으나 불행하게도 소스코드 내에서 리눅스 만의 화일 시스템 debugfs을 마운트하는 것 때문에 컴파일이 불가능했습니다.
여하튼 브라이언 덕분에 솔라리스용을 손쉽게 구할 수 있었습니다.
다음은 여기서 다운받은 LatencyTop 원본의 출력의 예입니다.
그렇지만 다운 받아서 출력을 해보니 뭔가 개인적으로 좀 불만스럽더군요. 출력도 다소 플렌들리하지 않고, 보고 싶은 부분도 추가가 필요해 보였습니다. 그래서, 약간의 수정을 가하여 다음과 같은 개선된 LatencyTop을 만들어 봤습니다.
새로 개선된 LatencyTop은 일단 가로줄을 더 넓게 쓰도록 했고, Mutex Lock과 같은 주요 병목 포인트는 물론이거니와 아울러서 Mutex Spin과 TCP 데이타 전송시 걸리는 소요 시간들도 보이도록 했습니다.
LatencyTop을 실행하면 6개의 컬럼이 나타나는데, 실행후 5초간 샘플링을 한 후 그 결과를 좌측으로 부터 프로세스의 이름, 프로세스 ID, 관련 병목 포인트, 그 병목 요소 호출수, 각 병목 요소 처리 최대 시간과 평균시간이 차례로 출력이 됩니다. 아래와 예를 참고하시기 바랍니다.
-Process- -PID- -Cause- -Count- -Maximum- -Average-
notification-dae [1631 ] mutex spin 1 1 usecs 1 usecs
wnck-applet [1575 ] mutex spin 1 2 usecs 2 usecs
xscreensaver [1584 ] mutex spin 1 26 usecs 26 usecs
firefox-bin [1709 ] Unlink file 1 102 usecs 102 usecs
Xorg [1410 ] mutex lock 1 129 usecs 129 usecs
gnome-terminal [1647 ] mutex lock 1 141 usecs 141 usecs
xscreensaver [1584 ] mutex lock 1 170 usecs 170 usecs
Xorg [1410 ] mutex spin 2 22 usecs 11 usecs
dtrace [2090 ] mutex spin 4 165 usecs 43 usecs
pageout [2 ] mutex lock 4 1521 usecs 462 usecs
gnome-terminal [1647 ] mutex spin 5 149 usecs 39 usecs
firefox-bin [1709 ] mutex lock 9 562 usecs 158 usecs
firefox-bin [1709 ] TCP write 10 1502 usecs 288 usecs
firefox-bin [1709 ] Reading from file 10 20863 usecs 3886 usecs
sched [0 ] mutex lock 28 214 usecs 65 usecs
firefox-bin [1709 ] mutex spin 41 49 usecs 6 usecs
zpool-rpool [5 ] mutex lock 51 3453 usecs 255 usecs
sched [0 ] mutex spin 67 1225 usecs 29 usecs
pageout [2 ] Writing to file 83 22971 usecs 1507 usecs
pageout [2 ] mutex spin 98 994 usecs 132 usecs
zpool-rpool [5 ] mutex spin 332 309 usecs 11 usecs
분석을 위해서는 이 결과에서 어떤 병목 요소의 호출수가 가장 많은가( 위의 예에서는 zpool-rpool )와 어떤 요소의 최대 지연시간이 많은 지를 보아야 합니다. 지연 시간 관점에서 위의 예를 살펴 보게 되면 pageout과 firefox-bin의 지연 시간이 긴 것을 할 수가 있는데, pageout은 화일 쓰기에 대한 병목을 유발하면서 호출당 최대 지연 시간이 22971/83 = 276.7590361445783 microseconds 인 반면에 firefox-bin은 화일 읽기를 위한 행위를 하고 있고, 호출당 최대 지연시간이 2086.3 microseconds 임을 알 수가 있습니다.
따라서, 단위 호출당 관점에서 튜닝을 접근해야 한다면 이 시스템은 firefox가 접근하는 스토리지를 개선하거나 firefox가 사용하는 메모리를 대폭 늘리거나 하여 보다 건전한 환경을 구축할 수 있다고 할 수 있겠습니다. 중요한 것은 지금 현재 이 시스템이 결코 느리거나 문제가 있는 것은 아니라는 것입니다.
부하가 일시적으로 몰리거나 하여 증폭되었을 때같은 최악의 경우를 생각했을 경우를 대비하여 사전에 준비하기 위한 데이타로 바라봐야 하며, 아울러, 이와 같은 샘플링을 여러번 반복하여서 나온 값을 기준으로 가장 중요한 것부터 환경을 개선하는 기반 데이타로 사용되어져야 합니다.
추가로 위 환경에서 발생한 pageout은 firefox-bin이 많은 읽기를 시도하기 때문에 발생하는 것임을 추측해볼 수 있는데(다른 Dtrace script로 추가 증명을 해볼 수 있습니다.) 따라서,결과적으로 본다면 화일에 대한 읽기와 쓰기를 동시에 개선해야 하는 것이 보다 더 중요하다고 생각해볼 수 있습니다. 결국 보다 좋은 스토리지의 확보가 더욱 중요하다는 것을 추리해볼 수가 있겠습니다.
수정된 LatencyTop의 소스는 다음과 같습니다.
#!/usr/sbin/dtrace -Cs
/*
#
# latencytop is monitoring hot places of bottlenecks
# This was written by Bryan Cantrill in 2008
# Bonghwan Kim, have updated a little bit to have more comfortable output. 2011
#
#
*/
#pragma D option quiet
#define RW_READER 0x1
dtrace:::BEGIN
{
printf("######\n");
printf("###### This script is written by Bryan Cantrill(2008) and updated by Bonghwan Kim(2011)\n");
printf("######\n");
printf("Tracing... Hit Ctrl-C to end.\n");
}
/*
* Reading from file
* Writing to file
*/
io:::start
{
start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
self->iostart=1;
}
io:::done
/self->iostart && start[args[0]->b_edev, args[0]->b_blkno]/
{
this->delta = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
this->cause = args[0]->b_flags & B_READ ?
"Reading from file" : "Writing to file";
@lcount[execname,pid,this->cause] = count();
@lmax[execname,pid,this->cause] = max(this->delta);
@lavg[execname,pid,this->cause] = avg(this->delta);
start[args[0]->b_edev, args[0]->b_blkno]=0;
self->iostart=0;
}
/*
* mutex lock
*/
lockstat:::adaptive-block
{
@lcount[execname,pid,"mutex lock"] = count();
@lmax[execname,pid,"mutex lock"] = max(arg1);
@lavg[execname,pid,"mutex lock"] = avg(arg1);
}
/*
* mutex spin
*/
lockstat:::adaptive-spin
{
@lcount[execname,pid,"mutex spin"] = count();
@lmax[execname,pid,"mutex spin"] = max(arg1);
@lavg[execname,pid,"mutex spin"] = avg(arg1);
}
/*
* rwsem read lock
* rwsem write lock
*/
lockstat:::rw-block
{
this->cause = arg2 == RW_READER ?
"rwsum read lock" : "rwsum write lock";
@lcount[execname,pid,this->cause] = count();
@lmax[execname,pid,this->cause] = max(arg1);
@lavg[execname,pid,this->cause] = avg(arg1);
}
/*
* Unlinking file
*/
syscall::unlink:entry
{
self->start_unlink = timestamp;
}
syscall::unlink:return
/self->start_unlink/
{
this->delta = timestamp - self->start_unlink;
@lcount[execname,pid,"Unlink file"] = count();
@lmax[execname,pid,"Unlink file"] = max(this->delta);
@lavg[execname,pid,"Unlink file"] = avg(this->delta);
self->start_unlink = 0;
}
/*
* sync system call
*/
syscall::syssync:entry
{
self->start_syssync = timestamp;
}
syscall::syssync:return
/self->start_syssync/
{
this->delta = timestamp - self->start_syssync;
@lcount[execname,pid,"sync system call"] = count();
@lmax[execname,pid,"sync system call"] = max(this->delta);
@lavg[execname,pid,"sync system call"] = avg(this->delta);
self->start_syssync = 0;
}
/*
* fsync system call
*/
syscall::fdsync:entry
{
self->start_fdsync = timestamp;
}
syscall::fdsync:return
/self->start_fdsync/
{
this->delta = timestamp - self->start_fdsync;
@lcount[execname,pid,"fsync system call"] = count();
@lmax[execname,pid,"fsync system call"] = max(this->delta);
@lavg[execname,pid,"fsync system call"] = avg(this->delta);
self->start_fdsync = 0;
}
/*
* Print output summary
*/
profile:::tick-5s,
dtrace:::END
{
/* normailze nanoseconds samples into microseconds samples */
normalize(@lmax, 1000);
normalize(@lavg, 1000);
printf("%-20s %-6s %-20s %12s %14s %14s\n", "-Process-","-PID-","-Cause-", "-Count-","-Maximum-","-Average-");
printa("%-20s[%-6d] %-20s %@12d %@9d usecs %@9d usecs\n", @lcount, @lmax, @lavg);
printf("\n");
trunc(@lcount);
trunc(@lmax);
trunc(@lavg);
}
