command line으로 손쉽게 test data를 삽입, 삭제하기 위해 TestingModule로 test server를 띄워 typeorm을 사용해 test data를 삽입, 삭제하는 script를 작성했다.
하지만 test data를 삽입할 때 data 크기가 그렇게 크지 않음에도 생각보다 시간이 너무 오래 걸리는 문제가 있었다. 고작 100명의 사용자를 생성하도록 script를 실행시켰을 때 random하게 생성된 총 14452개의 data를 삽입하는데에 12초 가까이 걸린 것을 확인할 수 있다.
**$ MYSQL_DATABASE=performance DATA_SIZE=100 npm run test:response-time**
> [email protected] test:response-time
> cross-env NODE_ENV=test ts-node ./test/performance/response-time.ts
Test server running at <http://localhost:3333>
Connected database: performance
Successfully inserted test data (**+11900ms**):
┌─────────┬─────────────────┬───────┐
│ (index) │ Entity │ Count │
├─────────┼─────────────────┼───────┤
│ 0 │ 'Users' │ 100 │
│ 1 │ 'Dogs' │ 245 │
│ 2 │ 'UserDogs' │ 245 │
│ 3 │ 'Journals' │ 2109 │
│ 4 │ 'JournalsDogs' │ 4295 │
│ 5 │ 'JournalPhotos' │ 3163 │
│ 6 │ 'Excrements' │ 4295 │
└─────────┴─────────────────┴───────┘
Total data size: **14452**
Cleared all test data
Query를 직접 실행시키는 것이 아니라 orm을 사용하기 때문에 불필요한 query가 발생하거나 내가 의도한 대로 query가 실행되지 않았을 가능성이 크다고 생각이 되어 query log를 확인해보았다.
query log를 확인해보니 bulk insert를 했음에도 각각의 query가 하나씩 분리되어 실행되고 INSERT 후 SELECT가 실행되는 문제가 있었다.
[2024-06-27T15:00:49.403Z][QUERY]: INSERT INTO `users`(`id`, `nickname`, `email`, `profile_image_url`, `role`, `main_dog_id`, `oauth_id`, `oauth_access_token`, `oauth_refresh_token`, `refresh_token`, `createdAt`) VALUES (DEFAULT, ?, ?, ?, ?, ?, ?, ?, ?, ?, DEFAULT) -- PARAMETERS: ["test-user1#421e871c-db10-42ab-bc84-0a7be46c052b","[email protected]","default/profile.png","USER",null,"1","oauth_access_token","oauth_refresh_token","eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJvYXV0aElkIjoiMTIzNDUiLCJwcm92aWRlciI6Imtha2FvIiwiaWF0IjoxNzE3NjAwNzIzLCJleHAiOjQ4NzMzNjA3MjN9.4FVH0-mkQ_qf4J0lmdu9lBrTrOYNk13fy7TJSjyyPV4"]
[2024-06-27T15:00:49.409Z][QUERY]: SELECT `Users`.`id` AS `Users_id`, `Users`.`role` AS `Users_role`, `Users`.`createdAt` AS `Users_createdAt` FROM `users` `Users` WHERE `Users`.`id` = ? -- PARAMETERS: [1]
[2024-06-27T15:00:49.412Z][QUERY]: INSERT INTO `users`(`id`, `nickname`, `email`, `profile_image_url`, `role`, `main_dog_id`, `oauth_id`, `oauth_access_token`, `oauth_refresh_token`, `refresh_token`, `createdAt`) VALUES (DEFAULT, ?, ?, ?, ?, ?, ?, ?, ?, ?, DEFAULT) -- PARAMETERS: ["test-user2#e1a2ed2f-0b44-41c6-940d-dd7b535ceddd","[email protected]","default/profile.png","USER",null,"2","oauth_access_token","oauth_refresh_token","eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJvYXV0aElkIjoiMTIzNDUiLCJwcm92aWRlciI6Imtha2FvIiwiaWF0IjoxNzE3NjAwNzIzLCJleHAiOjQ4NzMzNjA3MjN9.4FVH0-mkQ_qf4J0lmdu9lBrTrOYNk13fy7TJSjyyPV4"]
[2024-06-27T15:00:49.413Z][QUERY]: SELECT `Users`.`id` AS `Users_id`, `Users`.`role` AS `Users_role`, `Users`.`createdAt` AS `Users_createdAt` FROM `users` `Users` WHERE `Users`.`id` = ? -- PARAMETERS: [2]
⁝
다른 entity들도 마찬가지
이 문제가 발생하는 원인은 test data 삽입 시 save라는 method를 사용했기 때문이다. save는 기본적으로 삽입 후 삽입한 entity 반환하기 때문에 entity array를 넘겼음에도 query가 하나씩 실행되고 SELECT로 삽입한 entity까지 조회해 반환했던 것이다.
save에 { reload: false } option을 사용해 SELECT를 비활성화 할 수는 있었지만 여전히 INSERT가 하나씩 분리되어 실행되는 것을 확인했다. save에 배열을 넘길 수 있어서 bulk insert가 가능할 것이라 생각했었는데 설명을 보면 database에 entity가 존재하지 않을 때는 insert, 존재하면 update를 한다고 설명이 되어 있는 것으로 entity 존재 여부 확인이 필요하므로 bulk insert가 근본적으로 되지 않는 것 같다.
Saves all given entities in the database. If entities do not exist in the database then inserts, otherwise updates.
그래서 save 대신 insert를 사용해보았으나, Users와 Dogs entity는 여전히 INSERT 후 SELECT가 실행되었다. entity 정의 시 cascade: true option을 사용했기 때문인 것으로 추측되며 https://github.com/typeorm/typeorm/issues/2870를 참고해 queryBuilder에 updateEntity(false)를 추가해서 해결했다.
이제 깔끔하게 필요한 query만 실행되는 것을 확인할 수 있다.
[2024-06-27T15:38:20.726Z][QUERY]: SET GLOBAL FOREIGN_KEY_CHECKS = 0;
[2024-06-27T15:38:20.739Z][QUERY]: INSERT INTO `users`(`id`, `nickname`, …
[2024-06-27T15:38:20.750Z][QUERY]: INSERT INTO `dogs`(`id`, `walk_day_id`, …
[2024-06-27T15:38:20.807Z][QUERY]: INSERT INTO `users_dogs`(`user_id`, …
[2024-06-27T15:38:20.814Z][QUERY]: INSERT INTO `dog_walk_day`(`id`, `mon`, …
[2024-06-27T15:38:20.820Z][QUERY]: INSERT INTO `today_walk_time`(`id`, …
[2024-06-27T15:38:20.827Z][QUERY]: SELECT `usersDogs`.`user_id` AS `userId`, …
[2024-06-27T15:38:20.878Z][QUERY]: INSERT INTO `journals`(`id`, `user_id`, …
[2024-06-27T15:38:21.027Z][QUERY]: INSERT INTO `journals_dogs`(`journal_id`, …
[2024-06-27T15:38:21.163Z][QUERY]: INSERT INTO `journal_photos`(`id`, …
[2024-06-27T15:38:21.266Z][QUERY]: INSERT INTO `excrements`(`id`, …
[2024-06-27T15:38:21.436Z][QUERY]: SET GLOBAL FOREIGN_KEY_CHECKS = 1;
얼마나 개선되었는지도 측정하여 수치화하였다.
표의 순서대로 작업을 적용한 후 다음 명령어로 측정했다.
MYSQL_DATABASE=performance DATA_SIZE=100 npm run test:response-time