walredo: make request_redo() an async fn #5559
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
It says it in the comment.
Before this PR, the following race condition existed: ``` T1: does the apply_wal_records() call and gets back an error T2: does the apply_wal_records() call and gets back an error T2: does the kill_and_shutdown T2: new loop iteration T2: launches new walredo process T1: does the kill_and_shutdown of the new process ``` That last step is wrong, T2 already did the kill_and_shutdown. The symptom of this race condition was that T2 would observe an error when it tried to do something with the process after T1 killed it. For example, but not limited to: `POLLHUP` / `"WAL redo process closed its stderr unexpectedly"`. The fix in this PR is the following: * Use Arc to represent walredo processes. The Arc lives at least as long as the walredo process. * Use Arc::ptr_eq to determine whether to kill the process or not. The price is an additional Mutex to protect the new `redo_process` field that holds the Arc. I guess that could perhaps be an atomic pointer swap. I don't think the Mutex will be contentious, though, so, inclined to get race fixed without risking introducing a new race. Note: an earlier fix attempt was #5545 where we apply_batch_postgres would compare stdout_fd for equality. That's incorrect because the kernel can reuse the file descriptor when T2 launches the new process. Details: #5545 (review)
These changes have a 2% impact on `bench_walredo`.
That's likely because of the `block_on() in the innermost piece of
benchmark-only code.
So, it doesn't affect production code.
The use of closures in the benchmarking code prevents a straightforward
conversion of the whole benchmarking code to async.
before:
```
$ cargo bench --features testing --bench bench_walredo
Compiling pageserver v0.1.0 (/home/cs/src/neon/pageserver)
Finished bench [optimized + debuginfo] target(s) in 2m 11s
Running benches/bench_walredo.rs (target/release/deps/bench_walredo-d99a324337dead70)
Gnuplot not found, using plotters backend
short/short/1 time: [26.363 µs 27.451 µs 28.573 µs]
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high mild
short/short/2 time: [64.340 µs 64.927 µs 65.485 µs]
Found 2 outliers among 100 measurements (2.00%)
2 (2.00%) low mild
short/short/4 time: [101.98 µs 104.06 µs 106.13 µs]
short/short/8 time: [151.42 µs 152.74 µs 154.03 µs]
short/short/16 time: [296.30 µs 297.53 µs 298.88 µs]
Found 14 outliers among 100 measurements (14.00%)
10 (10.00%) high mild
4 (4.00%) high severe
medium/medium/1 time: [225.12 µs 225.90 µs 226.66 µs]
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) low mild
medium/medium/2 time: [490.80 µs 491.64 µs 492.49 µs]
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) low mild
medium/medium/4 time: [934.47 µs 936.49 µs 938.52 µs]
Found 5 outliers among 100 measurements (5.00%)
3 (3.00%) low mild
1 (1.00%) high mild
1 (1.00%) high severe
medium/medium/8 time: [1.8364 ms 1.8412 ms 1.8463 ms]
Found 4 outliers among 100 measurements (4.00%)
4 (4.00%) high mild
medium/medium/16 time: [3.6694 ms 3.6896 ms 3.7104 ms]
```
after:
```
$ cargo bench --features testing --bench bench_walredo
Compiling pageserver v0.1.0 (/home/cs/src/neon/pageserver)
Finished bench [optimized + debuginfo] target(s) in 2m 11s
Running benches/bench_walredo.rs (target/release/deps/bench_walredo-d99a324337dead70)
Gnuplot not found, using plotters backend
short/short/1 time: [28.345 µs 28.529 µs 28.699 µs]
change: [-0.2201% +3.9276% +8.2451%] (p = 0.07 > 0.05)
No change in performance detected.
Found 17 outliers among 100 measurements (17.00%)
4 (4.00%) low severe
5 (5.00%) high mild
8 (8.00%) high severe
short/short/2 time: [66.145 µs 66.719 µs 67.274 µs]
change: [+1.5467% +2.7605% +3.9927%] (p = 0.00 < 0.05)
Performance has regressed.
Found 5 outliers among 100 measurements (5.00%)
5 (5.00%) low mild
short/short/4 time: [105.51 µs 107.52 µs 109.49 µs]
change: [+0.5023% +3.3196% +6.1986%] (p = 0.02 < 0.05)
Change within noise threshold.
short/short/8 time: [151.90 µs 153.16 µs 154.41 µs]
change: [-1.0001% +0.2779% +1.4221%] (p = 0.65 > 0.05)
No change in performance detected.
short/short/16 time: [297.38 µs 298.26 µs 299.20 µs]
change: [-0.2953% +0.2462% +0.7763%] (p = 0.37 > 0.05)
No change in performance detected.
Found 2 outliers among 100 measurements (2.00%)
2 (2.00%) high mild
medium/medium/1 time: [229.76 µs 230.72 µs 231.69 µs]
change: [+1.5804% +2.1354% +2.6635%] (p = 0.00 < 0.05)
Performance has regressed.
medium/medium/2 time: [501.14 µs 502.31 µs 503.64 µs]
change: [+1.8730% +2.1709% +2.5199%] (p = 0.00 < 0.05)
Performance has regressed.
Found 7 outliers among 100 measurements (7.00%)
1 (1.00%) low mild
1 (1.00%) high mild
5 (5.00%) high severe
medium/medium/4 time: [954.15 µs 956.74 µs 959.33 µs]
change: [+1.7962% +2.1627% +2.4905%] (p = 0.00 < 0.05)
Performance has regressed.
medium/medium/8 time: [1.8726 ms 1.8785 ms 1.8848 ms]
change: [+1.5858% +2.0240% +2.4626%] (p = 0.00 < 0.05)
Performance has regressed.
Found 6 outliers among 100 measurements (6.00%)
1 (1.00%) low mild
3 (3.00%) high mild
2 (2.00%) high severe
medium/medium/16 time: [3.7565 ms 3.7746 ms 3.7934 ms]
change: [+1.5503% +2.3044% +3.0818%] (p = 0.00 < 0.05)
Performance has regressed.
Found 3 outliers among 100 measurements (3.00%)
3 (3.00%) high mild
```
2304 tests run: 2194 passed, 0 failed, 110 skipped (full report)Code coverage (full report)
The comment gets automatically updated with the latest test results
e394aaf at 2023-10-18T10:21:20.971Z :recycle: |
problame
changed the title
arpad-m
approved these changes
Oct 17, 2023
problame
added a commit
that referenced
this pull request
Oct 23, 2023
…#5560) Stacked atop #5559 Before this PR, there was the following race condition: ``` T1: polls for writeable stdin T1: writes to stdin T1: enters poll for stdout/stderr T2: enters poll for stdin write WALREDO: writes to stderr KERNEL: wakes up T1 and T2 Tx: reads stderr and prints it Ty: reads stderr and gets EAGAIN (valid values for (x, y) are (1, 2) or (2, 1)) ``` The concrete symptom that we observed repeatedly was with PG16, which started logging `registered custom resource manager` to stderr always, during startup, thereby giving us repeated opportunity to hit above race condition. PG14 and PG15 didn't log anything to stderr, hence we could have only hit this race condition if there was an actual error happening. This PR fixes the race by moving the reading of stderr into a tokio task. It exits when the stderr is closed by the child process, which in turn happens when the child exits, either by itself or because we killed it. The downside is that the async scheduling can reorder the log messages, which can be seen in the new `test_stderr`, which runs in a single-threaded runtime. I included the output below. Overall I think we should move the entire walredo to async, as Joonas proposed many months ago. This PR's asyncification is just the first step to resolve these false page reconstruction errors. After this is fixed, we should stop printing that annoying stderr message on walredo startup; it causes noise in the pageserver logs. That work is tracked in #5399 . ``` 2023-10-13T19:05:21.878858Z ERROR apply_wal_records{tenant_id=d546fb76ba529195392fb4d19e243991 pid=753986}: failed to write out the walredo errored input: No such file or directory (os error 2) target=walredo-1697223921878-1132-0.walredo length=1132 2023-10-13T19:05:21.878932Z DEBUG postgres applied 2 WAL records (1062 bytes) in 114666 us to reconstruct page image at LSN 0/0 2023-10-13T19:05:21.878942Z ERROR error applying 2 WAL records 0/16A9388..0/16D4080 (1062 bytes) to base image with LSN 0/0 to reconstruct page image at LSN 0/0 n_attempts=0: apply_wal_records Caused by: WAL redo process closed its stdout unexpectedly 2023-10-13T19:05:21.879027Z INFO kill_and_wait_impl{pid=753986}: wait successful exit_status=signal: 11 (SIGSEGV) (core dumped) 2023-10-13T19:05:21.879079Z DEBUG wal-redo-postgres-stderr{pid=753986 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: wal-redo-postgres stderr_logger_task started 2023-10-13T19:05:21.879104Z ERROR wal-redo-postgres-stderr{pid=753986 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: received output output="2023-10-13 19:05:21.769 GMT [753986] LOG: registered custom resource manager \"neon\" with ID 134\n" 2023-10-13T19:05:21.879116Z DEBUG wal-redo-postgres-stderr{pid=753986 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: wal-redo-postgres stderr_logger_task finished 2023-10-13T19:05:22.004439Z ERROR apply_wal_records{tenant_id=d546fb76ba529195392fb4d19e243991 pid=754000}: failed to write out the walredo errored input: No such file or directory (os error 2) target=walredo-1697223922004-1132-0.walredo length=1132 2023-10-13T19:05:22.004493Z DEBUG postgres applied 2 WAL records (1062 bytes) in 125344 us to reconstruct page image at LSN 0/0 2023-10-13T19:05:22.004501Z ERROR error applying 2 WAL records 0/16A9388..0/16D4080 (1062 bytes) to base image with LSN 0/0 to reconstruct page image at LSN 0/0 n_attempts=1: apply_wal_records Caused by: WAL redo process closed its stdout unexpectedly 2023-10-13T19:05:22.004588Z INFO kill_and_wait_impl{pid=754000}: wait successful exit_status=signal: 11 (SIGSEGV) (core dumped) 2023-10-13T19:05:22.004624Z DEBUG wal-redo-postgres-stderr{pid=754000 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: wal-redo-postgres stderr_logger_task started 2023-10-13T19:05:22.004653Z ERROR wal-redo-postgres-stderr{pid=754000 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: received output output="2023-10-13 19:05:21.884 GMT [754000] LOG: registered custom resource manager \"neon\" with ID 134\n" 2023-10-13T19:05:22.004666Z DEBUG wal-redo-postgres-stderr{pid=754000 tenant_id=d546fb76ba529195392fb4d19e243991 pg_version=16}: wal-redo-postgres stderr_logger_task finished ```
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Stacked atop #5557
Prep work for #5560
These changes have a 2% impact on
bench_walredo.That's likely because of the `block_on() in the innermost piece of
benchmark-only code.
So, it doesn't affect production code.
The use of closures in the benchmarking code prevents a straightforward
conversion of the whole benchmarking code to async.
before:
after: