Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mock time in tests #1986

Closed
na-- opened this issue Apr 23, 2021 · 5 comments
Closed

Mock time in tests #1986

na-- opened this issue Apr 23, 2021 · 5 comments

Comments

@na--
Copy link
Member

na-- commented Apr 23, 2021

Our tests, especially the ones for executors, are somewhat flaky and incomplete. Because we rely on real timers, we can't test them as well as we should... 馃槥

The solution is to somehow mock time. For example, instead of using functions from the time package directly, we can instead rely on an interface. For real-world code, that interface will be implemented by the same time package, so nothing would change, but for test we'd be able to manually control the time "flow"...

This was previously mentioned in #1357 (comment) and #1386 (comment), but it probably deserves its own issue, so I created this.

Specific issues that this will likely make easier: #1715, #1719, #1974

@oleiade
Copy link
Member

oleiade commented Nov 24, 2021

A collection of resources I've found as part of my research on the topic:

@oleiade
Copy link
Member

oleiade commented Nov 24, 2021

To help asses whether mocking time solved some related issues, here's a list of tests known to fail because of our current usage of time:

  • in go.k6.io/k6/core
    • in engine_test.go
    • TestEngineStopped
    • TestEngineAtTime
    • TestEngineRun/exits_with_context
  • in go.k6.io/k6/lib/executor
    • in constant_arrival_rate_test.go
      • TestConstantArrivalRateRunCorrectTiming/segment_0:1/3_sequence_0,1/3,2/3,1
  • in go.k6.io/k6/cloudapi
    • in logs_test.go
      • TestStreamLogsToLogger/RestoreConnFromLatestMessage

@na--
Copy link
Member Author

na-- commented Nov 24, 2021

I'd say that, In general, if we can mock time nicely, all of these tests and others could be written in both a much cleaner and a more deterministic manner. Right now we've made a bunch of compromises with their quality to get something working, but if time is deterministic, we won't care about CI performance differences all that much and should be able to write much better tests as a result.

@na--
Copy link
Member Author

na-- commented Dec 17, 2021

#537 was closed, but I decided to see which our our tests are slow with https://github.com/gotestyourself/gotestsum#finding-and-skipping-slow-tests

And we have a lot 馃槥

