Unix의 정신을 이어받은 제품들의 히스토리 그림입니다. 소스는 어디인지 모르겠네요.
2008/07/11
2008/07/08
추격자 : %sys의 범인은 누구일까 ?
솔라리스 뿐만 아니라, 유닉스 시스템을 이용하다 보면 간혹 사용자의 cpu% 사용율 보다, sys%의 사용율이 높은 경우가 있습니다. 이런 경우에 도대체 왜 sys% 높은지 답답할 때도 있습니다. 심한 경우에는 sys%가 높음에도 내 애플리케이션의 응답 시간이나 총처리량이 나쁜 경우에는 더욱 답답하죠.
운영체제 입장에서 sys%는 커널에서 동작되는 시간의 백분율입니다. 커널은 사용자 애플리케이션에서 호출하는 시스템 콜을 서비스하기 위해서 각종 서비스 모듈들과 관련 장치 드라이버, 내부 캐쉬, 커널 코어등의 코드(함수)들의 모음인데 s사용자가 단순히 open()을 했다고 해도, 커널 입장에서는 specfs, 관련 화일 시스템(ufs, zfs ... ), 각종 디바이스 드라이버등이 실행되어 집니다. 따라서, 어떤 계층에서 문제가 발생하는 지 알기가 쉽지 않았다고 할 수 있습니다. 커널내의 함수들이 유기적으로 작동되니까요.
그렇지만, 솔라리스 10이 생기면서 이 부분을 거의 정확하게 집어낼 수 있게되었습니다.
일단, 평상시에 어떤 커널 모듈이 많이 호출되는 지만 알면, 관련 패치가 있는 지를 쉽게 찾아볼 수 있습니다. 다음은 가장 바쁜 커널 모듈을 찾는 dtrace 스트립트입니다. 바쁘다는 관점은 두가지가 있습니다. 호출 횟수가 많은 것과 호출 당 처리 시간이 긴 것 두가지가 있을 수 있습니다. 이 두가지의 데이타를 dtrace는 한번에 관찰할 수 있습니다.
다음은 이것을 위한 dtrace script입니다. 커널 모듈에 대한 모든 콜을 트랩해서 호출 횟수와 호출당 소요 시간을 5초간 저장했다가 보여주는 역할을 합니다.
#dtrace -q -n 'fbt:::entry{self->trace=timestamp;}' -n 'fbt:::return/self->trace/{@c[probemod]=count();@e[probemod]=sum(timestamp-self->trace);}' -n 'tick-5s{printa(@c,@e);clear(@c);clear(@e);trunc(@c);trunc(@e);}'
...
mm 448 1677093
net80211 473 1608838
sha1 480 902546
fifofs 1315 7142051
specfs 1344 8330793
ip 1359 10275445
ufs 1439 6542160
usba 1542 5783685
skge 2335 12904313
pciehpc 2748 6571366
uhci 3221 14217584
nvidia 3260 61999111
TS 3347 12659840
ehci 3650 11595263
pcie_pci 5753 46414892
npe 13172 89669520
pcplusmp 110784 269213239
genunix 331691 1106575148
unix 500814 82226651922614
acpica 1929748 42631
제 랩탑에서 돌려본 예입니다. acpi module이 가장 많이 호출되죠. 반면에 총 처리 시간이 가장 긴 모듈은 unix 모듈입니다. 솔라리스 코어니 당연한 것이겠죠. sys%는 일정 시간동안 cpu를 점유한 커널 모듈의 시간이므로 어떤 모듈을 볼 것인지 상위 3~4개 정도 보면 직감이 나타나게 됩니다. 문제가 있는 시스템의 경우에는 요. 우측 두개의 숫자를 스프레드 시트를 이용해서 계산을 해보면, 호출당 처리 시간도 나오게 됩니다.
5초가 데이타가 나오므로, 연속적으로 저장하게 되면, 챠트도 형성할 수 있게 됩니다. 오픈솔라리스.org에 있는 chime이라는 툴을 사용하면, 챠트도 볼 수 있습니다.
위의 경우는 커널 모듈별만 계산했는데, 특정 모듈이 의심이 된다고 여기게 되면, 모듈내 어떤 함수에 문제가 있었는 지도 알 수 있습니다. 위에서 acpi 모듈이 의심이 간다면, apci 의 함수를 볼 수 있습니다.
#dtrace -q -n 'fbt:acpica::entry{self->trace=timestamp;}' -n 'fbt:acpica::return/self->trace/{@c[probefunc]=count();@e[probefunc]=sum(timestamp-self->trace)}' -n 'tick-5s{printa(@c,@e);clear(@c);clear(@e);trunc(@c);trunc(@e);}'
...
AcpiUtStatusExit 41842 174456493
AcpiFormatException 42079 189609876
AcpiUtGetMutexName 54557 112240926
AcpiNsGetNextValidNode 93576 205688515
AcpiNsGetNextNode 196392 872796601
AcpiUtDebugPrint 259500 507489364
AcpiUtTrackStackPtr 364434 750592053
acpica 모듈에서는 AcpiUtTrackStackPtr()가 호출당 처리 시간이 긴 것 같군요.
이런 방법으로 의심이 되는 모듈을 추적해볼 수 있습니다.
한편으로는 애플리케이션 관점에서 어떤 시스템콜 - 즉, 커널에게 어떤 서비스를 요청하는 지를 조사해볼 필요가 있습니다.
사용자 pid가 1234라고 했을때,
예전에 이런 목적으로 truss 를 사용했었습니다.
#truss -c -p 1234
dtrace는 이것보다 훨씬 더 화려한 출력을 제공합니다.
#dtrace -n 'syscall:::entry/pid==1234/{@[probemod,probefunc]=count()}'
를 사용하게 되면 pid 1234가 실행할때 발생하는 시스템 콜을 모듈별, 함수별로 보관했다 호출 횟수를 보여줌으로 어떤 서비스를 많이 쓰게 될 지 추측할 수 있게됩니다.
혹은
#dtrace -n 'syscall:::entry/pid==123/{self->sys=1}' \
-n 'fbt:::entry/self->sys/{@[probemod]=count();self->trace=timestamp;}'
와 같이 하게되면, pid 1234가 시스템 콜을 요청할 때, 작동되는 커널의 모듈들의 호출 회수를 저장했다가 보이게 할 수도 있습니다. 즉, 해당 애플리케이션에 의한 sys% 사용을 정확하게 잡아낼 수도 있습니다. 이 앞에서 썼던 timestamp 방식을 도입하면, 호출당 소요 시간도 추정할 수 있겠죠.
운영체제 입장에서 sys%는 커널에서 동작되는 시간의 백분율입니다. 커널은 사용자 애플리케이션에서 호출하는 시스템 콜을 서비스하기 위해서 각종 서비스 모듈들과 관련 장치 드라이버, 내부 캐쉬, 커널 코어등의 코드(함수)들의 모음인데 s사용자가 단순히 open()을 했다고 해도, 커널 입장에서는 specfs, 관련 화일 시스템(ufs, zfs ... ), 각종 디바이스 드라이버등이 실행되어 집니다. 따라서, 어떤 계층에서 문제가 발생하는 지 알기가 쉽지 않았다고 할 수 있습니다. 커널내의 함수들이 유기적으로 작동되니까요.
그렇지만, 솔라리스 10이 생기면서 이 부분을 거의 정확하게 집어낼 수 있게되었습니다.
일단, 평상시에 어떤 커널 모듈이 많이 호출되는 지만 알면, 관련 패치가 있는 지를 쉽게 찾아볼 수 있습니다. 다음은 가장 바쁜 커널 모듈을 찾는 dtrace 스트립트입니다. 바쁘다는 관점은 두가지가 있습니다. 호출 횟수가 많은 것과 호출 당 처리 시간이 긴 것 두가지가 있을 수 있습니다. 이 두가지의 데이타를 dtrace는 한번에 관찰할 수 있습니다.
다음은 이것을 위한 dtrace script입니다. 커널 모듈에 대한 모든 콜을 트랩해서 호출 횟수와 호출당 소요 시간을 5초간 저장했다가 보여주는 역할을 합니다.
#dtrace -q -n 'fbt:::entry{self->trace=timestamp;}' -n 'fbt:::return/self->trace/{@c[probemod]=count();@e[probemod]=sum(timestamp-self->trace);}' -n 'tick-5s{printa(@c,@e);clear(@c);clear(@e);trunc(@c);trunc(@e);}'
...
mm 448 1677093
net80211 473 1608838
sha1 480 902546
fifofs 1315 7142051
specfs 1344 8330793
ip 1359 10275445
ufs 1439 6542160
usba 1542 5783685
skge 2335 12904313
pciehpc 2748 6571366
uhci 3221 14217584
nvidia 3260 61999111
TS 3347 12659840
ehci 3650 11595263
pcie_pci 5753 46414892
npe 13172 89669520
pcplusmp 110784 269213239
genunix 331691 1106575148
unix 500814 82226651922614
acpica 1929748 42631
제 랩탑에서 돌려본 예입니다. acpi module이 가장 많이 호출되죠. 반면에 총 처리 시간이 가장 긴 모듈은 unix 모듈입니다. 솔라리스 코어니 당연한 것이겠죠. sys%는 일정 시간동안 cpu를 점유한 커널 모듈의 시간이므로 어떤 모듈을 볼 것인지 상위 3~4개 정도 보면 직감이 나타나게 됩니다. 문제가 있는 시스템의 경우에는 요. 우측 두개의 숫자를 스프레드 시트를 이용해서 계산을 해보면, 호출당 처리 시간도 나오게 됩니다.
5초가 데이타가 나오므로, 연속적으로 저장하게 되면, 챠트도 형성할 수 있게 됩니다. 오픈솔라리스.org에 있는 chime이라는 툴을 사용하면, 챠트도 볼 수 있습니다.
위의 경우는 커널 모듈별만 계산했는데, 특정 모듈이 의심이 된다고 여기게 되면, 모듈내 어떤 함수에 문제가 있었는 지도 알 수 있습니다. 위에서 acpi 모듈이 의심이 간다면, apci 의 함수를 볼 수 있습니다.
#dtrace -q -n 'fbt:acpica::entry{self->trace=timestamp;}' -n 'fbt:acpica::return/self->trace/{@c[probefunc]=count();@e[probefunc]=sum(timestamp-self->trace)}' -n 'tick-5s{printa(@c,@e);clear(@c);clear(@e);trunc(@c);trunc(@e);}'
...
AcpiUtStatusExit 41842 174456493
AcpiFormatException 42079 189609876
AcpiUtGetMutexName 54557 112240926
AcpiNsGetNextValidNode 93576 205688515
AcpiNsGetNextNode 196392 872796601
AcpiUtDebugPrint 259500 507489364
AcpiUtTrackStackPtr 364434 750592053
acpica 모듈에서는 AcpiUtTrackStackPtr()가 호출당 처리 시간이 긴 것 같군요.
이런 방법으로 의심이 되는 모듈을 추적해볼 수 있습니다.
한편으로는 애플리케이션 관점에서 어떤 시스템콜 - 즉, 커널에게 어떤 서비스를 요청하는 지를 조사해볼 필요가 있습니다.
사용자 pid가 1234라고 했을때,
예전에 이런 목적으로 truss 를 사용했었습니다.
#truss -c -p 1234
dtrace는 이것보다 훨씬 더 화려한 출력을 제공합니다.
#dtrace -n 'syscall:::entry/pid==1234/{@[probemod,probefunc]=count()}'
를 사용하게 되면 pid 1234가 실행할때 발생하는 시스템 콜을 모듈별, 함수별로 보관했다 호출 횟수를 보여줌으로 어떤 서비스를 많이 쓰게 될 지 추측할 수 있게됩니다.
혹은
#dtrace -n 'syscall:::entry/pid==123/{self->sys=1}' \
-n 'fbt:::entry/self->sys/{@[probemod]=count();self->trace=timestamp;}'
와 같이 하게되면, pid 1234가 시스템 콜을 요청할 때, 작동되는 커널의 모듈들의 호출 회수를 저장했다가 보이게 할 수도 있습니다. 즉, 해당 애플리케이션에 의한 sys% 사용을 정확하게 잡아낼 수도 있습니다. 이 앞에서 썼던 timestamp 방식을 도입하면, 호출당 소요 시간도 추정할 수 있겠죠.
피드 구독하기:
글 (Atom)
