https://velog.io/@goat_hoon/k6와함께하는성능개선기
지난번 포스트에서, 한가지 Request에 DB Write이 3번이 처리되는 상황에서, Transaction 처리 유무에 따라 100명의 요청이 동시에 들어왔을 때 Nest 서버에서 각 요청별로 DB Write 처리 순서가 보장되지 않아서 병목이 생겼을 것이라고 추측했었습니다. 하지만, 결국 이 문제가 아니었고, 다른 곳에서 성능을 개선할 수는 있었지만.. 그래도 이를 확실히 검증하고 공유하고자 글을 작성하였습니다.
1. 테스트 준비
테스트 수행 코드는 해당 브랜치에 커밋하였습니다.
https://github.com/skkuding/codedang/commits/test/local-taehoon/
최대한 회원가입과 비슷한 상황을 만들기위해 백엔드 코드를 작성하였습니다.
1. Controller 작성
Authentication 과정이 필요하지 않는 Controller에 testForLocal 함수를 만들었습니다.
@Controller('email-auth')
@AuthNotNeededIfOpenSpace()
export class EmailAuthenticationController {
private readonly logger = new Logger(EmailAuthenticationController.name)
constructor(private readonly userService: UserService) {}
@Post('test/local')
async testForLocal(@Body() signupDto: SignUpDto) {
return await this.userService.testForLocal(signupDto)
}
}2. Service 코드
Service 코드에서는 요청별로 고유 ID를 지정해야, 요청별 순서를 한눈에 파악할 수 있습니다. 그래서 고유 ID를 UUID로 지정하였습니다.
따라서, await DB Write을 하고 나서,
고유 ID(username)과, 현재 시간(Date.now()) 어떤 단계를 처리하였는지, 그리고 서비스 함수 시작부터 해당 await요청이 완료될 때 까지 걸린 시간을 console.log 로 남겼습니다.
// 처리가 다 끝난 상황의 console log
// 여기서 start는 서비스 코드 최초 함수 실행시간을 나타낸다.
console.log(
`username : ${_username} now Date : ${Date.now()} all done : ${performance.now() - start} `
)그리고, Transaction을 처리한 코드, 처리하지 않은 코드 두가지를 분기하였습니다.
(1) Transaction 처리
async testForLocal(signUpDto: SignUpDto): Promise<User> {
const start = performance.now()
const _username = randomUUID()
const _email = signUpDto.email + randomUUID()
const _password = signUpDto.password + randomUUID()
//트랜잭션 시작
const returnUser = await this.prisma.$transaction(async (prisma) => {
//첫번째 DB Write
const user = await prisma.user.create({
data: {
username: _username,
password: _password,
email: _email
}
})
// 첫번째 DB Write 종료후 로그 출력
console.log(
`username : ${_username} now Date : ${Date.now()} user create done : ${performance.now() - start} `
)
// 두번째 DB Write
await prisma.userProfile.create({
data: {
realName: _username,
user: {
connect: { id: user.id }
}
}
})
// 두번째 DB Write 종료후 로그 출력
console.log(
`username : ${_username} now Date : ${Date.now()} profile create done : ${performance.now() - start} `
)
// 세번째 DB Write
await prisma.userGroup.create({
data: {
userId: user.id,
groupId: 1,
isGroupLeader: false
}
})
// 세번째 DB Write 종료후 로그 출력 (모든 작업 완료)
console.log(
`username : ${_username} now Date : ${Date.now()} all done : ${performance.now() - start} `
)
return user
})
return returnUser
}(2) Transaction 미처리
Prisma의 transaction 처리 없이 await이 연달아 등장합니다.
하나의 Connection은 보장받지 못합니다.
async testForLocal(signUpDto: SignUpDto): Promise<User> {
const start = performance.now()
const _username = randomUUID()
const _email = signUpDto.email + randomUUID()
const _password = signUpDto.password + randomUUID()
// 첫번째 DB Write
const user = await this.prisma.user.create({
data: {
username: _username,
password: _password,
email: _email
}
})
// 첫번째 DB Write 종료후 로그 출력
console.log(
`username : ${_username} now Date : ${Date.now()} user create done : ${performance.now() - start} `
)
// 두번째 DB Write
await this.prisma.userProfile.create({
data: {
realName: _username,
user: {
connect: { id: user.id }
}
}
})
// 두번째 DB Write 종료후 로그 출력
console.log(
`username : ${_username} now Date : ${Date.now()} profile create done : ${performance.now() - start} `
)
// 세번째 DB Write
await this.prisma.userGroup.create({
data: {
userId: user.id,
groupId: 1,
isGroupLeader: false
}
})
// 세번째 DB Write 종료후 로그 출력
console.log(
`username : ${_username} now Date : ${Date.now()} all done : ${performance.now() - start} `
)
return user
}3. Prisma Schema에서 Connection 개수 조정
schema.prisma 파일에서 url로 Connection 개수를 조절할 수 있습니다.
정확히 말하자면, datasource url에 connection_limit 속성을 parameter로 넘기면 됩니다.
datasource db {
provider = "postgresql"
url = env("DATABASE_URL")
}예를들어
postgresql://postgres:1234@127.0.0.1:5433/skkuding?schema=public&connection_limit=1
처럼 하면 connection_limit의 개수를 지정할 수 있습니다.
저는 백엔드 팀장 재현이의 도움을 받아서,
pnpm cross-env DATABASE_URL="postgresql://postgres:1234@127.0.0.1:5433/skkuding?schema=public&connection_limit=1" nest start 로 env파일을 덮어 씌웠습니다.
4. K6 스크립트 준비
로컬로 검증한 것이라, BASE_URL만 유심히 보면 됩니다.
Request DTO에 필요한 것들을 미리 준비합시다.
로컬환경에서 얼만큼 많은 트래픽을 받을지 검증하는 것이 아니라, Request 처리 순서를 보는 것이기 때문에 vus는 100명으로 1초만 보내봤습니다. (100번의 동시 Request)
import { check, sleep } from 'k6'
import http from 'k6/http'
export const options = {
vus: 100,
duration: '1s'
}
const BASE_URL = 'http://localhost:4000'
const USERNAME = ""
const REALNAME = "name"
const USER_EMAIL = ""
const PASSWORD = "12345678"
export default function () {
const res2 = http.post(
BASE_URL + '/email-auth/test/local',
JSON.stringify({
username: USERNAME,
password: PASSWORD,
email: USER_EMAIL,
realName: REALNAME,
}),
{
headers: {
'Content-Type': 'application/json',
}
}
)
console.log(res2)
check(res2, { 'signup succeeded': (r) => r.status === 201 })
sleep(1)
}2. 테스트 결과
(1) Transaction 미처리의 경우
1. connection 수 1개
첫번째 DB Write의 순서가 Request(Request ID == username)별로 보장이 되지 않습니다. 즉 한가지의 Request가 들어오고 DB Write종료시 해당 Request를 계속 처리하는 것이 아니라, 다른 Request를 받아서 DB Write을 처리한다는 뜻입니다.
하나의 사진만 더 첨부하겠습니다(우연일 수도 있으니)
2. connection 수 5개
마찬가지입니다.
(2) Transaction 처리의 경우
1. connection 수 1개
첫번째 DB Write의 순서가 Request별로 보장이 되고 있습니다. 즉 첫번째 DB Write이 시작되면, 절대 해당 Connection을 다른 요청에게 양보하지 않고, 이를 그대로 사용하면서 다른 DB Write 작업을 완료할때까지 계속 사용하는 것입니다.
2. connection 수 2개
user create done 의 요청이 두개가 순차적으로 다른 Request 에서 출력되었습니다. 즉, 처음으로 Request가 도달시 Connection두개를 동시에 사용하면서 Nest가 이를 처리하고 있음을 알 수 있습니다.
3. connection 수 3개
마찬가지입니다.
4. connection 수 5개
비슷합니다. 다만 여기서는 특정 Connection에서 약간 처리가 밀린 것으로 예상됩니다.
정리
만약 Connection의 개수가 1개만 사용하는 경우, Transaction을 처리하면 하나의 Connection을 계속해서 사용해야 하기 때문에, 절대 다른 요청으로 Connection이 넘어가서는 안됩니다. 따라서 Transaction을 사용해야 Request별로 순서가 보장받는다는 사실을 알 수 있습니다.
3. 결과 분석
(1) Connection 수 2개의 상황
1. Transaction 미처리
저번 포스트에서 작성했었던 내용을 함께 가져오겠습니다.
왜 100개의 요청이 요청별 첫번째 Write을 하지 않은지 물으신다면, K6가 요청을 동시에 보낸다고는 하지만, k6 하나의 프로세스에서 보내는 요청이기에, 정확히 동시는 아니기 때문입니다. 또한 서버는 싱글 쓰레드 기반이므로, call stack의 top부터 순서대로 (다른 작업을 하고 있지 않으면) 이를 처리하기 때문이라고 생각합니다.
만일 요청이 먼저 들어와도, 다른 작업의 우선순위가 더 높거나, 해당 요청보다 나중에 들어온 요청이 call stack에 있다면, 그 요청부터 처리가 될 것입니다.
본론으로 넘어가겠습니다.
하나의 요청(username = a33d768d~) 별로, 수행시간을 살펴보면
1번 Write ~ 2번 Write 시간 차이 : 20ms
2번 Write ~ 3번 Write 시간 차이 : 39ms
입니다.
2. Transaction 처리
하나의 요청(username = 7e9c0842~) 별로, 수행시간을 살펴보면
1번 Write ~ 2번 Write 시간 차이 : 11ms
2번 Write ~ 3번 Write 시간 차이 : 4ms
입니다.
다른 요청들의 양상은 같습니다.
(2) Connection 수 5개
1. Transaction 미처리
저번 포스트에서 작성했었던 내용을 함께 가져오겠습니다.
본론으로 넘어가겠습니다.
하나의 요청(username = f245bf68~) 별로, 수행시간을 살펴보면
1번 Write ~ 2번 Write 시간 차이 : 44ms
2번 Write ~ 3번 Write 시간 차이 : 11ms
입니다.
2. Transaction 처리
하나의 요청(username = 67ab53cf~) 별로, 수행시간을 살펴보면
1번 Write ~ 2번 Write 시간 차이 : 25ms
2번 Write ~ 3번 Write 시간 차이 : 6ms
입니다.
정리
결국 처리 순서는 보장이 된다는 사실을 알 수 있습니다. 생각보다 Transaction을 처리해도 시간차이가 드라마틱하게 나진 않는 것 같습니다. 싱글 쓰레드의 어쩔 수 없는 숙명이 아닐까요..? 만일 싱글 쓰레드의 Nest 서버를 몇개를 띄워서 멀티프로세스처럼 사용하고 1개의 connection limit을 수행한다고 하면, 좀더 좋은 성능 향상이 일어나지 않을까 싶습니다.
다만 connection_limit을 1로하는 게, 더 빠른 시간을 보장받는 것 처럼 보이나,
엄연히 console.log를 찍는 작업이 call stack에서 싱글 쓰레드에 의해 이뤄지는 작업인 만큼, 쓰레드에 의해 작업이 전환 및 수행되는 시간만큼 추가적인 시간이 더 걸리므로, console log 시간에 약간의 부정확성이 있지 않을까 싶습니다.
위 사진은 Connection 5개가 트랜잭션 처리 된 상황입니다. 잘보시면, 처음 네개의 user create done이 실행되는 시간자체가 48,60,54,36으로 다소 느립니다.
그 이유는,
async testForLocal(signUpDto: SignUpDto): Promise<User> {
const start = performance.now()
const _username = randomUUID()
const _email = signUpDto.email + randomUUID()
const _password = signUpDto.password + randomUUID()
// 이후 transaction 로직트랜잭션 로직 이전에, start로 시간을 측정한 이후에, 로직이 전개되기 때문이라고 추측됩니다. 즉, 싱글 쓰레드에 의해서 각 요청의 performance.now() 가 실행된 이후에, transaction에 묶여있는 await이 실행되면서 수행시간이 다소 느려진 것 같은 결과가 나왔다고 예상합니다. 이후에 50ms가 넘어가는 user create done 로그도 마찬가지로, await로직이 처리되기 이전에 이미 싱글쓰레드에 의해서 start에 그 당시 처리 시간이 저장되었기 때문입니다.
빨간 사각형 안의 요청들은 모두, 초반에 동시에 요청이 들어오면서 최초 요청의 connection이 맺어지기 이전에 이미 싱글 쓰레드에 의해서 start 변수에 거의 비슷한 시간이 저장되었다는 것을 추측할 수 있습니다.
1개의 connection을 맺은 transaction상황에서도 이와 비슷한 현상을 발견할 수 있습니다.
4. 이후의 처리 순서는 보장이 되는 이유?
커넥션이 전환되는 시간보다, transaction이 처리하는 속도가 더 빠르기 때문이라고 추측합니다.
처리순서가 보장되는 부분들을 살펴보면 각 request별 user created된 시간들이 30ms정도 차이가납니다. 이 시간은 서비스 로직의 실행 시점부터 한번의 DB write이 발생하기 전까지인데, 이 시간에는 Connection 할당 시간 + I/O 시간이 포함되어 있습니다.
제가 원인으로 생각하는 이유는 두가지입니다.
- 커넥션을 지속적으로 사용하면서, 커넥션 할당 시간이 줄어 들었다.
- 처음의 요청들이 동시에 도착하고 이에 따라 이벤트 루프가 I/O과정으로 넘기는 과정이 다소 길었다. 하지만 그 이후부터는 차곡차곡 call stack에 요청이 쌓이면서 이벤트 루프가 I/O과정으로 넘기는 시간 자체가 줄어들었다.
어디까지나 추측..입니다
5. 마무리
write 100명에서 유의미한 성능차이는 없었어도, 미래를 대비해서 이러한 공부와 테스트는 해두는 것이 필요하다고 생각합니다. 각자 로컬에서 제가 작성한 브랜치로 테스트 가능하니, 궁금한거 있으면 물어봐주세요!
