Perf test begins at January 24, 2024 at 11:39:40 PM UTC A new loop begins at January 24, 2024 at 11:39: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-640.csv {"msg":"Upstairs starts","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.314372432Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"b3869548f2260f2d979be99f548637aa9680a1f5\",\n git_commit_timestamp: \"2024-01-24T22:12:17.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.73.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"cc66ad468955717ab92600c770da8c1601a4ff33\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.314680364Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.314690465Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154} {"msg":"Crucible bba640ff-0013-4c3c-8862-4664e6d852e5 has session id: f08eddf0-3a63-4e00-99f5-6775d10c2951","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.314698109Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Upstairs opts: Upstairs UUID: bba640ff-0013-4c3c-8862-4664e6d852e5, 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-01-24T23:39:49.314767769Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Crucible stats registered with UUID: bba640ff-0013-4c3c-8862-4664e6d852e5","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.314795965Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315379757Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154} {"msg":"bba640ff-0013-4c3c-8862-4664e6d852e5 active request set","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315428678Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315487196Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315547402Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315561237Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315616145Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315629821Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.31569227Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315709162Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315741513Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315754557Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.315949355Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.316125951Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.316147062Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"io task","client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317089868Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317125329Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317132872Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317140508Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317147449Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.317154457Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.31774437Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.317788344Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.317889239Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.323055659Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.323087308Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.32309483Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324141041Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324185831Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324200945Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324211421Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324247786Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324260607Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324270426Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324277942Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324284919Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324291977Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324298917Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.324306687Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.32431359Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"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-01-24T23:39:49.32432087Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.32434938Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324359407Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324366504Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324373913Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"":"downstairs","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.32438114Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324387297Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"0","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.32439419Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"1","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324429989Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"client":"2","":"downstairs","session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324444167Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324501094Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"bba640ff-0013-4c3c-8862-4664e6d852e5 is now active with session: f08eddf0-3a63-4e00-99f5-6775d10c2951","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324546225Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324585427Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154,"session_id":"f08eddf0-3a63-4e00-99f5-6775d10c2951"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:39:49.324624857Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1154} Wait for a query_work_queue command to finish before sending IO 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.88 30000 1 1588.65 0.00063 0.00153 0.00240 0.08660 16384 640 rwrites 14.87 30000 1 2016.81 0.00050 0.00113 0.00229 0.07616 16384 640 rreads 11.04 30000 1 2717.02 0.00037 0.00049 0.00064 0.01669 16384 640 rreads 10.99 30000 1 2729.36 0.00037 0.00049 0.00063 0.01669 16384 640 A new loop begins at January 24, 2024 at 11:40:58 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-01-24T23:40:58.197700593Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"b3869548f2260f2d979be99f548637aa9680a1f5\",\n git_commit_timestamp: \"2024-01-24T22:12:17.000000000Z\",\n git_branch: \"main\",\n rustc_semver: \"1.73.0\",\n rustc_channel: \"stable\",\n rustc_host_triple: \"x86_64-unknown-illumos\",\n rustc_commit_sha: \"cc66ad468955717ab92600c770da8c1601a4ff33\",\n cargo_triple: \"x86_64-unknown-illumos\",\n debug: false,\n opt_level: 3,\n}","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.197905786Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.197915658Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173} {"msg":"Crucible 5a6bd0b4-513f-4b76-bc8c-d406c070957d has session id: c70dda7a-8024-43be-89c1-797ea2a5cd12","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.197922413Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Upstairs opts: Upstairs UUID: 5a6bd0b4-513f-4b76-bc8c-d406c070957d, 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-01-24T23:40:58.197935789Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Crucible stats registered with UUID: 5a6bd0b4-513f-4b76-bc8c-d406c070957d","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.197945119Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198127574Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173} {"msg":"5a6bd0b4-513f-4b76-bc8c-d406c070957d active request set","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198157637Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198164837Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198179067Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198186278Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198202438Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198242465Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198260998Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198306461Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198325781Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198339326Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198703219Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198731545Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.198794356Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"io task","client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199151859Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199188499Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199197283Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199204311Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199215813Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.199229964Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.1999445Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.199990436Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.200128195Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.209701772Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.209736434Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.209744177Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212686437Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212724628Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212737873Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212749627Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212787612Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212801332Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.21281029Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212818151Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212825784Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212835328Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212874432Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212890057Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212903234Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"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-01-24T23:40:58.212915758Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.2129289Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212941633Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30Wait for a query_work_queue command to finish before sending IO ,"time":"2024-01-24T23:40:58.212953397Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212972796Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"":"downstairs","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212986814Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.212997648Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"0","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213099192Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"1","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213122735Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"client":"2","":"downstairs","session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213138076Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.21314949Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"5a6bd0b4-513f-4b76-bc8c-d406c070957d is now active with session: c70dda7a-8024-43be-89c1-797ea2a5cd12","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213162415Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213173074Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173,"session_id":"c70dda7a-8024-43be-89c1-797ea2a5cd12"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-01-24T23:40:58.213209699Z","hostname":"ip-10-150-1-108.us-west-2.compute.internal","pid":1173} 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 16.83 30000 1 1782.57 0.00056 0.00134 0.00253 0.05751 16384 1280 rwrites 16.72 30000 1 1794.50 0.00056 0.00137 0.00254 0.05216 16384 1280 rreads 10.83 30000 1 2769.51 0.00036 0.00048 0.00061 0.01831 16384 1280 rreads 10.84 30000 1 2768.58 0.00036 0.00048 0.00061 0.01831 16384 1280 Perf test finished on January 24, 2024 at 11:41:59 PM UTC