/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 1.5177338 Downstairs region 1 created at /var/tmp/dsc/8820 in 0.7213657 Downstairs region 2 created at /var/tmp/dsc/8830 in 0.67726946 Region set with 3 regions was created Using existing output directory "/tmp/dsc" start ds: 8810 start ds: 8820 start ds: 8830 start access at:127.0.0.1:9998 Starting downstairs at port 8820 Starting downstairs at port 8810 Make output file at "/tmp/dsc/downstairs-8820.txt" Make output file at "/tmp/dsc/downstairs-8810.txt" Starting downstairs at port 8830 Make output file at "/tmp/dsc/downstairs-8830.txt" [8820][1] reports Starting [8810][0] reports Starting [8830][2] reports Starting Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1171) [8810][0] reports Running Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1172) [8830][2] reports Running Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1173) [8820][1] reports Running Sep 22 23:32:57.732 INFO listening, local_addr: 127.0.0.1:9998 Control access at:127.0.0.1:9998 1171 1172 1173 Sep 22 23:33:02.806 INFO accepted connection, remote_addr: 127.0.0.1:46543, local_addr: 127.0.0.1:9998 Main task has work to do, go find it Sep 22 23:33:02.807 INFO request completed, latency_us: 334, response_code: 204, uri: /disablerestart/all, method: POST, req_id: 60fbd86c-9578-470b-8a99-d1b43e9fc6f9, remote_addr: 127.0.0.1:46543, local_addr: 127.0.0.1:9998 got dsc DisableRestartAll disable restart on all: 3 [8810] Disable keep_running [8820] Disable keep_running [8830] Disable keep_running A new loop begins at September 22, 2023 at 11:33:02 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":"2023-09-22T23:33:02.843961845Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"ed48f294784d46ea7d4bb99336918b74358eca46\",\n git_commit_timestamp: \"2023-09-22T22:51:18.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.70.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"90c541806f23a127002de5b4038be731ba1458ca\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.844376284Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Upstairs <-> Downstairs Message Version: 4","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.844387413Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Crucible stats registered with UUID: 99dec632-03ce-4976-8159-75bd660d3ec7","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.844394307Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Crucible 99dec632-03ce-4976-8159-75bd660d3ec7 has session id: ed230324-cf80-44f4-9cf6-80a215466129","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.844427976Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} Crucible runtime is spawned The guest has requested activation with gen:1 {"msg":"up_listen starts","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.84519838Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"task":"up_listen"} {"msg":"Wait for all three downstairs to come online","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845239454Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Flush timeout: 0.5","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845247064Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845428434Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"0"} {"msg":"[2] connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845459991Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"2"} {"msg":"[1] connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845467479Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"1"} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 active request set","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845561482Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Set desired generation to :1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845609744Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] 99dec632-03ce-4976-8159-75bd660d3ec7 looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.845877301Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"2"} {"msg":"[2] Proc runs for 127.0.0.1:8830 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.846005355Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] 99dec632-03ce-4976-8159-75bd660d3ec7 looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.846243969Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"1"} {"msg":"[1] Proc runs for 127.0.0.1:8820 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.846298301Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] 99dec632-03ce-4976-8159-75bd660d3ec7 looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.846309984Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181,"looper":"0"} {"msg":"[0] Proc runs for 127.0.0.1:8810 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.846321123Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) New New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848123119Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848144485Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] client is_active_req TRUE, promote! session d5f70f24-53eb-41cb-a091-f8999b2390ac","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848217595Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) WaitActive New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848235112Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848245888Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) WaitActive New WaitActive ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848256138Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848266527Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] client is_active_req TRUE, promote! session d5f70f24-53eb-41cb-a091-f8999b2390ac","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.84827665Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] client is_active_req TRUE, promote! session d5f70f24-53eb-41cb-a091-f8999b2390ac","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848286958Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] downstairs client at 127.0.0.1:8810 has UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848732723Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] Got region def 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":"2023-09-22T23:33:02.848769385Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] downstairs client at 127.0.0.1:8820 has UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848780872Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] Got region def RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 640, uuid: 12345678-0000-0000-0000-000000008820, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848791931Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848829412Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848840411Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] downstairs client at 127.0.0.1:8830 has UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848850986Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] Got region def RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 640, uuid: 12345678-0000-0000-0000-000000008830, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848862089Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.848873211Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) WaitActive WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87666777Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.876707992Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:02.876715898Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.876781349Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] 127.0.0.1:8820 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.876889361Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitActive WaitQuorum WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.876896614Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Waiting for 2 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87690307Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.876909679Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) WaitActive WaitQuorum WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877066205Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877094105Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:02.877100688Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877107039Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] 127.0.0.1:8830 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877113176Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitActive WaitQuorum WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877137149Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Waiting for 1 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877143576Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877149612Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] 99dec632-03ce-4976-8159-75bd660d3ec7 (d5f70f24-53eb-41cb-a091-f8999b2390ac) WaitActive WaitQuorum WaitQuorum ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877155745Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877162108Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:02.87716782Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877175132Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] 127.0.0.1:8810 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87718111Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 WaitQuorum WaitQuorum WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877186944Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877192989Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877215712Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877222346Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877228298Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877235573Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877241479Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877247124Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877253185Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"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":"2023-09-22T23:33:02.877259133Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877281586Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877287469Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877293322Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877381236Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"No downstairs repair required","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87741459Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"No initial repair work was required","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877421009Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Set Downstairs and Upstairs active","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877426792Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 is now active with session: d5f70f24-53eb-41cb-a091-f8999b2390ac","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877432744Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} The guest has finished waiting for activation with:1 {"msg":"99dec632-03ce-4976-8159-75bd660d3ec7 Set Active after no repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877494348Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Notify all downstairs, region set compare is done.","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877521948Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877528292Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877534115Z"Wait for a query_work_queue command to finish before sending IO ,"hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877544289Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877550185Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877564901Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877592539Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877602093Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87771146Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.87775515Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:02.877766479Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} Region: es:16384 ec:640 bs:4096 ts:42949672960 tb:10485760 max_io:256 or 1048576 {"msg":"Checking if live repair is needed","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:03.878456777Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"No Live Repair required at this time","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:33:03.878502388Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:06.409543448Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:06.411615092Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:06.412219915Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:33:59.752316371Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:00.243526272Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:00.364173105Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} rwrites 23.28 30000 1 1288.58 0.00078 0.00120 0.00162 0.02692 16384 640 {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:08.95823399Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:08.95910871Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:08.963171366Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:59.288307942Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:34:59.386868529Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:00.217103539Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1181} rwrites 23.59 30000 1 1271.56 0.00079 0.00123 0.00180 0.01841 16384 640 rreads 18.31 30000 1 1638.18 0.00061 0.00075 0.00091 0.01027 16384 640 rreads 18.26 30000 1 1642.83 0.00061 0.00075 0.00091 0.01027 16384 640 Perf test completed, stop all downstairs Sep 22 23:35:42.874 INFO accepted connection, remote_addr: 127.0.0.1:55477, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Sep 22 23:35:42.875 Shut it down INFO request completed, latency_us: 98, response_code:[8830] Disable keep_running 204, uri: /shutdown, method: [8830] Got stop action so:false kr:false POST, req_id: 27e70ef3-10e6-48c8-9920-f7004de06764, remote_addr: 127.0.0.1:55477, local_addr: 127.0.0.1:9998 [8810] Disable keep_running [8810] Got stop action so:false kr:false [8820] Disable keep_running [8820] Got stop action so:false kr:false [8830] Exited with: ExitStatus(unix_wait_status(9)) [8820] Exited with: ExitStatus(unix_wait_status(9)) [8810] Exited with: ExitStatus(unix_wait_status(9)) [8830][2] reports Exit [8820][1] reports Exit [8810][0] 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.2438431 Downstairs region 1 created at /var/tmp/dsc/8820 in 1.2521267 Downstairs region 2 created at /var/tmp/dsc/8830 in 1.3263755 Region set with 3 regions was created Using existing output directory "/tmp/dsc" 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 8830 Make output file at "/tmp/dsc/downstairs-8830.txt" [8810][0] reports Starting [8830][2] reports Starting Starting downstairs at port 8820 Make output file at "/tmp/dsc/downstairs-8820.txt" [8820][1] reports Starting Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1190) [8810][0] reports Running Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1191) [8820][1] reports Running Sep 22 23:35:48.024 INFO listeningDownstairs /var/tmp/dsc/8830 port 8830 PID:Some(1192) , local_addr: 127.0.0.1:9998 [8830][2] reports Running Control access at:127.0.0.1:9998 1190 1191 1192 Sep 22 23:35:53.101 INFO accepted connection, remote_addr: 127.0.0.1:49106, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc DisableRestartAll disable restart on all: 3 Sep 22 23:35:53.102 INFO request completed[8810] Disable keep_running [8820] Disable keep_running , [8830] Disable keep_running latency_us: 284, response_code: 204, uri: /disablerestart/all, method: POST, req_id: c9389530-4567-4f62-91db-b9b1ec2d82ae, remote_addr: 127.0.0.1:49106, local_addr: 127.0.0.1:9998 A new loop begins at September 22, 2023 at 11:35:53 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":"2023-09-22T23:35:53.140037669Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"ed48f294784d46ea7d4bb99336918b74358eca46\",\n git_commit_timestamp: \"2023-09-22T22:51:18.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.70.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"90c541806f23a127002de5b4038be731ba1458ca\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140411924Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Upstairs <-> Downstairs Message Version: 4","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140427048Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Crucible stats registered with UUID: 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140434107Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Crucible 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb has session id: 5e0d4b85-569f-4a9a-8191-9276137cc7d8","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140441235Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} Crucible runtime is spawned The guest has requested activation with gen:1 {"msg":"up_listen starts","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.1406943Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"task":"up_listen"} {"msg":"Wait for all three downstairs to come online","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140746706Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Flush timeout: 0.5","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140758082Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140874572Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"2"} {"msg":"[0] connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140931074Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"0"} {"msg":"[1] connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.140948402Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"1"} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb active request set","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141031745Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Set desired generation to :1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141041852Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141108696Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"2"} {"msg":"[0] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141124636Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"0"} {"msg":"[0] Proc runs for 127.0.0.1:8810 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141306856Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb looper connected","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141326884Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200,"looper":"1"} {"msg":"[2] Proc runs for 127.0.0.1:8830 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141346397Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Proc runs for 127.0.0.1:8820 in state New","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141459661Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) New New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141910296Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141968446Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) WaitActive New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.141981012Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.14199513Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] client is_active_req TRUE, promote! session 4b5eefb3-5712-49f7-893e-5d541a370b50","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.142002056Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] client is_active_req TRUE, promote! session 4b5eefb3-5712-49f7-893e-5d541a370b50","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.142008369Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) WaitActive New WaitActive ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.142028851Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.142073727Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] client is_active_req TRUE, promote! session 4b5eefb3-5712-49f7-893e-5d541a370b50","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.142085661Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] downstairs client at 127.0.0.1:8810 has UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143049625Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] downstairs client at 127.0.0.1:8830 has UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143063181Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] downstairs client at 127.0.0.1:8820 has UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143081854Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Got region def RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 1280, uuid: 12345678-0000-0000-0000-000000008820, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143105996Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] Got region def RegionDefinition { block_size: 4096, extent_size: Block { value: 16384, shift: 12 }, extent_count: 1280, uuid: 12345678-0000-0000-0000-000000008830, encrypted: false, database_read_version: 1, database_write_version: 1 }","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143149992Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] Got region def 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":"2023-09-22T23:35:53.143161413Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143300135Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143343512Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.143356036Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) WaitActive WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208738601Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.20878328Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:53.208795532Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208804835Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] 127.0.0.1:8810 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208814699Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitQuorum WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208824923Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Waiting for 2 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208834911Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.208908902Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) WaitQuorum WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.21518548Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215221458Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:53.215228213Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215234351Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] 127.0.0.1:8820 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215240709Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitQuorum WaitQuorum WaitActive","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215246931Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Waiting for 1 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215254454Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.215260515Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] 7b63a869-c07b-4a0d-b4e1-f86e7828e7eb (4b5eefb3-5712-49f7-893e-5d541a370b50) WaitQuorum WaitQuorum WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216561653Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216592774Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:53.216599291Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.21660691Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] 127.0.0.1:8830 task reports connection:true","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216613099Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb WaitQuorum WaitQuorum WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216619649Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216626151Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216634023Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216640514Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.21664671Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216652596Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216658557Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216664418Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216671276Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"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":"2023-09-22T23:35:53.216677373Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216683218Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216689107Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216696308Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216702388Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"No downstairs repair required","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216708591Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"No initial repair work was required","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216716445Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Set Downstairs and Upstairs active","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216722615Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb is now active with session: 4b5eefb3-5712-49f7-893e-5d541a370b50","v":0,"name":"crucibleThe guest has finished waiting for activation with:1 Wait for a query_work_queue command to finish before sending IO ","level":30,"time":"2023-09-22T23:35:53.216898696Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"7b63a869-c07b-4a0d-b4e1-f86e7828e7eb Set Active after no repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216914152Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Notify all downstairs, region set compare is done.","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216956587Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216965698Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216972264Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216978226Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216985808Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216991786Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.216997677Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.217003603Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.217009389Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.217015534Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:53.217039681Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} Region: es:16384 ec:1280 bs:4096 ts:85899345920 tb:20971520 max_io:256 or 1048576 {"msg":"Checking if live repair is needed","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:54.217616673Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"No Live Repair required at this time","v":0,"name":"crucible","level":30,"time":"2023-09-22T23:35:54.217662804Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:57.115463946Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:57.194270627Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:35:57.201812381Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:50.618609204Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:50.988081708Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:50.989488106Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} rwrites 23.76 30000 1 1262.77 0.00079 0.00122 0.00183 0.03262 16384 1280 {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:59.884348801Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:59.899762798Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:36:59.915194659Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:37:52.126085125Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:37:52.155244822Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-09-22T23:37:52.185879281Z","hostname":"ip-10-150-1-11.us-west-2.compute.internal","pid":1200} rwrites 24.53 30000 1 1223.04 0.00082 0.00130 0.00200 0.03237 16384 1280 rreads 18.24 30000 1 1644.97 0.00061 0.00076 0.00091 0.01021 16384 1280 rreads 18.05 30000 1 1661.86 0.00060 0.00075 0.00091 0.01021 16384 1280 Perf test completed, stop all downstairs Sep 22 23:38:34.977 INFO accepted connection, remote_addr: 127.0.0.1:38016, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Sep 22 23:38:34.977 INFO request completed, latency_us: 93, response_code:Shut it down [8820] Disable keep_running 204, uri: /shutdown, method: [8820] Got stop action so:false kr:false POST, req_id: 5669995f-3428-456a-859a-9354cf18cb00, remote_addr: 127.0.0.1:38016, [8830] Disable keep_running local_addr: 127.0.0.1:9998 [8810] Disable keep_running [8810] Got stop action so:false kr:false [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)) [8810][0] reports Exit [8820] Exited with: ExitStatus(unix_wait_status(9)) [8820][1] reports Exit TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 23.28 30000 1 1288.58 0.00078 0.00120 0.00162 0.02692 16384 640 rwrites 23.59 30000 1 1271.56 0.00079 0.00123 0.00180 0.01841 16384 640 rwrites 23.76 30000 1 1262.77 0.00079 0.00122 0.00183 0.03262 16384 1280 rwrites 24.53 30000 1 1223.04 0.00082 0.00130 0.00200 0.03237 16384 1280 TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rreads 18.31 30000 1 1638.18 0.00061 0.00075 0.00091 0.01027 16384 640 rreads 18.26 30000 1 1642.83 0.00061 0.00075 0.00091 0.01027 16384 640 rreads 18.24 30000 1 1644.97 0.00061 0.00076 0.00091 0.01021 16384 1280 rreads 18.05 30000 1 1661.86 0.00060 0.00075 0.00091 0.01021 16384 1280 Perf test finished on September 22, 2023 at 11:38:36 PM UTC