ぽよメモ

レガシーシステム考古学専攻

Cilium 1.16.5への更新でnode-local-dnsが壊れた話

何が起きた?

私物のKubernetesクラスタ(kubesprayで構築)のCiliumを1.15.11から1.16.5へ更新したところ、クラスタ内の名前解決が一斉にタイムアウトするようになりました。

CoreDNSサービス自体は正常に応答を返しているようでした。デバッグした結果、各ノードのkubeletが配る resolv.conf にはnode-local-dnsがリッスンしているリンクローカルアドレスが書かれており、このアドレスへの接続に問題が発生したことが分かりました。

悲しいことにこれによってArgoCDが機能不能になり、Ciliumの簡単なロールバックはできない状態になったためどうにか現状で復旧するしかありませんでした*1。最終的にnode-local-dnsを無効にしてノードを順番にdrain→uncordonして復旧しました。

再現手順

node-local-dns自体のマニフェストkubernetesのドキュメントにも載っています。

kubernetes.io

しかしこれを適用するだけでは配られる resolv.conf にリンクローカルアドレスが記載される状態にはなりません。kubesprayでnode-local-dnsのアドオンを有効化するとこの状態を作るようになります。

このような構成は上記の公式ドキュメントでも推奨されているものであり、特段に不審な構成ではありません。

NodeLocal DNSキャッシュのローカルリッスン用のIPアドレスは、クラスター内の既存のIPと衝突しないことが保証できるものであれば、どのようなアドレスでもかまいません。例えば、IPv4のリンクローカル範囲169.254.0.0/16やIPv6のユニークローカルアドレス範囲fd00::/8から、ローカルスコープのアドレスを使用することが推奨されています。

1. VMを作る

kubesprayでkubernetesクラスタを構築するため、VMを用意します。ここではmultipassを使っていますが、何でも良いです。

OSはUbuntu 24.04を問題になったクラスタで利用していたため、ここでも採用しました。他のOSの挙動は検証していませんが、おそらく同じだと思います。

GITHUB_USER=pddg

# cloud-initのconfigを記述する
cat << EOF > cloud-config.yaml
allow_public_ssh_keys: true
ssh_import_id: ["gh:${GITHUB_USER}"]
EOF

# VMを起動する
multipass launch \
  --name k8s-master \
  --memory 2G \
  --disk 30G \
  --cloud-init cloud-config.yaml \
  24.04

multipass launch \
  --name k8s-worker \
  --memory 2G \
  --disk 30G \
  --cloud-init cloud-config.yaml \
  24.04

2. kubesprayでクラスタを構築する

作成したクラスタとホストOSは普通にIPアドレスで通信できるようになっているので、これを元にkubesprayで使うためのAnsible Inventoryファイルを用意します。ユーザが ubuntu であることに注意してください(一敗)。

mkdir -p inventory/multipass
MASTER_IPADDR=$(multipass info --format json| jq -r '.info | to_entries[] | select(.key == "k8s-master") | .value.ipv4[]')
WORKER_IPADDR=$(multipass info --format json| jq -r '.info | to_entries[] | select(.key == "k8s-worker") | .value.ipv4[]')

cat << EOF > inventory/multipass/hosts.yaml
all:
  hosts:
    k8s-master:
      ansible_user: ubuntu
      ansible_host: ${MASTER_IPADDR}
      ip: ${MASTER_IPADDR}
      access_ip: ${MASTER_IPADDR}
    k8s-worker:
      ansible_user: ubuntu
      ansible_host: ${WORKER_IPADDR}
      ip: ${WORKER_IPADDR}
      access_ip: ${WORKER_IPADDR}
  children:
    kube_control_plane:
      hosts:
        k8s-master:
    kube_node:
      hosts:
        k8s-master:
        k8s-worker:
    etcd:
      hosts:
        k8s-master:
    k8s_cluster:
      children:
        kube_control_plane:
        kube_node:
EOF

このファイルを使って対象のホストがアクセス可能であることを確かめます。ここでは簡単のためdockerコンテナを利用しています。

# pingが成功することを確認する
docker run --rm  -it \
    --mount type=tmpfs,dst=/.ansible \
    --mount type=bind,source=$(pwd)/inventory,dst=/kubeproxy/inventory \
    --mount type=bind,source=${HOME}/.ssh/id_ed25519,dst=/root/.ssh/id_rsa \
    quay.io/kubespray/kubespray:v2.26.0 \
    ansible -i /kubeproxy/inventory/multipass/hosts.yaml -m ping all

うまくいけば各ホストからpongが返ってくるはずです*2

❯ docker run --rm \
        --mount type=tmpfs,dst=/.ansible \
        --mount type=bind,source=$(pwd)/inventory,dst=/kubeproxy/inventory \
        --mount type=bind,source=${HOME}/.ssh/id_ed25519,dst=/root/.ssh/id_rsa \
        quay.io/kubespray/kubespray:v2.26.0 \
        ansible -i /kubeproxy/inventory/multipass/hosts.yaml -m ping --private-key /root/.ssh/id_rsa all
WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested
[WARNING]: Skipping callback plugin 'ara_default', unable to load
k8s-worker | SUCCESS => {
    "ansible_facts": {
        "discovered_interpreter_python": "/usr/bin/python3"
    },
    "changed": false,
    "ping": "pong"
}
k8s-master | SUCCESS => {
    "ansible_facts": {
        "discovered_interpreter_python": "/usr/bin/python3"
    },
    "changed": false,
    "ping": "pong"
}

kubesprayの設定ファイルを書き、クラスタを構築します。

mkdir -p inventory/multipass/group_vars
cat << EOF > inventory/multipass/group_vars/all.yaml
---
kube_version: v1.30.4
container_manager: containerd

# 後からciliumを自分で入れる
kube_network_plugin: cni

# kube-proxyは削除しておく
kube_proxy_remove: true

