사이트가 느려지는 원인은 여러가지가 있겠지만, 크게 두가지로 나눌 수 있습니다.

• 서버의 하드웨어 자원이나 네트워크 속도와 같은 환경적인 요인
• 최적화되지 않은 프로그램 소스코드나 slow 쿼리와 같은 소프트웨어 결함의 요인

환경적인 요인의 해결은 금전적인 비용을 들이면 쉽게 해결 가능하지만 그 비용이 만만치 않아 쉽지 않습니다. 반면, 소프트웨어의 결함의 요인의 해결은 작은 비용으로 큰 효과를 볼 수도 있습니다. 어떤 소스코드에서 시간이나 CPU, 메모리를 많이 소모하는지, 어떤 쿼리가 시간을 많이 소모하는지를 파악하여 더 빠르게 작동하도록 최적화 한다면, 기대 이상의 효과를 볼 수도 있습니다.

이 글에서는 소프트웨어의 성능과 소스코드의 결함을 분석하여, 소스코드 최적화 작업을 돕는 프로파일링에 대하여 알아보려고 합니다. 또, PHP용 프로파일링 도구인 Xdebug + Webgrind를 활용하여 XE 1.7.3 과 1.7.5를 프로파일링 해보고, XE 버전이 업데이트 되면서 성능이 어떻게 바뀌었는지 분석해보겠습니다.

1.7.4와 1.7.5는 성능차이가 크지 않아 부득이하게 1.7.3과 1.7.5를 비교합니다.

프로파일링(Profiling) 소개

프로파일링에 대하여 더 알아보겠습니다.

대부분의 프로그램은 80:20 법칙을 따릅니다. 전체 코드의 20%가 전체 시간의 80%를 차지합니다. 그래서 프로그래머가 해당 컴퓨터 아키텍쳐의 세세한 부분보다는 논리에 집중하여 프로그래밍 시간을 줄여주는 자바나 C#같은 언어가 인기를 얻었습니다. 프로그램의 실행시간은 길어지지만, 프로그래머의 시간은 절약되는 것입니다. 그러나 프로그램을 더 빨리 실행하기위한 최적화가 필요하지 않다는 말은 아닙니다. 많은 컴파일러는 알아서 최적화를 합니다. 예를 들어, GCC 컴파일러는 (대문자 주의) -O 옵션으로 최적화 수준을 지정할 수 있습니다.

프로파일링(profiling)은 프로그램의 성능을 높이기 위해 최적화할 코드및 함수의 위치를 발견하도록 도와줍니다. 프로그램에서 10번만 호출하는 함수보다 1000번 호출하는 함수를 최적화하는게 당연할 것입니다. 프로그램을 프로파일링하면 코드의 어떤 부분을 자주 사용하고 어떤 함수가 CPU 시간을 많이 잡아먹는지 알 수 있는데, 이 두 정보는 최적화할 대상을 정하는데 유용합니다. 실제 프로그램을 실행하면서 정보를 모으기 때문에 감춰진 버그를 찾는데도 유용합니다. 실행 중에 예기치않게 어떤 함수를 1000번 호출한다면 설계상 문제이거나 버그일 수 있습니다. 또, 크고 복잡한 프로젝트에서 코드를 살펴볼때도 유용합니다.

출처: http://linuxgazette.net/100/vinayak.html (원문), http://yes.imhappyo.com/279 (한글)

XE 프로파일링

'XE가 느리다. 최적화(옵티마이징), 커스터마이징을 해서 속도를 높이고 싶다'고 하시는 분들이 많습니다. 하지만 최적화, 커스터마이징을 하려면 우선 XE를 분석하는 과정이 선행되어야 할 것입니다.(XE는 개발되고 사용된지 7년이 된, 꽤 오래된 소프트웨어이므로 성능 저하의 원인이 되는 수정 가능한 소스코드 결함을 찾기는 쉽지 않습니다.)

XE를 프로파일링하고 분석해 보았습니다.

사용된 툴

Xdebug와 Webgrind를 사용했습니다.

