[SERVER-47597] executionTimeMillisEstimate seems incorrect for some stages Created: 16/Apr/20  Updated: 27/Oct/23  Resolved: 28/Jul/20

Status: Closed
Project: Core Server
Component/s: Aggregation Framework
Affects Version/s: 4.4.0-rc1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Asya Kamsky Assignee: Asya Kamsky
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

In SERVER-21784 we added to each stage more details in explain output.

However, after first stage, every stage seems to show exact same value which is the total time execution of the entire pipeline which seems like a bug.

              {  "$cursor": {
                       ...
                        },
                        "nReturned" : NumberLong(500000),
                        "executionTimeMillisEstimate" : NumberLong(269)
                },
                {
                        "$lookup" : {
                                ...
                        },
                        "nReturned" : NumberLong(500000),
                        "executionTimeMillisEstimate" : NumberLong(16337)
                },
                {
                        "$group" : {
                              ...
                        },
                        "nReturned" : NumberLong(4000),
                        "executionTimeMillisEstimate" : NumberLong(16337)
                },
                {
                        "$group" : {
                             ...
                        },
                        "nReturned" : NumberLong(1),
                        "executionTimeMillisEstimate" : NumberLong(16337)
                },
                {
                        "$project" : {
                               ...
                        },
                        "nReturned" : NumberLong(1),
                        "executionTimeMillisEstimate" : NumberLong(16337)
                }
        ],

FYI the explain actually took 16339 ms to run...



 Comments   
Comment by Asya Kamsky [ 28/Jul/20 ]

I haven't been able to reproduce this so closing as gone away.

Comment by Asya Kamsky [ 16/Apr/20 ]

It seems this only happens when the first post $cursor stage takes a really long time, or maybe only when it's $lookup?

I see normal and expected values for other stages:

              {
                   "$cursor": {
                        },
                        "nReturned" : NumberLong(5000000),
                        "executionTimeMillisEstimate" : NumberLong(1356)
                },
                {
                        "$project" : {
                                "_id" : false
                        },
                        "nReturned" : NumberLong(5000000),
                        "executionTimeMillisEstimate" : NumberLong(1552)
                },
                {
                        "$group" : {
                                "_id" : {
                                        "$const" : null
                                },
                                "c" : {
                                        "$sum" : {
                                                "$const" : 1
                                        }
                                }
                        },
                        "nReturned" : NumberLong(1),
                        "executionTimeMillisEstimate" : NumberLong(1810)
                },
                {
                        "$project" : {
                                "c" : true,
                                "_id" : false
                        },
                        "nReturned" : NumberLong(1),
                        "executionTimeMillisEstimate" : NumberLong(1810)
                }

Generated at Thu Feb 08 05:14:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.