2주 챌린지 - 9. 1인 더미데이터

yy·2023년 11월 28일

개발일지

목록 보기

50/122

지금까지...

더미데이터에 20명 이상의 유저를 만들어서 실험을 해봤는데 돈과 표의 수량이 넉넉함에도 불구하고 구매를 하지않는다거나 구매했던 유저가 다시 구매하여 credit이 부족하다는 에러가 났다. 그 에러를 redis와 bull queue를 이용해서 잡아보려고 하던 중 최종적으로 서버에서 부하테스트를 해야하기때문에 로드밸런서, nginx의 서버 문제로 해결해보려던 중이었다.
서버 문제를 해결하던 중 연결은 되었으나 하위 파일들을 읽어오지 못하는 이슈가 발생하여 프론트를 수정하는 방향으로 가보려고 했으나 시간이 부족하여 로드밸런서, nginx를 포기하고 EC2 서버에 부하테스트를 하는걸로 계획을 수정하였다.
그러다 애초에 동시성 제어가 되지않았던 이유에 대해서 다시 생각해보았다. 애초에 많은 인원을 했을때에도 적정수량을 넣었을때에도(100장을 100명이 사는 테스트)에도 동시성이 지켜지지않았음은 transaction의 문제인가. 아니면 코드가 원초적으로 문제가 있었던건 아닐까라는 생각에 다시 확인하기로 했다.

알틸러리 테스트 중 400번 상태코드 다수 발견이 되었는데 코드 에러 의심 -> 알틸러리 csv 데이터 가져오는 방식에 의문 발생했다.
순차적으로 테스트를 진행할 것이라고 예상했으나 랜덤이었음을 확인했는데 그러나 재차 테스트를 통해 이것도 확인할 필요가 있었음.
10명의 유저 데이터로 10회의 티켓팅을 시도하여 순차적으로 csv 데이터를 불러오고 있다면 1인당 1매씩 티켓팅이 이뤄질것임을 예상. 하지만 특정유저 3회, 다른 유저는 0회 구매한 것으로 확인되었음. 그 후 알틸러리가 랜덤으로 데이터를 뽑아와 사용한다는 가정을 확신하게 되었고,
1명의 유저로 진행함. 계속 발생한 400번 상태코드가 어떤 원인인지 찾아내는 과정이
시간낭비였기에 200번으로 통일하기 위함.

이제부터...

1. 1인 더미데이터 duration 10 arraivalRate 20 : 성공 200 완 100%

2. 1인 더미데이터 duration 50 arraivalRate 20 : 성공 1000 완 100%

3. 1인 더미데이터 duration 500 arraivalRate 200 : 성공 0.2% / 실패 59.6%/ 기타에러 40.2%

All VUs finished. Total time: 8 minutes, 31 seconds
--------------------------------
Summary report @ 11:30:43(+0900)
--------------------------------
errors.EADDRINUSE: ............................................................. 23058
errors.ECONNREFUSED: ........................................................... 13974
errors.ETIMEDOUT: .............................................................. 3143
http.codes.200: ................................................................ 221
http.codes.400: ................................................................ 59604
http.downloaded_bytes: ......................................................... 5125387
http.request_rate: ............................................................. 200/sec
http.requests: ................................................................. 100000
http.response_time:
  min: ......................................................................... 16
  max: ......................................................................... 9997
  mean: ........................................................................ 6170.3
  median: ...................................................................... 6312.2
  p95: ......................................................................... 7865.6
  p99: ......................................................................... 8520.7
http.responses: ................................................................ 59825
vusers.completed: .............................................................. 59825
vusers.created: ................................................................ 100000
vusers.created_by_name.예매: ..................................................... 100000
vusers.failed: ................................................................. 40175
vusers.session_length:
  min: ......................................................................... 20.6
  max: ......................................................................... 10005.1
  mean: ........................................................................ 6187.3
  median: ...................................................................... 6439.7
  p95: ......................................................................... 7865.6
  p99: ......................................................................... 8692.8
Log file: report.json
Done in 515.92s.

