tidb session: add system variable tidb_general_log_post_exec to log query after it is executed

What problem does this PR solve?

Issue Number: close #xxx

Problem Summary:

What changed and how does it work?

GENERAL_LOG is useful for debugging subtle issues. But txnStartTS is 0 if the query is not inside a transaction, which makes the log message less useful.

This PR adds a system variable tidb_defer_general_log. If it is set, the GENERAL_LOG message is deferred until the query is executed (when txnStartTS is set).

mysql> set global tidb_general_log = '1';
mysql> set global tidb_defer_general_log = '1';
mysql> insert into t values (1);
mysql> select v from t where v=1;
mysql> set global tidb_defer_general_log = '0';
mysql> select v from t where v=1;

[2024/10/19 09:11:27.216 -07:00] [INFO] [session.go:3933] [GENERAL_LOG] [conn=1103101958] [session_alias=] [[email protected]] [schemaVersion=50] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="SET @@GLOBAL.`tidb_defer_general_log`=_UTF8MB4'1'"]
[2024/10/19 09:12:27.498 -07:00] [INFO] [session.go:3933] [GENERAL_LOG] [conn=1103101958] [session_alias=] [[email protected]] [schemaVersion=51] [txnStartTS=453339866057146369] [forUpdateTS=453339866057146369] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="insert into t values (1)"]
[2024/10/19 09:12:40.645 -07:00] [INFO] [session.go:3933] [GENERAL_LOG] [conn=1103101958] [session_alias=] [[email protected]] [schemaVersion=51] [txnStartTS=453339869504339969] [forUpdateTS=453339869504339969] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="select v from t where v=1"]
[2024/10/19 09:14:01.048 -07:00] [INFO] [session.go:3933] [GENERAL_LOG] [conn=1103101958] [session_alias=] [[email protected]] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="SET @@GLOBAL.`tidb_defer_general_log`=_UTF8MB4'0'"]
[2024/10/19 09:14:12.135 -07:00] [INFO] [session.go:3933] [GENERAL_LOG] [conn=1103101958] [session_alias=] [[email protected]] [schemaVersion=51] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=test] [isPessimistic=false] [sessionTxnMode=PESSIMISTIC] [sql="select v from t where v=2"]

Check List

Tests

[x] Unit test
[ ] Integration test
[ ] Manual test (add detailed scripts or steps below)
[ ] No need to test
- [ ] I checked and no code files have been changed.

Side effects

[ ] Performance regression: Consumes more CPU
[ ] Performance regression: Consumes more Memory
[ ] Breaking backward compatibility

Documentation

[ ] Affects user behaviors
[ ] Contains syntax changes
[ ] Contains variable changes
[ ] Contains experimental features
[ ] Changes MySQL compatibility

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

Oct 20 '24 03:10 b6g

Welcome @b6g!

It looks like this is your first PR to pingcap/tidb 🎉.

I'm the bot to help you request reviewers, add labels and more, See available commands.

We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to pingcap/tidb. :smiley:

Oct 20 '24 03:10 ti-chi-bot[bot]

Hi @b6g. Thanks for your PR.

I'm waiting for a pingcap member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Oct 20 '24 03:10 ti-chi-bot[bot]

Hi @b6g. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Oct 20 '24 03:10 tiprow[bot]

/ok-to-test

Oct 20 '24 05:10 lance6716

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 75.9611%. Comparing base (cec48bb) to head (00de036). Report is 59 commits behind head on master.

Additional details and impacted files

@@               Coverage Diff                @@
##             master     #56731        +/-   ##
================================================
+ Coverage   72.9242%   75.9611%   +3.0369%     
================================================
  Files          1659       1717        +58     
  Lines        458547     483235     +24688     
================================================
+ Hits         334392     367071     +32679     
+ Misses       103613      94521      -9092     
- Partials      20542      21643      +1101

Flag	Coverage Δ
integration	`50.4533% <100.0000%> (?)`
unit	`73.7550% <100.0000%> (+1.4969%)`	:arrow_up:

Flags with carried forward coverage won't be shown. Click here to find out more.

Components	Coverage Δ
dumpling	`52.7673% <ø> (ø)`
parser	`∅ <ø> (∅)`
br	`60.6843% <ø> (+15.6299%)`	:arrow_up:

Oct 20 '24 05:10 codecov[bot]

@songrijie PTAL

Oct 21 '24 06:10 lance6716

friendly ping

Nov 02 '24 01:11 b6g

friendly ping

I'll notify our PM to review the new configuration in weekdays. For now please sign CLA first.

Nov 02 '24 04:11 lance6716

I think I have already signed the CLA,

Nov 02 '24 23:11 b6g

All committers have signed the CLA.

Nov 04 '24 02:11 sre-bot

@b6g The commit belongs to zncoder , please check that user also signs CLA.

Nov 04 '24 03:11 lance6716

From product perspective, if we can make it right, it's not necessary to include variable for it. This can works as default behavior

