[SERVER-46391] Increased task runtime after hygienic is enabled Created: 25/Feb/20  Updated: 27/Oct/23  Resolved: 07/Apr/20

Status: Closed
Project: Core Server
Component/s: Build
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Robert Guo (Inactive) Assignee: Andrew Morrow (Inactive)
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screen Shot 2020-02-25 at 12.45.26 PM.png    
Operating System: ALL
Sprint: Dev Platform 2020-04-20
Participants:

 Description   

There seems to be a ~10sec increase in runtime for each task after hygienic is enabled. This is most pronounced on shorter tasks but is more or less consistent across all tasks.

See example in attached screenshot.



 Comments   
Comment by Robert Guo (Inactive) [ 07/Apr/20 ]

Sounds good. Thank you for the analysis!

Comment by Andrew Morrow (Inactive) [ 06/Apr/20 ]

Here is a commit from the good side of the change; total test time was 01:23:

And here is a commit from the "bad" side of the change; total test time was 01:55:

These are different by about 32 seconds, but there is a lot of noise overall, so much so that the good runs of the bad regime are about the same as the bad runs of the good regime. So it is hard to attribute to any one cause.

However, if you look, you can see that the slow case spent about 10 more seconds downloading debug symbols:

  • Good took 48 seconds:

    [2020/02/10 11:44:39.553] fetching mongodb-mongo-master/enterprise-rhel-62-64-bit/6017618f1ab32ea2b2fc1ce7332806ebce2d2fad/debugsymbols/debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_6017618f1ab32ea2b2fc1ce7332806ebce2d2fad_20_02_10_16_03_40.tgz from s3 bucket mciuploads (attempt 1 of 10)
    [2020/02/10 11:45:27.394] Running command 'shell.exec' in "do setup" (step 1.5 of 2)
    

  • Bad took 61 seconds:

    [2020/02/18 16:28:58.484] fetching mongodb-mongo-master/enterprise-rhel-62-64-bit/74306a6fd07a7194567f77c930e0dc4e18098df3/debugsymbols/debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_74306a6fd07a7194567f77c930e0dc4e18098df3_20_02_18_20_18_42.tgz from s3 bucket mciuploads (attempt 1 of 10)
    [2020/02/18 16:29:59.294] Running command 'shell.exec' in "do setup" (step 1.5 of 2)
    

That is a 27% increase in download time, and an overall difference of 13 seconds, in line with the observed change in test execution times between the good and the bad regimes. Additionally, if we look at the debug symbol files themselves, we find that the debug symbols file has grown from 3.1 GB in the first case to 4.0 GB in the second, a 29% increase:

$ ls -larth debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_*
-rw-rw-r-- 1 andrew andrew 3.2G Feb 10 11:36 debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_6017618f1ab32ea2b2fc1ce7332806ebce2d2fad_20_02_10_16_03_40.tgz
-rw-rw-r-- 1 andrew andrew 4.1G Feb 18 16:22 debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_74306a6fd07a7194567f77c930e0dc4e18098df3_20_02_18_20_18_42.tgz

