Crucible metrics not reflecting read/write activities

[askfongjojo]

I have a bunch of database workloads that have disk metrics reporting zero read/write ops and bytes when there were heavy activities. The metrics API, metrics database, propolis producer pipeline seems healthy (cpu and network i/o metrics are being reported).

Here are some example instances on rack2 (running ci c298def/c43b3b5):

ID                                   STATE   INTENT  PROPOLIS_ID                          SLED_ID                              HOST_SERIAL NAME   
3ca505de-d3b2-4236-92eb-9cd639b553a8 running running 91d3ddbc-970e-4720-ba1c-036b59117b1e a2adea92-b56e-44fc-8a0d-7d63b5fd3b93 BRM42220031 fio
6b252c74-548c-4f1b-a98a-6c0e2da02c09 running running f471942d-82c3-4c18-8c2a-2bb5250ecc39 b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88 BRM42220006 mongodb-xfs-bs4096-primary 

Propolis log for this instance has active metrics queries that all responded http 200 without any obvious issues.

$ oxide --insecure experimental system timeseries query --query 'get virtual_disk:bytes_read | filter timestamp > @now() - 15m &&  disk_id == "d0a14ae0-2c88-4f39-99ca-e7de947bc935" '
{
  "tables": [
    {
      "name": "virtual_disk:bytes_read",
      "timeseries": [
        {
          "fields": {
            "attached_instance_id": {
              "type": "uuid",
              "value": "6b252c74-548c-4f1b-a98a-6c0e2da02c09"
            },
            "project_id": {
              "type": "uuid",
              "value": "5e49b6de-cb2d-438d-83af-95c415bbb901"
            },
            "silo_id": {
              "type": "uuid",
              "value": "7bd7623a-68ed-4636-8ecb-b59e3b068787"
            },
            "block_size": {
              "type": "u32",
              "value": 4096
            },
            "disk_id": {
              "type": "uuid",
              "value": "d0a14ae0-2c88-4f39-99ca-e7de947bc935"
            }
          },
          "points": {
            "start_times": [
              "2025-12-24T17:10:59.153672591Z",
              "2025-12-30T02:24:02.905844787Z",
              "2025-12-30T02:24:12.906906714Z",
              "2025-12-30T02:24:22.907043460Z",
              "2025-12-30T02:24:32.907736135Z",
              "2025-12-30T02:24:42.907847793Z",
              "2025-12-30T02:24:52.908849987Z",
              "2025-12-30T02:25:02.910416705Z",
              "2025-12-30T02:25:12.909862207Z",
              "2025-12-30T02:25:22.909584185Z",
              "2025-12-30T02:25:32.911403294Z",
              "2025-12-30T02:25:42.911389984Z",
              "2025-12-30T02:25:52.910284606Z",
              "2025-12-30T02:26:02.912875373Z",
              "2025-12-30T02:26:13.029090188Z",
              "2025-12-30T02:26:22.912092856Z",
              "2025-12-30T02:26:32.916248823Z",
              "2025-12-30T02:26:42.916597432Z",
              "2025-12-30T02:26:52.914014420Z",
              "2025-12-30T02:27:02.914193998Z",
              "2025-12-30T02:27:12.915753883Z",
              "2025-12-30T02:27:22.914757437Z",
              "2025-12-30T02:27:32.916273112Z",
              "2025-12-30T02:27:42.916374870Z",
              "2025-12-30T02:27:52.916092019Z",
              "2025-12-30T02:28:02.916671068Z",
              "2025-12-30T02:28:12.917752623Z",
              "2025-12-30T02:28:22.918398970Z",
              "2025-12-30T02:28:32.917883596Z",
              "2025-12-30T02:28:42.918318721Z",
              "2025-12-30T02:28:52.919030121Z",
              "2025-12-30T02:29:02.920988194Z",
              "2025-12-30T02:29:12.921451360Z",
              "2025-12-30T02:29:22.920758838Z",
              "2025-12-30T02:29:32.921074009Z",
              "2025-12-30T02:29:42.921537705Z",
              "2025-12-30T02:29:52.921851810Z",
              "2025-12-30T02:30:02.921844069Z",
              "2025-12-30T02:30:13.028808749Z",
              "2025-12-30T02:30:22.922444814Z",
              "2025-12-30T02:30:32.924262408Z",
              "2025-12-30T02:30:42.924582051Z",
              "2025-12-30T02:30:52.925698009Z",
              "2025-12-30T02:31:02.924329379Z",
              "2025-12-30T02:31:12.924851690Z",
              "2025-12-30T02:31:22.926088490Z",
              "2025-12-30T02:31:32.926895149Z",
              "2025-12-30T02:31:42.926027623Z",
              "2025-12-30T02:31:52.926847988Z",
              "2025-12-30T02:32:02.926968985Z",
              "2025-12-30T02:32:12.929236134Z",
              "2025-12-30T02:32:22.927990449Z",
              "2025-12-30T02:32:32.928236052Z",
              "2025-12-30T02:32:42.929001825Z",
              "2025-12-30T02:32:52.929082805Z",
              "2025-12-30T02:33:02.929487669Z",
              "2025-12-30T02:33:12.930365887Z",
              "2025-12-30T02:33:22.931337291Z",
              "2025-12-30T02:33:32.932172497Z",
              "2025-12-30T02:33:42.931616282Z",
              "2025-12-30T02:33:52.932107753Z",
              "2025-12-30T02:34:02.932165349Z",
              "2025-12-30T02:34:12.932886365Z",
              "2025-12-30T02:34:22.934304300Z",
              "2025-12-30T02:34:32.933731314Z",
              "2025-12-30T02:34:42.934541051Z",
              "2025-12-30T02:34:52.936328638Z",
              "2025-12-30T02:35:02.937030097Z",
              "2025-12-30T02:35:12.935365472Z",
              "2025-12-30T02:35:22.938080276Z",
              "2025-12-30T02:35:32.936517956Z",
              "2025-12-30T02:35:42.937354514Z",
              "2025-12-30T02:35:52.937505247Z",
              "2025-12-30T02:36:02.937629836Z",
              "2025-12-30T02:36:12.938545546Z",
              "2025-12-30T02:36:22.938228025Z",
              "2025-12-30T02:36:32.938784530Z",
              "2025-12-30T02:36:42.939475378Z",
              "2025-12-30T02:36:52.939797747Z",
              "2025-12-30T02:37:02.940375521Z",
              "2025-12-30T02:37:12.941699716Z",
              "2025-12-30T02:37:22.941577167Z",
              "2025-12-30T02:37:32.941944612Z",
              "2025-12-30T02:37:42.942171829Z",
              "2025-12-30T02:37:52.942629467Z",
              "2025-12-30T02:38:02.943718816Z",
              "2025-12-30T02:38:12.945613778Z",
              "2025-12-30T02:38:22.944043154Z",
              "2025-12-30T02:38:32.946112628Z",
              "2025-12-30T02:38:42.945346734Z"
            ],
            "timestamps": [
              "2025-12-30T02:24:02.905844787Z",
              "2025-12-30T02:24:12.906906714Z",
              "2025-12-30T02:24:22.907043460Z",
              "2025-12-30T02:24:32.907736135Z",
              "2025-12-30T02:24:42.907847793Z",
              "2025-12-30T02:24:52.908849987Z",
              "2025-12-30T02:25:02.910416705Z",
              "2025-12-30T02:25:12.909862207Z",
              "2025-12-30T02:25:22.909584185Z",
              "2025-12-30T02:25:32.911403294Z",
              "2025-12-30T02:25:42.911389984Z",
              "2025-12-30T02:25:52.910284606Z",
              "2025-12-30T02:26:02.912875373Z",
              "2025-12-30T02:26:13.029090188Z",
              "2025-12-30T02:26:22.912092856Z",
              "2025-12-30T02:26:32.916248823Z",
              "2025-12-30T02:26:42.916597432Z",
              "2025-12-30T02:26:52.914014420Z",
              "2025-12-30T02:27:02.914193998Z",
              "2025-12-30T02:27:12.915753883Z",
              "2025-12-30T02:27:22.914757437Z",
              "2025-12-30T02:27:32.916273112Z",
              "2025-12-30T02:27:42.916374870Z",
              "2025-12-30T02:27:52.916092019Z",
              "2025-12-30T02:28:02.916671068Z",
              "2025-12-30T02:28:12.917752623Z",
              "2025-12-30T02:28:22.918398970Z",
              "2025-12-30T02:28:32.917883596Z",
              "2025-12-30T02:28:42.918318721Z",
              "2025-12-30T02:28:52.919030121Z",
              "2025-12-30T02:29:02.920988194Z",
              "2025-12-30T02:29:12.921451360Z",
              "2025-12-30T02:29:22.920758838Z",
              "2025-12-30T02:29:32.921074009Z",
              "2025-12-30T02:29:42.921537705Z",
              "2025-12-30T02:29:52.921851810Z",
              "2025-12-30T02:30:02.921844069Z",
              "2025-12-30T02:30:13.028808749Z",
              "2025-12-30T02:30:22.922444814Z",
              "2025-12-30T02:30:32.924262408Z",
              "2025-12-30T02:30:42.924582051Z",
              "2025-12-30T02:30:52.925698009Z",
              "2025-12-30T02:31:02.924329379Z",
              "2025-12-30T02:31:12.924851690Z",
              "2025-12-30T02:31:22.926088490Z",
              "2025-12-30T02:31:32.926895149Z",
              "2025-12-30T02:31:42.926027623Z",
              "2025-12-30T02:31:52.926847988Z",
              "2025-12-30T02:32:02.926968985Z",
              "2025-12-30T02:32:12.929236134Z",
              "2025-12-30T02:32:22.927990449Z",
              "2025-12-30T02:32:32.928236052Z",
              "2025-12-30T02:32:42.929001825Z",
              "2025-12-30T02:32:52.929082805Z",
              "2025-12-30T02:33:02.929487669Z",
              "2025-12-30T02:33:12.930365887Z",
              "2025-12-30T02:33:22.931337291Z",
              "2025-12-30T02:33:32.932172497Z",
              "2025-12-30T02:33:42.931616282Z",
              "2025-12-30T02:33:52.932107753Z",
              "2025-12-30T02:34:02.932165349Z",
              "2025-12-30T02:34:12.932886365Z",
              "2025-12-30T02:34:22.934304300Z",
              "2025-12-30T02:34:32.933731314Z",
              "2025-12-30T02:34:42.934541051Z",
              "2025-12-30T02:34:52.936328638Z",
              "2025-12-30T02:35:02.937030097Z",
              "2025-12-30T02:35:12.935365472Z",
              "2025-12-30T02:35:22.938080276Z",
              "2025-12-30T02:35:32.936517956Z",
              "2025-12-30T02:35:42.937354514Z",
              "2025-12-30T02:35:52.937505247Z",
              "2025-12-30T02:36:02.937629836Z",
              "2025-12-30T02:36:12.938545546Z",
              "2025-12-30T02:36:22.938228025Z",
              "2025-12-30T02:36:32.938784530Z",
              "2025-12-30T02:36:42.939475378Z",
              "2025-12-30T02:36:52.939797747Z",
              "2025-12-30T02:37:02.940375521Z",
              "2025-12-30T02:37:12.941699716Z",
              "2025-12-30T02:37:22.941577167Z",
              "2025-12-30T02:37:32.941944612Z",
              "2025-12-30T02:37:42.942171829Z",
              "2025-12-30T02:37:52.942629467Z",
              "2025-12-30T02:38:02.943718816Z",
              "2025-12-30T02:38:12.945613778Z",
              "2025-12-30T02:38:22.944043154Z",
              "2025-12-30T02:38:32.946112628Z",
              "2025-12-30T02:38:42.945346734Z",
              "2025-12-30T02:38:52.945111829Z"
            ],
            "values": [
              {
                "metric_type": "delta",
                "values": {
                  "type": "integer",
                  "values": [
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0,
                    0
                  ]
                }
              }
            ]
          }
        }
      ]
    }
  ]
}

