DAOS-15937 test: Automate metadata duplicate rpc detection time consuming

[dinghwah]

Automate metadata duplicate rpc detection time consuming

Skip-unit-tests: true
Skip-fault-injection-test: true
Skip-func-hw-test-large-md-on-ssd: false
Test-tag: test_metadata_dup_rpc
Doc-only: false
Required-githooks: true

Signed-off-by: Ding Ho [email protected]

Before requesting gatekeeper:

• Two review approvals and any prior change requests have been resolved.
• Testing is complete and all tests passed or there is a reason documented in the PR why it should be force landed and forced-landing tag is set.
• Features: (or Test-tag*) commit pragma was used or there is a reason documented that there are no appropriate tags for this PR.
• Commit messages follows the guidelines outlined here.
• Any tests skipped by the ticket being addressed have been run and passed in the PR.

Gatekeeper:

• You are the appropriate gatekeeper to be landing the patch.
• The PR has 2 reviews by people familiar with the code, including appropriate owners.
• Githooks were used. If not, request that user install them and check copyright dates.
• Checkpatch issues are resolved. Pay particular attention to ones that will show up on future PRs.
• All builds have passed. Check non-required builds for any new compiler warnings.
• Sufficient testing is done. Check feature pragmas and test tags and that tests skipped for the ticket are run and now pass with the changes.
• If applicable, the PR has addressed any potential version compatibility issues.
• Check the target branch. If it is master branch, should the PR go to a feature branch? If it is a release branch, does it have merge approval in the JIRA ticket.
• Extra checks if forced landing is requested
  • Review comments are sufficiently resolved, particularly by prior reviewers that requested changes.
  • No new NLT or valgrind warnings. Check the classic view.
  • Quick-build or Quick-functional is not used.
• Fix the commit message upon landing. Check the standard here. Edit it to create a single commit. If necessary, ask submitter for a new summary.

[github-actions]

Errors are Unable to load ticket data
https://daosio.atlassian.net/browse/DAOS-15937

[daosbuild1]

Test stage Functional Hardware Medium completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/2/testReport/

[kccain]

first pass review

[kccain]

this will raise engine log_mask to DEBUG, which can be useful during setup phases. But it should be restored to the original log_mask: ERR that the .yaml file specifies) beforestarting timing loops.

i.e., probably need another call to server_set_logmasks to restore the original setting

[dinghwah]

Updated. server log mask defined by test yaml.

[kccain]

if the .yaml file specifies multiple threads, wouldn't the code here need to perform that number of container_manager.add() calls, one per thread?

Also, passing cont_num here maybe isn't so useful for the thread function metadata_workload_test() - maybe it can be removed from the arguments to that method?

[dinghwah]

Thanks for the comment.
When multiple threads specified (in testcase-2, 2, 4, or 8 threads), each thread will create it's own container and perform their individual metadata workload.
Have updated. It should be number_of_container (instead of cont_num).

[kccain]

If the yaml file specifies number_thread: 2 (anything larger than 1), then this code will need to change so that it has a loop to call container_manager.add() calls so that all of the threads get created, is that right?

==>when yaml file specifies number_thread: 2 (4 or 8), script will generate different number of container-thread (2, 4 or 8) on the same pool (thread). Script does not need to change. This has been tested.

[daltonbohning]

I agree with @kccain here. If num_of_cont is increased, this still only runs a single thread because the code only calls container_manager.add one time

script will generate different number of container-thread (2, 4 or 8) on the same pool (thread)

Where? What line(s) of code does this?
==> Please see the new commit. I missed a loop for adding the container-thread.
Thanks for catching.

[dinghwah]

Line #107 to #110 generate different number of container-thread (2, 4 or 8) on the same pool.

[daltonbohning]

        container_manager = ThreadManager(
            self.metadata_workload_test, self.get_remaining_time() - 30)
        container_manager.add(
            pool=self.pool, num_of_cont=num_of_cont, workload_cycles=w_cycles, test_loops=t_loops)

That is one thread, no matter what num_of_cont is

[kccain]

Test steps documentation for step 4 should not specify that it is calculating an average for those loops following svc_ops_entry_age time.

