/input/rbuild/work Create region with ES:16384 EC:640 BS:4096 Creating region directory at: /var/tmp/dsc Creating dsc directory at: /tmp/dsc Downstairs region 0 created at /var/tmp/dsc/8810 in 0.7445072 Downstairs region 1 created at /var/tmp/dsc/8820 in 0.7779178 Downstairs region 2 created at /var/tmp/dsc/8830 in 0.8146672 Created 3 regions Using existing output directory "/tmp/dsc" Update our region info with: Some(RegionExtentInfo { block_size: 4096, blocks_per_extent: 16384, extent_count: 640 }) start ds: 8810 start access at:127.0.0.1:9998 start ds: 8820 start ds: 8830 Starting downstairs at port 8810 Starting downstairs at port 8820 Make output file at "/tmp/dsc/downstairs-8810.txt" [8810][0] initial start wait reports Starting Make output file at "/tmp/dsc/downstairs-8820.txt" [8820][1] initial start wait reports Starting Starting downstairs at port 8830 Make output file at "/tmp/dsc/downstairs-8830.txt" [8830][2] initial start wait reports Starting Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1186) [8810][0] initial start wait reports Running Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1187) [8830][2] initial start wait reports Running Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1188) [8820][1] initial start wait reports Running All downstairs are running Oct 09 15:59:36.794 INFO listening, local_addr: 127.0.0.1:9998 Control access at:127.0.0.1:9998 1186 1187 1188 Oct 09 15:59:41.830 INFO accepted connection, remote_addr: 127.0.0.1:39451, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc DisableRestartAll disable restart on all: 3 Oct 09 15:59:41.831 INFO request completed, latency_us: 111, response_code: 204, uri: /disablerestart/all, method: POST, req_id: d15b765c-3ea2-43c2-934d-595bf4a6cd03, remote_addr: 127.0[8820] Disable keep_running .[8810] Disable keep_running 0.1:39451, local_addr: 127.0.0.1:9998[8830] Disable keep_running A new loop begins at October 9, 2024 at 03:59:41 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-10-09T15:59:41.854303718Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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-10-09T15:59:41.894479692Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"task":"crutest"} {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.895078697Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"2c0786a526029769ef78500aefc86c57b8d88d36\",\n git_commit_timestamp: \"2024-10-09T15:37:03.000000000Z\",\n git_branch: \"alan/test-more-regions\",\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-10-09T15:59:41.895112724Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196} {"msg":"Upstairs <-> Downstairs Message Version: 11","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.895127102Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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-10-09T15:59:41.895132392Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196} {"msg":"Crucible aeca3363-cb59-4bdf-856b-c680db30b71a has session id: dab384d3-85e9-4971-8626-eb010c22c5c8","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.895690062Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Upstairs opts: Upstairs UUID: aeca3363-cb59-4bdf-856b-c680db30b71a, 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-10-09T15:59:41.895748076Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Crucible stats registered with UUID: aeca3363-cb59-4bdf-856b-c680db30b71a","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.895754905Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925759461Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"task":"crutest"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925785788Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196} {"msg":"aeca3363-cb59-4bdf-856b-c680db30b71a active request set","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925823764Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925840482Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925875179Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925880788Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925885978Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925890607Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925895057Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925899466Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925943961Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.9259544Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_connection connected from Ok(127.0.0.1:62087)","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.925962229Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_connection connected from Ok(127.0.0.1:59026)","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926041101Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_connection connected from Ok(127.0.0.1:33756)","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926125372Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"io task","client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926500641Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926527569Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926538497Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926558935Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926567924Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.926576893Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.926809928Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.926827466Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.926833076Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.92902985Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929049967Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929057627Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929064486Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929069296Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929073865Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929077875Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929083334Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.92912535Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929137638Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929146097Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929150617Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929154806Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929159726Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929163885Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929167945Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"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-10-09T15:59:41.929180253Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929188353Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929192842Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929197502Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929202001Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"":"downstairs","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929206171Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.92921046Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"0","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.9292151Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"1","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929219239Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"client":"2","":"downstairs","session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929223929Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929227579Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"aeca3363-cb59-4bdf-856b-c680db30b71a is now active with session: dab384d3-85e9-4971-8626-eb010c22c5c8","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929231208Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} Wait for a query_work_queue command to finish before sending IO {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929283482Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1196,"session_id":"dab384d3-85e9-4971-8626-eb010c22c5c8"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T15:59:41.929295031Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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.30 30000 1 5660.69 0.00018 0.00051 0.00124 0.05156 16384 640 rwrites 5.45 30000 1 5508.89 0.00018 0.00056 0.00128 0.05996 16384 640 rreads 5.40 30000 1 5553.14 0.00018 0.00023 0.00029 0.00952 16384 640 rreads 5.35 30000 1 5609.13 0.00018 0.00023 0.00028 0.00952 16384 640 Perf test completed, stop all downstairs Oct 09 16:00:09.713 INFO accepted connection, remote_addr: 127.0.0.1:55296, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Shut it down Oct 09 16:00:09.713 INFO request completed, latency_us: 60, response_code[8810] Disable keep_running : 204, uri:[8810] Got stop action so:false kr:false [8830] Disable keep_running /shutdown[8820] Disable keep_running , [8820] Got stop action so:false kr:false method: POST, req_id: e5c9f06c-683e-4f06-9cce-c17553b150bc, remote_addr: 127.0.0.1:55296, local_addr: 127.0.0.1:9998 [8830] Got stop action so:false kr:false [8810] Exited with: ExitStatus(unix_wait_status(9)) [8810][0] reports Exit [8830] Exited with: ExitStatus(unix_wait_status(9)) [8830][2] reports Exit [8820] Exited with: ExitStatus(unix_wait_status(9)) [8820][1] reports Exit Create region with ES:16384 EC:1280 BS:4096 Removing existing dsc directory "/tmp/dsc" Removing existing region "/var/tmp/dsc" Creating region directory at: /var/tmp/dsc Creating dsc directory at: /tmp/dsc Downstairs region 0 created at /var/tmp/dsc/8810 in 1.4226413 Downstairs region 1 created at /var/tmp/dsc/8820 in 1.4875231 Downstairs region 2 created at /var/tmp/dsc/8830 in 1.4422677 Created 3 regions Using existing output directory "/tmp/dsc" Update our region info with: Some(RegionExtentInfo { block_size: 4096, blocks_per_extent: 16384, extent_count: 1280 }) start ds: 8810 start ds: 8820 start ds: 8830 start access at:127.0.0.1:9998 Starting downstairs at port 8810 Make output file at "/tmp/dsc/downstairs-8810.txt" Starting downstairs at port 8820 [8810][0] initial start wait reports Starting [8820][1] initial start wait reports Starting Starting downstairs at port 8830 Make output file at "/tmp/dsc/downstairs-8820.txt" [8830][2] initial start wait reports Starting Make output file at "/tmp/dsc/downstairs-8830.txt" Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1205) [8810][0] initial start wait reports Running Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1206) [8820][1] initial start wait reports Running Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1207) [8830][2] initial start wait reports Running All downstairs are running Oct 09 16:00:15.129 INFO listening, local_addr: 127.0.0.1:9998 Control access at:127.0.0.1:9998 1206 1205 1207 Oct 09 16:00:20.168 INFO accepted connection, remote_addr: 127.0.0.1:63770, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc DisableRestartAll disable restart on all: 3 Oct 09 16:00:20.169 INFO request completed, latency_us: 108, response_code: 204, uri: /disablerestart/all, method: POST, req_id: 6e916874-d63a-4c67-b6aa-9bcc5632b945, remote_addr: 127.0.0.1:63770, local_addr: 127.0.0[8820] Disable keep_running .[8810] Disable keep_running 1:9998 [8830] Disable keep_running A new loop begins at October 9, 2024 at 04:00:20 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-10-09T16:00:20.189203097Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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-10-09T16:00:20.229736662Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"task":"crutest"} {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.230167286Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"2c0786a526029769ef78500aefc86c57b8d88d36\",\n git_commit_timestamp: \"2024-10-09T15:37:03.000000000Z\",\n git_branch: \"alan/test-more-regions\",\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-10-09T16:00:20.23022448Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215} {"msg":"Upstairs <-> Downstairs Message Version: 11","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.230235199Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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-10-09T16:00:20.230241298Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215} {"msg":"Crucible c1e079c1-7c32-40fa-b7a4-3330c49cdac1 has session id: 4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.230488211Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Upstairs opts: Upstairs UUID: c1e079c1-7c32-40fa-b7a4-3330c49cdac1, 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-10-09T16:00:20.230518918Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Crucible stats registered with UUID: c1e079c1-7c32-40fa-b7a4-3330c49cdac1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.230527897Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Downstairs in volume = 3","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261219959Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"task":"crutest"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261239337Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215} {"msg":"c1e079c1-7c32-40fa-b7a4-3330c49cdac1 active request set","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261254526Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261267984Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261279643Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261293431Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261299151Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.26130543Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.26131097Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261317249Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261322978Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261358624Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_connection connected from Ok(127.0.0.1:34970)","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261542975Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_connection connected from Ok(127.0.0.1:35160)","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261556963Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_connection connected from Ok(127.0.0.1:56124)","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261565582Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"io task","client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261793328Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261813356Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261886548Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261906656Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.261925374Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.26195434Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.262128642Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.262176057Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.262231881Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267611733Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.26763376Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267641769Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267645899Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267650108Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Waiting for more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267654498Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267691634Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267704513Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267709112Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267713632Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267717981Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267722741Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.26772703Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.26773171Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267736429Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267740669Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"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-10-09T16:00:20.267744868Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267749508Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267753727Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267757927Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267762056Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"":"downstairs","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267766146Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267770276Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"0","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267774425Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"1","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267778395Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"client":"2","":"downstairs","session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267783134Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267786794Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"c1e079c1-7c32-40fa-b7a4-3330c49cdac1 is now active with session: 4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267790413Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267794523Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","pid":1215,"session_id":"4fd3a509-0ed3-43d3-b4ef-97e0eb7f0ca3"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-10-09T16:00:20.267798113Z","hostname":"w-01J9S01QXFT4HWGBVG6X7YVJE4","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.44 30000 1 4659.97 0.00021 0.00080 0.00132 0.05977 16384 1280 rwrites 5.94 30000 1 5051.28 0.00020 0.00061 0.00129 0.07216 16384 1280 rreads 5.29 30000 1 5675.53 0.00018 0.00022 0.00027 0.00567 16384 1280 rreads 5.31 30000 1 5651.71 0.00018 0.00022 0.00027 0.00610 16384 1280 Perf test completed, stop all downstairs Oct 09 16:00:49.834 INFO accepted connection, remote_addr: 127.0.0.1:39587, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Shut it down Oct 09 16:00:49.835[8810] Disable keep_running [8810] Got stop action so:false kr:false INFO[8820] Disable keep_running request completed, latency_us: 63, response_code: 204, uri: /shutdown, method: POST, req_id: 9552d005-406e-4ac5-add0-4597d48832da, remote_addr: 127.0.0.1:39587, local_addr: 127.0.0.1:9998 [8820] Got stop action so:false kr:false [8830] Disable keep_running [8830] Got stop action so:false kr:false [8830] Exited with: ExitStatus(unix_wait_status(9)) [8830][2] reports Exit [8810] Exited with: ExitStatus(unix_wait_status(9)) [8820] Exited with: ExitStatus(unix_wait_status(9)) [8810][0] reports Exit [8820][1] reports Exit TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 5.30 30000 1 5660.69 0.00018 0.00051 0.00124 0.05156 16384 640 rwrites 5.45 30000 1 5508.89 0.00018 0.00056 0.00128 0.05996 16384 640 rwrites 6.44 30000 1 4659.97 0.00021 0.00080 0.00132 0.05977 16384 1280 rwrites 5.94 30000 1 5051.28 0.00020 0.00061 0.00129 0.07216 16384 1280 TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rreads 5.40 30000 1 5553.14 0.00018 0.00023 0.00029 0.00952 16384 640 rreads 5.35 30000 1 5609.13 0.00018 0.00023 0.00028 0.00952 16384 640 rreads 5.29 30000 1 5675.53 0.00018 0.00022 0.00027 0.00567 16384 1280 rreads 5.31 30000 1 5651.71 0.00018 0.00022 0.00027 0.00610 16384 1280 Perf test finished on October 9, 2024 at 04:00:50 PM UTC