12초 걸리던 쿼리 장애를 처음 겪고, 끝까지 파고든 기록

// 개선과는 연관없는 부분은 제외하고 꼭 필요한 부분만 남겼습니다.
await Users.aggregate([ // 유저 컬렉션에서 시작
    {
        // 특정 문자열을 가진 유저를 1차로 필터링
        $match: {
            userName: { $regex: new RegExp(`^${userName}`, 'i') } 
        }
    },
    {
      	// 내려온 도큐먼트들에 대해 "a" role 을 가진 유저만 조인
        $lookup: {
            from: 'usersDetail', // user 와 1:1 관계
            localField: '_id',
            foreignField: 'usersId',
            pipeline: [
                {
                    $match: {
                        roles: { $in: ['a'] }
                    }
                }
            ],
            as: 'usersDetail'
        }
    },
    {
      	// $lookup 결과 배열 평탄화
        $unwind: { path: '$usersDetail' }
    },
    { 
        $project: {
          	// 필요한 필드 추가 or 리네이밍 
        }
    },
    { $sort: { createdAt: -1 } } // 내림차순
]);

{
    "stages" : [
        {
            "$cursor" : {
                "executionStats" : {
                    "nReturned" : 124638.0,
                    "executionTimeMillis" : 12921.0,
                    "totalKeysExamined" : 124638.0,
                    "totalDocsExamined" : 124638.0,
                    "executionStages" : {
                        "isCached" : false, // 여러번 실행해도 캐싱이 안됨
                        // 옵티마이저 최적화로 컬렉션쪽 필드에 한해 fetch 이후 바로 projection
                        "stage" : "PROJECTION_SIMPLE",
                        "executionTimeMillisEstimate" : 555.0,
                        "inputStage" : { 
                            "stage" : "FETCH", // WiredTiger 캐시 또는 디스크에서 가져옴
                            "executionTimeMillisEstimate" : 487.0,
                            "inputStage" : {
                                // 정규식에 의해 전체 도큐먼트가 선택되므로 사실상 풀스캔과 다를바가 없습니다.
                                "stage" : "IXSCAN", // 인덱스 스캔
                                "filter" : {
                                    "userName" : { "$regex" : "^", "$options" : "i" }
                                },
                                "executionTimeMillisEstimate" : 232.0,
                                "indexName" : "userName_1",
                                "direction" : "forward"
                            }
                        }
                    }
                }
            },
            "nReturned" : 124638,
            "executionTimeMillisEstimate" : 569
        },
        {
            "$lookup" : { },
            "totalDocsExamined" : 26,
            "totalKeysExamined" : 26,
            "collectionScans" : 0,
            "indexesUsed" : [
                "usersId_1_roles_1"
            ],
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 12921 // 문제의 부분
        },
        {
            "$project" : { },
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 12921
        },
        {
            "$sort" : { },
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 12921
        }
    ],
}

        {
            "$lookup" : { },
            "totalDocsExamined" : 26,
            "totalKeysExamined" : 26,
            "collectionScans" : 0,
            "indexesUsed" : [
                "usersId_1_roles_1"
            ],
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 12921
        },