# 構築したクラスタへアクセスするためのKUBECONFIGをローカルに配置する
kubeconfig_localhost: true

dns_mode: coredns

# node-local-dnsを有効化
enable_nodelocaldns: true
# node-local-dnsがリッスンするアドレス(デフォルト)
nodelocaldns_ip: 169.254.25.10
EOF

docker run --rm \
    --mount type=tmpfs,dst=/.ansible \
    --mount type=bind,source=$(pwd)/inventory,dst=/kubeproxy/inventory \
    --mount type=bind,source=${HOME}/.ssh/id_ed25519,dst=/root/.ssh/id_rsa \
    quay.io/kubespray/kubespray:v2.26.0 \
    ansible-playbook -i /kubeproxy/inventory/multipass/hosts.yaml --become cluster.yml

しばらく待つと構築が完了するので、 .envrcKUBECONFIG の設定を書いてここで使うkubernetesクラスタの情報を設定します。

cat << 'EOF' > .envrc
export KUBECONFIG=$KUBECONFIG:inventory/multipass/artifacts/admin.conf
EOF

direnv allow .

いくつかのpodはpendingですが、Kubernetesクラスタが構築出来たことを確認します。

❯ kubectl get po -n kube-system
NAME                                 READY   STATUS    RESTARTS   AGE
coredns-776bb9db5d-jsnjw             0/1     Pending   0          2m36s
dns-autoscaler-6ffb84bd6-9xt7x       0/1     Pending   0          2m34s
kube-apiserver-k8s-master            1/1     Running   0          3m46s
kube-controller-manager-k8s-master   1/1     Running   1          3m45s
kube-scheduler-k8s-master            1/1     Running   1          3m45s
nginx-proxy-k8s-worker               1/1     Running   0          2m49s
nodelocaldns-75h97                   1/1     Running   0          2m33s
nodelocaldns-jhpmt                   1/1     Running   0          2m33s

3. helmでCilium 1.16.4をインストール

まずはCIlium 1.16.4をインストールします。実際に壊れた環境では1.15.12→1.16.5への更新で壊れたのですが、再現環境を作って試していると1.16.4まではこの構成でも普通に動作していました。

helm repo add cilium https://helm.cilium.io/

cat << EOF > cilium-values.yaml
# kube-proxyがない環境でmasterにアクセスできる必要がある
k8sServiceHost: ${MASTER_IPADDR}
k8sServicePort: 6443
# kube-proxyレスモードでインストールする
kubeProxyReplacement: true
ipam:
  mode: kubernetes
securityContext:
  privileged: true

# この設定を入れると再現する
bpf:
  masquerade: true
EOF

helm install cilium cilium/cilium \
  --version 1.16.4 \
  --values cilium-values.yaml \
  --namespace kube-system

# cilium agentがreadyになるまで待つ
kubectl wait --timeout=90s --for=condition=Ready -n kube-system \
  pods -l k8s-app=cilium


# ciliumインストール前から存在し、hostNetwork以外で動くpodをdeleteして作り直す
kubectl get pods \
  --all-namespaces \
  -o custom-columns=NAMESPACE:.metadata.namespace,NAME:.metadata.name,HOSTNETWORK:.spec.hostNetwork \
  --no-headers=true \
  | grep '<none>' \
  | awk '{print "-n "$1" "$2}' \
  | xargs -L 1 -r kubectl delete pod

4. 名前解決出来ることを確認する

公式ドキュメントの以下で紹介されているイメージを使うことにします。 kubernetes.io

cat << EOF > dnsutil.yaml
apiVersion: v1
kind: Pod
metadata:
  name: dnsutils
  namespace: default
spec:
  containers:
  - name: dnsutils
    image: registry.k8s.io/e2e-test-images/agnhost:2.39
    imagePullPolicy: IfNotPresent
  restartPolicy: Always
EOF

kubectl apply -f dnsutil.yaml

# PodがReadyになるまで待つ
kubectl wait --timeout=90s --for=condition=Ready pods/dnsutils

1.16.4ではこの状態で名前解決に成功します。

❯ kubectl exec -i -t dnsutils -- nslookup kubernetes.default
Server:     169.254.25.10
Address:    169.254.25.10#53

Name:   kubernetes.default.svc.cluster.local
Address: 10.233.0.1

resolv.confにはnode-local-dnsのリッスンするリンクローカルアドレスが書かれています。

❯ kubectl exec -i -t dnsutils -- cat /etc/resolv.conf
search default.svc.cluster.local svc.cluster.local cluster.local flets-east.jp iptvf.jp
nameserver 169.254.25.10
options ndots:5

kubernetesノードには以下の様なデバイスが生えるようです。

❯ ssh ubuntu@$WORKER_IPADDR ip a show dev nodelocaldns
3: nodelocaldns: <BROADCAST,NOARP> mtu 1500 qdisc noop state DOWN group default
    link/ether 6e:a5:52:ac:8a:b2 brd ff:ff:ff:ff:ff:ff
    inet 169.254.25.10/32 scope global nodelocaldns
       valid_lft forever preferred_lft forever

hubbleを使って通信を観測してみます。

# 対象のpodが乗っているノードのcilium-agentを出力する便利スクリプト
wget -O k8s-get-cilium-pod.sh \
  https://raw.githubusercontent.com/cilium/cilium/refs/tags/v1.16.4/contrib/k8s/k8s-get-cilium-pod.sh
chmod +x k8s-get-cilium-pod.sh

kubectl exec -ti pod/$(./k8s-get-cilium-pod.sh dnsutils default) -n kube-system -c cilium-agent \
  -- hubble observe --since 1m --pod default/dnsutils

手元で実行した記録

❯ kubectl exec -ti pod/$(./k8s-get-cilium-pod.sh dnsutils default) -n kube-system -c cilium-agent \
  -- hubble observe --since 1m --pod default/dnsutils
