changefeedccl: Add timeout to testfeed library. #84007
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
|
This change is |
stevendanna
approved these changes
Jul 7, 2022
| latestResolved hlc.Timestamp | ||
| } | ||
|
|
||
| var _ cdctest.TestFeed = (*sinklessFeed)(nil) | ||
|
|
||
| func deadline() time.Duration { | ||
| if util.RaceEnabled { | ||
| return time.Minute |
There was a problem hiding this comment.
Race can be really slow in CI sometimes. I might even consider something like 5 minutes.
stevendanna
approved these changes
Jul 7, 2022
miretskiy
force-pushed
the
flake
branch
2 times, most recently
from
31cd6c3
to
2e17cff
Compare
|
I'm fine with this merging as forward progress, but I think there is probably a long tail of places that need to be able to respect the contexts. Based on the code, I kinda expected this test to complete in roughly 30 seconds per sink, but it doesn't seem to (depending on the sink, kafka appears to work, sinkless and cloudsink don't) func TestChangefeedTestTimesOut(t *testing.T) {
defer leaktest.AfterTest(t)()
defer log.Scope(t).Close(t)
testFn := func(t *testing.T, s TestServer, f cdctest.TestFeedFactory) {
sqlDB := sqlutils.MakeSQLRunner(s.DB)
sqlDB.Exec(t, `CREATE TABLE foo (a INT PRIMARY KEY)`)
nada := feed(t, f, "CREATE CHANGEFEED FOR foo")
defer closeFeed(t, nada)
require.Error(t, withTimeout(func(ctx context.Context) error {
return assertPayloadsBaseErr(ctx, nada, []string{`not gonna happen: [2]->{"after": {"a": 2}}`}, false, false)
}))
}
cdcTest(t, testFn)
} |
stevendanna
reviewed
Jul 7, 2022
Comment on lines
171
to
184
| ctx := context.Background() | ||
| c.ctx, c.cancel = context.WithCancel(context.Background()) |
There was a problem hiding this comment.
For sinkless feeds, I think we need a timeout here. I don't think Query will return until at least one row returns, so if our changefeed never returns any rows, we don't time out.
There was a problem hiding this comment.
Not sure actually; I arrange to call cancel in Next():
defer time.AfterFunc(deadline(), c.cancel).Stop()
There was a problem hiding this comment.
But we never make it to next. Because Query never returns:
goroutine 38 [IO wait, 1 minutes]:
internal/poll.runtime_pollWait(0x370ba790, 0x72)
GOROOT/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc0006dda00, 0xc000196400, 0x0)
GOROOT/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
GOROOT/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0006dda00, {0xc000196400, 0x8e7, 0x8e7})
GOROOT/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0006dda00, {0xc000196400, 0x8e7, 0x0})
GOROOT/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc001fed320, {0xc000196400, 0xc00601c9f8, 0xc00601ca08})
GOROOT/src/net/net.go:183 +0x45
crypto/tls.(*atLeastReader).Read(0xc001fcab10, {0xc000196400, 0x0, 0x400ab8d})
GOROOT/src/crypto/tls/conn.go:778 +0x3d
bytes.(*Buffer).ReadFrom(0xc005fa7e78, {0x9ea9140, 0xc001fcab10})
GOROOT/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc005fa7c00, {0x9eb77c0, 0xc001fed320}, 0x4042391)
GOROOT/src/crypto/tls/conn.go:800 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc005fa7c00, 0x0)
GOROOT/src/crypto/tls/conn.go:607 +0x112
crypto/tls.(*Conn).readRecord(...)
GOROOT/src/crypto/tls/conn.go:575
crypto/tls.(*Conn).Read(0xc005fa7c00, {0xc002b4622d, 0x1dd3, 0xc0028d8000})
GOROOT/src/crypto/tls/conn.go:1278 +0x16f
io.ReadAtLeast({0x13e10e20, 0xc005fa7c00}, {0xc002b4622d, 0x1dd3, 0x1dd3}, 0x5)
GOROOT/src/io/io.go:328 +0x9a
github.com/jackc/chunkreader/v2.(*ChunkReader).appendAtLeast(...)
github.com/jackc/chunkreader/v2/external/com_github_jackc_chunkreader_v2/chunkreader.go:88
github.com/jackc/chunkreader/v2.(*ChunkReader).Next(0xc00505a340, 0x5)
github.com/jackc/chunkreader/v2/external/com_github_jackc_chunkreader_v2/chunkreader.go:78 +0x2ac
github.com/jackc/pgproto3/v2.(*Frontend).Receive(0xc005189000)
github.com/jackc/pgproto3/v2/external/com_github_jackc_pgproto3_v2/frontend.go:74 +0x50
github.com/jackc/pgconn.(*PgConn).peekMessage(0xc0056cec60)
github.com/jackc/pgconn/external/com_github_jackc_pgconn/pgconn.go:499 +0x136
github.com/jackc/pgconn.(*ResultReader).readUntilRowDescription(0xc0056cecf8)
github.com/jackc/pgconn/external/com_github_jackc_pgconn/pgconn.go:1529 +0x31
github.com/jackc/pgconn.(*PgConn).execExtendedSuffix(0xc0056cec60, {0xc0028d8000, 0xc004fbce00, 0x0}, 0xc0056cecf8)
github.com/jackc/pgconn/external/com_github_jackc_pgconn/pgconn.go:1131 +0x24b
github.com/jackc/pgconn.(*PgConn).ExecPrepared(0xc0056cec60, {0x9f549c0, 0xc004fbce00}, {0xc000567760, 0xa}, {0x0, 0x0, 0x0}, {0x0, 0x0, ...}, ...)
github.com/jackc/pgconn/external/com_github_jackc_pgconn/pgconn.go:1076 +0x196
github.com/jackc/pgx/v4.(*Conn).Query(0xc003934870, {0x9f549c0, 0xc004fbce00}, {0x88e5005, 0x19}, {0x0, 0x68, 0x78})
github.com/jackc/pgx/v4/external/com_github_jackc_pgx_v4/conn.go:651 +0xd8d
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*sinklessFeed).start(0xc0006dd900)
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/testfeed_test.go:201 +0x37e
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*sinklessFeedFactory).Feed(0xc00235eb60, {0x88e5005, 0x19}, {0x0, 0x0, 0x0})
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/testfeed_test.go:88 +0x19d
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.feed({0xa023850, 0xc00235eb60}, {0x9eaa780, 0xc0040aa780}, {0x88e5005, 0x19}, {0x0, 0x0, 0x0})
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/helpers_test.go:596 +0x98
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.TestChangefeedTestTimesOut.func1(_, {0xc005d5fc70, {0xa055510, 0xc001435dc0}, {{0xc003e15890}, {0xc003e15890}, 0x0}, {{0x0, 0x0}, {0x0, ...}, ...}}, ...)
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_test.go:701 +0xe6
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.cdcTestNamed.func1(_, {{0xc005d5fc70, {0xa055510, 0xc001435dc0}, {{0xc003e15890}, {0xc003e15890}, 0x0}, {{0x0, 0x0}, {0x0, ...}, ...}}, ...}, ...)
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/helpers_test.go:820 +0x5d
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.cdcTestNamedWithSystem.func1(0xc00235eb60)
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/helpers_test.go:848 +0x24d
testing.tRunner(0xc00235eb60, 0xc00089fdd0)
GOROOT/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
GOROOT/src/testing/testing.go:1306 +0x35a
There was a problem hiding this comment.
But we never make it to next. Because Query never returns:
Ahh.. i see.
|
Made some additional changes; added the test you wrote -- almost verbatim; seems to correctly |
miretskiy
force-pushed
the
flake
branch
3 times, most recently
from
b69d2b8
to
0c8a129
Compare
|
cancelling sinkless feed proving to be more problematic; removed WithCancel logic and replaced it with direct call to connection cancellation instead. Let's see if that makes CI happy. |
Add timeout to testfeed sink implementations to timeout if no messages are received for too long. Release Notes: None
|
bors r+ |
|
Build succeeded: |
miretskiy
pushed a commit
to miretskiy/cockroach
that referenced
this pull request
Jul 19, 2022
Fixes cockroachdb#84121 cockroachdb#84007 introduced a change to add a timeout to test feed library to prevent flaky tests from hanging for a long time. This timeout lead to `TestChangefeedBackfillCheckpoint` test to become flaky. The main contributor of the slowness of that test was the fact that the test processes 1000 messages (twice), and the fact that a `webhook` sink and it's mock sink implementation are very slow (50+ms per message). The webhook sink, and mock webhook sink performance will be addressed separately (cockroachdb#84676) For now, marginally improve mock webhook sink performance by detecting when messages become available directly, instead of relying on resolved timestamps. Also, significantly increase the internal test timeout when reading many messages in a unit test. While troubleshooting this issue, observed large number of error messages `http: TLS handshake error from 127.0.0.1:34276: EOF`. The problem is that the webhook sink specified an arbitrary, and very small default timeout of 3 seconds. The default in Go library is 0 -- no timeout; and we should have this default as well. Fixes 75745 Release Notes: None
craig bot
pushed a commit
that referenced
this pull request
Jul 20, 2022
84572: obsservice: update README r=andreimatei a=dhartunian update README to reference the `./dev` command which includes the UI build. Release note: None 84678: changefeedccl: De-flake TestChangefeedBackfillCheckpoint test. r=miretskiy a=miretskiy Fixes #84121 #84007 introduced a change to add a timeout to test feed library to prevent flaky tests from hanging for a long time. This timeout lead to `TestChangefeedBackfillCheckpoint` test to become flaky. The main contributor of the slowness of that test was the fact that the test processes 1000 messages (twice), and the fact that a `webhook` sink and it's mock sink implementation are very slow (50+ms per message). The webhook sink, and mock webhook sink performance will be addressed separately (#84676) For now, marginally improve mock webhook sink performance by detecting when messages become available directly, instead of relying on resolved timestamps. Also, significantly increase the internal test timeout when reading many messages in a unit test. While troubleshooting this issue, observed large number of error messages `http: TLS handshake error from 127.0.0.1:34276: EOF`. The problem is that the webhook sink specified an arbitrary, and very small default timeout of 3 seconds. The default in Go library is 0 -- no timeout; and we should have this default as well. Fixes #75745 Release Notes: None 84682: opt: fix crdb_internal.decode_plan_gist to work with unknown index r=rytaft a=rytaft Release note (bug fix): `crdb_internal.decode_plan_gist` will no longer produce an internal error when it is used to decode a plan gist for which no schema information is available. Co-authored-by: David Hartunian <davidh@cockroachlabs.com> Co-authored-by: Yevgeniy Miretskiy <yevgeniy@cockroachlabs.com> Co-authored-by: Rebecca Taft <becca@cockroachlabs.com>
30 tasks
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.
Add timeout to testfeed sink implementations to timeout
if no messages are received for too long.
Informs #83946
Release Notes: None