Transaction API error: Transaction already closed: A query cannot be executed on an expired transaction. The timeout for this transaction was 5000 ms, however 5433 ms passed since the start of the transaction. Consider increasing the interactive transaction timeout or doing less work in the transaction.
    at ni.handleRequestError (C:\2week\node_modules\@prisma\client\runtime\library.js:124:6817)
    at ni.handleAndLogRequestError (C:\2week\node_modules\@prisma\client\runtime\library.js:124:6206)
    at ni.request (C:\2week\node_modules\@prisma\client\runtime\library.js:124:5926)
    at async l (C:\2week\node_modules\@prisma\client\runtime\library.js:129:10023)

=> 트랜잭션 에러가 떴다. 트랜잭션은 기본적으로 5000ms의 시간을 갖고있는데 그 시간을 초과해버려서 발생한 오류였다. 그래서 기본 트랜잭션 시간(5000ms)을 변경하도록 했다.

{
	isolationLevel: Prisma.TransactionIsolationLevel.RepeatableRead, timeout: 20000
},

4. 1인 더미데이터 duration 100 arraivalRate 100 : 중단 (에러발생)

catch로 빠진 PrismaClientKnownRequestError: Transaction API error: Unable to start a transaction in the given time.
PrismaClientKnownRequestError: Transaction API error: Unable to start a transaction in the given time.
    at Wt.transaction (C:\2week\node_modules\@prisma\client\runtime\library.js:114:19314)
    at async Proxy._transactionWithCallback (C:\2week\node_modules\@prisma\client\runtime\library.js:129:8610)
    at async file:///C:/2week/src/routes/reservation.router.js:105:19 {
  code: 'P2028',
  clientVersion: '5.6.0',
  meta: { error: 'Unable to start a transaction in the given time.' }

5. 1인 더미데이터 duration 200 arraivalRate 50 : 성공 10000 / 실패 0

//초당 보내는 양을 줄이니 commit수가 많이 늘어남
//동시성 제어가 안돈다고 생각했던게 알틸러리의 문제가 아니었을까 하는 생각이 듬

---- duration 200 / arrivalRate : 50 ----
http.codes.200: ................................................................ 10000
http.downloaded_bytes: ......................................................... 530000
http.request_rate: ............................................................. 50/sec
http.requests: ................................................................. 10000
http.response_time:
  min: ......................................................................... 8
  max: ......................................................................... 69
  mean: ........................................................................ 16.8
  median: ...................................................................... 16
  p95: ......................................................................... 26.8
  p99: ......................................................................... 37.7
http.responses: ................................................................ 10000
vusers.completed: .............................................................. 10000
vusers.created: ................................................................ 10000
vusers.created_by_name.예매: ..................................................... 10000
vusers.failed: ................................................................. 0
vusers.session_length:
  min: ......................................................................... 9.9
  max: ......................................................................... 71.5
  mean: ........................................................................ 19.5
  median: ...................................................................... 18
  p95: ......................................................................... 29.7
  p99: ......................................................................... 40.9
Log file: report.json
Done in 207.56s.

6. 1인 더미데이터 duration 100 arraivalRate 50 :

All VUs finished. Total time: 1 minute, 47 seconds

--------------------------------
Summary report @ 14:27:47(+0900)
--------------------------------

errors.ETIMEDOUT: .............................................................. 258
http.codes.200: ................................................................ 100
http.codes.400: ................................................................ 4642
http.downloaded_bytes: ......................................................... 398309        
http.request_rate: ............................................................. 44/sec        
http.requests: ................................................................. 5000
http.response_time:
  min: ......................................................................... 15
  max: ......................................................................... 7718
  mean: ........................................................................ 5043.6        
  median: ...................................................................... 5168
  p95: ......................................................................... 6976.1        
  p99: ......................................................................... 7117
http.responses: ................................................................ 4742
vusers.completed: .............................................................. 4742
vusers.created: ................................................................ 5000
vusers.created_by_name.예매: ..................................................... 5000        
vusers.failed: ................................................................. 258
vusers.session_length:
  min: ......................................................................... 18.7
  max: ......................................................................... 7720.9        
  mean: ........................................................................ 5046.7        
  median: ...................................................................... 5168
  p95: ......................................................................... 6976.1        
  p99: ......................................................................... 7117
Log file: report.json

발생에러