Dec 22 07:51:41.852: 127.0.0.1:39065 (world) <> default/dnsutils (ID:32060) pre-xlate-rev TRACED (UDP)
Dec 22 07:51:41.852: default/dnsutils:50642 (ID:32060) -> 169.254.25.10:53 (world) to-stack FORWARDED (UDP)
Dec 22 07:51:41.853: default/dnsutils:50642 (ID:32060) <- 169.254.25.10:53 (world) to-endpoint FORWARDED (UDP)
Dec 22 07:51:41.853: 169.254.25.10:53 (world) <> default/dnsutils (ID:32060) pre-xlate-rev TRACED (UDP)
Dec 22 07:51:41.853: default/dnsutils:60221 (ID:32060) -> 169.254.25.10:53 (world) to-stack FORWARDED (UDP)
Dec 22 07:51:41.853: default/dnsutils:60221 (ID:32060) <- 169.254.25.10:53 (world) to-endpoint FORWARDED (UDP)
Dec 22 07:51:41.853: 169.254.25.10:53 (world) <> default/dnsutils (ID:32060) pre-xlate-rev TRACED (UDP)
Dec 22 07:51:41.855: default/dnsutils:51283 (ID:32060) -> 169.254.25.10:53 (world) to-stack FORWARDED (UDP)
Dec 22 07:51:41.856: default/dnsutils:51283 (ID:32060) <- 169.254.25.10:53 (world) to-endpoint FORWARDED (UDP)
Dec 22 07:51:41.856: 169.254.25.10:53 (world) <> default/dnsutils (ID:32060) pre-xlate-rev TRACED (UDP)

5. Cilium 1.16.5に更新する

helm upgrade cilium cilium/cilium \
  --version 1.16.5 \
  --namespace kube-system \
  --values cilium-values.yaml

# cilium agentがreadyになるまで待つ
kubectl wait --timeout=90s --for=condition=Ready -n kube-system \
  pods -l k8s-app=cilium

dnsutils Podでのnslookupがタイムアウトするようになります。

❯ kubectl exec -i -t dnsutils -- nslookup kubernetes.default
;; connection timed out; no servers could be reached


command terminated with exit code 1

corednsのClusterIPを指定すると通るので、node-local-dnsとの通信だけが途絶えている事が分かります。

❯ kubectl get svc -n kube-system
NAME           TYPE        CLUSTER-IP      EXTERNAL-IP   PORT(S)                  AGE
cilium-envoy   ClusterIP   None            <none>        9964/TCP                 6m56s
coredns        ClusterIP   10.233.0.3      <none>        53/UDP,53/TCP,9153/TCP   56m
hubble-peer    ClusterIP   10.233.15.182   <none>        443/TCP                  6m56s

❯ kubectl exec -i -t dnsutils -- nslookup kubernetes.default 10.233.0.3
Server:     10.233.0.3
Address:    10.233.0.3#53

Name:   kubernetes.default.svc.cluster.local
Address: 10.233.0.1

hubble observeすると虚空に消えて返って来ないようです。

❯ kubectl exec -ti pod/$(./k8s-get-cilium-pod.sh dnsutils default) -n kube-system -c cilium-agent \
  -- hubble observe --since 1m --pod default/dnsutils
Dec 22 07:45:18.830: 127.0.0.1:45439 (world) <> default/dnsutils (ID:32060) pre-xlate-rev TRACED (UDP)
Dec 22 07:45:18.830: default/dnsutils:55914 (ID:32060) -> 169.254.25.10:53 (world) to-network FORWARDED (UDP)
Dec 22 07:45:28.849: default/dnsutils:55914 (ID:32060) -> 169.254.25.10:53 (world) to-network FORWARDED (UDP)

試したこと

masqLinkLocal: false

bpf.masquerade: true にすると問題が発生することから、IPマスカレードの仕組みのどこかでおかしくなっているのではと考えました。

docs.cilium.io

In addition, if the masqLinkLocal is not set or set to false, then 169.254.0.0/16 is appended to the non-masquerade CIDRs list.

node-local-dnsのリンクローカルアドレスは169.254.25.10なので、なにかの設定変更でIPマスカレードの対象になりおかしくなったのかもしれません。 下記の設定を追加してみましたが効果はありませんでした。

ipMasqAgent:
  enabled: true
  masqLinkLocal: false

hostLegacyRouting: true

以下のissueは起きた現象としては似ているなと思ったので参考にし、この設定を入れてcilium agentを再起動したところ接続出来るようになりました。

github.com

メンテナの見解では、これはBPF Host Routingが正しく動作するようになった結果なので、このオプションを有効化するのが正しいとのこと(できればChangelogに書いて欲しかったなぁ)。

https://github.com/cilium/cilium/issues/36761#issuecomment-2559123347

Ciliumにおける正しい(?)node-local-dnsアーキテクチャ

node-local-dnsと言えばhost networkで動作させるものだと思っていました。しかしCiliumではpod networkで動作させ、 CiliumLocalRedirectPolicy リソースでCoreDNS Cluster IPあての通信をnode-local-dnsサービスにルーティングするという構成が想定されているようです。

docs.cilium.io

自分のクラスタはこの構成に移行することにし、kubesprayのaddonとしてのnode-local-dnsは無効にしました。

まとめ

stagingとかdevみたいなクラスタは用意しないポリシーだったんですが、やっぱりあった方が良いかもと言う気持ちになりました。

通常のKubernetesでのデファクトな構成と、自分が利用しているコンポーネントの想定する構成が一致するとは限りません。ちゃんとドキュメントは確認しましょう。


*1:ArgoCDのhelm integrationを使っていたため、手元には生のマニフェストが無い状態でした。脱helm integrationの決意を固くしました。

*2:応答が返ってこなくなる(no route hostになったりconnection refusedになったりする)ことが一度だけあったのですが、VMを作り直したら直ったので深く追求していません

ISUCONにおけるGrafana・Loki活用Tips

はじめに

これはあくあたん工房アドベントカレンダー 2024 13日目の記事です。他の記事も面白いので、是非見ていってください。