Xdebug는 보통 'PHP 디버깅'을 위하여 많이 사용되는 툴이지만 프로파일링 툴로도 많이 사용되고 있습니다. 다만, 프로파일링 데이터만 생성할 뿐 결과를 보여주는 뷰어는 제공하지 않습니다. 그래서 별도의 뷰어를 사용해야 하는데, 여러 뷰어 중에 'Webgrind'를 사용하기로 하였습니다. Webgrind는 Xdebug가 프로파일링 데이터를 파일로 저장해 놓으면, 그 파일을 읽어서 웹페이지에서 쉽게 볼 수 있도록 해줍니다.

이해를 돕기 위해 Webgrind의 출력 화면을 잠깐 보겠습니다.

화면 상단 부분은 프로파일링 데이터를 선택하고, 출력단위(percent/milliseconds/microseconds)를 설정하는 부분입니다.

중요한 부분은 화면 하단의 표 영역입니다.
표 영역은 Function, Invocation Count, Total Self Cost, Total Inclusive Cost 컬럼으로 구성돼 있습니다.

표의 첫번째 row에 있는 {main}은 index.php의 실행을 의미합니다. xe는 한번의 요청이 index.php함수에서 시작하고 끝나므로 Total Inclusive Cost가 당연히 100(%)입니다.

프로파일링 수행 계획

XE에서 자주 사용되는 시나리오를 대상으로 프로파일링을 했습니다.

• 게시판 글 보기
• 회원정보 보기
• 게시판 글 검색
• 관리자페이지에서 회원그룹 목록 보기

이 글에서는 게시판 글 보기 페이지만 다루도록 하겠습니다.

각각의 시나리오를 10회씩 요청하는 동안 프로파일링하였고, 프로파일링 데이터에는 10회의 요청동안 누적된 수치가 기록됩니다.

프로파일링 환경

서버는 웹서버 1대, DB서버 1대로 구성하였고 두 서버의 사양은 동일합니다.

프로파일링 분석

프로파일링 한 결과를 여러 관점에서 분석해 보았습니다.

라이프사이클 분석

XE의 대략적인 라이프사이클의 수행시간을 분석해보겠습니다. 게시판의 글을 열람할 때의 프로파일링 데이터입니다.

위 표는 Webgrind로 출력된 화면의 일부입니다. {main}함수는 index.php를 의미합니다. 'Called from script host' 영역은 {main}을 클릭하면 나타나며, index.php에서 호출된 함수들이 나타납니다. index.php에서 호출되는 함수들을 보면 XE의 대략적인 라이프사이클을 살펴볼 수 있습니다.

중요한 몇가지 함수만 살펴보겠습니다.

Context->init

이 함수는 XE가 요청(Request)을 받을 때마다 항상 작동하며 여러가지 환경을 설정(요청 검사, 전역변수 설정, 세션설정, 언어파일 로드, 로그인 검사, 대상 모듈 찾기 등) 하는 역할을 합니다.
전체 소요시간중 약 13%로 꽤 큰 비중을 차지하고 있습니다. 모든 요청이 들어올 때마다 항상 반복되어 수행되는 코드이므로 이 함수 내부를 조금 더 최적화 한다면 큰 효과를 볼 수 있는 부분입니다.

ModuleHandler->procModule

이 함수는 우선 요청 URL을 분석하여 담당 모듈과 act를 찾습니다. 그 다음 찾은 담당 모듈의 act를 실행합니다. 우리의 시나리오에서는 게시판 모듈의 dispBoardContent act가 찾아지고 실행됩니다. 게시판 모듈은 화면에 출력할 게시글과 게시글 리스트 등의 데이터를 DB에서 조회해 옵니다.
전체 소요시간중 약 26%를 차지하고 있습니다. 이 함수는 요청되는 모듈 및 act에 따라 소요시간이 많이 차이 날 수 있습니다.

ModuleHandler->displayContent

