Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 2020930

Summary:	Running cyclictest with LATENCY_TEST_DELAY=60 fails with invalid value "60" for flag -cyclictest-start-delay: parse error
Product:	OpenShift Container Platform	Reporter:	OpenShift BugZilla Robot <openshift-bugzilla-robot>
Component:	CNF Platform Validation	Assignee:	Martin Sivák <msivak>
Status:	CLOSED ERRATA	QA Contact:	Shereen Haj Makhoul <shajmakh>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	4.9	CC:	aos-bugs, titzhak, yliu1
Target Milestone:	---
Target Release:	4.9.z
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2022-02-09 19:43:56 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	2006675
Bug Blocks:

Description OpenShift BugZilla Robot 2021-11-07 13:26:04 UTC

+++ This bug was initially created as a clone of Bug #2006675 +++

Description of problem:

When running cyclictest with cnf-tests image and when passing -e LATENCY_TEST_DELAY=60 I get the following error:

invalid value "60" for flag -cyclictest-start-delay: parse error
Usage of usr/bin/cyclictest-runner:
  -add_dir_header
    	If true, adds the file directory to the header
  -alsologtostderr
    	log to standard error as well as files
  -cyclictest-start-delay duration
    	delay in second before running the cyclictest binary
  -duration string
    	specify a length for the test run. Append 'm', 'h', or 'd' to specify minutes, hours or days. (default "15s")
  -histogram string
    	dump a latency histogram to stdout after the run US is the max latency time to be be tracked in microseconds (default "30")
  -interval int
    	base interval of thread in us default=1000 (default 1000)
  -log_backtrace_at value
    	when logging hits line file:N, emit a stack trace
  -log_dir string
    	If non-empty, write log files in this directory
  -log_file string
    	If non-empty, use this log file
  -log_file_max_size uint
    	Defines the maximum size a log file can grow to. Unit is megabytes. If the value is 0, the maximum file size is unlimited. (default 1800)
  -logtostderr
    	log to standard error instead of files (default true)
  -rt-priority string
    	specify the SCHED_FIFO priority (1-99) (default "1")
  -skip_headers
    	If true, avoid header prefixes in the log messages
  -skip_log_headers
    	If true, avoid headers when opening log files
  -stderrthreshold value
    	logs at or above this threshold go to stderr (default 2)
  -v value
    	number for the log level verbosity
  -vmodule value
    	comma-separated list of pattern=N settings for file-filtered logging

Version-Release number of selected component (if applicable):
"vcs-ref": "b46a47f7c4d3007b8150551c771cc8460fba9dfa"

How reproducible:
100%

Steps to Reproduce:
1.

podman run --name cnf-container-tests  \
  --net=host  \
  -v /home/kni/cnf_tests_dir:/kubeconfig:Z  \
  -v /home/kni/cnf_tests_dir/junit:/junit:Z \
  -v /home/kni/cnf_tests_dir/report:/report:Z \
  -e KUBECONFIG=/kubeconfig/kubeconfig \
  -e IMAGE_REGISTRY=registry.kni-qe-0.lab.eng.rdu2.redhat.com:5000/ \
  -e CNF_TESTS_IMAGE=cnf-tests \
  -e LATENCY_TEST_RUN=true \
  -e LATENCY_TEST_RUNTIME=3600 \
  -e LATENCY_TEST_CPUS=44 \
  -e OSLAT_MAXIMUM_LATENCY=10 \
  -e LATENCY_TEST_DELAY=60 \
  -e CYCLICTEST_MAXIMUM_LATENCY=10 \
  -e HWLATDETECT_MAXIMUM_LATENCY=10 \
  -e ROLE_WORKER_CNF=master \
  -e PERF_TEST_PROFILE=openshift-node-performance-profile \
  -e DISCOVERY_MODE=true \
  quay.io/openshift-kni/cnf-tests \
  /usr/bin/test-run.sh  \
  -ginkgo.focus="\[performance\]\[config\]|\[performance\]\ Latency\ Test\ with\ the\ cyclictest" \
  --junit /junit -ginkgo.v


Actual results:
Test pod exits with invalid value "60" for flag -cyclictest-start-delay: parse error

Expected results:
Test runs without errors.

Additional info:

--- Additional comment from msivak on 2021-09-22 07:52:50 UTC ---

Just for the record, my hypothesis is this:

We have a conflict between https://github.com/openshift-kni/performance-addon-operators/blob/1987e77b0803ab040eb6def52fae62b975826720/functests/4_latency/latency.go#L360 and https://github.com/openshift-kni/cnf-features-deploy/blob/6285b110359a63ebd72fd46d2ab8c6a9d019fc37/cnf-tests/pod-utils/cyclictest-runner/main.go#L22