[bnaecker]

It doesn't look like this Propolis instance is even reporting the virtual disk metrics any longer. These are the timeseries_names for everything its producer server is emitting samples for:

root@oxz_propolis:~# curl http://[fd00:1122:3344:106::1:100d]:53716/6b252c74-548c-4f1b-a98a-6c0e2da02c09 | jq '.[0] | .info | .[].timeseries_name'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  103k  100  103k    0     0  5755k      0 --:--:-- --:--:-- --:--:-- 6068k
"instance_network_interface:packets_received"
"instance_network_interface:bytes_received"
"instance_network_interface:errors_received"
"instance_network_interface:packets_dropped"
"instance_network_interface:packets_sent"
"instance_network_interface:bytes_sent"
"instance_network_interface:errors_sent"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"
"virtual_machine:vcpu_usage"

I'd have to go back to the code to check, but I think this should be reporting something, even if there was no disk activity. Last I checked, this code was written to create a cumulative timeseries for this data, and update it whenever an I/O was completed. That means we should at least be reporting zeros.

More confusing, it does look like we have zeros in the database. In fact, we have a lot of zeros. Every sample from 2025-12-02 00:05:47.638201086 onwards is zero:

oxz_clickhouse_aa646c82-c6d7-4d0c-8401-150130927759.local :) select timestamp, datum from measurements_cumulativeu64 where timeseries_name = 'virtual_disk:bytes_read' and timeseries_key = 8651888958317335649 and timestamp < '2025-12-02 00:10:00' order by timestamp desc limit 25;