ModuleHandler->displayContent 함수는 브라우저에 되돌려 줄 view(html코드)를 만드는 역할을 하는데, 레이아웃 출력, 스킨 출력, 레이아웃과 스킨에 지정된 위젯 출력 등의 많은 템플릿 파싱 과정을 거칩니다.
전체 소요시간에서 약 48%의 가장 큰 비중을 차지하고 있습니다. 하지만 48%의 비중이 모두 레이아웃, 스킨, 위젯의 순수한 템플릿 파싱 비용이라고 생각하면 안 됩니다. 예를 들어, 이 시나리오에서는 게시판 스킨에서 $documentItem->getComments() 함수가 호출되고 있습니다. 이 코드가 48%중 꽤 많은 비중을 차지하고 있습니다. 48%의 대부분은 이렇게 템플릿에서 호출되는 함수의 수행시간입니다.

함수별 분석

라이프사이클 분석은 XE의 전체 흐름에서 어떤 과정이 시간을 많이 소요하는지 대략적으로 분석할 수 있었습니다. 이번에는 함수 중에서 어떤 함수가 많은 시간이 소요되는지 분석해보려고 합니다. 많이 소요되는 함수를 찾기 위해 microseconds 단위로 출력하고, 'Total Self Cost'순으로 정렬합니다.

거의 대부분의 함수는 함수 내에서 다른 함수를 호출하기 때문에 함수 자체의 수행시간만 계산한 'Total Self Cost'를 'Total Inclusive Cost'와 함께 봐야 합니다.

Total Self Cost가 높은 상위 30개의 함수입니다. 주요 함수를 분석해보겠습니다.

ModuleHandler::getModuleInstance

이 함수는 XE의 여러 모듈 클래스를 로드하고 인스턴스를 생성하여 반환하는 함수입니다. 보통 XE에서 getModel, getController 등의 함수를 호출할 때마다 내부적으로 이 함수가 호출됩니다. Inclusive Cost도 큰 편이긴 하지만 Self Cost가 상당히 크게 나타나고 있습니다(397,050 micro sec/10 requests). 사실 이 함수의 Self Cost가 큰 이유는 함수 내부에서 많은 클래스 파일을 로드하기 때문입니다.

파일을 로드(include)하는 코드의 수행시간은 XCache, Zend OPcache, APC와 같은 opcode caching을 이용하면 대폭 줄일 수 있습니다. 분석결과 동일한 프로파일링 환경에서 Zend OPcache(PHP5.5 내장)을 사용했을 경우, 28%의 속도향상이 있었습니다.

Xdebug에서 클래스 파일을 로드하는 시간을 로드한 함수의 Self Cost로 계산한 것인데, Xdebug의 오류로 판단됩니다.

php::mysqli_prepare
php::mysqli_stmt_execute
DBMysqli->__query
DB->_executeQuery
DBMysqli->_fetch
Query->getArguments
DBMysqli->__query
DBMysql->_executeSelectAct
php::mysqli_connect
DB->getSelectSql
Query->getSelectString
DBMysqli->_prepareQueryParameters
DB->executeQuery
Query->getWhereString
require::/home/DOMAINS/prof1738.test4.xehub.kr/classes/db/DB.class.php

위의 함수들은 상위 30개의 함수중 DB 관련 함수입니다. DB 쿼리를 위해 상당히 많은 비용이 소모되고 있습니다. 위 함수의 수행시간을 더하면 전체 수행시간의 약 27%를 차지합니다.

require::/home/DOMAINS/prof1738.test4.xehub.kr/config/config.inc.php

XE가 실행되는 초기에 실행되는 코드들이 포함된 파일입니다. XE의 시동을 걸기 위해 무거운 코드들이 많습니다.

Context::getUrl

getUrl, getFullUrl 함수를 사용할 때 요청되는 함수입니다. Self Cost가 큰 편입니다.
소스코드 최적화를 해야 할 여지가 있어 보입니다.

include::/home/DOMAINS/prof1738.test4.xehub.kr/files/cache/addons/0pc.acivated_addons.cache.php

이 파일은 활성화된 애드온을 호출하는 역할을 합니다. 내부에서 활성화 되어 있는 애드온 파일을 로드합니다.

include::/home/DOMAINS/prof1738.test4.xehub.kr/files/cache/template_compiled/cb36026766d1306b2ea281a972fc9749.compiled.php

컴파일된 게시판 스킨 파일입니다.

FrontEndFileHandler->getFileInfo

js, css을 로드하는 함수입니다.

Context::loadLang