let testQueryExecutorStatsWithIndexScan = function() {
	createIndexForCollection(fromColl, "foreignField");

    let output = doAggregationLookup(localColl, fromColl, {allowDiskUse: false});

    let expectedOutput = [
        {_id: 0, localField: 0, output: [{_id: 0, foreignField: 0}]},
        {_id: 1, localField: 1, output: [{_id: 1, foreignField: 1}]}
    ];

    assert.eq(output, expectedOutput);

    let [curScannedObjects, curScannedKeys] = getCurrentQueryExecutorStats();

    // 인덱스 스캔의 경우, 총 scannedObjects는
    // (로컬 컬렉션의 전체 도큐먼트 수 + 외부 컬렉션에서 매칭된 도큐먼트 수)의 합이어야 한다
    assert.eq(localDocCount + localDocCount, curScannedObjects);

    // 외부 컬렉션에서 스캔된 키 수는 로컬 컬렉션의 도큐먼트 수와 동일해야 한다
    assert.eq(localDocCount, curScannedKeys);

    if (isSBELookupEnabled) {
        checkExplainOutputForAllVerbosityLevels(
            localColl,
            fromColl, 
            {
                // SBE lookup이 활성화된 경우, 실행 통계에서 모든 스캔 객체를 캡처할 수 있다
                // 따라서 totalDocsExamined는
                // (로컬 컬렉션의 전체 도큐먼트 수 + 외부 컬렉션에서 매칭된 도큐먼트 수)와 동일해야 한다
                totalDocsExamined: 2 + 2,
                // 로컬 컬렉션의 각 도큐먼트마다 인덱스 seek이 한번씩 수행되고,
                // seek당 키 하나가 검사된다 = 2
                totalKeysExamined: 2,
                // 로컬 컬렉션이 스캔된 횟수 = 1
                collectionScans: 1,
                // 인덱스 스캔 단계에서 검사된 키마다 외부 컬렉션에 대한 seek이 수행되어
                // 해당 도큐먼트를 가져온다 = 2
                collectionSeeks: 2,
                indexScans: 0,
                // 로컬 컬렉션의 각 도큐먼트마다 인덱스 seek이 한번씩 수행된다 = 2.
                indexSeeks: 2,
                indexesUsed: ["foreignField_1"]
			},
            {allowDiskUse: false},
            {strategy: "IndexedLoopJoin", indexName: "foreignField_1"});
    } else {
        checkExplainOutputForAllVerbosityLevels(localColl,
            fromColl, 
            {
                totalDocsExamined: 2,
                totalKeysExamined: 2,
                collectionScans: 0,
                indexesUsed: ["foreignField_1"]
            }, 
            {allowDiskUse: false}
        );
    }
};

// 개선과는 연관없는 부분은 제외하고 꼭 필요한 부분만 남겼습니다.
await UsersDetail.aggregate([ // UsersDetail 에서 시작
    {
        // "a" role 을 가진 유저만 필터링(현재 26건)
        $match: {
            roles: { $in: ['a'] }
        }
    },
    {
        // 앞서 필터링된 26건 각각에 대해서만 users 컬렉션과 조인
        $lookup: {
            from: 'users', // UsersDetail 과 1:1 관계
            localField: 'usersId',
            foreignField: '_id',
            pipeline: userName ? [
                // 검색어가 있을 때만 정규식 필터를 추가
                {
                    $match: {
                        userName: { $regex: new RegExp(`^${username}`, 'i') }
                    }
                }
            ] : [],
            as: 'users'
        }
    },
    {
        // $lookup 결과 배열 평탄화
        $unwind: { path: '$users' }
    },
    {
        $project: {
            // 필요한 필드 추가 or 리네이밍
        }
    },
    // 두 컬렉션간의 `createdAt` 은 앱 수준에서 동일한 시간을 보장
    { $sort: { createdAt: -1 } } // 내림차순
]);

db.usersDetail.createIndex({ roles: 1, createdAt: -1 });

{
    "stages" : [
        {
            "$cursor" : {
                "executionStats" : {
                    "nReturned" : 26.0,
                    "executionTimeMillis" : 2.0,
                    "totalKeysExamined" : 26.0,
                    "totalDocsExamined" : 26.0,
                    "executionStages" : {
                        "isCached" : true,
                        "stage" : "PROJECTION_SIMPLE",
                        "executionTimeMillisEstimate" : 0.0,
                        "inputStage" : {
                            "stage" : "FETCH",
                            "executionTimeMillisEstimate" : 0.0,
                            "inputStage" : {
                                "stage" : "IXSCAN",
                                "executionTimeMillisEstimate" : 0.0,
                                "indexName" : "roles_1",
                                "direction" : "forward",
                            }
                        }
                    }
                }
            },
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 0
        },
        {
            "$lookup" : { },
            "totalDocsExamined" : 26,
            "totalKeysExamined" : 26,
            "collectionScans" : 0,
            "indexesUsed" : [
                "_id_"
            ],
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 2
        },
        {
            "$project" : { },
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 2
        },
        {
            "$sort" : { },
            "nReturned" : 26,
            "executionTimeMillisEstimate" : 2
        }
    ]
}