Perf test begins at February 6, 2024 at 10:13:55 PM UTC A new loop begins at February 6, 2024 at 10:14: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":"2024-02-06T22:14:02.262991622Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"7fe08e7f028451780bfe14aca37215026453fbc6\",\n git_commit_timestamp: \"2024-02-06T21:52:40.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.75.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"82e1608dfa6e0b5569232559e3d385fea5a93112\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.26323238Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263240603Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} {"msg":"Crucible e554d356-edb5-4ba9-8fd5-3dc35238ba61 has session id: 442a9e29-32e1-4fa7-aa61-6b3499f7e616","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263247195Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Upstairs opts: Upstairs UUID: e554d356-edb5-4ba9-8fd5-3dc35238ba61, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263299965Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Crucible stats registered with UUID: e554d356-edb5-4ba9-8fd5-3dc35238ba61","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263306637Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263402902Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} {"msg":"e554d356-edb5-4ba9-8fd5-3dc35238ba61 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263577296Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263599424Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263610148Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263620071Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263630275Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263639238Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263648622Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263682284Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263706683Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263717837Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263772047Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.263802048Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.26381044Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"io task","client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264373245Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264389722Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264395593Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264399915Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264405457Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.26441261Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264678376Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264731686Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.264751763Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.268212173Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.26823278Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.268238972Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.271937839Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.271957786Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.271963448Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272712871Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272732578Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[0]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272774283Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[0]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272809536Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[0]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272817949Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[1]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272826162Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[1]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272834215Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[1]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272841778Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[2]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.27284935Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[2]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,Wait for a query_work_queue command to finish before sending IO "name":"crucible","level":30,"time":"2024-02-06T22:14:02.272860054Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272867237Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272883653Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272889485Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272893686Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272898128Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.27290242Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272906671Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272911683Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272919666Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272926649Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272934301Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"e554d356-edb5-4ba9-8fd5-3dc35238ba61 is now active with session: 442a9e29-32e1-4fa7-aa61-6b3499f7e616","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272940814Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272947016Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160,"session_id":"442a9e29-32e1-4fa7-aa61-6b3499f7e616"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:02.272953948Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} Region: es:16384 ec:640 bs:4096 ts:42949672960 tb:10485760 max_io:256 or 1048576 Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 9.33 30000 1 3215.85 0.00031 0.00116 0.00150 0.09504 16384 640 rwrites 6.37 30000 1 4710.99 0.00021 0.00035 0.00098 0.06246 16384 640 rreads 5.86 30000 1 5117.02 0.00020 0.00027 0.00032 0.01227 16384 640 rreads 5.78 30000 1 5187.11 0.00019 0.00027 0.00031 0.01286 16384 640 {"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2024-02-06T22:14:35.497290497Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1160} A new loop begins at February 6, 2024 at 10:14:45 PM UTC /var/tmp/bins/crutest perf -g 1 -t 127.0.0.1:8810 -t 127.0.0.1:8820 -t 127.0.0.1:8830 -c 30000 -q --write-loops 2 --read-loops 2 --perf-out /tmp/perf-ES-16384-EC-1280.csv {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227610503Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"7fe08e7f028451780bfe14aca37215026453fbc6\",\n git_commit_timestamp: \"2024-02-06T21:52:40.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.75.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"82e1608dfa6e0b5569232559e3d385fea5a93112\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227746293Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227753405Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179} {"msg":"Crucible 8203eb39-6079-4ce5-b23b-c9592468932e has session id: bd3f8e09-805f-4334-879c-d1b92e0fa3db","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227757597Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Upstairs opts: Upstairs UUID: 8203eb39-6079-4ce5-b23b-c9592468932e, Targets: [127.0.0.1:8810, 127.0.0.1:8820, 127.0.0.1:8830], lossy: false, flush_timeout: None, key populated: false, cert_pem populated: false, key_pem populated: false, root_cert_pem populated: false, Control: None, read_only: false","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.22776806Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Crucible stats registered with UUID: 8203eb39-6079-4ce5-b23b-c9592468932e","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227774483Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"Crucible runtime is spawned bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227840027Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179} {"msg":"8203eb39-6079-4ce5-b23b-c9592468932e active request set","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227922767Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227936171Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227946665Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227951757Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227955969Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.22796029Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227967603Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227975156Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.22798626Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.227993663Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228001365Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228008858Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228016361Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"io task","client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228489583Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228506339Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228515372Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228520004Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228556668Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228571593Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"downstairs client at Some(127.0.0.1:8810) has region UUID 12345678-0000-0000-0000-000000008810","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.22886557Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"downstairs client at Some(127.0.0.1:8820) has region UUID 12345678-0000-0000-0000-000000008820","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228888428Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"downstairs client at Some(127.0.0.1:8830) has region UUID 12345678-0000-0000-0000-000000008830","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.228937576Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23471902Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234739918Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23474717Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234792257Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234809203Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234815626Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234849728Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234867624Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[0]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234872766Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[0]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234878028Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[0]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23488304Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[1]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234887742Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[1]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234901397Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[1]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234907609Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[2]R flush_numbers[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23491217Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[2]R generation[0..12]: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234917152Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234921864Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234926226Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234930617Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234934759Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23493922Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234947293Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234953946Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.234961139Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":Wait for a query_work_queue command to finish before sending IO 1179,"client":"1","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.235032144Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.235040307Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.23504663Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"8203eb39-6079-4ce5-b23b-c9592468932e is now active with session: bd3f8e09-805f-4334-879c-d1b92e0fa3db","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.235053752Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.235060034Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179,"session_id":"bd3f8e09-805f-4334-879c-d1b92e0fa3db"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-06T22:14:45.235066647Z","hostname":"ip-10-150-1-230.us-west-2.compute.internal","pid":1179} Region: es:16384 ec:1280 bs:4096 ts:85899345920 tb:20971520 max_io:256 or 1048576 Perf test TEST SECONDS COUNT DPTH IOPS MEAN P95 P99 MAX ES EC rwrites 7.31 30000 1 4104.39 0.00024 0.00048 0.00129 0.05931 16384 1280 rwrites 7.38 30000 1 4062.66 0.00025 0.00050 0.00123 0.06187 16384 1280 rreads 5.60 30000 1 5356.12 0.00019 0.00023 0.00029 0.01522 16384 1280 rreads 5.60 30000 1 5358.46 0.00019 0.00023 0.00028 0.01522 16384 1280 Perf test finished on February 6, 2024 at 10:15:14 PM UTC