XE 코어 및 각종 모듈의 언어파일을 로드하는 함수입니다. XML 언어파일은 php코드로 변환하여 캐싱해 놓고 필요할 때마다 로딩합니다. php코드를 보면 각각 언어 아이템마다 각각 변수 할당을 하는 구조입니다. 언어 아이템을 각각 변수에 할당하지 않고, 하나의 array에 한번에 할당하는 구조로 변경한다면 약간의 성능향상이 기대됩니다.

php::iconv

string의 캐릭터셋을 변경하는 함수인데, URL에 포함된 파라메터의 캐릭터셋을 항상 utf8로 유지하기 위해 사용됩니다.(Context->convertEncoding 참고)

최근버전(1.7.5.3)에서는 그 사용빈도가 상당히 줄었습니다.

require::/home/DOMAINS/prof1738.test4.xehub.kr/classes/mail/Mail.class.php

config.inc.php에서 로드하는 메일전송을 위한 클래스입니다. 메일 전송은 자주 사용되는 기능이 아니므로 사용될 때에만 로드하도록 변경할 필요가 있습니다.

XE 1.7.3.8 vs XE 1.7.5.3

XE 코어의 두버전을 비교해 보았습니다. 아래표는 동일한 환경에서 테스트한 XE 1.7.5.3 버전의 프로파일링 데이터입니다.

프로파일링 데이터를 비교해보면 전체적으로 1.7.3.8보다 30% 가량의 속도향상(요청당 0.401초 -> 0.280초)이 있습니다.

XE의 모든 요청에 대한 30% 향상은 아니며, 캐싱된 데이터가 모두 유효할 경우의 요청만 해당합니다.

자세히 살펴보면 DB 쿼리와 관련된 함수들의 수행시간이 많이 줄어든 것을 볼 수 있습니다. 가장 큰 원인은 XE 1.7.4에서 적용한 대규모의 object cache로 인해 DB 쿼리수가 많이 줄었기 때문입니다.

결론

속도 향상을 위해 고려해 보아야 할 점들입니다.

• 모든 요청에서 수행되는 불필요한 코드 줄이기
  현재 XE 코어에서는 소스코드가 변경됐을 경우, 변경된 소스코드를 감지하는 과정을 매 요청에서 수행하는 코드가 있습니다. (언어파일 캐시를 검사하는 부분 등)
  매번 요청을 받을 때마다 소스코드의 변경을 감지하려고 하지 말고, 관리자가 소스코드 변경시 캐시파일 재생성과 같은 별도의 명령을 수동으로 실행하는 방법으로 바꾼다면 미비하지만 약간의 성능 향상이 있을 것으로 기대됩니다.

• DB 쿼리
  1.7.3.8과 1.7.5.3 사이의 성능향상은 결국 DB 쿼리수를 줄였기 때문입니다.
  DB 쿼리의 수를 줄일수 있으면 확연히 빨라질 수 있습니다.

• opcode cache 사용
  opcode 캐싱은 PHP와 같은 스크립트 언어의 단점을 만회할 수 있습니다. 속도향상도 뚜렷하게 느낄수 있습니다. 소스코드의 최적화가 아닌 서버 환경설정과 관련된 영역이지만 강력히 추천합니다.

소프트웨어의 개발만큼 중요한 작업이 소프트웨어를 분석하는 것이라 생각됩니다. 특히 많은 사람들이 사용하는 오픈소스에서 프로파일링 및 분석은 더욱 중요한 작업입니다. XE를 프로파일링하고 데이터를 분석하는 작업이 그리 간단하지는 않지만 반드시 거치고 있는 이유입니다.
또, 분석을 통해 발견된 문제점을 보완하는 작업 역시 뒤따라야 할 것입니다. (이 글을 쓰는 동안에도 몇가지 결함 발견되었고, github에 이슈로 등록되었습니다.)

감사합니다.

이 글에서 설명하고 있는 XE 프로파일링 과정 및 분석에 대한 많은 분들의 이의 제기나 질문을 통하여 좀 더 정확하고 깊이 있는 지식을 공유할 수 있기를 바랍니다. 많은 의견 부탁드립니다.