catch로 빠진 PrismaClientKnownRequestError: Transaction API error: Unable to start a transaction in the given time.
PrismaClientKnownRequestError: Transaction API error: Unable to start a transaction in the given time.
    at Wt.transaction (C:\Users\82107\Desktop\nodeClass\challenge\2weekProject\node_modules\@prisma\client\runtime\library.js:114:19314)
    at async Proxy._transactionWithCallback (C:\Users\82107\Desktop\nodeClass\challenge\2weekProject\node_modules\@prisma\client\runtime\library.js:129:8610)
    at async file:///C:/Users/82107/Desktop/nodeClass/challenge/2weekProject/src/routes/reservation.router.js:76:19 {
  code: 'P2028',
  clientVersion: '5.6.0',
  meta: { error: 'Unable to start a transaction in the given time.' }
}

100장의 예매는 완료되었으나 트랜잭션의 주어신 시간안에 트랜잭션이 시작을 못하는 이슈 발견.
Interactive 트랜잭션의 timeout 이슈 발견.

실행했더니 확실히 성공 확률이 늘었다. : 성공 68.2% / 실패 29.7% / 기타에러 2.0%

All VUs finished. Total time: 1 minute, 51 seconds

--------------------------------
Summary report @ 16:31:02(+0900)
--------------------------------

errors.ETIMEDOUT: .............................................................. 102
http.codes.200: ................................................................ 3412
http.codes.400: ................................................................ 1486
http.downloaded_bytes: ......................................................... 307790
http.request_rate: ............................................................. 50/sec
http.requests: ................................................................. 5000
http.response_time:
  min: ......................................................................... 10
  max: ......................................................................... 7488
  mean: ........................................................................ 1569.5
  median: ...................................................................... 32.1
  p95: ......................................................................... 6569.8
  p99: ......................................................................... 7117
http.responses: ................................................................ 4898
vusers.completed: .............................................................. 4898
vusers.created: ................................................................ 5000
vusers.created_by_name.예매: ..................................................... 5000
vusers.failed: ................................................................. 102
vusers.session_length:
  min: ......................................................................... 12.9
  max: ......................................................................... 7490.3
  mean: ........................................................................ 1572.7
  median: ...................................................................... 35.5
  p95: ......................................................................... 6569.8
  p99: ......................................................................... 7117
Log file: report.json

router.post('/reservation/:showId', authMiddleware, async (req, res, next) => {
  let transaction;
  try {
    const { showId } = req.params;
    const { userId } = req.user;

    transaction = await prisma.$transaction(
      async (tx) => {
        const user = await tx.users.findFirst({
          where: { userId: +userId },
        });

        if (!user) {
          throw new Error('유저 정보를 찾을 수 없습니다.');
        }

        await tx.$queryRaw`SELECT * FROM Shows FOR UPDATE;`;

        let updatedShow = await prisma.shows.findFirst({
          where: { showId: +showId },
        });

        if (user.credit < updatedShow.price || user.credit === 0) {
          console.log(`${userId} : credit부족`);
          throw new Error('credit이 부족합니다.');
        }
        await tx.$executeRaw`UPDATE Users SET credit = credit - ${updatedShow.price} WHERE userId=${userId};`;

        if (updatedShow.quantity <= 0) {
          console.log(`${userId} : 예매수량부족`);
          throw new Error('예매 수량이 부족합니다.');
        }

        await tx.$executeRaw`UPDATE Shows SET quantity = quantity-1 WHERE showId=${showId};`;

        await tx.$executeRaw`INSERT INTO Reservation(UserId, ShowId) VALUES (${user.userId}, ${showId});`;
      },
      {
        isolationLevel: Prisma.TransactionIsolationLevel.RepeatableRead,
        timeout: 2000,
      },
    );
    return res.status(200).json({ message: '좌석 예매가 완료되었습니다.' });
  } catch (error) {
    console.log(`catch로 빠진 ${error}`);
    next(error);
    // if (transaction) {
    //   await prisma.$executeRaw`ROLLBACK`;
    // }
  }
});

duration 500, arrivalRate 100, timeout 6000ms

All VUs finished. Total time: 8 minutes, 28 seconds

--------------------------------
Summary report @ 18:58:30(+0900)
--------------------------------

