Perf test begins at February 4, 2024 at 01:57:58 PM UTC A new loop begins at February 4, 2024 at 01:58:07 PM UTC /var/tmp/bins/crutest perf -g 1 -t 127.0.0.1:8810 -t 127.0.0.1:8820 -t 127.0.0.1:8830 -c 30000 -q --write-loops 2 --read-loops 2 --perf-out /tmp/perf-ES-16384-EC-640.csv {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284161718Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"93b33136315e8cafbb8542022f326676bfda840d\",\n git_commit_timestamp: \"2024-02-04T04:19:59.000000000Z\",\n git_branch: \"renovate/reedline-0.x\",\n rustc_semver: \"1.75.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"82e1608dfa6e0b5569232559e3d385fea5a93112\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284473074Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.28448754Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} {"msg":"Crucible 8f5d5e22-4fd9-4a8b-b751-cc759aaa4e8d has session id: 149848e9-26cf-41c6-be26-0a4e7864b97b","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284494947Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Upstairs opts: Upstairs UUID: 8f5d5e22-4fd9-4a8b-b751-cc759aaa4e8d, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284572381Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Crucible stats registered with UUID: 8f5d5e22-4fd9-4a8b-b751-cc759aaa4e8d","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284597736Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.284917604Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} {"msg":"8f5d5e22-4fd9-4a8b-b751-cc759aaa4e8d active request set","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.28513043Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285168963Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285204982Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285213949Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285222107Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285229631Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285236933Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285391135Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285440665Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285457851Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285471113Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285490826Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.285513604Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"io task","client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286886446Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286921408Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286933308Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286941027Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286948222Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.286956697Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.287610197Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.28765435Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.287667852Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292484695Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292527485Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.29253698Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292684241Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292723318Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292732656Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292801592Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.29283524Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[0]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292844109Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[0]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292851932Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[0]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292859721Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[1]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292868447Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[1]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292875476Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[1]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292899544Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[2]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292907146Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[2]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292914362Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292921423Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Max found gen is 1","v":0,"name":"crucibleWait for a query_work_queue command to finish before sending IO ","level":30,"time":"2024-02-04T13:58:07.292948629Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.29295632Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292963474Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292987644Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.292995932Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293002573Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293009774Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.29301684Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293044977Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.29305146Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"8f5d5e22-4fd9-4a8b-b751-cc759aaa4e8d is now active with session: 149848e9-26cf-41c6-be26-0a4e7864b97b","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293057894Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293064302Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154,"session_id":"149848e9-26cf-41c6-be26-0a4e7864b97b"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:58:07.293070656Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} Region: es:16384 ec:640 bs:4096 ts:42949672960 tb:10485760 max_io:256 or 1048576 Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 19.13 30000 1 1568.23 0.00064 0.00153 0.00239 0.07084 16384 640 rwrites 14.59 30000 1 2056.75 0.00049 0.00105 0.00221 0.08654 16384 640 rreads 10.43 30000 1 2875.54 0.00035 0.00046 0.00057 0.01678 16384 640 rreads 10.46 30000 1 2869.31 0.00035 0.00046 0.00057 0.01731 16384 640 {"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2024-02-04T13:59:04.340255475Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1154} A new loop begins at February 4, 2024 at 01:59:15 PM UTC /var/tmp/bins/crutest perf -g 1 -t 127.0.0.1:8810 -t 127.0.0.1:8820 -t 127.0.0.1:8830 -c 30000 -q --write-loops 2 --read-loops 2 --perf-out /tmp/perf-ES-16384-EC-1280.csv {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078264936Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"93b33136315e8cafbb8542022f326676bfda840d\",\n git_commit_timestamp: \"2024-02-04T04:19:59.000000000Z\",\n git_branch: \"renovate/reedline-0.x\",\n rustc_semver: \"1.75.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"82e1608dfa6e0b5569232559e3d385fea5a93112\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078491143Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078501496Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173} Crucible runtime is spawned {"msg":"Crucible 4229b86b-648e-4a57-b510-5cc9de139c96 has session id: cff81e85-6b7e-4097-b502-863ba0b8ea36","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078589969Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Upstairs opts: Upstairs UUID: 4229b86b-648e-4a57-b510-5cc9de139c96, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078629458Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Crucible stats registered with UUID: 4229b86b-648e-4a57-b510-5cc9de139c96","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078637817Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078644522Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173} {"msg":"4229b86b-648e-4a57-b510-5cc9de139c96 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.07865406Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078681853Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078694503Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078701974Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078709736Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078744096Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078759036Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078806005Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078855734Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.078871507Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079003748Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079039169Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079183798Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"io task","client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079462801Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079515554Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079561953Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079576033Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079590335Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.079613398Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.080161642Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.080425197Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.08046512Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.090077501Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.090109526Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.090118339Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.092683818Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.092726496Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.092735943Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.09301835Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093049721Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[0]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.09305806Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[0]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093065982Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[0]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093073585Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[1]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.09308136Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[1]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093088824Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[1]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093096457Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[2]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093131238Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[2]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093144112Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093194255Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093234622Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093274242Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.09331377Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093354024Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093393768Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093432429Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.09347213Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093511087Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093550334Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093588937Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"4229b86b-648e-4a57-b510-5cc9de139c96 is now active with session: cff81e85-6b7e-4097-b502-863ba0b8ea36","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093627598Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093665864Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173,"session_id":"cff81e85-6b7e-4097-b502-863ba0b8ea36"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-04T13:59:15.093704325Z","hostname":"ip-10-150-1-34.us-west-2.compute.internal","pid":1173} Wait for a query_work_queue command to finish before sending IO Region: es:16384 ec:1280 bs:4096 ts:85899345920 tb:20971520 max_io:256 or 1048576 Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 16.60 30000 1 1807.57 0.00055 0.00135 0.00260 0.05975 16384 1280 rwrites 16.91 30000 1 1773.97 0.00056 0.00145 0.00263 0.06949 16384 1280 rreads 10.45 30000 1 2871.59 0.00035 0.00046 0.00058 0.01769 16384 1280 rreads 10.38 30000 1 2890.37 0.00035 0.00045 0.00057 0.01769 16384 1280 Perf test finished on February 4, 2024 at 02:00:15 PM UTC