Overall, this supports my contention that the additional 10 seconds is primarily driven by the cost to download the more complete debug information made available by hygienic builds. You can see that the post-hygienic version contains several debug files not present in the older one.

  • Older build:

    $ tar tvf debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_6017618f1ab32ea2b2fc1ce7332806ebce2d2fad_20_02_10_16_03_40.tgz
    -rw-r--r-- root/root     17699 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/LICENSE-Enterprise.txt
    -rw-r--r-- root/root       371 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/snmp/MONGODBINC-MIB.txt
    -rw-r--r-- root/root     16726 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/MPL-2
    -rw-r--r-- root/root      2013 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/README
    -rwxr-xr-x root/root 1369516992 2020-02-10 11:23 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongo.debug
    -rwxr-xr-x root/root  357842952 2020-02-10 11:25 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongokerberos.debug
    -rw-r--r-- root/root      30341 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/snmp/MONGOD-MIB.txt
    -rwxr-xr-x root/root 2911649648 2020-02-10 11:26 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongod.debug
    -rw-r--r-- root/root       1465 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/snmp/mongod.conf.master
    -rwxr-xr-x root/root  370810760 2020-02-10 11:24 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongodecrypt.debug
    -rw-r--r-- root/root        668 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/snmp/mongod.conf.subagent
    -rwxr-xr-x root/root 1350715944 2020-02-10 11:24 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongocryptd.debug
    -rwxr-xr-x root/root 1043348752 2020-02-10 11:23 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongoldap.debug
    -rwxr-xr-x root/root 1914243000 2020-02-10 11:24 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/bin/mongos.debug
    -rw-r--r-- root/root      75685 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/THIRD-PARTY-NOTICES
    -rw-r--r-- root/root        735 2020-02-10 11:21 mongodb-linux-x86_64-enterprise-rhel62-4.3.3-230-g6017618/snmp/README-snmp.txt
    

  • Newer build:

    $ tar tvf debugsymbols-mongodb_mongo_master_enterprise_rhel_62_64_bit_74306a6fd07a7194567f77c930e0dc4e18098df3_20_02_18_20_18_42.tgz
    -rwxr-xr-x root/root 1049737664 2020-02-18 16:08 dist-test/bin/mongobridge.debug
    -rwxr-xr-x root/root   30212544 2020-02-18 16:05 dist-test/bin/wt.debug
    -rw-r--r-- root/root      30341 2020-02-18 16:04 dist-test/snmp/MONGOD-MIB.txt
    -rwxr-xr-x root/root 1065975960 2020-02-18 16:06 dist-test/bin/mongoldap.debug
    -rwxr-xr-x root/root 1422945352 2020-02-18 16:08 dist-test/bin/mongotmock.debug
    -rwxr-xr-x root/root 3019933576 2020-02-18 16:10 dist-test/bin/mongod.debug
    -rw-r--r-- root/root      75685 2020-02-18 16:04 dist-test/THIRD-PARTY-NOTICES
    -rw-r--r-- root/root        735 2020-02-18 16:04 dist-test/snmp/README-snmp.txt
    -rwxr-xr-x root/root  371604456 2020-02-18 16:07 dist-test/bin/mongokerberos.debug
    -rwxr-xr-x root/root 1378660688 2020-02-18 16:07 dist-test/bin/mongocryptd.debug
    -rw-r--r-- root/root      17699 2020-02-18 16:04 dist-test/LICENSE-Enterprise.txt
    -rw-r--r-- root/root        668 2020-02-18 16:04 dist-test/snmp/mongod.conf.subagent
    -rwxr-xr-x root/root  384594744 2020-02-18 16:06 dist-test/bin/mongodecrypt.debug
    -rw-r--r-- root/root       2013 2020-02-18 16:04 dist-test/README
    -rw-r--r-- root/root        371 2020-02-18 16:04 dist-test/snmp/MONGODBINC-MIB.txt
    -rwxr-xr-x root/root 1397371872 2020-02-18 16:07 dist-test/bin/mongo.debug
    -rwxr-xr-x root/root 1959795840 2020-02-18 16:09 dist-test/bin/mongos.debug
    -rw-r--r-- root/root      16726 2020-02-18 16:04 dist-test/MPL-2
    -rw-r--r-- root/root       1465 2020-02-18 16:04 dist-test/snmp/mongod.conf.master
    

As you can see, the newer build properly includes debug data for test programs like mongobridge and mongotmock, which the old one lacked.

Finally, I'd like to note that the unconditional download of the debug symbols in these tests, intended to support use of the hang analyzer in failed assert.soon calls, costs a whopping 57% and 53% of the entire test time. But the truly appalling part is that in both runs the overall time actually spent running resmoke is less than two seconds. The overhead we are paying to get this test running and clean up after it is astounding.

robert.guo, unless you disagree with something in this analysis, I plan to close this as "works as designed". Please let me know if you have any concerns.

Comment by Andrew Morrow (Inactive) [ 06/Apr/20 ]

Also note that a major change to structured logging went in at the same time: https://github.com/mongodb/mongo/commit/a84c09a19720b73cedb2e8ef7c5cfeedfa1c9761. I'm running the gle_auth_basics_passthrough on a few nearby commits to try to get a few more datapoints and hopefully make clear whether this was hygienic or structured logging, or something else.

Comment by Andrew Morrow (Inactive) [ 30/Mar/20 ]

This is almost certainly due to larger debug info, since we always download the debug info, and the debug info package is now more complete (and therefore larger) than before hygienic builds.

Comment by Mathew Robinson (Inactive) [ 28/Feb/20 ]

This could potentially be caused by all the tasks now doing a $PATH lookup for every binary execution?

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