SELECT
    timestamp,
    datum
FROM measurements_cumulativeu64
WHERE (timeseries_name = 'virtual_disk:bytes_read') AND (timeseries_key = 8651888958317335649) AND (timestamp < '2025-12-02 00:10:00')
ORDER BY timestamp DESC
LIMIT 25

Query id: e1bbab5c-c4b2-4cb3-8668-c2021b081bd9

┌─────────────────────timestamp─┬────datum─┐
│ 2025-12-02 00:09:56.449091707 │        0 │
│ 2025-12-02 00:09:46.449159506 │        0 │
│ 2025-12-02 00:09:36.674511130 │        0 │
│ 2025-12-02 00:09:26.449627671 │        0 │
│ 2025-12-02 00:09:17.650416934 │        0 │
│ 2025-12-02 00:09:07.499892663 │        0 │
│ 2025-12-02 00:09:04.344899256 │        0 │
│ 2025-12-02 00:08:53.740951222 │        0 │
│ 2025-12-02 00:08:34.914057162 │        0 │
│ 2025-12-02 00:07:06.445370201 │        0 │
│ 2025-12-02 00:06:56.444671278 │        0 │
│ 2025-12-02 00:06:46.443967661 │        0 │
│ 2025-12-02 00:06:36.543573056 │        0 │
│ 2025-12-02 00:06:26.449506998 │        0 │
│ 2025-12-02 00:06:16.441639175 │        0 │
│ 2025-12-02 00:06:06.441537364 │        0 │
│ 2025-12-02 00:05:56.440487819 │        0 │
│ 2025-12-02 00:05:47.882239334 │        0 │
│ 2025-12-02 00:05:47.638201086 │        0 │
│ 2025-12-01 22:31:56.035636552 │ 51167232 │
│ 2025-12-01 22:31:46.034798144 │ 51167232 │
│ 2025-12-01 22:31:36.034085486 │ 51167232 │
│ 2025-12-01 22:31:26.033906532 │ 51167232 │
│ 2025-12-01 22:31:16.033307853 │ 51167232 │
│ 2025-12-01 22:31:06.034139604 │ 51167232 │
└───────────────────────────────┴──────────┘

