Perf test begins at September 27, 2024 at 11:06:53 PM UTC A new loop begins at September 27, 2024 at 11:07:01 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":"look at: http://127.0.0.1:12810 ","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.346933443Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"task":"crutest"} {"msg":"RI is: RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 640, uuid: 12345678-0000-0000-0000-000000008810, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.38809805Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"task":"crutest"} {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.388707204Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"60f78286ad49cec90cdcc3e028e5e9c76d4fdc1d\",\n git_commit_timestamp: \"2024-09-27T22:46:32.000000000Z\",\n git_branch: \"alan/tests-use-dsc\",\n rustc_semver: \"1.80.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"051478957371ee0084a7c0913941d2a8c4757bb9\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.38876007Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} {"msg":"Upstairs <-> Downstairs Message Version: 11","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.388772889Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} {"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 640, uuid: 00000000-0000-0000-0000-000000000000, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.388777408Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} {"msg":"Crucible bca26bc1-dbb8-4ebb-9024-7879bd618f84 has session id: e4636d35-9142-4927-bb2e-eb5082a04300","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.389265071Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Upstairs opts: Upstairs UUID: bca26bc1-dbb8-4ebb-9024-7879bd618f84, 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-09-27T23:07:01.389371903Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Crucible stats registered with UUID: bca26bc1-dbb8-4ebb-9024-7879bd618f84","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.389387322Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.419909492Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} {"msg":"bca26bc1-dbb8-4ebb-9024-7879bd618f84 active request set","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.41993354Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.419941769Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.419998235Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420010144Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420019503Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420029353Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420049081Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.42005866Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420069999Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420076089Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_connection connected from Ok(127.0.0.1:34747)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420218328Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_connection connected from Ok(127.0.0.1:35385)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420346358Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_connection connected from Ok(127.0.0.1:40847)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420390375Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"io task","client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420685272Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420698642Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420753807Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420771456Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420776965Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.420781415Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.420953862Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.42097247Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.42098054Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.423550704Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.423566072Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.423570982Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424087413Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424104562Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424110341Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424114791Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.42412014Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424206924Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424221962Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424227642Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424232852Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424237961Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.424243381Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.42424872Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.4242539Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"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-09-27T23:07:01.42425976Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424265629Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424270929Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424276058Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424281088Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"":"downstairs","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424287377Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424291747Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"0","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424296787Z","Wait for a query_work_queue command to finish before sending IO hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"1","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424305046Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"client":"2","":"downstairs","session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424310826Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424315365Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"bca26bc1-dbb8-4ebb-9024-7879bd618f84 is now active with session: e4636d35-9142-4927-bb2e-eb5082a04300","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424319745Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424324195Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196,"session_id":"e4636d35-9142-4927-bb2e-eb5082a04300"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:01.424328664Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1196} 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 5.15 30000 1 5830.23 0.00017 0.00046 0.00124 0.06689 16384 640 rwrites 5.05 30000 1 5935.09 0.00017 0.00046 0.00119 0.07630 16384 640 rreads 5.44 30000 1 5512.07 0.00018 0.00023 0.00029 0.00672 16384 640 rreads 5.39 30000 1 5564.10 0.00018 0.00023 0.00028 0.00672 16384 640 A new loop begins at September 27, 2024 at 11:07:39 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":"look at: http://127.0.0.1:12810 ","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.316814817Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"task":"crutest"} {"msg":"RI is: RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 1280, uuid: 12345678-0000-0000-0000-000000008810, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.357169996Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"task":"crutest"} {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.357758131Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"60f78286ad49cec90cdcc3e028e5e9c76d4fdc1d\",\n git_commit_timestamp: \"2024-09-27T22:46:32.000000000Z\",\n git_branch: \"alan/tests-use-dsc\",\n rustc_semver: \"1.80.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"051478957371ee0084a7c0913941d2a8c4757bb9\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.357789199Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} {"msg":"Upstairs <-> Downstairs Message Version: 11","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.357799119Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} {"msg":"Using region definition RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 1280, uuid: 00000000-0000-0000-0000-000000000000, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.357807988Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} {"msg":"Crucible 046bf7a6-afcf-4028-bffa-afead9e0ef88 has session id: 268fbf69-4373-4cad-bbab-177d1380aa12","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.358109655Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Upstairs opts: Upstairs UUID: 046bf7a6-afcf-4028-bffa-afead9e0ef88, 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-09-27T23:07:39.358141582Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Crucible stats registered with UUID: 046bf7a6-afcf-4028-bffa-afead9e0ef88","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.358151472Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388005102Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} {"msg":"046bf7a6-afcf-4028-bffa-afead9e0ef88 active request set","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.38803168Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.38804062Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388058209Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388067088Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388087586Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388097095Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388106845Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388116214Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388126073Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388135912Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_connection connected from Ok(127.0.0.1:38646)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388249454Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_connection connected from Ok(127.0.0.1:54798)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388262483Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_connection connected from Ok(127.0.0.1:55760)","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388270572Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"io task","client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388585928Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388606947Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388620535Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388625645Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388666292Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.388714308Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.388838899Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.388918643Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.389042753Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.394444331Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.394468069Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.394474399Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395604912Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.39563236Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.39564233Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395650639Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395661178Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395698355Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395717164Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395722653Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395727703Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395732892Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395737562Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395743822Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395748081Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"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-09-27T23:07:39.395752231Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395758521Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.39576708Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395776279Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395783789Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"":"downstairs","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395800687Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395805157Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"0","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395809337Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"1","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395813336Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"client":"2","":"downstairs","session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395818216Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395822716Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"046bf7a6-afcf-4028-bffa-afead9e0ef88 is now active with session: 268fbf69-4373-4cad-bbab-177d1380aa12","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395826475Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395830995Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215,"session_id":"268fbf69-4373-4cad-bbab-177d1380aa12"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-09-27T23:07:39.395845594Z","hostname":"w-01J8TVQCPGEHTFRK3TP053XNFM","pid":1215} 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 6.19 30000 1 4848.00 0.00021 0.00067 0.00135 0.05480 16384 1280 rwrites 6.29 30000 1 4767.02 0.00021 0.00077 0.00136 0.06287 16384 1280 rreads 5.37 30000 1 5586.96 0.00018 0.00022 0.00028 0.00661 16384 1280 rreads 5.33 30000 1 5627.18 0.00018 0.00022 0.00027 0.00661 16384 1280 Perf test finished on September 27, 2024 at 11:08:06 PM UTC