Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sql: TestPerfLogging failed #74811

Closed
cockroach-teamcity opened this issue Jan 13, 2022 · 1 comment · Fixed by #75119
Closed

sql: TestPerfLogging failed #74811

cockroach-teamcity opened this issue Jan 13, 2022 · 1 comment · Fixed by #75119
Assignees
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-sql-queries SQL Queries Team

Comments

@cockroach-teamcity
Copy link
Member

sql.TestPerfLogging failed with artifacts on release-21.2 @ 4df1305911133426c8c5bb2983048c4486a52cfa:

    event_log_test.go:703: INSERT INTO t(i) VALUES (7), (8), (9)
    event_log_test.go:732: {INFO 1642099809455257000 365944 util/log/event_log.go 32 {"Timestamp":1642099809455218086,"EventType":"txn_rows_written_limit","Statement":"INSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹7›), (‹8›), (‹9›)","Tag":"INSERT","User":"root","TxnID":"d28039f9-ffa1-4f8b-bb39-483e84b85260","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 32 true SQL_PERF 309 0 0}
    event_log_test.go:696: INSERT INTO t(i) VALUES (-1), (-2), (-3)
    event_log_test.go:703: UPDATE t SET i = i - 10 WHERE i < 0
    event_log_test.go:732: {INFO 1642099809548900000 365944 util/log/event_log.go 32 {"Timestamp":1642099809548863230,"EventType":"txn_rows_written_limit","Statement":"UPDATE ‹\"\"›.‹\"\"›.‹t› SET ‹i› = ‹i› - ‹10› WHERE ‹i› < ‹0›","Tag":"UPDATE","User":"root","TxnID":"e468daf1-274f-4cff-b6b1-d610c8f70cc6","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 34 true SQL_PERF 313 0 0}
    event_log_test.go:696: BEGIN
    event_log_test.go:703: INSERT INTO t(i) VALUES (10); INSERT INTO t(i) VALUES (11), (12);
    event_log_test.go:732: {INFO 1642099809622227000 365944 util/log/event_log.go 32 {"Timestamp":1642099809622182681,"EventType":"txn_rows_written_limit","Statement":"INSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹11›), (‹12›)","Tag":"INSERT","User":"root","TxnID":"7aa1cdcc-bbe5-4c0b-8682-cd14d9db05a6","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 36 true SQL_PERF 300 0 0}
    event_log_test.go:741: COMMIT
    event_log_test.go:696: SET transaction_rows_written_log = 1
    event_log_test.go:703: INSERT INTO t(i) VALUES (13), (14)
    event_log_test.go:732: {INFO 1642099809691211000 365944 util/log/event_log.go 32 {"Timestamp":1642099809691153059,"EventType":"txn_rows_written_limit","Statement":"INSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹13›), (‹14›)","Tag":"INSERT","User":"root","TxnID":"4a3ece9e-31b9-4bb7-b5d1-b47a0941869e","SessionID":"16c9e911d242b5130000000000000001","NumRows":2} n1,client=‹127.0.0.1:44278›,hostssl,user=root 37 true SQL_PERF 300 0 0}
    event_log_test.go:741: RESET transaction_rows_written_log
    event_log_test.go:703: INSERT INTO t(i) VALUES (15), (16), (17), (18)
    event_log_test.go:732: {INFO 1642099809761565000 365944 util/log/event_log.go 32 {"Timestamp":1642099809761523965,"EventType":"txn_rows_written_limit","Statement":"INSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹15›), (‹16›), (‹17›), (‹18›)","Tag":"INSERT","User":"root","TxnID":"f84cd536-3e8f-4e6b-ac45-2ca339dfbd87","SessionID":"16c9e911d242b5130000000000000001","NumRows":4} n1,client=‹127.0.0.1:44278›,hostssl,user=root 38 true SQL_PERF 324 0 0}
    event_log_test.go:696: INSERT INTO t(i) VALUES (-1)
    event_log_test.go:703: DELETE FROM t WHERE i < 0
    event_log_test.go:732: {INFO 1642099809841271000 365944 util/log/event_log.go 32 {"Timestamp":1642099809841231445,"EventType":"txn_rows_written_limit","Statement":"DELETE FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› < ‹0›","Tag":"DELETE","User":"root","TxnID":"3842f401-eb45-4f7d-8697-b7022a1f1352","SessionID":"16c9e911d242b5130000000000000001","NumRows":4} n1,client=‹127.0.0.1:44278›,hostssl,user=root 39 true SQL_PERF 285 0 0}
    event_log_test.go:703: UPSERT INTO t(i) VALUES (-2), (-3), (-4), (-5)
    event_log_test.go:732: {INFO 1642099809907683000 365944 util/log/event_log.go 32 {"Timestamp":1642099809907642325,"EventType":"txn_rows_written_limit","Statement":"UPSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹-2›), (‹-3›), (‹-4›), (‹-5›)","Tag":"INSERT","User":"root","TxnID":"0f11de00-6273-4668-a1f2-ac96bb52331e","SessionID":"16c9e911d242b5130000000000000001","NumRows":4} n1,client=‹127.0.0.1:44278›,hostssl,user=root 40 true SQL_PERF 324 0 0}
    event_log_test.go:696: BEGIN
    event_log_test.go:703: INSERT INTO t(i) VALUES (15), (16), (17); INSERT INTO t(i) VALUES (18);
    event_log_test.go:732: {INFO 1642099809975272000 365944 util/log/event_log.go 32 {"Timestamp":1642099809975232084,"EventType":"txn_rows_written_limit","Statement":"INSERT INTO ‹\"\"›.‹\"\"›.‹t›(‹i›) VALUES (‹15›), (‹16›), (‹17›)","Tag":"INSERT","User":"root","TxnID":"e0fa90a8-7853-4ba3-922e-1d0019c9ea6c","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 41 true SQL_PERF 312 0 0}
    event_log_test.go:741: ROLLBACK
    event_log_test.go:696: SET transaction_rows_written_err = 1
    event_log_test.go:703: INSERT INTO t(i) VALUES (15), (16)
    event_log_test.go:741: RESET transaction_rows_written_err
    event_log_test.go:703: SELECT * FROM t WHERE i = 6
    event_log_test.go:703: SELECT * FROM t WHERE i IN (6, 7, 8)
    event_log_test.go:732: {INFO 1642099810172341000 365944 util/log/event_log.go 32 {"Timestamp":1642099810172302286,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› IN (‹6›, ‹7›, ‹8›)","Tag":"SELECT","User":"root","TxnID":"d2989346-ddcc-425d-8912-ff65eda3f3d1","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 42 true SQL_PERF 305 0 0}
    event_log_test.go:696: BEGIN
    event_log_test.go:703: SELECT * FROM t WHERE i = 6; SELECT * FROM t WHERE i = 7; SELECT * FROM t WHERE i = 8;
    event_log_test.go:732: {INFO 1642099810236223000 365944 util/log/event_log.go 32 {"Timestamp":1642099810236185309,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› = ‹8›","Tag":"SELECT","User":"root","TxnID":"b34da160-b405-4657-bfbf-9251e22f745b","SessionID":"16c9e911d242b5130000000000000001","NumRows":3} n1,client=‹127.0.0.1:44278›,hostssl,user=root 43 true SQL_PERF 284 0 0}
    event_log_test.go:741: COMMIT
    event_log_test.go:696: SET transaction_rows_read_log = 1
    event_log_test.go:703: SELECT * FROM t WHERE i IN (6, 7)
    event_log_test.go:732: {INFO 1642099810297138000 365944 util/log/event_log.go 32 {"Timestamp":1642099810297099116,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› IN (‹6›, ‹7›)","Tag":"SELECT","User":"root","TxnID":"10e4fcf9-a67f-4198-befe-110352b323f7","SessionID":"16c9e911d242b5130000000000000001","NumRows":2} n1,client=‹127.0.0.1:44278›,hostssl,user=root 44 true SQL_PERF 296 0 0}
    event_log_test.go:741: RESET transaction_rows_read_log
    event_log_test.go:703: SELECT * FROM t WHERE i IN (6, 7, 8, 9)
    event_log_test.go:732: {INFO 1642099810360163000 365944 util/log/event_log.go 32 {"Timestamp":1642099810360106693,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› IN (‹6›, ‹7›, ‹8›, ‹9›)","Tag":"SELECT","User":"root","TxnID":"4372b076-9e3d-48ab-9d28-1f34cbd715a8","SessionID":"16c9e911d242b5130000000000000001","NumRows":4} n1,client=‹127.0.0.1:44278›,hostssl,user=root 45 true SQL_PERF 314 0 0}
    event_log_test.go:696: BEGIN
    event_log_test.go:703: SELECT * FROM t WHERE i IN (6, 7); SELECT * FROM t WHERE i IN (8, 9)
    event_log_test.go:732: {INFO 1642099810424957000 365944 util/log/event_log.go 32 {"Timestamp":1642099810424921561,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM ‹\"\"›.‹\"\"›.‹t› WHERE ‹i› IN (‹8›, ‹9›)","Tag":"SELECT","User":"root","TxnID":"83003e46-efbf-47b6-aabd-614b68305a45","SessionID":"16c9e911d242b5130000000000000001","NumRows":4} n1,client=‹127.0.0.1:44278›,hostssl,user=root 46 true SQL_PERF 296 0 0}
    event_log_test.go:741: ROLLBACK
    event_log_test.go:696: SET transaction_rows_read_err = 1
    event_log_test.go:703: SELECT * FROM t WHERE i = 6 OR i = 7
    event_log_test.go:725: 2 log messages for query ``SELECT * FROM t WHERE i = 6 OR i = 7`` matching ````, expected zero messages
    panic.go:632: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestPerfLogging080179049
--- FAIL: TestPerfLogging (11.22s)
Reproduce

To reproduce, try:

make stressrace TESTS=TestPerfLogging PKG=./pkg/sql TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @cockroachdb/sql-queries michae2

This test on roachdash | Improve this report!

@cockroach-teamcity cockroach-teamcity added branch-release-21.2 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Jan 13, 2022
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Jan 13, 2022
@rytaft
Copy link
Collaborator

rytaft commented Jan 18, 2022

Looking at the slow query log, I don't see any that match SELECT * FROM t WHERE i = 6 OR i = 7. It's strange that the regex doesn't show up in the error message above, but the regex used in this test case is "EventType":"txn_rows_read_limit".

The last two lines in the slow query log do include this regex, though, so it's possible that the timestamps got messed up and the test looked at these last two lines (the test only starts scanning the log by timestamp, it doesn't validate that the query matches). Here are the last two lines:

I220113 18:50:10.360163 365944 10@util/log/event_log.go:32  [n1,client=127.0.0.1:44278,hostssl,user=root] 45 ={"Timestamp":1642099810360106693,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM \"\".\"\".t WHERE i IN (6, 7, 8, 9)","Tag":"SELECT","User":"root","TxnID":"4372b076-9e3d-48ab-9d28-1f34cbd715a8","SessionID":"16c9e911d242b5130000000000000001","NumRows":4}
I220113 18:50:10.424957 365944 10@util/log/event_log.go:32  [n1,client=127.0.0.1:44278,hostssl,user=root] 46 ={"Timestamp":1642099810424921561,"EventType":"txn_rows_read_limit","Statement":"SELECT * FROM \"\".\"\".t WHERE i IN (8, 9)","Tag":"SELECT","User":"root","TxnID":"83003e46-efbf-47b6-aabd-614b68305a45","SessionID":"16c9e911d242b5130000000000000001","NumRows":4}

To avoid future flakes, maybe we should update the test to also check that the query matches.

rytaft added a commit to rytaft/cockroach that referenced this issue Jan 19, 2022
This commit deflakes TestPerfLogging by ensuring that test cases
that should not produce log entries do not match with unrelated log
entries and thus cause the test to fail. This is ensured by making
the regex more precise for the specific test case.

Fixes cockroachdb#74811

Release note: None
craig bot pushed a commit that referenced this issue Jan 19, 2022
74863: import: check readability earlier r=benbardin a=benbardin

Release note (sql change): Import now checks readability earlier for multiple files, to fail sooner if e.g. permissions are invalid.

74914: opt,tree: fix bugs with Next(), Prev(), and histogram calculation for DTimeTZ r=rytaft a=rytaft

**sql/sem/tree: fix Next() and Prev() for DTimeTZ**

Prior to this commit, the `DTimeTZ` functions `Next()` and `Prev()`
could skip over valid values according to the ordering of `DTimeTZ`
values in an index (which matches the ordering defined by the
`TimeTZ` functions `After()` and `Before()`).

This commit fixes these functions so that `Next()` now returns the smallest
valid `DTimeTZ` that is greater than the receiver, and `Prev()` returns
the largest valid `DTimeTZ` that is less than the receiver. This is
an important invariant that the optimizer relies on when building index
constraints.

Fixes #74912

Release note (bug fix): Fixed a bug that could occur when a `TIMETZ`
column was indexed, and a query predicate constrained that column using
a `<` or `>` operator with a `timetz` constant. If the column contained values
with time zones that did not match the time zone of the `timetz` constant,
it was possible that not all matching values could be returned by the
query. Specifically, the results may not have included values within one
microsecond of the predicate's absolute time. This bug was introduced
when the timetz datatype was first added in 20.1. It exists on all
versions of 20.1, 20.2, 21.1, and 21.2 prior to this patch.

**opt: fix bug in histogram calculation for TimeTZ**

This commit fixes a bug in the histogram estimation code for `TimeTZ`
that made the faulty assumption that `TimeTZ` values are ordered by
`TimeOfDay`. This is incorrect since it does not take the `OffsetSecs`
into account. As a result, it was possible to estimate that the size
of a histogram bucket was negative, which caused problems in the
statistics estimation code. This commit fixes the problem by taking
into account both `TimeOfDay` and `OffsetSecs` when estimating the size of
a bucket in a `TimeTZ` histogram.

Fixes #74667

Release note (bug fix): Fixed an internal error, "estimated row count must
be non-zero", that could occur during planning for queries over a table
with a `TimeTZ` column. This error was due to a faulty assumption in the
statistics estimation code about ordering of `TimeTZ` values, which has now
been fixed. The error could occur when `TimeTZ` values used in the query had
a different time zone offset than the `TimeTZ` values stored in the table.

75112: sql: fix casts between REG* types r=mgartner a=mgartner

The newly introduced `castMap` does not contain entries for casts
between all combinations of REG* types, which is consistent with
Postgres, but inconsistent with behavior in versions up to 21.2 where
these casts are allowed.

The `castMap` changes result in more than just backward incompatibility.
We allow branches of CASE statements to be equivalent types (i.e., types
in the same family), like `REGCLASS` and `REGTYPE`, and we automatically
add casts to a query plan to support this. However, because these casts
don't exist in the `castMap`, internal errors are raised when we try to
fetch the volatility of the cast while building logical properties.

According to Postgres's type conversion rules for CASE, we should only
allow branches to be different types if they can be implicitly cast to
the first non-NULL branch. Implicit casts between REG* types are not
allowed, so CASE expressions with branches of different REG* types
should result in a user error like `CASE/WHEN could not convert type
regclass to regtype`. However, this is a much larger project and the
change will not be fully backward compatible. This work is tracked by
issue #75103.

For now, this commit adds casts between REG* types to the `castMap` to
maintain backward compatibility and prevent an internal error.

There is no release note because this bug does not exist in any
releases.

Fixes #74784

Release note: None

75119: sql: deflake TestPerfLogging r=rytaft a=rytaft

This commit deflakes `TestPerfLogging` by ensuring that test cases
that should not produce log entries do not match with unrelated log
entries and thus cause the test to fail. This is ensured by making
the regex more precise for the specific test case.

Fixes #74811

Release note: None

75146: backupccl: "skip" TestChangefeedRestartDuringBackfill.. r=irfansharif a=irfansharif

under span configs. This test flakes pretty reliably after span configs
were enabled (#73876). Investigating this further is being tracked in
\#75080; lets have this test use the old subsystem for now (only down in
KV; we've narrowed down the failure to having something to do with
concurrent range splits, within the tenant keyspace, while a changefeed
is declared).

Release note: None

Co-authored-by: Ben Bardin <[email protected]>
Co-authored-by: Rebecca Taft <[email protected]>
Co-authored-by: Marcus Gartner <[email protected]>
Co-authored-by: irfan sharif <[email protected]>
@craig craig bot closed this as completed in 311c2e0 Jan 19, 2022
rytaft added a commit to rytaft/cockroach that referenced this issue Jan 19, 2022
This commit deflakes TestPerfLogging by ensuring that test cases
that should not produce log entries do not match with unrelated log
entries and thus cause the test to fail. This is ensured by making
the regex more precise for the specific test case.

Fixes cockroachdb#74811

Release note: None
rytaft added a commit to rytaft/cockroach that referenced this issue Jan 19, 2022
This commit deflakes TestPerfLogging by ensuring that test cases
that should not produce log entries do not match with unrelated log
entries and thus cause the test to fail. This is ensured by making
the regex more precise for the specific test case.

Fixes cockroachdb#74811

Release note: None
gtr pushed a commit to gtr/cockroach that referenced this issue Jan 24, 2022
This commit deflakes TestPerfLogging by ensuring that test cases
that should not produce log entries do not match with unrelated log
entries and thus cause the test to fail. This is ensured by making
the regex more precise for the specific test case.

Fixes cockroachdb#74811

Release note: None
@mgartner mgartner moved this to Done in SQL Queries Jul 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-sql-queries SQL Queries Team
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

2 participants