今回のスコア

今年も過去回↓と同じくtaxio、shanpuと3人でチームツナ缶として出場しました。

poyo.hatenablog.jp

最高得点2万点くらい、最終スコア17110点で、おそらく80位前後くらい58位(ChatGPT調べ)くらいでした(failが多かったよう)。惨敗です。

Grafana・Loki活用Tips

やっていることは前回と大きく変わらないのですが、いくつか改善を入れているのでそれを紹介します。

表示範囲内のログ全てから統計値を計算する

例えば過去30分以内のnginxのログデータから、レスポンスタイムの統計を取りたいとします。↓のようなダッシュボードです。

alp相当の統計データを出すダッシュボード

前回のISUCON参加時のダッシュボードでは例えば表示範囲内のログ行のカウント方法がよく分からず、↓のようなクエリを組んでいました*1

sum by (uri_normalized, method) (
  cont by (uri_normalized, method) (
    count_over_time(
      {app="nginx", type="accesslog"}
        | regexp `$accesslog_pattern`
        | __error__ = `` [$__auto]
    )
  )
)

$__auto というのはGrafanaの自動変数の一つ*2で、Grafanaがグラフを表示する際の step の値を元に設定されます*3。 つまり各step(例えば1秒)ごとにアクセスログをカウントし、その結果をまた別のパラメータごとにカウントし直し、最後に足すという手順になっています。正規表現のパースと合わせてこのクエリは非常に遅く、前回は競技終盤ではこのダッシュボードは見れる状態ではなくなっていました。さらに足すだけなら良いのですが、全体から90パーセンタイルのレスポンスタイムを求めるといったクエリが表現できず困っていました。

Grafanaには $__range という自動変数があり、これは今設定している表示範囲が入ることがわかりました。

https://grafana.com/docs/grafana/latest/dashboards/variables/add-template-variables/#__range

つまり、 2024-12-08T00:00:00Z から 2024-12-08T01:00:00Z を表示範囲としていると、 $__range1h になります。計算するクエリをinstantクエリ*4とし、 $__range を使うことで「表示範囲内のログ全てを対象にしたクエリ」が書けます*5

sum by (uri_normalized, method) (
  count_over_time(
    {app="nginx", instance=~"$instance", type="access"}
      | json
      | __error__ = `` [$__range]
  )
)

これを活用すると90パーセンタイルのレスポンスタイムタイムは以下の様に計算出来ます。めちゃくちゃシンプル。

quantile_over_time(
  0.90,
  {app="nginx", instance=~"$instance", type="access"}
    | json
    | __error__ = ``
    | unwrap request_time [$__range]
) by (uri_normalized)

実際、1回のベンチマーク試行では数秒で表示できるので競技終盤でも使える状態でした。

ベンチマーク一回分の計算結果にフォーカスする速度

レスポンスが遅かったログを特定する

ISUCONではあるエンドポイントについてレスポンスタイムの最小値と最大値の差が大きいとき、それを引き起こすパラメータを特定したくなるのではないかと考えていました。

LogQLにsortおよび sort_desc という機能はあるのですが、これはMetrics Queryつまり unwrap request_time などとした場合のソートができるだけです*6。「レスポンスタイムが遅いログ上位N件だけ表示する」みたいなクエリは難しいようです。しかしいくつかの機能を組み合わせることで概ねその機能を実装出来ました。

あるエンドポイントの最も遅いリクエストのログを見るまで

着目したのは以下の特徴です。

  • LokiのLogQLはログをパースしてN秒以上のresponse timeを持つログを取り出せる
    • 扱える行数は非常に大きい
  • Grafanaのテーブルデータとしてログを表示すると、そのラベルの値に基づいてソートできる
    • 扱える行数は最大でも5000
  • LokiのLogQLはログのラベルからNパーセンタイルなどのレスポンスタイムを計算出来る

つまり、まずNパーセンタイルのレスポンスタイムを計算し、それ以上のレスポンスタイムを持つログを抽出、数を絞ってGrafanaの機能でソートすることで遅い順にN%のログを取り出せます。

これをUI上で無理なく表現するため、リクエストの統計値のサマリを出すダッシュボードからGrafanaのData Linkを使って別ダッシュボードへ飛ばします。

まず、Overridesを使ってテーブルの特定のカラムにだけData linkを設定します。複数設定も可能です。

OverrideでURIカラムにだけData Linkを設定する

遷移先ダッシュボードのVariableに値を渡すため、以下の様にData Linkを設定しました。ここでは対象のエンドポイントの正規表現、対象にするインスタンス、90パーセンタイルのレスポンスタイムを数値として*7、そして今表示している時間範囲を渡しています。渡せる値などは以下のページが参考になります。

https://grafana.com/docs/grafana/latest/panels-visualizations/configure-data-links/#data-link-variables

Data Linksの設定

遷移先のダッシュボードではnginxのログをフィルタしてN秒以上のログを抽出し、Grafanaのテーブル機能でソートします。このとき、1000件しか取得していないのでフィルタした結果が1000件を超えているとソートが不完全になります(取得した1000件の中に最悪値が含まれるとは限らないため)。そういう場合は閾値を手動で調整します。

nginxのログをフィルタしてソートするダッシュボード

Grafanaのテーブルパネルはログパネルと違ってクリック時に詳細を表示するみたいなことが綺麗にできなかったので、そこから更にrequest idやクエリパラメータまで含めたURIの一致でログを絞り込むダッシュボードに遷移するようにしています。

スロークエリログの統計値も計算したい

昨年は生のスロークエリログをそのままGrafana Cloudにアップロードしていたのですが、クエリが正規化されていないのでどういうクエリが遅かったとかを解析出来ませんでした。今年はその反省を活かし、pt-query-digestを使ってスローログの正規化を試みました。