$ gotestsum --format dots --jsonfile json.log
$ gotestsum tool slowest --jsonfile json.log --threshold 500ms
go.k6.io/k6/core TestActiveVUsCount 10.05s
go.k6.io/k6/core TestEmittedMetricsWhenScalingDown 8.22s
go.k6.io/k6/lib/executor TestRampingVUsRampDownNoWobble 6.02s
go.k6.io/k6/lib/executor TestRampingArrivalRateRunGracefulStop 6s
go.k6.io/k6/core/local TestDNSResolver/cache/3s 5.76s
go.k6.io/k6/core/local TestDNSResolver/cache/default 5.73s
go.k6.io/k6/core/local TestDNSResolver/cache/1000 5.72s
go.k6.io/k6/core/local TestDNSResolver/cache/0 5.72s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunNotEnoughAllocatedVUsWarn 5.62s
go.k6.io/k6/core/local TestRealTimeAndSetupTeardownMetrics 5.57s
go.k6.io/k6/js TestInitContextRequire 5.26s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatch 5.21s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectRate 5s
go.k6.io/k6/core TestMinIterationDurationInSetupTeardownStage/Test_teardown 4.19s
go.k6.io/k6/core TestMinIterationDurationInSetupTeardownStage/Test_setup 4.18s
go.k6.io/k6/core/local TestExecutionInfoVUSharing 4.14s
go.k6.io/k6/core/local TestExecutionSchedulerStages/four 4.09s
go.k6.io/k6/lib/executor TestExecutionStateGettingVUs 4.01s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS 3.96s
go.k6.io/k6/lib/executor TestRampingArrivalRateRunNotEnoughAllocatedVUsWarn 3.96s
go.k6.io/k6/lib/executor TestCompareCalImplementation 3.93s
go.k6.io/k6/lib/executor TestVUHandleSimple/start_after_gracefulStop_finishes 3.1s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'valid_env_vars_with_spaces' 3.06s
go.k6.io/k6/lib/executor TestPerVUIterationsRunVariableVU 3.01s
go.k6.io/k6/lib/executor TestRampingArrivalRateRunCorrectRate 3s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatch/Timeout 3s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'mixed_system_and_cli_env_2' 2.89s
go.k6.io/k6/core TestMetricsEmission/sleepBeforeCounterAdd 2.84s
go.k6.io/k6/js TestLoadCycleBinding 2.77s
go.k6.io/k6/js TestLoadCycle 2.74s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'enabled_sys_env_by_env' 2.71s
go.k6.io/k6/js TestLoadOnceGlobalVars/module.exports 2.68s
go.k6.io/k6/js TestLoadDoesntBreakHTTPGet 2.67s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/ramping-vus 2.62s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'enabled_sys_env_by_cli_2' 2.6s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'disabled_system_env_with_cli_params' 2.52s
go.k6.io/k6/core TestMetricsEmission/sleepAfterCounterAdd 2.52s
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomConfigNoCrossover 2.52s
go.k6.io/k6/lib/executor TestRampingVUsGracefulStopStops 2.5s
go.k6.io/k6/lib/executor TestRampingVUsGracefulRampDown 2.5s
go.k6.io/k6/js/modules/k6/http TestResponseTimingsWhenTimeout 2.5s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'overwriting_system_env_with_cli_param' 2.49s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'mixed_system_and_cli_env' 2.44s
go.k6.io/k6/js/modules/k6/http TestResponseWaitingAndReceivingTimings 2.41s
go.k6.io/k6/lib/executor TestRampingVUsRun 2.4s
go.k6.io/k6/js TestVURunInterruptDoesntPanic/Archive 2.27s
go.k6.io/k6/core TestMetricsEmission/minIterationDuration 2.24s
go.k6.io/k6/js TestVURunInterruptDoesntPanic/Source 2.21s
go.k6.io/k6/core/local TestExecutionInfoScenarioIter 2.2s
go.k6.io/k6/js TestLoadOnceGlobalVars/direct_export 2.12s
go.k6.io/k6/lib/executor TestExternallyControlledRun 2.11s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'summary_and_thresholds_from_env_overwritten_by_CLI' 2.1s
go.k6.io/k6/core/local TestExecutionSchedulerSystemTags 2.09s
go.k6.io/k6/js TestLoadGlobalVarsAreNotSharedBetweenVUs 2.06s
go.k6.io/k6/core/local TestExecutionSchedulerStages/two 2.029s
go.k6.io/k6/js TestOpen/OsFS/relative1 2.02s
go.k6.io/k6/lib/executor TestExecutionStateGettingVUsWhenNonAreAvailable 2.009s
go.k6.io/k6/core TestEngineAbortedByThresholds 2.009s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_1/3:2/3_sequence_<nil> 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_0:1/3_sequence_0,1/3,2/3,1 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_1/6:1/2_sequence_<nil> 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_2/3:1_sequence_0,1/3,2/3,1 2s
go.k6.io/k6/lib/executor TestRampingArrivalRateRunCorrectRateWithSlowRate 2s
go.k6.io/k6/output/csv TestRun 2s
go.k6.io/k6/lib/executor TestArrivalRateCancel/constant 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_0:1/3_sequence_<nil> 2s
go.k6.io/k6/lib/executor TestArrivalRateCancel/ramping 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_2/3:1_sequence_<nil> 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_1/3:2/3_sequence_0,1/3,2/3,1 2s
go.k6.io/k6/lib/executor TestConstantArrivalRateRunCorrectTiming/segment_1/6:1/2_sequence_1/6,1/2 2s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'disabled_sys_env_by_env' 1.99s
go.k6.io/k6/js TestOpen/OsFS/relative2 1.98s
go.k6.io/k6/js TestOpen/OsFS/relative_wonky 1.94s
go.k6.io/k6/lib/executor TestRampingArrivalRateGlobalIters/0,1/4,3/4,1_1/4:3/4 1.93s
go.k6.io/k6/lib/executor TestRampingArrivalRateRunUnplannedVUs 1.9s
go.k6.io/k6/core TestRunTags 1.88s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/ramping-vus 1.84s
go.k6.io/k6/js TestOpen/OsFS/simple_with_two_dots 1.83s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/ramping-arrival-rate 1.78s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'valid_env_vars_with_special_chars' 1.77s
go.k6.io/k6/js TestLoadExportsIsUsableInModule 1.74s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/ramping-arrival-rate 1.68s
go.k6.io/k6/js TestOpen/OsFS/file_is_missing 1.61s
go.k6.io/k6/api/v1 TestSetupData/setupNoReturn 1.6s
go.k6.io/k6/lib/executor TestVUHandleSimple/start_before_gracefulStop_finishes 1.56s
go.k6.io/k6/lib/executor TestRampingArrivalRateGlobalIters/0,1/4,3/4,1_3/4:1 1.56s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[4](25,2) 1.55s
go.k6.io/k6/api/v1 TestSetupData/noSetup 1.54s
go.k6.io/k6/lib/executor TestVUHandleSimple/start_after_hardStop 1.53s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[1](2,2) 1.52s
go.k6.io/k6/js TestBundleEnv 1.51s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'disabled_sys_env_by_default_with_ext_compat_mode' 1.5s
go.k6.io/k6/lib/executor TestRampingVUsGracefulStopWaits 1.5s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[2](2,1) 1.49s
go.k6.io/k6/api/v1 TestSetupData/setupReturns 1.47s
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomTags/ramping-arrival-rate 1.47s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[5](50,5) 1.45s
go.k6.io/k6/core/local TestSharedIterationsStable 1.45s
go.k6.io/k6/converter/har TestBuildK6RequestObject 1.43s
go.k6.io/k6/js TestBundleNotSharable 1.43s
go.k6.io/k6/js TestBrowserified 1.42s
go.k6.io/k6/js TestOpen/OsFS/empty_open_doesn't_panic 1.4s
go.k6.io/k6/lib/executor TestRampingArrivalRateGlobalIters/0,1/4,3/4,1_0:1/4 1.38s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[0](1,1) 1.38s
go.k6.io/k6/js/modules/k6 TestSetupDataMarshalling 1.35s
go.k6.io/k6/js/compiler TestTransform 1.35s
go.k6.io/k6/core/local TestExecutionInfoAll/constant-arrival-rate 1.34s
go.k6.io/k6/js/compiler TestTransform/blank 1.33s
go.k6.io/k6/js TestOpen/OsFS/file_is_dir 1.31s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/shared-iterations 1.31s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'enabled_sys_env_by_default' 1.29s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'run_only_system_env' 1.28s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[1]_case[3](5,2) 1.27s
go.k6.io/k6/js TestOpen/OsFS/notOpeningUrls 1.27s
go.k6.io/k6/core/local TestExecutionInfoAll/ramping-arrival-rate 1.24s
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'enabled_sys_env_by_cli_1' 1.24s
go.k6.io/k6/core/local TestNewExecutionSchedulerHasWork 1.23s
go.k6.io/k6/core/local TestExecutionInfoAll/ramping-vus 1.21s
go.k6.io/k6/core/local TestExecutionInfoAll/externally-controlled 1.19s
go.k6.io/k6/js TestRequestWithBinaryFile 1.13s
go.k6.io/k6/lib/netext TestResolver/LookupIP/1s_first_preferIPv4 1.1s
go.k6.io/k6/lib/netext TestResolver 1.1s
go.k6.io/k6/lib/netext TestResolver/LookupIP 1.1s
go.k6.io/k6/core/local TestExecutionInfoAll/constant-vus 1.07s
go.k6.io/k6/lib/executor TestConstantVUsRun 1.05s
go.k6.io/k6/js TestRequestWithMultipleBinaryFiles 1.03s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[3]_case[2](2,1) 1.03s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/externally-controlled 1.02s
go.k6.io/k6/output/cloud TestNewOutputClientTimeout 1.02s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[3]_case[0](1,1) 1.01s
go.k6.io/k6/core/local TestExecutionSchedulerRuntimeErrors 1.01s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[0]_case[5](50,5) 1.01s
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[3]_case[1](2,2) 1.01s
go.k6.io/k6/core/local TestExecutionSchedulerStages/one 1.01s
go.k6.io/k6/core/local TestExecutionSchedulerEndTime 1.01s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatch/Timeout/10s#01 1s
go.k6.io/k6/js/modules/k6 TestSleep/Cancel 1s
go.k6.io/k6/js/modules/k6 TestSleep/1.0 1s
go.k6.io/k6/js/modules/k6 TestSleep/0.5 1s
go.k6.io/k6/lib/executor TestPerVuIterationsEmitDroppedIterations 1s
go.k6.io/k6/core/local TestExecutionSchedulerEndErrors 1s
go.k6.io/k6/lib/executor TestConstantArrivalRateGlobalIters/0,1/4,3/4,1_3/4:1 1s
go.k6.io/k6/lib/executor TestConstantArrivalRateGlobalIters/0,1/4,3/4,1_0:1/4 1s
go.k6.io/k6/lib/netext/httpext TestConnReset 1s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatch/Timeout/10s#02 1s
go.k6.io/k6/lib/executor TestConstantArrivalRateGlobalIters/0,1/4,3/4,1_1/4:3/4 1s
go.k6.io/k6/js/modules/k6/http TestRequestAndBatch/Timeout/10s 1s
go.k6.io/k6/js/modules/k6 TestSleep/1 1s
go.k6.io/k6/lib/executor TestSharedIterationsEmitDroppedIterations 1s
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/constant-arrival-rate 980ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[3]_case[3](5,2) 950ms
go.k6.io/k6/lib/executor TestConstantArrivalRateDroppedIterations 950ms
go.k6.io/k6/js TestOpen/OsFS/fullpath 930ms
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'disabled_sys_env_by_default' 920ms
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'empty_env' 920ms
go.k6.io/k6/js TestRunnerIntegrationImports/Modules 900ms
go.k6.io/k6/js TestOpen/OsFS/simple_with_dot 880ms
go.k6.io/k6/js/modules/k6/ws TestSession 860ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/constant-vus 850ms
go.k6.io/k6/js TestNewBundle/stdin 850ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[0](1,1) 840ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[0]_case[2](2,1) 830ms
go.k6.io/k6/js TestOpen/OsFS/simple 830ms
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomTags/ramping-vus 820ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[0]_case[3](5,2) 820ms
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomTags/constant-arrival-rate 810ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/externally-controlled 800ms
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomTags/externally-controlled 770ms
go.k6.io/k6/core/local TestExecutionSchedulerRunCustomTags/constant-vus 770ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/constant-vus 770ms
go.k6.io/k6/js/modules/k6/data TestSharedArrayRaceInInitialization 760ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="/path/to/lib.js"/const="./sub/const.js" 750ms
go.k6.io/k6/js TestNewBundle/Minimal 750ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[0]_case[4](25,2) 740ms
go.k6.io/k6/cmd TestRuntimeOptions/RuntimeOptions_test_'summary_and_thresholds_from_env' 740ms
go.k6.io/k6/js TestOpen/MemMapFS/relative2 740ms
go.k6.io/k6/js TestOpen/MemMapFS/relative_wonky 740ms
go.k6.io/k6/js TestOpen/MemMapFS/relative1 720ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="/path/to/lib.js"/const="../const.js" 720ms
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS/cipher_suite_ecc384 720ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="/path/to/lib.js"/const="./const.js" 710ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[1](2,2) 700ms
go.k6.io/k6/js TestNewBundleFromArchive/es6_script_explicit 680ms
go.k6.io/k6/js TestOpen/MemMapFS/fullpath2 670ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[0]_case[1](2,2) 670ms
go.k6.io/k6/js TestOpen/MemMapFS/fullpath 670ms
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS/tls11 660ms
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS/cipher_suite_cbc 660ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/SupportedVersion/Source 660ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/constant-arrival-rate 650ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/SupportedVersion/Archive 650ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/shared-iterations 650ms
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS/tls10 650ms
go.k6.io/k6/js TestNewBundleFromArchive/es6_script_default 650ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/NullVersion/Source 650ms
go.k6.io/k6/js TestInitContextRequire/Files/Invalid 640ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[4](25,2) 640ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/NullVersion/Archive 630ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[3](5,2) 630ms
go.k6.io/k6/api/v1 TestPatchStatus 630ms
go.k6.io/k6/js/modules/k6/http TestRequestAndBatchTLS/tls12 620ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="/path/to/lib.js"/inline 610ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[2](2,1) 610ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[2]_case[5](50,5) 600ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/SupportedCipherSuite/Source 580ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/SupportedCipherSuite/Archive 580ms
go.k6.io/k6/js TestVUIntegrationInsecureRequests/True/Archive 580ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/NullCipherSuites/Archive 580ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/global/per-vu-iterations 580ms
go.k6.io/k6/js TestVUIntegrationTLSConfig/NullCipherSuites/Source 570ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="../lib.js"/const="../const.js" 570ms
go.k6.io/k6/js TestVUIntegrationInsecureRequests/True/Source 560ms
go.k6.io/k6/js TestInitContextRequire/Files/lib="../lib.js"/const="./sub/const.js" 560ms
go.k6.io/k6/core TestSetupException 550ms
go.k6.io/k6/core/local TestExecutionSchedulerRunEnv/override/per-vu-iterations 540ms
go.k6.io/k6/js TestOpen/MemMapFS/simple_with_two_dots 520ms
go.k6.io/k6/js TestOpen/MemMapFS/simple_with_dot 520ms
go.k6.io/k6/js TestNewBundle/DefaultWrongType 520ms
go.k6.io/k6/core TestSentReceivedMetrics/group/SentReceivedMetrics_script[3]_case[4](25,2) 510ms
go.k6.io/k6/js/modules/k6/ws TestSession/timeout 500ms
go.k6.io/k6/js TestNewBundleFromArchive/messed_up_archive 500ms
go.k6.io/k6/js TestBundleMakeArchive/extended 500ms

