[SERVER-66614] Speed up unit tests on macOS Created: 20/May/22  Updated: 29/Oct/23  Resolved: 16/Jun/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 6.0.3, 6.1.0-rc0

Type: Improvement Priority: Major - P3
Reporter: Gregory Noma Assignee: Jordi Olivares Provencio
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
related to SERVER-66343 Increase timeouts for mac unittests Closed
related to SERVER-65146 Run unit tests with wiredTiger by def... Closed
Backwards Compatibility: Fully Compatible
Backport Requested:
v6.0
Sprint: Execution Team 2022-06-27
Participants:
Linked BF Score: 47

 Description   

After SERVER-65146, unit tests saw a dramatic increase in runtime on macOS. (Other platforms expectedly saw a slight increase as well.) However, this extreme slowdown on macOS is somewhat mysterious because even unit tests which don't use a storage engine, such as db_sorter_test, were affected. Once the the test times have been brought down, we can undo the timeout increases added in SERVER-66343.



 Comments   
Comment by Githook User [ 30/Sep/22 ]

Author:

{'name': 'Jordi Olivares Provencio', 'email': 'jordi.olivares-provencio@mongodb.com', 'username': 'jordiolivares'}

Message: SERVER-66614 Run Unit Tests with ephemeral WiredTiger by default
Branch: v6.0
https://github.com/mongodb/mongo/commit/707c6255886a53b6848c01fb8dc8697d4ad796cc

Comment by Githook User [ 16/Jun/22 ]

Author:

{'name': 'Jordi Olivares Provencio', 'email': 'jordi.olivares-provencio@mongodb.com', 'username': 'jordiolivares'}

Message: SERVER-66614 Run Unit Tests with ephemeral WiredTiger by default
Branch: master
https://github.com/mongodb/mongo/commit/432bd15ef30c7850766dd36b6b9eb05329922994

Comment by Jordi Olivares Provencio [ 13/Jun/22 ]

Compiling and running the db_sorter_test locally yields the same numbers as Linux

Comment by Jordi Olivares Provencio [ 13/Jun/22 ]

Curiously enough, looking at db_sorter_test appears to show that macOS might have an issue with disk I/O.

A test from before SERVER-65146 reveals that a particular test in there that does I/O was already taking dramatically longer on macOS than on Linux:

macOS

[cpp_unit_test:db_sorter_test] Starting C++ unit test build/install/bin/db_sorter_test...
...
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:36.913Z I  TEST     23059   [main] "Running","attr":\{"test":"mongo::sorter::(anonymous namespace)::SorterTests::LotsOfDataLittleMemory<true>","rep":1,"reps":1}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:36.935Z I  TEST     23051   [main] "Created temporary directory: \{path}","attr":\{"path":"/data/mci/0f7dcf7494a9efcd981711b886943cfe/tmp/sorterTests-8d59-dfec-50be-6258"}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:38.893Z I  TEST     6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:47.754Z I  TEST     6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:49.554Z I  TEST     6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:56.153Z I  TEST     6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:08:59.703Z I  TEST     6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:09:11.912Z I  TEST     6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:09:11.912Z I  TEST     6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-05-09T22:09:23.833Z I  TEST     6033100 [main] "Finished merging spills"
...

Linux

[cpp_unit_test:db_sorter_test] Starting C++ unit test build/install/bin/db_sorter_test...
...
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.395Z I  TEST     23059   [main] "Running","attr":\{"test":"mongo::sorter::(anonymous namespace)::SorterTests::LotsOfDataLittleMemory<false>","rep":1,"reps":1}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.396Z I  TEST     23051   [main] "Created temporary directory: \{path}","attr":\{"path":"/data/mci/aa39de40af1186ef98332d6d8f8db64f/tmp/sorterTests-cbf6-48b2-477a-6a73"}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.427Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.592Z I  -        6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.671Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.835Z I  -        6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:22.939Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.105Z I  -        6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.106Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.273Z I  -        6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.469Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.713Z I  -        6033100 [main] "Finished merging spills"
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.713Z I  -        6033104 [main] "Number of spills exceeds maximum spills to merge at a time, proceeding to merge them to reduce the number","attr":\{"currentNumSpills":62,"maxNumSpills":2}
[cpp_unit_test:db_sorter_test] | 2022-06-12T05:51:23.917Z I  -        6033100 [main] "Finished merging spills"
...

Maybe the issue was brought to light with the WT change due to going from in memory to disk, thus affecting everything with slow disk I/O.

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