errors.ECONNREFUSED: ........................................................... 2908        
errors.ETIMEDOUT: .............................................................. 3113        
http.codes.200: ................................................................ 10
http.codes.400: ................................................................ 43969       
http.downloaded_bytes: ......................................................... 3994137     
http.request_rate: ............................................................. 100/sec     
http.requests: ................................................................. 50000       
http.response_time:
  min: ......................................................................... 116
  max: ......................................................................... 10280       
  mean: ........................................................................ 6552.1      
  median: ...................................................................... 6439.7      
  p95: ......................................................................... 8692.8      
  p99: ......................................................................... 9607.1      
http.responses: ................................................................ 43979       
vusers.completed: .............................................................. 43979       
vusers.created: ................................................................ 50000       
vusers.created_by_name.예매: ..................................................... 50000     
vusers.failed: ................................................................. 6021        
vusers.session_length:
  min: ......................................................................... 147.1       
  max: ......................................................................... 10283.7     
  mean: ........................................................................ 6564.1      
  median: ...................................................................... 6439.7      
  p95: ......................................................................... 8692.8      
  p99: ......................................................................... 9607.1      
Log file: report.json

에러 이유

errors.ECONNREFUSED: 서버가 요청을 처리할 수 있는 상태가 아니거나 부하가 매우 큰 경우에도 연결이 거부될 수 있다고함.
errors.ETIMEDOUT:

Transaction API error: Transaction already closed: A query cannot be executed on an expired transaction. The timeout for this transaction was 2000 ms, however 2017 ms passed since the start of the transaction. Consider increasing the interactive transaction timeout or doing less work in the transaction.

http.codes.400: PrismaClientKnownRequestError

자꾸 트랜잭션의 시간 초과 에러가 발생한다. 시간을 줄여보고 늘리기도 했으나 완전히 해결되진않는다. 그럼 다른 방법을 찾아야겠다.

1). 트랜잭션에서 수행되는 작업 감소

chatGPT한테 문제점을 말하고 해결방안에 대해서 물어보니 이렇게 답변을 줬다.
트랜잭션 내에서 수행되는 작업을 최소화하거나 최적화하여 트랜잭션이 더 빨리 완료되도록 할 수 있으며 이는 데이터베이스 쿼리를 최적화하거나 트랜잭션 범위를 줄이는 등의 방법

1) 조회되는 정보만 나오도록 쿼리 최적화
![](https://velog.velcdn.com/images/dbsdud143/post/bf47c121-5e0d-4ac5-97de-af6013532276/image.png)
단순히 불러지는 쿼리만 비교해보면 이렇게 짧아질수있다.
2) 로우쿼리로 변경 -> 이미 진행함

duration 100, arrivalRate 100 timeout: 2000ms

쿼리 최적화 전

--------------------------------
Summary report @ 21:04:10(+0900)
--------------------------------

errors.ECONNREFUSED: ........................................................... 440
errors.ETIMEDOUT: .............................................................. 801
http.codes.200: ................................................................ 20
http.codes.400: ................................................................ 8739
http.downloaded_bytes: ......................................................... 798573       
http.request_rate: ............................................................. 100/sec      
http.requests: ................................................................. 10000        
http.response_time:
  min: ......................................................................... 54
  max: ......................................................................... 10011        
  mean: ........................................................................ 6627.4       
  median: ...................................................................... 6569.8       
  p95: ......................................................................... 8868.4       
  p99: ......................................................................... 9607.1       
http.responses: ................................................................ 8759
vusers.completed: .............................................................. 8759
vusers.created: ................................................................ 10000        
vusers.created_by_name.예매: ..................................................... 10000      
vusers.failed: ................................................................. 1241
vusers.session_length:
  min: ......................................................................... 80.1
  max: ......................................................................... 10014.8      
  mean: ........................................................................ 6631.9       
  median: ...................................................................... 6569.8       
  p95: ......................................................................... 8868.4       
  p99: ......................................................................... 9607.1       
Log file: report.json

쿼리 최적화 후
duration 100, arrivalRate 100 timeout: 2000ms

All VUs finished. Total time: 1 minute, 48 seconds

--------------------------------
Summary report @ 21:08:32(+0900)
--------------------------------

