Perf test begins at February 7, 2024 at 06:58:45 PM UTC A new loop begins at February 7, 2024 at 06:58:52 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-07T18:58:52.95327968Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"49aa1f31c117032612b377e7cd7453d4ff2c50d7\",\n git_commit_timestamp: \"2024-02-07T18:13:13.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-07T18:58:52.953453227Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953461037Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160} {"msg":"Crucible aa2ff3ff-dd48-4dd0-8252-8ddd4db00d02 has session id: 4c86ba17-d816-4a3f-9e29-f6572c110f41","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953466558Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Upstairs opts: Upstairs UUID: aa2ff3ff-dd48-4dd0-8252-8ddd4db00d02, 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-07T18:58:52.95351899Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Crucible stats registered with UUID: aa2ff3ff-dd48-4dd0-8252-8ddd4db00d02","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.95352525Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953665076Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160} {"msg":"aa2ff3ff-dd48-4dd0-8252-8ddd4db00d02 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953813672Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953832403Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953844253Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953855353Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953864594Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953874594Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953883514Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953893335Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953926486Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.953936757Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954044541Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954069882Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954079162Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"io task","client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954669016Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954689407Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954697267Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954704678Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954717858Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.954725388Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.954933767Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.954977759Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.955090653Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.957577474Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.957594684Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.957600664Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958630006Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958644837Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958649907Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.95873478Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958748981Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958771702Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958783112Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958787912Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958793132Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958798183Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958802523Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958807593Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958812263Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"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-07T18:58:52.958816573Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958821864Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO ,"time":"2024-02-07T18:58:52.958837174Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958845915Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958854315Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"":"downstairs","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958861835Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958866455Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"0","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958871186Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"1","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958876516Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"client":"2","":"downstairs","session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958884186Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958890556Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"aa2ff3ff-dd48-4dd0-8252-8ddd4db00d02 is now active with session: 4c86ba17-d816-4a3f-9e29-f6572c110f41","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958897967Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958905047Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160,"session_id":"4c86ba17-d816-4a3f-9e29-f6572c110f41"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:58:52.958911297Z","hostname":"ip-10-150-1-158.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 18.14 30000 1 1653.41 0.00060 0.00144 0.00195 0.04681 16384 640 rwrites 9.87 30000 1 3039.08 0.00033 0.00125 0.00185 0.02989 16384 640 rreads 5.51 30000 1 5446.73 0.00018 0.00023 0.00027 0.01491 16384 640 rreads 5.54 30000 1 5416.27 0.00018 0.00023 0.00027 0.01567 16384 640 {"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2024-02-07T18:59:39.722583745Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1160} A new loop begins at February 7, 2024 at 06:59:49 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-07T18:59:49.524277614Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"49aa1f31c117032612b377e7cd7453d4ff2c50d7\",\n git_commit_timestamp: \"2024-02-07T18:13:13.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-07T18:59:49.524390648Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524399699Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179} {"msg":"Crucible fc68fc27-5cb3-4ebe-acee-e59495f66419 has session id: eefa5094-2ec3-48a6-9375-fc5acccca365","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524406679Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Upstairs opts: Upstairs UUID: fc68fc27-5cb3-4ebe-acee-e59495f66419, 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-07T18:59:49.524417039Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Crucible stats registered with UUID: fc68fc27-5cb3-4ebe-acee-e59495f66419","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524422129Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524498463Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179} {"msg":"fc68fc27-5cb3-4ebe-acee-e59495f66419 active request set","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524540404Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524555615Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524566685Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524572766Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524579446Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524585696Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524592276Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524612017Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524635498Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524645058Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524782664Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524804645Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.524856367Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"io task","client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525066826Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525084826Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525090267Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525094857Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525100857Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.525108397Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.525449591Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.525470672Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.525504693Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.531903801Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.531920562Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.531925552Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.532296187Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.532310858Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.532315558Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544801671Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544820022Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544825912Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544831182Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544835642Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544839943Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544844203Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544848523Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544852933Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544857743Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"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-07T18:59:49.544862284Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544866644Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544871184Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544877274Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544884414Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"":"downstairs","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544892305Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544899275Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":Wait for a query_work_queue command to finish before sending IO 1179,"client":"0","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544910195Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"1","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544917386Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"client":"2","":"downstairs","session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544932646Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544936847Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"fc68fc27-5cb3-4ebe-acee-e59495f66419 is now active with session: eefa5094-2ec3-48a6-9375-fc5acccca365","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544940847Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544944507Z","hostname":"ip-10-150-1-158.us-west-2.compute.internal","pid":1179,"session_id":"eefa5094-2ec3-48a6-9375-fc5acccca365"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-07T18:59:49.544948227Z","hostname":"ip-10-150-1-158.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.77 30000 1 3863.24 0.00026 0.00056 0.00114 0.06589 16384 1280 rwrites 7.88 30000 1 3806.92 0.00026 0.00059 0.00110 0.06626 16384 1280 rreads 5.54 30000 1 5417.54 0.00018 0.00023 0.00028 0.01526 16384 1280 rreads 5.50 30000 1 5455.17 0.00018 0.00023 0.00027 0.01594 16384 1280 Perf test finished on February 7, 2024 at 07:00:20 PM UTC