Skimming that list, I think that once we have capabilities to mock time in tests, for a lot of thse we can both refactor them to be more resilient (less "flaky"), but also reduce the time they actually take to execute. Right now they take a bunch of time because we are running actual executors or load tests and we leave generous margins to get our expected results, since we don't know exactly how long certain actions will take.

@olegbespalov olegbespalov self-assigned this Jan 19, 2022
@oleiade
Copy link
Member

oleiade commented Feb 9, 2022

In the process of working with @olegbespalov on #1719 we had the opportunity to experiment and learn a lot about time mocking. After discussing our results and findings with @na--, we've reached the agreement that we should not pursue our effort towards mocking time. Instead, we should invest some time into refactoring our codebase components to be less dependent on time.

Whenever making an assertion about some code execution based on time, we are making assumptions on scheduling (both from the OS and Go perspective), and on performance. Asserting that a given operation takes a given amount of time with a set acceptance delta, asserts whether the program, (and the OS and hardware running it) were able to perform it in said time. A problem we experienced in that context is that while those kinds of tests would pass on a beefy setup, they were much more likely to behave in a flaky way on shared/virtualized hardware with minimal, unreliable, specs, such as CI's.

// lorem_test.go 
func TestLorem(t *testing.T) {
  ...
  go func() {
     // bad practice, since we have no control/guaranty from the go scheduler when this go-routine will be executed 
     now := time.Now()
     
    assert.WithinDuration(t,
        startTime.Add(expectedTime),
        time.Now(),
        time.Millisecond*12,
        "%d expectedTime %s", current, expectedTime,
    )
  }
}

