Perf test begins at February 3, 2024 at 05:21:09 PM UTC A new loop begins at February 3, 2024 at 05:21:18 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-03T17:21:18.512636291Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"c8a96ab04e38cc0df6791339b390675d7b569c4e\",\n git_commit_timestamp: \"2024-02-03T15:19:02.000000000Z\",\n git_branch: \"renovate/base64-0.x\",\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-03T17:21:18.51291721Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.512928273Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} {"msg":"Crucible e291c872-5437-4c23-baf1-7402a321477e has session id: aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513003232Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Upstairs opts: Upstairs UUID: e291c872-5437-4c23-baf1-7402a321477e, 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-03T17:21:18.513136765Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Crucible stats registered with UUID: e291c872-5437-4c23-baf1-7402a321477e","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513167436Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} Crucible runtime is spawned {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513447327Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} {"msg":"e291c872-5437-4c23-baf1-7402a321477e active request set","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513753627Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513791369Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.51386094Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513877122Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.5138899Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513928442Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513945144Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513957998Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.513998197Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.514011085Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.514191102Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.514500393Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.514523035Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"io task","client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.515262042Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.515302386Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.515315716Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.515328008Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.51534131Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.515354703Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.515886901Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.515959996Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.516106472Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.520846562Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.520963948Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.520997284Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521193739Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521228504Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521237809Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521251381Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521280871Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521289026Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521296834Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521304425Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521313024Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521320199Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521344305Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521352051Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.52135928Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"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-03T17:21:18.521366914Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521378412Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.52140607Z","hostname":Wait for a query_work_queue command to finish before sending IO "ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521417797Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521425135Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"":"downstairs","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521433543Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521439641Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"0","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521446582Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"1","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521453511Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"client":"2","":"downstairs","session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521461855Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521468076Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"e291c872-5437-4c23-baf1-7402a321477e is now active with session: aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521474363Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.52148167Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157,"session_id":"aa60b80d-dfcc-4b54-aaef-23cb4ca2d02e"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:21:18.521487858Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} 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 19.09 30000 1 1571.14 0.00064 0.00155 0.00270 0.06983 16384 640 rwrites 15.21 30000 1 1972.59 0.00051 0.00109 0.00255 0.06284 16384 640 rreads 10.83 30000 1 2769.40 0.00036 0.00048 0.00062 0.01846 16384 640 rreads 10.81 30000 1 2775.76 0.00036 0.00048 0.00061 0.01848 16384 640 {"msg":"Guest handle has been dropped","v":0,"name":"crucible","level":40,"time":"2024-02-03T17:22:16.839964739Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1157} A new loop begins at February 3, 2024 at 05:22:27 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-03T17:22:27.608292745Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176} {"msg":"Crucible Version: BuildInfo {\n version: \"0.0.1\",\n git_sha: \"c8a96ab04e38cc0df6791339b390675d7b569c4e\",\n git_commit_timestamp: \"2024-02-03T15:19:02.000000000Z\",\n git_branch: \"renovate/base64-0.x\",\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-03T17:22:27.608510491Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176} {"msg":"Upstairs <-> Downstairs Message Version: 5","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608520961Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176} {"msg":"Crucible 8af87fba-4fd4-4400-a779-e21cc425e05e has session id: ef65f295-328d-4296-b70a-7dbdbfd83212","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608527922Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Upstairs opts: Upstairs UUID: 8af87fba-4fd4-4400-a779-e21cc425e05e, 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-03T17:22:27.608544824Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Crucible stats registered with UUID: 8af87fba-4fd4-4400-a779-e21cc425e05e","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608553793Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_idCrucible runtime is spawned ":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"The guest has requested activation with gen:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608650971Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176} {"msg":"8af87fba-4fd4-4400-a779-e21cc425e05e active request set","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608731029Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.6087655Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608779419Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.60878739Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608841146Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"sending connect oneshot to client","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608856473Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"client set_active_request while in New; waiting...","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608869107Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"connecting to 127.0.0.1:8810","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608881677Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"connecting to 127.0.0.1:8830","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.608984485Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"connecting to 127.0.0.1:8820","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609077397Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609086725Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609231452Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_connection connected","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609251437Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"io task","client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609748125Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[1] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.60979087Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609804719Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[2] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609898124Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609928702Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[0] Transition from New to WaitActive","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.609941328Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.610603456Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.610706322Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.610753638Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620139677Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[0] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620196441Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620210915Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620512849Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[1] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620555764Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Waiting for true more clients to be ready","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620568936Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"ds_transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620651245Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[2] Transition from WaitActive to WaitQuorum","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620696232Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620710246Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.62072305Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620735541Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620783242Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620796976Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620811652Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620826024Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"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-03T17:22:27.620839064Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"[2]R dirty[0..12]: [false, false, false, false, false, false, false, false, false, false, false, false]","v":0,"name":"crucible","Wait for a query_work_queue command to finish before sending IO level":30,"time":"2024-02-03T17:22:27.620856689Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Max found gen is 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620869571Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Generation requested: 1 >= found:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.6208813Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Next flush: 1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620957824Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"All extents match","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.620995772Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"":"downstairs","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"No downstairs reconciliation required","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621009165Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621020211Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"0","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621032482Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"1","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Transition from WaitQuorum to Active","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621068848Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"client":"2","":"downstairs","session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"All required reconciliation work is completed","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621080802Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Set Downstairs and Upstairs active after reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621091619Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"8af87fba-4fd4-4400-a779-e21cc425e05e is now active with session: ef65f295-328d-4296-b70a-7dbdbfd83212","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.62110355Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"Set Active after no reconciliation","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621113953Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176,"session_id":"ef65f295-328d-4296-b70a-7dbdbfd83212"} {"msg":"The guest has finished waiting for activation with:1","v":0,"name":"crucible","level":30,"time":"2024-02-03T17:22:27.621164207Z","hostname":"ip-10-150-1-53.us-west-2.compute.internal","pid":1176} 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.73 30000 1 1793.23 0.00056 0.00128 0.00229 0.06982 16384 1280 rwrites 16.79 30000 1 1786.95 0.00056 0.00131 0.00236 0.04927 16384 1280 rreads 10.77 30000 1 2786.80 0.00036 0.00048 0.00062 0.01675 16384 1280 rreads 10.75 30000 1 2791.70 0.00036 0.00048 0.00061 0.01909 16384 1280 Perf test finished on February 3, 2024 at 05:23:26 PM UTC