Nov 04 '24 03:11 songrijie

@b6g The commit belongs to zncoder , please check that user also signs CLA.

My bad. I will fix the commit author.

Nov 06 '24 08:11 b6g

From product perspective, if we can make it right, it's not necessary to include variable for it. This can works as default behavior

Agree. I will remove the system variable.

Nov 06 '24 08:11 b6g

removed the system variable and added a test of the general log message.

Nov 07 '24 21:11 b6g

Please run `make bazel_prepare` to update `.bazel` files, or just apply the following git diff (run `git apply -` and paste following contents with ctrl-D as ending):
diff --git a/pkg/session/test/variable/BUILD.bazel b/pkg/session/test/variable/BUILD.bazel
index 3f0a3dabf6..ccef03c3b2 100644
--- a/pkg/session/test/variable/BUILD.bazel
+++ b/pkg/session/test/variable/BUILD.bazel
@@ -8,7 +8,7 @@ go_test(
         "variable_test.go",
     ],
     flaky = True,
-    shard_count = 9,
+    shard_count = 11,
     deps = [
         "//pkg/config",
         "//pkg/kv",
@@ -19,10 +19,13 @@ go_test(
         "//pkg/testkit/testmain",
         "//pkg/testkit/testsetup",
         "//pkg/util/dbterror/exeerrors",
+        "//pkg/util/logutil",
         "//pkg/util/memory",
         "@com_github_pingcap_failpoint//:failpoint",
         "@com_github_stretchr_testify//require",
         "@com_github_tikv_client_go_v2//tikv",
         "@org_uber_go_goleak//:goleak",
+        "@org_uber_go_zap//:zap",
+        "@org_uber_go_zap//zapcore",
     ],
 )

Nov 08 '24 01:11 lance6716

/test tidb_parser_test

Nov 08 '24 05:11 b6g

@b6g: The specified target(s) for /test were not found. The following commands are available to trigger required jobs:

/test build
/test check-dev
/test check-dev2
/test mysql-test
/test pull-br-integration-test
/test pull-integration-ddl-test
/test pull-lightning-integration-test
/test pull-mysql-client-test
/test pull-unit-test-ddlv1
/test unit-test

The following commands are available to trigger optional jobs:

/test pingcap/tidb/canary_ghpr_unit_test
/test pull-common-test
/test pull-e2e-test
/test pull-integration-common-test
/test pull-integration-copr-test
/test pull-integration-e2e-test
/test pull-integration-jdbc-test
/test pull-integration-mysql-test
/test pull-integration-nodejs-test
/test pull-sqllogic-test
/test pull-tiflash-test

Use /test all to run the following jobs that were automatically triggered:

pingcap/tidb/ghpr_build
pingcap/tidb/ghpr_check
pingcap/tidb/ghpr_check2
pingcap/tidb/ghpr_mysql_test
pingcap/tidb/ghpr_unit_test
pingcap/tidb/pull_integration_ddl_test
pingcap/tidb/pull_mysql_client_test

In response to this:

/test tidb_parser_test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Nov 08 '24 05:11 ti-chi-bot[bot]

ping @lcwangchao

Nov 11 '24 04:11 lance6716

ping. Can I get another approval to merge the PR? Thanks,

Nov 14 '24 21:11 b6g

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: lance6716, lcwangchao

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [lance6716,lcwangchao]

Approvers can indicate their approval by writing /approve in a comment Approvers can cancel approval by writing /approve cancel in a comment

Nov 15 '24 02:11 ti-chi-bot[bot]

[LGTM Timeline notifier]

Timeline:

2024-11-09 03:21:31.83975878 +0000 UTC m=+67254.030627778: :ballot_box_with_check: agreed by lance6716.
2024-11-15 02:45:48.643027361 +0000 UTC m=+583510.833896358: :ballot_box_with_check: agreed by lcwangchao.

Nov 15 '24 02:11 ti-chi-bot[bot]

/test unit-test

Nov 15 '24 07:11 b6g

@b6g: The specified target(s) for /test were not found. The following commands are available to trigger required jobs:

/test fast_test_tiprow
/test fast_test_tiprow_ddlargsv1
/test tidb_parser_test

Use /test all to run the following jobs that were automatically triggered:

fast_test_tiprow
tidb_parser_test

In response to this:

/test unit-test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Nov 15 '24 07:11 tiprow[bot]

/retest

Nov 15 '24 08:11 b6g

/retest

Nov 15 '24 10:11 lance6716

/test mysql-test

Nov 15 '24 16:11 b6g

@b6g: The specified target(s) for /test were not found. The following commands are available to trigger required jobs:

/test fast_test_tiprow
/test fast_test_tiprow_ddlargsv1
/test tidb_parser_test

Use /test all to run the following jobs that were automatically triggered:

fast_test_tiprow
tidb_parser_test

In response to this:

/test mysql-test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Nov 15 '24 16:11 tiprow[bot]