pt-query-digest --no-report --output secure-slowlog のようにすると、pt-query-digestは統計値を計算せずただただクエリを正規化してスロークエリログ形式で出力するようになるので、単にMySQLが吐く生のスロークエリログをtailしてstdinから流し込むだけで良い感じの出力を得られます。本番では以下の様なsystemd unitを用意しました。

[Unit]
Description=Normalize slow logs by pt-query-digest

[Service]
Type=simple
User=mysql
ExecStartPre=/bin/bash -c '[ -f "/tmp/slow_query.log" ] || touch /tmp/slow_query.log'
ExecStart=/bin/bash -c "tail -F -n +1 /tmp/slow_query.log | pt-query-digest --no-report --output secure-slowlog"
Restart=always

[Install]
WantedBy=multi-user.target

Grafana Alloy*8を使って、昨年と同様にスロークエリログを正規表現でパースします。

// スロークエリログの処理本体
loki.process "slowquery" {
    // ここでGrafana Cloudやその前段のフィルタステップに流す
    forward_to = [argument.write_to.value]

    // マッチするログだけを処理する
    stage.match {
        selector = "{app=\"slow-query-normalizer.service\"}"

        stage.static_labels {
            values = {
                app = "mysql",
                type = "slowquery",
            }
        }
        // スロークエリログは複数行にまたがっているのでまとめる
        stage.multiline {
            firstline = "^#\\sTime:.*$"
        }
        // 正規表現でスロークエリログをパース、query_timeなどを抽出
        stage.regex {
            expression = "#\\s*Time:\\s*(?P<timestamp>.*)\\n#\\s*User@Host:\\s*(?P<user>[^\\[]+).*@\\s*(?P<host>.*]).*\\n#\\s*Thread_id:\\s*(?P<id>\\d+)\\n#\\s*Query_time:\\s*(?P<query_time>\\d+\\.\\d+)\\s*Lock_time:\\s*(?P<lock_time>\\d+\\.\\d+)\\s*Rows_sent:\\s*(?P<rows_sent>\\d+)\\s*Rows_examined:\\s*(?P<rows_examined>\\d+)\\n(?P<query>(?s:.*))$"
        }
        stage.timestamp {
            source = "timestamp"
            format = "RFC3339Nano"
        }
        // packでLokiが認識できる形にラベルをまとめてログ行として挿入
        stage.pack {
            labels = [
                "query_time",
                "lock_time",
                "rows_sent",
                "rows_examined",
                "query",
            ]
            ingest_timestamp = false
        }
    }
}

// Journalログのいくつかのパラメータを取り出す
loki.relabel "journallog" {
    forward_to = []
    rule {
        source_labels = ["__journal__systemd_unit"]
        target_label = "app"
    }
    rule {
        source_labels = ["__journal_priority_keyword"]
        target_label = "level"
    }
}

// Journalログを読み出してルールに従ってreleabelした後、冒頭のprocessステップに流し込む
loki.source.journal "journallog" {
    forward_to = [loki.process.slowquery.receiver]
    max_age = "10m"
    relabel_rules = loki.relabel.journallog.rules
    labels = {
        job = "loki.source.journal",
    }
}

ポイントはmultilineで複数行のデータを一つにまとめることと、packを使うことです。LogQLには unpack という機能があり、長らく謎だったのですがこれはpromtailやGrafana Alloyの持つこの pack という機能を使ってインジェクトしたパラメータを取り出す機能だったのです。

以下の様なログがあるとします。

2024-12-01T00:00:00Z info message=hoge response_time=0.001
2024-12-01T00:00:01Z info message=fuga response_time=0.012

ここで、response_timeは非常にカーディナリティの高い値であるとします。Lokiのログラベルは非常に高いカーディナリティを持つと非効率になってしまうことから制限がかけられており、そのまま投入してしまうとリミットに触れてしまう可能性があります*9。こうなるとLogQLの実行時にパースすることを考える必要があります。例えば以下の様に pattern や、 regexp を使うことになるでしょう。

{app="sample"}
  | pattern `<time> <level> message=<message> response_time=<response_time>`
  | __error__ = ``
  | response_time > 0.1

patternやregexpを毎回記述するのは面倒です。特にGrafanaのExploreのようなユーザがアドホックにクエリを組んで可視化したいときにも必要になることが有り、不便です。 pack はPromtailやAlloyに実装されている機能で、LogQLが識別しやすい形でラベルを埋め込んでおき、実行時に unpack することで patternregexp を使わずに非JSONなログ行からパラメータを簡単に取り出せます。

Alloyの処理段階でパース・packすると、先の例のログを以下の様な内容のログ行に変換してくれます。

{"_entry": "2024-12-01T00:00:00Z info message=hoge response_time=0.001", "response_time": "0.001"}
{"_entry": "2024-12-01T00:00:01Z info message=fuga response_time=0.001", "response_time": "0.012"}

これをLogQLでunpackすると、元のログ行に追加のラベルを付与した状態で展開してくれるので、response_time に基づくフィルタなどを記述できます。

{app="sample"}
  | unpack
  | __error__ = ``
  | response_time > 0.1

ログ行として埋め込んでいるのでラベルのカーディナリティ制限は問題になりません。元のログ行はそのまま保持するので再利用性も良いです。ただしログ行の内容が純増するので、巨大になりすぎないように注意しましょう。

こうしてスロークエリログのQuery_timeやLock_timeを取り出して pack し、Grafana上でLogQLを書いて unpack することで、正規化されたクエリごとの90パーセンタイルの処理時間などを計測し、遅い順にソートしたりできるようになります。

スロークエリログの統計ダッシュボード

当日やったこと