Unless I am mistaken, Duration requires the unit to be specified, but we pass plain int into it: https://pkg.go.dev/time#ParseDuration

--- Additional comment from msivak on 2021-09-22 13:13:41 UTC ---

Our cyclictest and hwlatdetect runners expect Duration, but the oslat one uses Int... https://github.com/openshift-kni/cnf-features-deploy/blob/6285b110359a63ebd72fd46d2ab8c6a9d019fc37/cnf-tests/pod-utils/oslat-runner/main.go

Few more patches will be needed.

--- Additional comment from titzhak on 2021-10-26 06:26:07 UTC ---

Decided to keep the original type and pass it as an Int and change the runner to accept Int. 
Thus, the previous patch got reverted https://github.com/openshift-kni/performance-addon-operators/pull/743 and a new patch was provided instead.

Comment 3 Shereen Haj Makhoul 2022-02-08 13:47:08 UTC

Verification:

Version: 
ocp: 4.9.19
POA: 4.9.5 (image hash d791b343b5b16e94f4fdc0d0585e7843c1aa9d6e140526fda1911078baf6aec5, corresponds to performance-addon-operator-container-v4.9.5-3)
cnf-test image: cnf-tests-container-v4.9.5-5

Run podman focusing on latency tools' tests:

podman run --net=host -v /home/kni/clusterconfigs/auth:/kubeconfig:Z -e KUBECONFIG=/kubeconfig/kubeconfig -e IMAGE_REGISTRY=registry-proxy.engineering.redhat.com/rh-osbs/ -e CNF_TESTS_IMAGE=openshift4-cnf-tests:v4.9.5-5  -e LATENCY_TEST_RUN=true -e LATENCY_TEST_RUNTIME=5 -e LATENCY_TEST_CPUS=2 -e OSLAT_MAXIMUM_LATENCY=3000 -e LATENCY_TEST_DELAY=65 -e CYCLICTEST_MAXIMUM_LATENCY=5200 -e HWLATDETECT_MAXIMUM_LATENCY=5300 -e ROLE_WORKER_CNF=worker-cnf -e PERF_TEST_PROFILE=performance -e DISCOVERY_MODE=true registry-proxy.engineering.redhat.com/rh-osbs/openshift4-cnf-tests:v4.9.5-5 /usr/bin/test-run.sh -ginkgo.focus="\[performance\]\ Latency\ Test" -ginkgo.v 

Result:

Cyclictest: 

------------------------------
[performance] Latency Test with the cyclictest image 
  should succeed
  /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:183
STEP: Waiting two minutes to download the latencyTest image
STEP: Waiting another two minutes to give enough time for the cluster to move the pod to Succeeded phase
Feb  8 13:34:01.915: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:34:02.410: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:34:02.905: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:34:03.380: [INFO]: Log file created at: 2022/02/08 13:32:50
Running on machine: cyclictest-fw4sg
Binary: Built with gc go1.16.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0208 13:32:50.893511       1 node.go:37] Environment information: /proc/cmdline: BOOT_IMAGE=(hd1,gpt3)/ostree/rhcos-56fabc639a679b757ebae30e5f01b2ebd38e9fde9ecae91c41be41d3e89b37f8/vmlinuz-4.18.0-305.34.2.rt7.107.el8_4.x86_64 ip=dhcp random.trust_cpu=on console=tty0 console=ttyS0,115200n8 ostree=/ostree/boot.1/rhcos/56fabc639a679b757ebae30e5f01b2ebd38e9fde9ecae91c41be41d3e89b37f8/0 ignition.platform.id=openstack root=UUID=76fa644f-016b-4160-a091-bba2ccece674 rw rootflags=prjquota skew_tick=1 nohz=on rcu_nocbs=3-5 tuned.non_isolcpus=0000ffff,ffffffff,ffffffc7 intel_pstate=disable nosoftlockup tsc=nowatchdog intel_iommu=on iommu=pt isolcpus=managed_irq,3-5 systemd.cpu_affinity=0,1,2,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79 + +
I0208 13:32:50.893709       1 node.go:44] Environment information: kernel version 4.18.0-305.34.2.rt7.107.el8_4.x86_64
I0208 13:33:55.894523       1 main.go:51] running the cyclictest command with arguments [-D 5 -p 95 -t 2 -a 3,43 -h 30 -i 1000 --mlockall --quiet]
I0208 13:34:00.959314       1 main.go:57] succeeded to run the cyclictest command: # /dev/cpu_dma_latency set to 0us
# Histogram
000000 000000	000000
000001 000000	000000
000002 004695	004615
000003 000293	000373
000004 000001	000004
000005 000002	000002
000006 000000	000000
000007 000002	000000
000008 000003	000001
000009 000000	000003
000010 000001	000001
000011 000001	000001
000012 000001	000000
000013 000000	000000
000014 000000	000000
000015 000000	000000
000016 000000	000000
000017 000000	000000
000018 000000	000000
000019 000000	000000
000020 000000	000000
000021 000000	000000
000022 000000	000000
000023 000000	000000
000024 000000	000000
000025 000000	000000
000026 000000	000000
000027 000000	000000
000028 000000	000000
000029 000000	000000
# Total: 000004999 000005000
# Min Latencies: 00002 00002
# Avg Latencies: 00002 00002
# Max Latencies: 00012 00011
# Histogram Overflows: 00000 00000
# Histogram Overflow at cycle number:
# Thread 0:
# Thread 1:

Feb  8 13:34:03.388: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:35:04.820: [ERROR]: timed out waiting for the condition

• [SLOW TEST:137.004 seconds]
[performance] Latency Test
/remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:60
  with the cyclictest image
  /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:171
    should succeed
    /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:183
------------------------------

Hwlatdetect: 

[performance] Latency Test with the hwlatdetect image 
  should succeed
  /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:221
STEP: Waiting two minutes to download the latencyTest image
STEP: Waiting another two minutes to give enough time for the cluster to move the pod to Succeeded phase
Feb  8 13:36:27.933: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:36:28.458: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:36:28.944: [INFO]: Log file created at: 2022/02/08 13:35:08
Running on machine: hwlatdetect-2gbdd
Binary: Built with gc go1.16.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0208 13:35:08.402028       1 node.go:37] Environment information: /proc/cmdline: BOOT_IMAGE=(hd1,gpt3)/ostree/rhcos-56fabc639a679b757ebae30e5f01b2ebd38e9fde9ecae91c41be41d3e89b37f8/vmlinuz-4.18.0-305.34.2.rt7.107.el8_4.x86_64 ip=dhcp random.trust_cpu=on console=tty0 console=ttyS0,115200n8 ostree=/ostree/boot.1/rhcos/56fabc639a679b757ebae30e5f01b2ebd38e9fde9ecae91c41be41d3e89b37f8/0 ignition.platform.id=openstack root=UUID=76fa644f-016b-4160-a091-bba2ccece674 rw rootflags=prjquota skew_tick=1 nohz=on rcu_nocbs=3-5 tuned.non_isolcpus=0000ffff,ffffffff,ffffffc7 intel_pstate=disable nosoftlockup tsc=nowatchdog intel_iommu=on iommu=pt isolcpus=managed_irq,3-5 systemd.cpu_affinity=0,1,2,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79 + +
I0208 13:35:08.402396       1 node.go:44] Environment information: kernel version 4.18.0-305.34.2.rt7.107.el8_4.x86_64
I0208 13:36:13.403251       1 main.go:50] running the hwlatdetect command with arguments [/usr/bin/hwlatdetect --threshold 5300 --hardlimit 5300 --duration 5 --window 10000000us --width 950000us]
I0208 13:36:26.079344       1 main.go:56] succeeded to run the hwlatdetect command: hwlatdetect:  test duration 5 seconds
   detector: tracer
   parameters:
        Latency threshold: 5300us
        Sample window:     10000000us
        Sample width:      950000us
     Non-sampling period:  9050000us
        Output File:       None

Starting test
test finished
Max Latency: Below threshold
Samples recorded: 0
Samples exceeding threshold: 0
Feb  8 13:36:28.950: [INFO]: found mcd machine-config-daemon-jn26h for node worker-0
Feb  8 13:37:30.421: [ERROR]: timed out waiting for the condition

• [SLOW TEST:145.597 seconds]
[performance] Latency Test
/remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:60
  with the hwlatdetect image
  /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:213
    should succeed
    /remote-source/app/vendor/github.com/openshift-kni/performance-addon-operators/functests/4_latency/latency.go:221
------------------------------
SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS
JUnit report was created: /junit.xml/cnftests-junit.xml

Ran 3 of 151 Specs in 477.078 seconds
SUCCESS! -- 3 Passed | 0 Failed | 0 Pending | 148 Skipped

According to the above output, the tools ran successfully with a delay of 65s.

Comment 5 errata-xmlrpc 2022-02-09 19:43:56 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (OpenShift Container Platform 4.9.19 low-latency extras update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:0471