This verification seems OK, since we expect the "early" loops before svc_ops_entry_age to be quicker than what the performance will "stabilize" to after svc_ops_entry_age time. i.e., all timings before and after svc_ops_entry_age time should fit underneath the baseline times the threshold_factor. But we particularly care about the iterations after svc_ops_entry_age time has passed.

[dinghwah]

Please see the new commit, which should have addressed all the comments.

[daosbuild1]

Test stage Functional Hardware Medium MD on SSD completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/14/testReport/

[daosbuild1]

Test stage Functional Hardware Medium completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/14/testReport/

[kccain]

Test stage Functional Hardware Medium MD on SSD completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/14/testReport/

The job.log has 200,000 lines of output, 100,000 pairs of items like this, that are output during the timing loops. We may want to look at making the output quiet. I think I had experimented with this at some point, but not sure if I can find the prototype code I used since it has been a while.

2024-08-23 08:32:00,394 test_utils_conta L0624 INFO | Opening container 138475AD-324F-4A86-8E25-D2D213FAABEB
2024-08-23 08:32:00,399 test_utils_conta L0645 INFO | Closing container 138475AD-324F-4A86-8E25-D2D213FAABEB

Failure reason
#Dup rpc detection time 13.781859397888184 > baseline_time 5.202355599403381 * threshold_factor 2.5
but the actual time comparison should be 5.x versus 19..x seconds, which is the "stabilized" time after getting through the initial svc_ops_entry_age:60 seconds period

From the job.log, the first 10 test-loops with svc_ops_enabled:1

2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 0,  8.415847
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 1,  13.758781
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 2,  18.333476
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 3,  19.055028
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 4,  19.116618
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 5,  19.093971
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 6,  19.083379
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 7,  19.085228
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 8,  19.120708
2024-08-23 08:34:54,578 metadata_svc_ops L0060 INFO | Test time of Metadata test-loop: 9,  19.120152

I have an experimental PR #14997 to try to establish a baseline timing expectation for pools with svc_ops_enabled:1 and svc_ops_entry_age:60, on a variety of HW cluster configurations, by running the existing C code daos_test -c --subtests="34" (co_op_dup_timing).

That test is run daily, but is done on Functional Hardware Medium Verbs Provider, and Functional Hardware Medium Verbs Provider MD on SSD configurations (whereas this PR executes on Functional Hardware Medium, and Functional Hardware Medium MD on SSD).

Experimental PR 14997 results:

• Functional HW Medium: after running svc_ops_entry_age:60 warmup loop of container open/close, a time seen for for svc_ops_enabled;1 1000 loops of container open/close was 2.969 seconds

2024-08-28 18:31:12,452 process          L0416 DEBUG| [stdout] [1,0]<stdout>:1K open/close pairs in    2.969 sec

• Functional HW Medium MD on SSD: after running svc_ops_entry_age:60 warmup loop of container open/close, a time seen for for svc_ops_enabled;1 1000 loops of container open/close was 1.617 seconds (versus 19.x seconds seen in this PR)

2024-08-28 18:27:15,163 process          L0416 DEBUG| [stdout] [1,0]<stdout>:1K open/close pairs in    1.617 sec

[daosbuild1]

Test stage Functional Hardware Medium MD on SSD completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/15/testReport/

[daosbuild1]

Test stage Functional Hardware Medium completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/15/testReport/

[daosbuild1]

Test stage Functional Hardware Medium MD on SSD completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/16/testReport/

[daosbuild1]

Test stage Functional Hardware Medium completed with status UNSTABLE. https://build.hpdd.intel.com/job/daos-stack/job/daos//view/change-requests/job/PR-14473/16/testReport/

[kccain]

updated my comment from a few days ago, after updating the debug PR to get a proper 1000 container open/close loop timing in the daos_test -c co_op_dup_timing() with svc_ops_enabled:1 and svc_ops_entry_age:60, and preceding the 1000 loop timing with a 60 second warmup loop.

The timings measured were 2.969 seconds (Functional HW Medium) and 1.617 seconds (Functional HW Medium MD on SSD)