自分のやった内容です。

  • ~11:00:環境構築・解析基盤の準備
    • writeアクセス権のないAPIトークンを発行してしまっていてミスしたり、alloyがlistenするportが既に使われていたりして焦った
    • 最初に整えてベンチマーク流したのが10:45頃。その後nginxとmysqlの簡単なチューニングだけ実施。
  • ~12:00:index張ったりownerGetChairsの重いクエリをちょっとマシにした
  • ~14:00:複数台構成を組みながらmatcherの重要性に気付く
  • ~16:00:ベンチマークが全く通らず色々切り戻して初期状態に戻る
    • isuride-matcherが複数台で動いていてそれらが同じDBを参照していた
    • 最初期にssh configで2番目と3番目のインスタンスIPアドレスを間違えて配っており、一部メンバーだけ実行ホストが想定と違った状態になっていることに気付かなかった
  • ~17:00:これまでの作業の復元
  • ~17:30:matcherが叩くintervalやRetryAfterの微調整をしたがfailしまくる
  • ~18:00:再起動して壊れないか見たり色々
    • isuride-matcherをdisableする必要があることに気付いてナイス

やや初期構築に時間をかけすぎたなと感じています。そして細かいミスが多すぎました。さすがに反省。

途中あまりにもベンチマークが通らず、ほぼ初期状態まで切り戻したことで大幅に時間をロスしてしまったのが痛かったです。 複数台構成を組んだ際、他のメンバーが自由に作業できるよう共有のDBインスタンス一台と、それを参照する各々のアプリ用インスタンス2台としていました。アプリが非同期に処理を実行していたためマッチングの処理内容によっては容易に壊れうる状態にしてしまいました。ちゃんとmatcherのことに気付いていながら思い至らなかったのは反省です。

今後の展望

遅いリクエストを特定できるようになったので、OpenTelemetryによる分散トレーシングと組み合わせれば、そのとき実行されたアプリ側の処理や発行されたSQLまで追いかけられて便利なのではと思っています。 またnonyleneくんに先に行かれてしまった……。

nonylene.hatenablog.jp

ただオブザーバビリティにかける時間が増えるほど、問題を解く時間は減ってしまいます。今は最初期に設定を入れたら後はノーメンテであり、どういうバランスを取るか悩ましいです。

GrafanaやLokiは便利ですがちゃんと知らないと上手く可視化できません。何かヒントになっていれば嬉しいです。次は優勝するぞ。


*1:前回はnginxのログをLTSV形式で出してaccess_patternという変数に入れた正規表現でパースしていました。これもかなり遅い原因の一つでした

*2:Loki template variables | Grafana documentation

*3:Loki query editor | Grafana documentation

*4:今の表示範囲の最新時間について1回だけ実行されるクエリ

*5:今回はnginxにJSON形式でログを吐かせることにしたので、regexpではなくjsonを使っています。シンプルでこの方が明らかに取り回しがよい!

*6:機能としてはPrometheusのsortと同じです。 https://prometheus.io/docs/prometheus/latest/querying/functions/#sort

Prometheusでは最近experimentalな機能としてsort_by_labelなどが実装され始めたようです。 https://prometheus.io/docs/prometheus/latest/querying/functions/#sort_by_label

*7:numericにしないと、50msのように表示されている値そのままになってしまいます。

*8:昨年はGrafana Agent Flow modeでしたが、これはメンテモードとなり後続の製品としてGrafana Alloyが出ました。だいたい一緒で、ちょっとだけ違うという感じなので乗り換えはそこまで大変では無いと思います。Web UIがあって、experimentalではあるもののデバッグモードを有効化するとリアルタイムにどういうデータが流れてきてフィルタされたり加工されたりしているか見れるので便利です

*9:https://poyo.hatenablog.jp/entry/2023/11/26/170000#%E4%BD%95%E3%81%A7%E3%82%82%E3%83%AD%E3%82%B0%E3%81%AE%E3%83%A9%E3%83%99%E3%83%AB%E3%81%AB%E4%BB%98%E4%B8%8E%E3%81%99%E3%82%8B%E3%81%A8%E6%AD%BB%E3%81%AC

あなたの知らない全国家計構造調査の世界

はじめに

これはあくあたん工房アドベントカレンダー2024 6日目の記事です。他の記事も是非ご覧下さい。

2024年9月、全国家計構造調査の対象世帯として選ばれたので調査への協力を依頼したいという旨の連絡を頂きました。無作為選出によって選ばれてしまって大変面倒な気持ちでいっぱい国のお役に立てると嬉しいので具体的に選ばれると何をやるのか書いておきます。

全国家計構造調査とは

www.stat.go.jp

「家計における消費、所得、資産及び負債の実態を総合的に把握し、世帯の所得分布及び消費の水準、構造等を全国的及び地域別に明らかにすることを目的とする調査」です。 統計法(平成19年法律第53号)に基づく基幹統計調査*1で、5年ごとに実施されており令和6年の調査で14回目だそうです。前回はコロナ禍前の2019年に行われたそうです。

調査の対象

基本的には単身世帯・外国人世帯を除く通常の世帯はほとんどが対象になり得ます。全国から無作為に90000世帯が選ばれるそうです。詳しくは下記ページの「4 調査の対象」をご覧下さい。

https://www.stat.go.jp/data/zenkokukakei/2024/cgaiyo.html

調査の内容

調査はいくつかの種類があるのですが、基本調査では以下の3種類を回答します。

  • 世帯票
    • 世帯の構成人数・扶養の有無、学歴、勤務先の種類など
    • 土地・住宅の所有の有無、住居の構造、住宅ローン返済の有無など
  • 年収・貯蓄等調査票
    • 世帯の構成員の勤め先からの収入・それ以外からの収入(例えば家賃収入など)、年金や給付金の受け取り額
    • 銀行口座の残高・株式や投資信託、債券、生命保険などの保険商品等
  • 家計簿
    • その世帯における口座の入出金や日々の支出を記録したもの
    • 「食費:○○円」のようなざっくりしたカテゴリ分けではなく、細かく「牛乳:○○円」「キャベツ 1/4:○○円」などと記録していく

世帯票と年収・貯蓄等調査票の2つだけを提出する簡易調査というものもあるそうです。

調査期間