25 rows in set. Elapsed: 0.011 sec. Processed 229.38 thousand rows, 2.97 MB (21.27 million rows/s., 275.59 MB/s.)
Peak memory usage: 4.11 MiB.

oxz_clickhouse_aa646c82-c6d7-4d0c-8401-150130927759.local :) select distinct datum from measurements_cumulativeu64 where timeseries_name = 'virtual_disk:bytes_read' and timeseries_key = 8651888958317335649 and timestamp > '2025-12-02';

SELECT DISTINCT datum
FROM measurements_cumulativeu64
WHERE (timeseries_name = 'virtual_disk:bytes_read') AND (timeseries_key = 8651888958317335649) AND (timestamp > '2025-12-02')

Query id: 9cbde62a-3b7e-47e4-932e-870fa251fdf7

┌─datum─┐
│     0 │
└───────┘

1 row in set. Elapsed: 0.027 sec. Processed 352.26 thousand rows, 19.53 MB (13.14 million rows/s., 728.21 MB/s.)
Peak memory usage: 11.73 MiB.

oxz_clickhouse_aa646c82-c6d7-4d0c-8401-150130927759.local :) select max(timestamp) from measurements_cumulativeu64 where timeseries_name = 'virtual_disk:bytes_read' and timeseries_key = 8651888958317335649;

So we have a pause in data of about 1 hour 34 minutes at 2025-12-02, after which we've only ever recorded a measurement of zero.