errors.ETIMEDOUT: .............................................................. 571
http.codes.200: ................................................................ 13
http.codes.400: ................................................................ 9416
http.downloaded_bytes: ......................................................... 834525       
http.request_rate: ............................................................. 89/sec       
http.requests: ................................................................. 10000        
http.response_time:
  min: ......................................................................... 52
  max: ......................................................................... 9991
  mean: ........................................................................ 5774.9       
  median: ...................................................................... 5826.9       
  p95: ......................................................................... 6976.1       
  p99: ......................................................................... 8024.5       
http.responses: ................................................................ 9429
vusers.completed: .............................................................. 9429
vusers.created: ................................................................ 10000        
vusers.created_by_name.예매: ..................................................... 10000      
vusers.failed: ................................................................. 571
vusers.session_length:
  min: ......................................................................... 76.7
  max: ......................................................................... 9993.9       
  mean: ........................................................................ 5778.3       
  median: ...................................................................... 5826.9       
  p95: ......................................................................... 6976.1       
  p99: ......................................................................... 8024.5       
Log file: report.json

=> ETIMEDOUT (801 -> 571) 감소 / 응답시간 (6569.8 -> 5826.9) 감소

2) 예외 처리 추가: 쿼리 최적화 후 에러를 예외처리

duration 100, arrivalRate 100 timeout: 2000ms

} catch (error) {
    console.log(`catch로 빠진 ${error}`);
    if (
      error instanceof PrismaClientKnownRequestError &&
      error.code === 'P2028'
    ) {
      console.error('PrismaClientKnownRequestError, P2028 에러발생');
    }
    next(error);
  }

All VUs finished. Total time: 1 minute, 51 seconds

--------------------------------
Summary report @ 08:01:03(+0900)
--------------------------------

errors.ECONNREFUSED: ........................................................... 53
errors.ETIMEDOUT: .............................................................. 9934
http.codes.200: ................................................................ 13
http.downloaded_bytes: ......................................................... 689
http.request_rate: ............................................................. 89/sec       
http.requests: ................................................................. 10000        
http.response_time:
  min: ......................................................................... 118
  max: ......................................................................... 7015
  mean: ........................................................................ 4293.4       
  median: ...................................................................... 6064.7       
  p95: ......................................................................... 6187.2       
  p99: ......................................................................... 6187.2       
http.responses: ................................................................ 13
vusers.completed: .............................................................. 13
vusers.created: ................................................................ 10000        
vusers.created_by_name.예매: ..................................................... 10000      
vusers.failed: ................................................................. 9987
vusers.session_length:
  min: ......................................................................... 149.9        
  max: ......................................................................... 7022.7       
  mean: ........................................................................ 4306.4       
  median: ...................................................................... 6064.7       
  p95: ......................................................................... 6187.2       
  p99: ......................................................................... 6187.2       
Log file: report.json

=> errors.ECONNREFUSED, errors.ETIMEDOUT, http.codes.200를 제외하고 감소 추세.

아니 이거는 대체 어떻게 나온거냐고 진짜 화나네 사람 허언증 만들고마네

--------------------------------
Summary report @ 21:20:07(+0900)
--------------------------------

errors.ECONNREFUSED: ........................................................... 99
errors.ETIMEDOUT: .............................................................. 9892
http.codes.200: ................................................................ 9
http.downloaded_bytes: ......................................................... 477
http.request_rate: ............................................................. 89/sec       
http.requests: ................................................................. 10000        
http.response_time:
  min: ......................................................................... 55
  max: ......................................................................... 252
  mean: ........................................................................ 175.8        
  median: ...................................................................... 165.7        
  p95: ......................................................................... 232.8        
  p99: ......................................................................... 232.8        
http.responses: ................................................................ 9
vusers.completed: .............................................................. 9
vusers.created: ................................................................ 10000        
vusers.created_by_name.예매: ..................................................... 10000      
vusers.failed: ................................................................. 9991
vusers.session_length:
  min: ......................................................................... 82.4
  max: ......................................................................... 274.1        
  mean: ........................................................................ 196.2        
  median: ...................................................................... 183.1        
  p95: ......................................................................... 257.3        
  p99: ......................................................................... 257.3        
Log file: report.json

시간이 걸릴 뿐 내가 못할 건 없다.

이전 포스트

2주 챌린지 - 8. 동시성 제어 : bull, redis

다음 포스트