2024/10〜2024/11の2ヶ月間実施されます。この期間の家計簿を記録して提出する必要があります。

回答方法

紙もしくはインターネットでの回答が可能で、調査員から紙で提出する場合の家計簿の冊子を渡されます(使わなくとも良い)。

調査のながれ

まず最初に、地域ごとに収集される必要があるという観点から住民票と居住実態が一致する人を対象とするため、実際に調査員が訪問して問題が無いことを確かめるようです。我が家にも一度調査員の方が来られました。確か暑い夏の日だったと思うのですが、炎天下に色んな家を回るなんて大変だなと思った覚えがあります。

次に実際に選定されましたよというお知らせの紙が届きます。総務省のなんか立派なヤツです。その後調査員が再度訪問し、詳しい説明を受け、回答のための備品が配布されました。実際に配布される書類のサンプルは以下のページからも見ることができます。我が家ではインターネット経由で提出すると言っていましたが、備品なのでと電卓やボールペン、メモ帳、紙で提出する用の家計簿などを多数いただき、無事紙ゴミとなりました。

www.stat.go.jp

実際に回答期間になるとインターネットで公開されている調査システムにログインし、まずは世帯票を回答します。MUIとおぼしきフレームワークで構成されたWebアプリケーションで、複数の設問が並んでいるので順番に回答して提出します。

世帯票の回答画面(設問は省略)

10月に入ると日々の支出を記録する期間が始まります。ここでは全ての支出・収入を細かく記録していきます。前述したように「食費:○○円」ではなく「牛乳:○○円」などのように細目まで付けて記録する必要があり、これまでクレジットカードの明細だけを見て家計簿を付けていた我が家ではあらゆるレシートをもらうことが義務づけられました*2

10月の家計簿における項目入力フォーム

このフォームを見ると分かるように、単に値段を記録するだけでは済みません。支払い方法や割引の有無・その割引額まで記載する必要があります。また、中古で購入するなどしたものについてはその旨を記述したり、診療代・検診代は分ける、歯科は別にするなどの必要もあります。記録の例示などを見たり問い合わせしながらこれらを埋めていくことになります。

更に、定期的に発生する光熱費・家賃や住宅ローン返済・携帯電話の通信料金などは別途自動引き落としという項目で入力が必要です。

自動引き落としの料金入力(項目はデフォルトでいくつか+自分で追加も可能)

また収入についても細かく記載が必要で、手取り額だけでなく額面いくらでそのうち手当と控除がどうなっているかなどまで記載します。

収入の入力画面(手当・控除は自分で項目追加も可能)

11月に入ると家計簿の回答項目が増え、購入先(スーパーとかコンビニとか)・購入地域(同市町村や県内・県外など)も追加で入力します。スクショ撮ろうと思ったら回答期間が終わってから入力画面は開けなくなってしまいました。

11月中旬になると年収・貯蓄等調査票に回答し、後は11月末まで家計簿を記録しきってフィニッシュです。最後にアンケートがあるのでそれも回答しました。

大変だったところ

家計簿大変すぎ

とにかくこれです。本当に大変で、消費の意欲をごっそり持って行かれました。「家計簿入れないといけなくなるから買うの辞めるか……」って思ったことが何度もあります。食費はまだしも、趣味にかけた費用などはこの期間明らかに減ったはずです。おそらく2ヶ月間でキーボードのパーツいくつかと、Factorio Space Ageしか趣味のものを買っていません。節約したい人はあらゆるものを家計簿に入れなければならないというレギュレーションを課してみると良いと思いました。

一応レシートを画像認識して入力する機能もありました。が、スーパーのレシートなど長尺でたくさんの項目が並び、品目名が中途半端になってしまうものが多いと誤認識が著しく、結局自分は手入力していました。自分のための家計簿なら多少入力タイトルに不備があっても許せますが、調査に回答するのに明らかに意味不明な品目を入力するのは良くないだろうと感じたためです。「地元野菜 ¥128」という項目を見てピーマンだと分かるのも、「HD キャラメル ¥228」を見てハーゲンダッツだと分かるのも自分がそれを買った記憶があるからなので、認識能力を上げてもこれは解消しなさそうです。

たまたまこれは回避したのですが、期間中に海外渡航していてもこの調査の例外にはならず、「滞在中のいずれかのタイミングのレートで日本円に換算した額を記入する」という対応が必要だそうです。もし海外行っていたらもっと大変な目に遭っていた……

同一世帯なら支出・収入を互いに把握しているという前提

うちは妻と二人の世帯なのですが、特にお互いの支出・収入には深く踏み込んでいません。年収としてだいたいどれくらいお互いが稼いでいるかや、どの程度投資や貯蓄に回しているかをざっくり感覚で知っているだけです。そのためお互いが日々いくら何にお金を費やしているかをこれまで知ることはありませんでした*3

大変困ったことに家計構造調査の回答Webアプリのログインユーザは世帯当たり1つです。お互いの支出などを入力するためにはIDとパスワードを共有して両方が入力するか、どちらかに伝えて入力してもらう必要があります。つまりどちらか片方は必ず相手の支出を全て知ってしまうことになります。

うちは1Password Familyに加入しているので、夫婦の共有領域にIDとパスワードを入れて管理することにしました。これで自分の出費も妻の出費も、品目単位で全て筒抜けになりました*4。また日々の支出だけでなく給与・貯蓄・株式や投資信託の額も1万円単位で全額把握してしまいました。

入力欄に「こづかい」などの項目があることからも、基本的にこの調査では

  • ある世帯の収入は一度全て回収・合算される
  • 「こづかい」という形で各人が自由に使える金額を再分配する
  • 残りを世帯全体のための収入として計上し、生活に必要な支出を賄う

みたいなモデルを標準としているように見えます。しかし、我が家では互いが独立した収入源を持ち、互いの支出入に口を出さないというこのモデルから大きく外れた状態になっています。お互い自分の収入をほとんど自由に取り扱っていますが、これはこづかいとは呼ばないでしょう。

このようなモデルであることから、自動引き落としの料金入力は個人単位ではなく世帯単位になっており、例えば携帯電話の通信料金やクレジットカード引き落としなど世帯構成員のそれぞれの口座で発生する支出イベントも回答欄は一つです。つまり二人の色んな支出をそこで合算して記入する必要があります。全体を把握・管理している人がいればその人が知っている額を入れるだけで済みますが、うちではお互いの口座の取引明細は見れません。口頭で伝えたり、先に入れたから合算して入れ直して等の依頼をしていました。収入の入力は構成員ごとにできるようになっているので、自動引き落としもそうなっていたら互いが好きなタイミングで入れられて良かったのにと思わずにはいられません。まぁ合算するだけなので、そうなってくれないと困ると言うほどではないです。

実は個人の収支を個別に収集する調査は「個人収支状況調査」として個別に存在するようなのですが、回答する側としてはもはや違いがイマイチ分からないというのが自分の感想です*5

統計局ホームページ/全国家計構造調査に関するQ&A(回答)

個人収支状況調査は、通常の家計調査では捉えきれていない「個人の判断で自由に使えるお金」の収支内容を、世帯員一人一人に配布する「個人収支簿」で調査します。

プライバシーへの配慮が微妙

まず大前提として家計構造調査の調査上知り得た秘密を漏洩させることは当然犯罪です。

www.stat.go.jp

統計法第41条では、調査の結果知り得た秘密は漏らしてはならないことが規定されており、これに違反した者に対する罰則が定められています (統計法第57条)。
 さらに、統計法第40条では、「この法律(地方公共団体の長その他の執行機関にあっては、この法律又は当該地方公共団体の条例)に特別の定めがある場合を除き、その行った統計調査の目的以外の目的のために、当該統計調査に係る調査票情報を自ら利用し、又は提供してはならない」と規定されています。
調査票は外部の人の目に触れないように厳重に保管され、集計が完了した後は溶解処分されます。

このように調査票を紙で提出する場合の破棄方法などには言及があるものの、Webアプリのシステムに関する言及を自分は見つけられませんでした。

レシート認識機能を使うとレシート画像がサーバに保存されるようなのですが、そういう説明はどこにも無かったと思いますし、明らかに調査対象で無いレシート画像そのもののデータの取り扱いが今後どうなるかの言及がありませんでした。問い合わせたところ「終了後削除する」という、まぁそうだろうねという回答だけ得られました。

また「代行入力」という機能があり、レシート画像を撮影してオペレータに代理で入力してもらう機能があるのですが、どこのどういう人に送られてその画像はどうなってみたいな説明が軽く探しても見つからなかったので使いませんでした*6

レシート画像には店舗名や日付などが含まれ居住地をある程度推測できるほか、購入したものから家族構成や年齢層まである程度把握できてしまいかねないもので、いくら統計法で守秘義務が課されているといってももう少し配慮が欲しかったところです。

良かったこと

特にないですが、強いて言うなら自分の求めるレベルの家計管理に細目まで含めた詳細な記帳は不要であることを実際に試して体感したのは良かったです。

これまでMoneyForwardとOsidOriにクレカと銀行口座の明細を食わせて、明細ごとにカテゴリ分けしたざっくり家計簿でやってきていました。時々異なるカテゴリの支出が一つの明細にまとまってしまうことがあり(例えばスーパーで食品と一緒にティッシュペーパーのような日用品を買ったなど)、これは過半数を占める支出カテゴリに設定していました。実際に細目まで記帳していくと全体に対してこのような出費は大抵誤差の範囲内程度であり、かかる労力の方がはるかに大きかったため今後も無視することにしました。

後はちゃんとインターネット回答でき、使っている限り深刻なバグらしきものには出くわさなかったのも良かったです。紙だったら耐えられていなかったと思います。ちゃんと go.jpサブドメインで提供されていたのもポイントが高かったです。

動作が死ぬほど遅いとかが途中で起きたり、ログイン出来るブラウザと出来ないブラウザがあったり、UIがスマホ特化でPCから使いづらいなどはありましたが政府が用意したWebアプリとしてはマシな部類でしょう。今後も日本政府にはIT関連がんばって欲しいです。

FAQ

Q. 面倒だから調査依頼が来たら無視してもいい?
A. 統計法第13条により家計構造調査は「個人又は法人その他の団体に対し報告を求めることができる」と規定されており、同法第61条で「報告を拒み、又は虚偽の報告をした者」には「五十万円以下の罰金に処する」と書かれています。自分からは以上です。

最後に

不満はだいたいアンケートにも書いたので、次の開催時には軽減されていると嬉しいなと思います。

また、家計構造調査など総務省統計局による調査を装った詐欺も発生しています。特に家計構造調査では収入や世帯構成などの情報を取得するため、そういった情報が欲しい悪い人のターゲットにされる可能性があります。政府の正規のWebサイトのみに情報を入力すること、尋ねてきた調査員には詳細を話さず、怪しいと思ったら自治体に相談するようにしましょう。調査員自らが調査内容の詳細を尋ねてくることはありません。

www.stat.go.jp


*1:特に重要な統計調査として法務大臣が指定したもの

*2:もらいわすれるとがんばって値段を思い出して埋めるしか無くなります。実際何度かセブンイレブンの公式サイトに救われたことがあります。

*3:クレジットカードの家族カードを渡しているので、妻が共有で使うこれ(と思われるもの)をamazonで決済したなとかはわかりますが、妻本人のカードの明細などは見たことがありません。

*4:これが原因で家庭内に不和が生じた家庭とかありそう……うちは特に何もありませんでした

*5:家計簿の調査では誰が使ったかがやや不明なのでその情報を収集したいのだと思うのですが、それなら最初から個人ごとに収拾して世帯で合算された方が良かったのではと思ってしまいます。

*6:使ってみたらあったのかもしれないですがそこまでは見ていません