3장 프로파일링
016 급여명세서
1999년 10월 오라클을 떠나 MBA 과정 동기와 새 회사를 창업했다.
2001년 초쯤 영업사원이 댈러스에 본사를 둔 한 회사와 접점을 뒀고 그해 9월 일이 터졌다.
이 회사는 수개월 동안 매달 급여일마다 직원들에게 제때 급여를 지급하지 못했다.
회사에서 사용 중인 오라클 급여 시스템이 너무 느린게 이유였다.
데이터베이스 서버의 700MHz CPU를 모두 1GHz CPU로 업그레이드 했지만 전보다 더 느렸다.
동료 제프 홀트와 함께 회사의 기술 팀을 방문했고, 다음과 같은 사실을 알았다.
- 파이유젠PYUGEN 급여 명세 프로그램이 너무 느리게 동작한다는 점이 문제였다.
- 파이유젠이 실행되면 CPU 사용률이 100%에 달했다. 그래서 회사는 CPU를 업그레이드를 했었다.
- 모니터링 도구로 관찰해보니, 파이유젠이 실행될 때 오라클 데이터베이스의 시간을 두 번째로 오래 잡아먹는 건 래치 프리latch free라고 불리는 내부 이벤트였다.
- 래치 프리: 락과 유사한 오라클의 잠금 장치, 래치 프리 이벤트는 래치 획득에 실패해 프로세스가 대기 상태에 들어간다는 것을 의미한다.
파이유젠의 데이터베이스 프로세스가 실행 중일 때 추적trace 해야 했는데
추적은 데이터베이스 프로세스가 실행되는 동안 호출하는 모든 서브루틴에 대한 상세 로그를 기록하는 오라클 데이터베이스 표준 기능이다.
상세 로그는 파이유젠 같은 프로그램이 시간을 오래 잡아먹는 이유를 찾아내기 위해 꼭 필요한 정보였다.
30분간 파이유젠 프로그램을 추적하고 데이터를 확보했다.
- 파이유젠은 얼마나 오래 실행됐나? 1957.470초, 약 32분이 조금 넘는 시간이다.
- CPU 서비스 호출을 제거하면? 248.69초 정도의 시간을 줄일 수 있다. 12.7%에 해당하는 시간
- 만약 래치 프리 호출을 모두 제거한다면? 23.690초를 줄일 수 있다. 1.2%에 해당하는 시간
- 파이유젠이 대부분 시간을 소비하는 지점은 어디인가? SQL*Net 서브루틴이다. 첫번째 서브루틴은 50.5%의 시간을 차지하고 있었으며최상위 두 개를 합치면 71.7%에 달하는 시간이다.
- 파이유젠을 빠르게 동작시키려면 뭘 해야 할까? SQL*Net 서브루틴이 뭔지 알아내 파이유젠이 서브루틴을 더 빠르게 호출하게 하거나 두 서브루틴이 더 빠르게 실행되어야 한다.
이 애플리케이션은 네트워크 라운드 트립 수를 조정하는 매개변수를 제공하지 않았고 라운드 트립 수를 줄이도록 애플리케이션의 소스 코드를 수정할 수도 없었다.
제프는 데이터를 보고 클라이언트의 SQL*Net 메시지 서브루틴의 평균값이 0.011 340초라는 점이 이상하다고 했다.
같은 서버에서 동작하는 두 프로그램 간의 라운드 트립이 10밀리초일 수는 없다고 했다.
제프는 DBA와 함께 약 15분간의 테스트를 거쳐 자신의 논리를 증명했다.
네트워크 설정 파일의 매개변수를 수정하면 클라이언트의 SQLNet 메시지 서브루틴이 55배 빠르게 동작할 수 있다는 점을 보여준 것이다.
각 서브루틴 호출이 55배 빨라지면, 클라이언트의 SQLNET 메시지라는 서브루틴의 총 실행 시간은 984초에서 20초 미만으로 줄어들어 파이유젠의 총 실행 시간을 절반 가깝게 줄일 수 있었다.
우리가 제안했던 방법을 곧바로 시도해 볼 수는 없어서 아쉬웠지만
며칠 후 DBA가 우리가 제안한 방법을 테스트하고 구현했다고 알려줬다.
우리의 예상대로 파이유젠은 분당 2배 이상의 급여 처리를 실행하고 있었고 고객사는 매우 만족해했다.
017 시퀀스 다이어그램
시퀀스 다이어그램sequene diagram은 객체 간의 상호 동작을 순차적으로 보여주는 그래프의 한 종류다.
응답 시간을 쉽게 시각화할 수 있는 도표이다.
급여 지급 문제의 시퀀스 다이어그램은 다음과 같다.
이 시퀀스 다이어그램에 따르면, 스케줄러가 파이유젠을 실행하고 파이유젠은 SQLNet이라는 오라클 네트워크 소프트웨어를 호출해 데이터베이스에 연결한다.
다이어그램상으로 파이유젠은 SQLNet을 이용해 2번의 데이터베이스 호출을 실행하지만, 실제로는 추적 데이터에서 확인한 바로 10만번의 라운드 트립이 발생하고 있었다.
시퀀스 다이어그램을 빠르게 그려 보면 시스템이 시간을 어떻게 소비하고 있는지 파악할 수 있다.
018 간트 차트
고객사 중 한 곳은 야간 배치 무제를 겪고 있었다.
자정에 대규모 작업을 실행해 전날 데이터를 요약하고 오전 8시 업무 시작에 맞춰 시스템을 준비하는 과정을 갖추고 있었다.
하지만 작업이 점점 더 오래 걸리기 시작해 8시 30분이 되도 끝나지 않는 상황이 발생했었다.
이를 분석하기 위해 간트 차트Gantt Chart를 사용했다.
간트 차트는 어느 지점에서 시간이 허비되고 있는지를 이해하는 데 도움이 된다.
다음 간트 차트에서는 데이터베이스가 야간에 시간을 허비하고 있는 지점을 추적했다.
이 지점은 몇 가지 패턴 현상을 보이고 있었다.
"로드와 작업 처리 사이 시간 동안 무슨 일이 벌어지는 걸까? 왜 이 시간에는 데이터베이스가 한가한 걸까?"
이 질문이야 말로 증상을 해결할 수 있는 실마리였다.
알고 보니, 성능 개선은 데이터베이스가 아니라 애플리케이션이었다.
검토가 필요한 사항 중에 해결책이 있었지만 고객사는 이 문제가 당장 중요하다고 생각하지 않은 것이다.
애플리케이션의 몇몇 지점에서 이 특정 패턴만 찾아내는 것으로 작업 시간을 3시간 이상 단축할 수 있었다.
이후 야간 배치 작업은 새벽 5시면 끝낼 수 있게 되었다.
019 애플리케이션 동작의 추적
컴퓨터 프로그램이 시간을 어떻게 소비하는지 어떻게 관찰할 수 있을까? 그 답은 바로 추적이다.
추적은 프로그램 실행 과정에 대한 정보를 파일에 출력하는 몇 가지 print 구문을 실행하는 것이다.
추적은 요구사항이 무엇인지에 따라 넣거나 뺄 수 있는 기능이다.
소스 코드에 특별한 동작을 추가하지 않고도 프로그램의 추적이 가능하다.
eBPF, DTrace, strace, sruss, tcpdump, EWT 등의 도구가 있다.
020 프로파일
프로파일profile이란 하나 혹은 그 이상의 어트리뷰트attribute를 이용해 추적 스트림을 그룹화해 요약한 테이블이다.
021 프로파일의 생성
프로파일은 추적 스트림을 표 형식으로 집계한 것이다.
생성하려면 먼저 집계에 사용할 그룹화 키를 선택해야 한다.
집계aggregation 과정은 기계적으로 처리되며, 엑셀로 볼 수 있다.
이벤트 별 실행 시간이 기록된 스트림에서 그룹화를 하면 실행 횟수와 평균 실행 시간, 평균 실행 횟수 등을 추가로 생성할 수 있다.
프로파일러가 해주는 작업이 이런 작업이다.
집계 절차의 복잡도는 추적 기능을 얼마나 주의깊게 설계했느냐에 따라 다르다.
하지만 성능에 대한 이슈를 해결해야 한다면 좋은 추적 데이터와 뛰어난 프로파일러가 필요하다.
지금까지 시도했던 방법보다 성능에 대해 가장 잘 알려준 것은 프로파일링이었다.
3장 프로파일링
016 급여명세서
1999년 10월 오라클을 떠나 MBA 과정 동기와 새 회사를 창업했다.
2001년 초쯤 영업사원이 댈러스에 본사를 둔 한 회사와 접점을 뒀고 그해 9월 일이 터졌다.
이 회사는 수개월 동안 매달 급여일마다 직원들에게 제때 급여를 지급하지 못했다.
회사에서 사용 중인 오라클 급여 시스템이 너무 느린게 이유였다.
데이터베이스 서버의 700MHz CPU를 모두 1GHz CPU로 업그레이드 했지만 전보다 더 느렸다.
동료 제프 홀트와 함께 회사의 기술 팀을 방문했고, 다음과 같은 사실을 알았다.
파이유젠의 데이터베이스 프로세스가 실행 중일 때 추적trace 해야 했는데
추적은 데이터베이스 프로세스가 실행되는 동안 호출하는 모든 서브루틴에 대한 상세 로그를 기록하는 오라클 데이터베이스 표준 기능이다.
상세 로그는 파이유젠 같은 프로그램이 시간을 오래 잡아먹는 이유를 찾아내기 위해 꼭 필요한 정보였다.
30분간 파이유젠 프로그램을 추적하고 데이터를 확보했다.
이 애플리케이션은 네트워크 라운드 트립 수를 조정하는 매개변수를 제공하지 않았고 라운드 트립 수를 줄이도록 애플리케이션의 소스 코드를 수정할 수도 없었다.
제프는 데이터를 보고 클라이언트의 SQL*Net 메시지 서브루틴의 평균값이 0.011 340초라는 점이 이상하다고 했다.
같은 서버에서 동작하는 두 프로그램 간의 라운드 트립이 10밀리초일 수는 없다고 했다.
제프는 DBA와 함께 약 15분간의 테스트를 거쳐 자신의 논리를 증명했다.
네트워크 설정 파일의 매개변수를 수정하면 클라이언트의 SQLNet 메시지 서브루틴이 55배 빠르게 동작할 수 있다는 점을 보여준 것이다.
각 서브루틴 호출이 55배 빨라지면, 클라이언트의 SQLNET 메시지라는 서브루틴의 총 실행 시간은 984초에서 20초 미만으로 줄어들어 파이유젠의 총 실행 시간을 절반 가깝게 줄일 수 있었다.
우리가 제안했던 방법을 곧바로 시도해 볼 수는 없어서 아쉬웠지만
며칠 후 DBA가 우리가 제안한 방법을 테스트하고 구현했다고 알려줬다.
우리의 예상대로 파이유젠은 분당 2배 이상의 급여 처리를 실행하고 있었고 고객사는 매우 만족해했다.
017 시퀀스 다이어그램
시퀀스 다이어그램sequene diagram은 객체 간의 상호 동작을 순차적으로 보여주는 그래프의 한 종류다.
응답 시간을 쉽게 시각화할 수 있는 도표이다.
급여 지급 문제의 시퀀스 다이어그램은 다음과 같다.
이 시퀀스 다이어그램에 따르면, 스케줄러가 파이유젠을 실행하고 파이유젠은 SQLNet이라는 오라클 네트워크 소프트웨어를 호출해 데이터베이스에 연결한다.
다이어그램상으로 파이유젠은 SQLNet을 이용해 2번의 데이터베이스 호출을 실행하지만, 실제로는 추적 데이터에서 확인한 바로 10만번의 라운드 트립이 발생하고 있었다.
시퀀스 다이어그램을 빠르게 그려 보면 시스템이 시간을 어떻게 소비하고 있는지 파악할 수 있다.
018 간트 차트
고객사 중 한 곳은 야간 배치 무제를 겪고 있었다.
자정에 대규모 작업을 실행해 전날 데이터를 요약하고 오전 8시 업무 시작에 맞춰 시스템을 준비하는 과정을 갖추고 있었다.
하지만 작업이 점점 더 오래 걸리기 시작해 8시 30분이 되도 끝나지 않는 상황이 발생했었다.
이를 분석하기 위해 간트 차트Gantt Chart를 사용했다.
간트 차트는 어느 지점에서 시간이 허비되고 있는지를 이해하는 데 도움이 된다.
다음 간트 차트에서는 데이터베이스가 야간에 시간을 허비하고 있는 지점을 추적했다.
이 지점은 몇 가지 패턴 현상을 보이고 있었다.
"로드와 작업 처리 사이 시간 동안 무슨 일이 벌어지는 걸까? 왜 이 시간에는 데이터베이스가 한가한 걸까?"
이 질문이야 말로 증상을 해결할 수 있는 실마리였다.
알고 보니, 성능 개선은 데이터베이스가 아니라 애플리케이션이었다.
검토가 필요한 사항 중에 해결책이 있었지만 고객사는 이 문제가 당장 중요하다고 생각하지 않은 것이다.
애플리케이션의 몇몇 지점에서 이 특정 패턴만 찾아내는 것으로 작업 시간을 3시간 이상 단축할 수 있었다.
이후 야간 배치 작업은 새벽 5시면 끝낼 수 있게 되었다.
019 애플리케이션 동작의 추적
컴퓨터 프로그램이 시간을 어떻게 소비하는지 어떻게 관찰할 수 있을까? 그 답은 바로 추적이다.
추적은 프로그램 실행 과정에 대한 정보를 파일에 출력하는 몇 가지 print 구문을 실행하는 것이다.
추적은 요구사항이 무엇인지에 따라 넣거나 뺄 수 있는 기능이다.
소스 코드에 특별한 동작을 추가하지 않고도 프로그램의 추적이 가능하다.
eBPF, DTrace, strace, sruss, tcpdump, EWT 등의 도구가 있다.
020 프로파일
프로파일profile이란 하나 혹은 그 이상의 어트리뷰트attribute를 이용해 추적 스트림을 그룹화해 요약한 테이블이다.
021 프로파일의 생성
프로파일은 추적 스트림을 표 형식으로 집계한 것이다.
생성하려면 먼저 집계에 사용할 그룹화 키를 선택해야 한다.
집계aggregation 과정은 기계적으로 처리되며, 엑셀로 볼 수 있다.
이벤트 별 실행 시간이 기록된 스트림에서 그룹화를 하면 실행 횟수와 평균 실행 시간, 평균 실행 횟수 등을 추가로 생성할 수 있다.
프로파일러가 해주는 작업이 이런 작업이다.
집계 절차의 복잡도는 추적 기능을 얼마나 주의깊게 설계했느냐에 따라 다르다.
하지만 성능에 대한 이슈를 해결해야 한다면 좋은 추적 데이터와 뛰어난 프로파일러가 필요하다.
지금까지 시도했던 방법보다 성능에 대해 가장 잘 알려준 것은 프로파일링이었다.