context deadline exceeded

[pgassmann]

I see many logs like this:

ts=2024-01-23T09:46:48.905Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.24057311 err="context deadline exceeded"
ts=2024-01-23T09:46:48.911Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.247038288 err="context deadline exceeded"
ts=2024-01-23T09:46:48.934Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.269771076 err="context deadline exceeded"

What's the meaning of those messages? The --deadline option is set to the default 8s

Full command and output:

./zfs_exporter --web.listen-address 127.0.0.1:9134 --properties.dataset-filesystem="available,logicalused,quota,referenced,used,usedbydataset,written,usedsnap,logicalreferenced,usedchild,compressratio" --exclude='/docker' --deadline=8s
ts=2024-01-23T09:45:21.298Z caller=zfs_exporter.go:39 level=info msg="Starting zfs_exporter" version="(version=2.3.2, branch=master, revision=30f2d5a069cfff3021f498e8bf4bf2cf82097af0)"
ts=2024-01-23T09:45:21.298Z caller=zfs_exporter.go:40 level=info msg="Build context" context="(go=go1.20.10, platform=linux/amd64, user=root@c4294b1b2f1d, date=20231013-21:14:42, tags=netgo)"
ts=2024-01-23T09:45:21.299Z caller=dataset.go:179 level=warn msg="Unsupported dataset property, results are likely to be undesirable" help="Please file an issue at https://github.com/pdf/zfs_exporter/issues" collector=filesystem property=usedsnap err="unsupported property"
ts=2024-01-23T09:45:21.299Z caller=dataset.go:179 level=warn msg="Unsupported dataset property, results are likely to be undesirable" help="Please file an issue at https://github.com/pdf/zfs_exporter/issues" collector=filesystem property=usedchild err="unsupported property"
ts=2024-01-23T09:45:21.299Z caller=zfs_exporter.go:66 level=info msg="Enabling pools" pools=(all)
ts=2024-01-23T09:45:21.299Z caller=zfs_exporter.go:75 level=info msg="Enabling collectors" collectors="pool, dataset-filesystem, dataset-volume"
ts=2024-01-23T09:45:21.299Z caller=tls_config.go:274 level=info msg="Listening on" address=127.0.0.1:9134
ts=2024-01-23T09:45:21.299Z caller=tls_config.go:277 level=info msg="TLS is disabled." http2=false address=127.0.0.1:9134

[pdf]

Something doesn't add up here - your first quoted output shows durationSeconds of ~250ms, clearly less than 8s, but that path can only be triggered by the exceeding the specified deadline (with a little bit of slop for setup time). Your second quoted output shows deadline being set to 8s, but does not show the deadline being exceeded.

Are you certain that you're not starting with a different deadline in the first example?

[pgassmann]

yes, that's what I see. the numbers don't match.

sorry for cutting too short. here's the current full output:

# ./zfs_exporter --web.listen-address 127.0.0.1:9134 --properties.dataset-filesystem="available,logicalused,quota,referenced,used,usedbydataset,written,logicalreferenced,usedbysnapshots,usedbychildren,compressratio" --exclude='/docker' --deadline=8s
ts=2024-01-23T10:34:24.144Z caller=zfs_exporter.go:39 level=info msg="Starting zfs_exporter" version="(version=2.3.2, branch=master, revision=30f2d5a069cfff3021f498e8bf4bf2cf82097af0)"
ts=2024-01-23T10:34:24.145Z caller=zfs_exporter.go:40 level=info msg="Build context" context="(go=go1.20.10, platform=linux/amd64, user=root@c4294b1b2f1d, date=20231013-21:14:42, tags=netgo)"
ts=2024-01-23T10:34:24.145Z caller=zfs_exporter.go:66 level=info msg="Enabling pools" pools=(all)
ts=2024-01-23T10:34:24.145Z caller=zfs_exporter.go:75 level=info msg="Enabling collectors" collectors="dataset-volume, pool, dataset-filesystem"
ts=2024-01-23T10:34:24.146Z caller=tls_config.go:274 level=info msg="Listening on" address=127.0.0.1:9134
ts=2024-01-23T10:34:24.146Z caller=tls_config.go:277 level=info msg="TLS is disabled." http2=false address=127.0.0.1:9134
ts=2024-01-23T10:46:49.363Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.019482096 err="context deadline exceeded"
ts=2024-01-23T10:46:49.548Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.204538892 err="context deadline exceeded"
ts=2024-01-23T10:46:49.565Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.221625978 err="context deadline exceeded"
ts=2024-01-23T11:16:01.781Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.015354416 err="context deadline exceeded"
ts=2024-01-23T11:16:01.953Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.187339439 err="context deadline exceeded"
ts=2024-01-23T11:16:01.992Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.226176125 err="context deadline exceeded"
ts=2024-01-23T11:48:13.476Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.610463541 err="context deadline exceeded"
ts=2024-01-23T11:48:13.480Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.614287327 err="context deadline exceeded"
ts=2024-01-23T11:48:13.482Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.616521768 err="context deadline exceeded"
ts=2024-01-23T12:48:11.029Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.551715655 err="context deadline exceeded"
ts=2024-01-23T12:48:11.030Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.551936546 err="context deadline exceeded"
ts=2024-01-23T12:48:11.047Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.568824848 err="context deadline exceeded"
ts=2024-01-23T13:16:08.791Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.555208498 err="context deadline exceeded"
ts=2024-01-23T13:16:08.792Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.556043769 err="context deadline exceeded"
ts=2024-01-23T13:16:08.799Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.563405356 err="context deadline exceeded"
ts=2024-01-23T13:46:04.780Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=1.070427678 err="context deadline exceeded"
ts=2024-01-23T13:46:04.781Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=1.071565296 err="context deadline exceeded"
ts=2024-01-23T13:46:04.781Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=1.071417318 err="context deadline exceeded"
ts=2024-01-23T13:48:33.155Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-volume durationSeconds=0.348306596 err="context deadline exceeded"
ts=2024-01-23T13:48:33.157Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=pool durationSeconds=0.350007631 err="context deadline exceeded"
ts=2024-01-23T13:48:33.212Z caller=zfs.go:229 level=warn msg="Executing collector" status=delayed collector=dataset-filesystem durationSeconds=0.40515226 err="context deadline exceeded"

System Information:

# zfs --version
zfs-2.1.5-1ubuntu6~22.04.2
zfs-kmod-2.1.9-2ubuntu1.1

# uname -a
Linux backup2 6.2.0-39-generic #40~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Thu Nov 16 10:53:04 UTC 2 x86_64 x86_64 x86_64 GNU/Linux


# ./zfs_exporter --version
zfs_exporter, version 2.3.2 (branch: master, revision: 30f2d5a069cfff3021f498e8bf4bf2cf82097af0)
  build user:       root@c4294b1b2f1d
  build date:       20231013-21:14:42
  go version:       go1.20.10
  platform:         linux/amd64
  tags:             netgo