Our understanding of most tests involving time assertions was they really wanted to verify some behavior over time, rather than timings and durations themselves. Given an executor's configuration, they would assert that its behavior is corresponding to our expectation; based on when certain actions happen. The conclusion of our research and experimentation were: while this expectation and behavior does need to be asserted to validate k6 behaves appropriately, we believe another strategy should be used to achieve it. How to do that without relying on duration-based assertions is one of the ongoing objectives we set out for ourselves.

While experimenting with time mocking, specifically with the clock library, we've also found out that time mocking can lead to somewhat unpredictable behaviors. When addressable, we judged these workarounds would lead to introducing logic and code in the tests, which would effectively add more complexity than a plain redesign. One of the main issues we've encountered first hand is that, in the context of using a mocked clock, while time.Add(10 * time.Milliseconds) does move the clock's needles forward, the code depending on it still needs some amount of actual time to get scheduled and executed. Yet, the time mocking library does sleep under the hood, but for 1ms only. Thus, potentially heavy or blocking operations might not have the time to get executed, before assertions made on (mocked) timing are executed.

Finally, and linked to the previous finding, scheduling is neither predictable, nor controllable. Scanning through clock's documentation, and the mocking time in Go article, one will notice they recommend using runtime.Gosched() explicitly. Performing that operation asks the Go Scheduler to schedule some work. This intends to be a "workaround", potentially addressing the previously mentioned issue. Yet, our understanding is that calling runtime.Gosched() works on the best effort basis. It does guarantee all the (go routine) work that needs to happen between two clock ticks was scheduled nor performed.

Nonetheless, we still intend to make flaky tests reliable again. To do so, we have decided on a few axes moving forward. We want to redesign components which led to time-based assertions in the first place. Moving forward, we need to keep asserting performance still. It allows us having certainties about the behavior of the program. It also allows us to provide our users guarantees. Thus, we will drive an effort towards establishing such a performance testing strategy. One that's more reliable than what we have now.

@oleiade oleiade closed this as completed Feb 9, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants