influxdata / influxdata/influxdb
VM freeze on InfluxDB 2.0 OSS during snapshot create
- Dominant language
- Rust
- Stars
- 31.7k
- Forks
- 3.7k
- Avg merge
- 13h 37m
- Merged PRs (30d)
- 8
Description
__Expected behavior:__
We've been running InfluxDB 2.0 beta 16 on an AWS EC2 instance for several months now and it has worked well for us except that with large queries we have noticed the whole VM locks up completely and requires a restart. This week we decided to migrate to the most recent version using the steps at https://docs.influxdata.com/influxdb/v2.0/upgrade/v2-beta-to-v2/, in the hope that if InfluxDB were responsible, there would be better protection against freezes. Alas the problem is still present but the migration afforded me the chance to dive a bit deeper.
__Environment info:__
* System info: Run `uname -srm` and copy the output here
```
Linux 5.4.0-1048-aws x86_64
```
(actually Ubuntu 18.04.5 LTS).
* InfluxDB version: Run `influxd version` and copy the output here
```
InfluxDB 2.0.6 (git: 4db98b4c9a) build_date: 2021-04-29T16:48:12Z
```
(although this appears to report `Version 2.0.5 ('7c3ead)` on the client login screen, it was installed with https://dl.influxdata.com/influxdb/releases/influxdb2-2.0.6-amd64.deb).
* Other relevant environment details: Container runtime, disk info, etc
It's an AWS m5n.large instance (2 vCPU, 8GB RAM, shared tenancy) with a single 64GB gp3 disk (3000IOPS, 125MiB/s, no bursting). `df -h` reports 49G free and `df -i` reports 7,820,646 IFree. There is no swap configured.
InfluxDB2 and Amazon Cloudwatch Agent are the only things installed on the VM beyond default. There is a security group that permits inbound on 22, 8086, and 9999 and outbound on 80 and 443.
__Steps to reproduce:__
1. Vanilla install of InfluxDB 2.0 as described in the v2-beta-to-v2 steps linked above
2. Mass install of monthly data for 14 months, created using the export command in the steps. The data is roughly 2.5GB, 22,070,328 rows total.
```sh
$ influx query -c influx_old 'from(bucket: "Fp") |> range(start: -1mo, stop: -1day)' --raw > Fp01.csv
$ influx query -c influx_old 'from(bucket: "Fp") |> range(start: -2mo, stop: -1mo)' --raw > Fp02.csv
...
$ influx write -c default --format csv -b Fp -f Fp01.csv -o Roxhill -t --skipRowOnError
$ influx write -c default --format csv -b Fp -f Fp02.csv -o Roxhill -t --skipRowOnError
```
__Actual behavior:__
At some point during the import (not always the same point) the VM will appear to freeze. It will be impossible to SSH into and after a while AWS will report that it has failed its instance reachability check. There seems to be nothing to do to recover but reboot which is apparently successful, returning the system including InfluxDB 2 to a fully running state.
I noted that HTOP shows load average climbing to more than 20 (from 2-3 normal), mem at 7.41G of 7.57G and the InfluxD process VIRT 9.9G and RES 7368M.
__Logs:__
Journalctl shows a normal cycle of snapshot creation until the moment of failure:
```
May 19 09:58:20 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:20.730186Z lvl=info msg="index opened with 8 partitions" log_id=0UCFsmvl000 service=storage-engine index=tsi
May 19 09:58:20 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:20.731048Z lvl=info msg="Reindexing TSM data" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 db_shard_id=115
May 19 09:58:20 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:20.731259Z lvl=info msg="Reindexing WAL data" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 db_shard_id=115
May 19 09:58:21 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:21.015199Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/76 duration=1327.336ms
May 19 09:58:21 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:21.017527Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=1329.663ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.483248Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/78 duration=3935.700ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.485706Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=3938.158ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.493985Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/80 duration=3995.259ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.494007Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=3999.701ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.707440Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/79 duration=4250.302ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.707479Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=4247.469ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.742064Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/77 duration=4244.228ms
May 19 09:58:23 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:23.742098Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=4244.263ms
May 19 09:58:52 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:52.126028Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:58:52 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:52.762812Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:58:52 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:52.843535Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:58:52 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:52.870812Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:58:58 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:58.343335Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/83 duration=5470.896ms
May 19 09:58:58 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:58.439096Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/82 duration=5676.292ms
May 19 09:58:58 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:58.439131Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=5676.328ms
May 19 09:58:58 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:58.599725Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=5486.757ms
May 19 09:58:59 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:59.927970Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/81 duration=7804.660ms
May 19 09:58:59 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:59.928020Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=7803.830ms
May 19 09:58:59 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:59.937357Z lvl=info msg="Snapshot for path written" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/engine/data/74d3e8f4aa42d5ee/autogen/84 duration=7093.829ms
May 19 09:58:59 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:58:59.937395Z lvl=info msg="Cache snapshot (end)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=end op_elapsed=7093.867ms
May 19 09:59:24 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:59:24.179734Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:59:24 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:59:24.205659Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:59:24 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:59:24.243330Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 09:59:24 ip-172-29-5-79 influxd[851]: ts=2021-05-19T09:59:23.974613Z lvl=info msg="Cache snapshot (start)" log_id=0UCFsmvl000 service=storage-engine engine=tsm1 op_name=tsm1_cache_snapshot op_event=start
May 19 10:02:58 ip-172-29-5-79 systemd[1]: snapd.service: Watchdog timeout (limit 5min)!
May 19 10:03:04 ip-172-29-5-79 systemd[1]: snapd.service: Killing process 847 (snapd) with signal SIGABRT.
May 19 10:05:54 ip-172-29-5-79 systemd[1]: snapd.service: State 'stop-sigabrt' timed out. Terminating.
May 19 10:07:30 ip-172-29-5-79 systemd[1]: snapd.service: State 'stop-sigterm' timed out. Killing.
May 19 10:07:37 ip-172-29-5-79 systemd[1]: snapd.service: Killing process 847 (snapd) with signal SIGKILL.
May 19 10:07:43 ip-172-29-5-79 systemd[1]: snapd.service: Main process exited, code=killed, status=9/KILL
May 19 10:07:43 ip-172-29-5-79 systemd[1]: snapd.service: Failed with result 'watchdog'.
...
```
__Config:__
Copy any non-default config values here or attach the full config as a gist or file.
The installation is a vanilla one but I did try a run adding
```
GODEBUG=madvdontneed=1
```
to `/etc/default/influxdb2` without any real expectation of improvement. Sadly I was right!
Contributor guide
Research direction
Start by reproducing the monthly CSV import with influxd on the stated AWS m5n.large Ubuntu environment while monitoring htop, journalctl, and the cache snapshot logs. The issue names no repository files or tests; done means identifying the cause of the VM freeze during snapshot creation and verifying a fix against this import scenario.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- aws, go, linux, ubuntu
- Domain
- databases, operating-systems, performance
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100