/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.3102016 Downstairs region 1 created at /var/tmp/dsc/8820 in 0.8745623 Downstairs region 2 created at /var/tmp/dsc/8830 in 0.73289824 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 8830 Starting downstairs at port 8810 Make output file at "/tmp/dsc/downstairs-8810.txt" Starting downstairs at port 8820 Make output file at "/tmp/dsc/downstairs-8820.txt" Make output file at "/tmp/dsc/downstairs-8830.txt" [8830][2] reports Starting [8810][0] reports Starting [8820][1] 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 Oct 13 18:18:15.773 INFO listening, local_addr: 127.0.0.1:9998 Control access at:127.0.0.1:9998 1171 1172 1173 Oct 13 18:18:20.846 INFO accepted connection, remote_addr: 127.0.0.1:53205, 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 13 18:18:20.847 INFO request completed, latency_us: 292, response_code: 204, uri: /disablerestart/all, method[8810] Disable keep_running : POST, req_id: 0ccce78f-1ea1-42bd-a8a1-38df40c66778, remote_addr: 127.0.0.1:53205, local_addr: 127.0.0.1:9998 [8820] Disable keep_running [8830] Disable keep_running A new loop begins at October 13, 2023 at 06:18: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-640.csv {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.884626091Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"a730f3b26afaf115f27149ef849470fd85caef41\",\n git_commit_timestamp: \"2023-10-13T17:42:12.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-10-13T18:18:20.884943688Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Upstairs <-> Downstairs Message Version: 4","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.884954487Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Upstairs opts: Upstairs UUID: a76c2c75-faeb-44e6-9d63-279b3b78d414, 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":"2023-10-13T18:18:20.884962613Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Crucible stats registered with UUID: a76c2c75-faeb-44e6-9d63-279b3b78d414","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.884969676Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Crucible a76c2c75-faeb-44e6-9d63-279b3b78d414 has session id: 08de3fdb-771c-4cd7-82e0-37871bad5b21","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.885107471Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.885843667Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.885907268Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Flush timeout: 0.5","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.885940886Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.885947875Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.886107471Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181,"looper":"1"} {"msg":"[2] a76c2c75-faeb-44e6-9d63-279b3b78d414 looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886152548Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181,"looper":"2"} {"msg":"[0] connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886258796Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181,"looper":"0"} {"msg":"[1] a76c2c75-faeb-44e6-9d63-279b3b78d414 looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886270751Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181,"looper":"1"} {"msg":"[0] a76c2c75-faeb-44e6-9d63-279b3b78d414 looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886361847Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181,"looper":"0"} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 active request set","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886751321Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Set desired generation to :1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886770112Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] Proc runs for 127.0.0.1:8830 in state New","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886781832Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] Proc runs for 127.0.0.1:8820 in state New","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.886992354Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] Proc runs for 127.0.0.1:8810 in state New","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887041579Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) New New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887885121Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887902498Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) WaitActive New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887912498Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887922465Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] client is_active_req TRUE, promote! session 4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887932532Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] client is_active_req TRUE, promote! session 4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.887943469Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) WaitActive WaitActive New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.888159437Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.88832304Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] client is_active_req TRUE, promote! session 4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.888336208Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.888726513Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.888782952Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.888795505Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.88885456Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.888866262Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.888876408Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.888886887Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.888938793Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.888951908Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) WaitActive WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908068006Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908096062Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:18:20.908180426Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908221148Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908228612Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 WaitActive WaitActive WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908234816Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) WaitActive WaitActive WaitQuorum ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908242131Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908248577Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:18:20.90825438Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Waiting for 1 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908260696Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908266799Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908327524Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] a76c2c75-faeb-44e6-9d63-279b3b78d414 (4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee) WaitQuorum WaitActive WaitQuorum ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.90836057Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908367024Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:18:20.908372721Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 WaitQuorum WaitQuorum WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908378781Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908384957Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908390678Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908552037Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908583374Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908589825Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.90859553Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908601217Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908607018Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908613326Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908619721Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.908625305Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908631816Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908638522Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908644464Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908858354Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"No downstairs repair required","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908889233Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"No initial repair work was required","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908895231Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Set Downstairs and Upstairs active","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.908900723Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} The guest has finished waiting for activation with:1 {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 is now active with session: 4dcb97cd-94cf-40a6-a2c8-9bd97ef6fbee","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO ,"time":"2023-10-13T18:18:20.909000578Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 Set Active after no repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909121873Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Notify all downstairs, region set compare is done.","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909133129Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.90914285Z","hostname":"ip-10-150-1-56.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-10-13T18:18:20.909153568Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.90916459Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"a76c2c75-faeb-44e6-9d63-279b3b78d414 Active Active Active","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909174205Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909183431Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909220636Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909229332Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909235322Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909240951Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.90931861Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909440615Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909450783Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:20.909456806Z","hostname":"ip-10-150-1-56.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-10-13T18:18:21.910865238Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"No Live Repair required at this time","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:18:21.910914632Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} 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-10-13T18:18:23.970794148Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:18:23.971161846Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:18:23.972052724Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:20.464472129Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:20.516517527Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:20.934152742Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} rwrites 8.06 30000 1 3720.44 0.00027 0.00041 0.00062 0.01671 16384 640 {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:27.757768041Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:27.759054974Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:19:27.760071406Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:20:14.397457927Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:20:14.406429089Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:20:14.634515608Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1181} rwrites 9.90 30000 1 3029.19 0.00033 0.00056 0.00087 0.02149 16384 640 rreads 14.65 30000 1 2048.42 0.00049 0.00059 0.00077 0.01264 16384 640 rreads 14.62 30000 1 2052.05 0.00049 0.00059 0.00077 0.01273 16384 640 Perf test completed, stop all downstairs Oct 13 18:20:50.318 INFO accepted connection, remote_addr: 127.0.0.1:45639, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Oct 13 18:20:50.319 INFOShut it down [8820] Disable keep_running request completed[8820] Got stop action so:false kr:false , latency_us: 89, response_code: 204, uri: /shutdown, method: [8810] Disable keep_running POST, req_id: 1df345cc-c2bb-4be6-bf5e-a4f7d2a66e11, remote_addr: 127.0.0.1:45639, local_addr: 127.0.0.1:9998 [8810] Got stop action so:false kr:false [8830] Disable keep_running [8830] Got stop action so:false kr:false [8810] Exited with: ExitStatus(unix_wait_status(9)) [8810][0] reports Exit [8820] Exited with: ExitStatus(unix_wait_status(9)) [8820][1] reports Exit [8830] Exited with: ExitStatus(unix_wait_status(9)) [8830][2] 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.3074663 Downstairs region 1 created at /var/tmp/dsc/8820 in 1.4869379 Downstairs region 2 created at /var/tmp/dsc/8830 in 1.286438 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 Starting downstairs at port 8820 Make output file at "/tmp/dsc/downstairs-8810.txt" [8810][0] reports Starting [8820][1] reports Starting Make output file at "/tmp/dsc/downstairs-8820.txt" Starting downstairs at port 8830 Make output file at "/tmp/dsc/downstairs-8830.txt" [8830][2] reports Starting Downstairs /var/tmp/dsc/8810 port 8810 PID:Some(1190) [8810][0] reports Running Downstairs /var/tmp/dsc/8830 port 8830 PID:Some(1191) [8830][2] reports Running Downstairs /var/tmp/dsc/8820 port 8820 PID:Some(1192) [8820][1] reports Running Oct 13 18:20:55.734 INFO listening, local_addr: 127.0.0.1:9998 Control access at:127.0.0.1:9998 1192 1191 1190 Oct 13 18:21:00.805 INFO accepted connection, remote_addr: 127.0.0.1:38832, 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 13 18:21:00.806 INFO request completed, latency_us[8810] Disable keep_running :[8820] Disable keep_running 240, response_code: 204, uri: /disablerestart/all, method: POST, req_id: 4ad8ecf0-32fc-4ee3-8d30-32961145f0c3, remote_addr: 127.0.0.1:38832, local_addr: 127.0.[8830] Disable keep_running 0.1:9998 A new loop begins at October 13, 2023 at 06:21:00 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-10-13T18:21:00.835522539Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"a730f3b26afaf115f27149ef849470fd85caef41\",\n git_commit_timestamp: \"2023-10-13T17:42:12.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-10-13T18:21:00.835749799Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Upstairs <-> Downstairs Message Version: 4","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.835759727Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Upstairs opts: Upstairs UUID: b52d43f5-294c-4241-9a53-5dbf1248d82f, 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":"2023-10-13T18:21:00.835766862Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Crucible stats registered with UUID: b52d43f5-294c-4241-9a53-5dbf1248d82f","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.835774969Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Crucible b52d43f5-294c-4241-9a53-5dbf1248d82f has session id: f55b6169-b005-462e-9132-2a8aca006a58","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.835782111Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} Crucible runtime is spawned The guest has requested activation with gen:1 {"msg":"[0] connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836175064Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.83622799Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200,"looper":"1"} {"msg":"[2] connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836242046Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200,"looper":"2"} {"msg":"up_listen starts","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836252334Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.836267798Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Flush timeout: 0.5","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836313472Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] b52d43f5-294c-4241-9a53-5dbf1248d82f looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836325524Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200,"looper":"1"} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f active request set","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836336785Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Set desired generation to :1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836348415Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.836421015Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] b52d43f5-294c-4241-9a53-5dbf1248d82f looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836434Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200,"looper":"2"} {"msg":"[0] b52d43f5-294c-4241-9a53-5dbf1248d82f looper connected","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.836445389Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.836567152Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] Proc runs for 127.0.0.1:8830 in state New","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.83661845Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) New New New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.837944634Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838151962Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] client is_active_req TRUE, promote! session cb44f26e-1ce4-4186-9483-da519439f3fe","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838171362Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) New WaitActive New ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838182323Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.83819212Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] client is_active_req TRUE, promote! session cb44f26e-1ce4-4186-9483-da519439f3fe","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838202231Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) New WaitActive WaitActive ds_transition to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838212418Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838222323Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] client is_active_req TRUE, promote! session cb44f26e-1ce4-4186-9483-da519439f3fe","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.838231764Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.839655089Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.839738307Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.839749618Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.839760195Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.839770301Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.839779991Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.84000271Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.840016298Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitActive WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.840056903Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) WaitActive WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877405316Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877451197Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:00.877458749Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877464873Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.877482385Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitQuorum WaitActive WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877489619Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Waiting for 2 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877506799Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877535761Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) WaitQuorum WaitActive WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877781366Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877812856Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:00.877819213Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877825328Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.877831049Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitQuorum WaitQuorum WaitActive","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877859155Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Waiting for 1 more clients to be ready","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.877865199Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.8778706Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] b52d43f5-294c-4241-9a53-5dbf1248d82f (cb44f26e-1ce4-4186-9483-da519439f3fe) WaitQuorum WaitQuorum WaitActive ds_transition to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880755213Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880786389Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] new RM replaced this: None","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:00.880792153Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] Starts reconcile loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880797535Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880804518Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f WaitQuorum WaitQuorum WaitQuorum","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880810401Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880817704Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880823552Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880830655Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880836903Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880842628Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880848519Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880854477Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880860268Z","hostname":"ip-10-150-1-56.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-10-13T18:21:00.880866142Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880871822Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880877535Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880883283Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880960549Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"No downstairs repair required","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880992413Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"No initial repair work was required","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.880998518Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Set Downstairs and Upstairs active","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881004087Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} The guest has finished waiting for activation with:1 {"msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f is now active with session: cb44f26e-1ce4-4186-9483-da519439f3fe","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881013725Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {Wait for a query_work_queue command to finish before sending IO "msg":"b52d43f5-294c-4241-9a53-5dbf1248d82f Set Active after no repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881022225Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Notify all downstairs, region set compare is done.","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.88102852Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Set check for repair","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881057363Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881162658Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881202949Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] received reconcile message","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881338531Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881373719Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881379899Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881538527Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881572684Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} Region: es:16384 ec:1280 bs:4096 ts:85899345920 tb:20971520 max_io:256 or 1048576 {"msg":"[1] All repairs completed, exit","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881778671Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] Starts cmd_loop","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:00.881827637Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"Checking if live repair is needed","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:01.881759137Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"No Live Repair required at this time","v":0,"name":"crucible","level":30,"time":"2023-10-13T18:21:01.881809883Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} 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-10-13T18:21:04.14298267Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:04.144842377Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:04.146162845Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:57.814982655Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:57.907306624Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:21:57.923893964Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} rwrites 9.72 30000 1 3085.73 0.00032 0.00052 0.00076 0.02088 16384 1280 {"msg":"[1] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:05.473619979Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:05.476370908Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control start ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:05.481138816Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[2] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:58.270688171Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[0] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:58.300128861Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} {"msg":"[1] flow control end ","v":0,"name":"crucible","level":40,"time":"2023-10-13T18:22:58.373854463Z","hostname":"ip-10-150-1-56.us-west-2.compute.internal","pid":1200} rwrites 10.34 30000 1 2901.29 0.00034 0.00059 0.00097 0.02116 16384 1280 rreads 14.81 30000 1 2025.49 0.00049 0.00061 0.00079 0.01301 16384 1280 rreads 14.70 30000 1 2040.47 0.00049 0.00061 0.00078 0.01301 16384 1280 Perf test completed, stop all downstairs Oct 13 18:23:34.341 INFO accepted connection, remote_addr: 127.0.0.1:46199, local_addr: 127.0.0.1:9998 Main task has work to do, go find it got dsc Shutdown Shutdown Oct 13 18:23:34.341 INFO request completed, Shut it down latency_us[8820] Disable keep_running : [8830] Disable keep_running 85, [8830] Got stop action so:false kr:false response_code: 204, uri[8810] Disable keep_running : /shutdown, method: POST, req_id[8820] Got stop action so:false kr:false : 02264e02-7174-4fa5-9fd0-5a2f35a530f9, remote_addr: 127.0.0.1:46199, local_addr: 127.0.[8810] Got stop action so:false kr:false 0.1:9998 [8810] Exited with: ExitStatus(unix_wait_status(9)) [8810][0] reports Exit [8820] Exited with: ExitStatus(unix_wait_status(9)) [8820][1] reports Exit [8830] Exited with: ExitStatus(unix_wait_status(9)) [8830][2] reports Exit TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 8.06 30000 1 3720.44 0.00027 0.00041 0.00062 0.01671 16384 640 rwrites 9.90 30000 1 3029.19 0.00033 0.00056 0.00087 0.02149 16384 640 rwrites 9.72 30000 1 3085.73 0.00032 0.00052 0.00076 0.02088 16384 1280 rwrites 10.34 30000 1 2901.29 0.00034 0.00059 0.00097 0.02116 16384 1280 TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rreads 14.65 30000 1 2048.42 0.00049 0.00059 0.00077 0.01264 16384 640 rreads 14.62 30000 1 2052.05 0.00049 0.00059 0.00077 0.01273 16384 640 rreads 14.81 30000 1 2025.49 0.00049 0.00061 0.00079 0.01301 16384 1280 rreads 14.70 30000 1 2040.47 0.00049 0.00061 0.00078 0.01301 16384 1280 Perf test finished on October 13, 2023 at 06:23:35 PM UTC