session: add session var to update global logger max days #27595

db-will · 2021-08-26T02:28:10Z

What problem does this PR solve?

Issue Number: close #27520

Problem Summary: Currently, it is required to restart instance to change max-days of log files(log.file.max-days in config file). We want to enable user to change such config dynamically.

What is changed and how it works?

What's Changed:

added a session scope variable(tidb_log_file_max_days) to adjust max days of logger

How it Works:

when user want to dynamically change max days of general log, they can change the session variable
internally, it will create a new logger instance with new max days config to replace the global logger instance
the session value is stored in memory, and it may inconsistent with the actual log file config. the main purpose is to provide a way to dynamically adjust the max days, but not to provide a consistent view of log file max days config

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
No code

We setup and run an tidb cluster with a given max-days=30 and max-size=30 in config

mysql> select @@tidb_log_file_max_days;
+--------------------------+
| @@tidb_log_file_max_days |
+--------------------------+
| 30                       |
+--------------------------+
1 row in set (0.00 sec)

Enable general log

mysql> set tidb_general_log = 1;
Query OK, 0 rows affected (0.01 sec)

Run sysbench prepare to init table and add data, so that we can generate some general logs

sysbench oltp_read_write --table-size=1000000 --mysql-db=sysbench --mysql-user=root --mysql-host=127.0.0.1 --mysql-port=4000 prepare

❯ ls -larth
total 392488
drwxr-xr-x  11 will  staff   352B  2 Sep 22:08 ..
-rw-r--r--   1 will  staff    30M  2 Sep 22:10 tidb-2021-09-02T22-10-56.957.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-00.343.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-03.773.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-07.151.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-10.400.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-13.926.log
drwxr-xr-x  10 will  staff   320B  2 Sep 22:11 .
-rw-r--r--   1 will  staff    11M  2 Sep 22:11 tidb.log
-rw-r--r--   1 will  staff   2.4K  2 Sep 22:11 tidb-slow.log

We can fake some last 5 days log files by creating similar log files with different timestamp and clean up the generate logs:

❯ cp tidb-2021-09-02T22-10-56.957.log tidb-2021-08-25T22-10-56.957.log
❯ cp tidb-2021-09-02T22-11-00.343.log tidb-2021-08-26T22-11-00.343.log
❯ cp tidb-2021-09-02T22-11-03.773.log tidb-2021-08-27T22-11-03.773.log
❯ cp tidb-2021-09-02T22-11-07.151.log tidb-2021-08-28T22-11-07.151.log
❯ cp tidb-2021-09-02T22-11-10.400.log tidb-2021-08-29T22-11-10.400.log
❯ ls -larth
total 695648
drwxr-xr-x  11 will  staff   352B  2 Sep 22:08 ..
-rw-r--r--   1 will  staff    30M  2 Sep 22:10 tidb-2021-09-02T22-10-56.957.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-00.343.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-03.773.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-07.151.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-10.400.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:11 tidb-2021-09-02T22-11-13.926.log
-rw-r--r--   1 will  staff   2.4K  2 Sep 22:11 tidb-slow.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:16 tidb-2021-08-25T22-10-56.957.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:17 tidb-2021-08-26T22-11-00.343.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:17 tidb-2021-08-27T22-11-03.773.log
-rw-r--r--   1 will  staff    30M  2 Sep 22:18 tidb-2021-08-28T22-11-07.151.log
-rw-r--r--   1 will  staff    11M  2 Sep 22:18 tidb.log
drwxr-xr-x  15 will  staff   480B  2 Sep 22:18 .
-rw-r--r--   1 will  staff    30M  2 Sep 22:18 tidb-2021-08-29T22-11-10.400.log

Let set max days to some values and run sysbench to generate new logs, and check if logs are purged as expected(this is due to purge only happen when new logs are generated):

mysql> set tidb_log_file_max_days = 5;
Query OK, 0 rows affected (0.01 sec)

❯ sysbench oltp_read_write --mysql-db=sysbench --mysql-user=root --mysql-port=4000  --max-time=10 --mysql-host=127.0.0.1 run

❯ ls
tidb-2021-08-29T22-11-10.400.log tidb-2021-09-02T22-11-10.400.log
tidb-2021-09-02T22-10-56.957.log tidb-2021-09-02T22-11-13.926.log
tidb-2021-09-02T22-11-00.343.log tidb-slow.log
tidb-2021-09-02T22-11-03.773.log tidb.log
tidb-2021-09-02T22-11-07.151.log

change max days to larger value, and we expect it won't wrongly purge files:

mysql> set tidb_log_file_max_days = 10;
Query OK, 0 rows affected (0.00 sec)

❯ sysbench oltp_read_write --mysql-db=sysbench --mysql-user=root --mysql-port=4000  --max-time=10 --mysql-host=127.0.0.1 run

❯ ls
tidb-2021-08-29T22-11-10.400.log tidb-2021-09-02T22-11-10.400.log
tidb-2021-09-02T22-10-56.957.log tidb-2021-09-02T22-11-13.926.log
tidb-2021-09-02T22-11-00.343.log tidb-slow.log
tidb-2021-09-02T22-11-03.773.log tidb.log
tidb-2021-09-02T22-11-07.151.log

Set to max days = 1

mysql> set tidb_log_file_max_days = 1;
Query OK, 0 rows affected (0.00 sec)

❯ sysbench oltp_read_write --mysql-db=sysbench --mysql-user=root --mysql-port=4000  --max-time=10 --mysql-host=127.0.0.1 run

❯ ls
tidb-2021-09-02T22-10-56.957.log tidb-2021-09-02T22-11-10.400.log
tidb-2021-09-02T22-11-00.343.log tidb-2021-09-02T22-11-13.926.log
tidb-2021-09-02T22-11-03.773.log tidb-slow.log
tidb-2021-09-02T22-11-07.151.log tidb.log

Side effects

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

Documentation

Release note

Add session variable tidb_log_file_max_days to dynamically adjust general log and slow log max days

ti-chi-bot · 2021-08-26T02:28:11Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

morgo
xhebox

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

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

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

CLAassistant · 2021-08-26T02:28:15Z

All committers have signed the CLA.

sre-bot · 2021-08-26T02:28:49Z

Please follow PR Title Format:

pkg [, pkg2, pkg3]: what is changed

Or if the count of mainly changed packages are more than 3, use

*: what is changed

After you have format title, you can leave a comment /run-check_title to recheck it

db-will · 2021-08-26T23:25:29Z

/assign @morgo

db-will · 2021-08-26T23:25:53Z

/run-check_title

morgo · 2021-08-26T23:38:11Z

sessionctx/variable/sysvar.go

+
+		return nil
+	}, GetSession: func(s *SessionVars) (string, error) {
+		return strconv.FormatInt(int64(atomic.LoadInt32(&GeneralLogMaxAge)), 10), nil


I think this will be out of sync until the first ReplaceLogger event happens right? So if they never replace the logger, it will not be safe to read TiDBGeneralLogMaxAge to see what the value defined in config is.

A workaround is, you can set the sysvar in tidb-server/main.go when the server starts up. We have some examples for global sysvars, but because you have a getter func (and it's session scope) you can just atomic.StoreInt32(&GeneralLogMaxAge, maxAge)?

i found setGlobalVars in tidb-server/main.go initialize variables during startup, from what i can tell, we can actually change this to be global variable here and i think it make more sense.

Most of these are setting ScopeNone (read-only) sysvars. If you make this ScopeGlobal it will be cluster wide.

The behavior of ScopeGlobal + config file is weird, because any new joining server would overwrite the other server's log configuration. Usually with logs (or things refering to the local filesystem) we have kept them instance scoped. This also supports the use case that a user might want to have one server log everything.

I hope in future we clean this up though, so there is a native concept of instance scope.

morgo · 2021-08-29T17:50:01Z

@db-will Please run go fmt sessionctx/variable/tidb_vars.go. Otherwise LGTM.

morgo

LGTM

db-will · 2021-08-30T01:04:46Z

/assign @SabaPing

ti-chi-bot · 2021-08-30T01:04:48Z

@db-will: GitHub didn't allow me to assign the following users: SabaPing.

Note that only pingcap members, repo collaborators and people who have commented on this issue/PR can be assigned. Additionally, issues/PRs can only have 10 assignees at the same time.
For more information please see the contributor guide

In response to this:

/assign @SabaPing

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.

bb7133 · 2021-08-30T02:12:19Z

This variable is named 'tidb_general_log_max_days' but it is not limited to the 'general log' actually. Is it a good idea to name it 'tidb_log_file_max_days'?

SabaPing

There are max-size and max-backups variables in log config. Should we add them to session var to make the behavior consistent?

SabaPing · 2021-08-30T03:35:10Z

sessionctx/variable/tidb_vars.go

@@ -121,6 +121,9 @@ const (
 	// tidb_general_log is used to log every query in the server in info level.
 	TiDBGeneralLog = "tidb_general_log"

+	// tidb_general_log is used to log every query in the server in info level.
+	TiDBGeneralLogMaxDays = "tidb_general_log_max_days"


As @bb7133 said, should we rename it to tidb_log_file_max_days?

SabaPing · 2021-08-30T03:40:00Z

util/logutil/log.go

@@ -143,6 +144,24 @@ func initGRPCLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) {
 	return l, prop, nil
 }

+// ReplaceLogger replace global logger instance with given log config.
+func ReplaceLogger(cfg *LogConfig) error {


Do we need to replace slow query logger to enable slow log runtime modification either?

db-will · 2021-08-30T17:58:48Z

@bb7133 Previously, i found newSlowQueryLogger() doesn't change max days of slow logger, but @SabaPing is creating a PR to fix that: #27625. Combined with these two, we can make it as tidb_log_file_max_days . good suggestions here!

db-will · 2021-09-03T03:00:54Z

/assign @bb7133

db-will · 2021-09-15T02:04:00Z

/assign @yudongusa
/assign @XuHuaiyu
/assign @cfzjywxk

Looking for one another approval to meet the merge criterial

dveeden · 2021-10-14T05:51:43Z

Unfortunately libfaketime doesn't work with Go, that would have made testing easier and/or more realistic. Interesting enough the golang playground etc are using a fake time (example). However I think the testing here is sufficient for this PR.

In MySQL expire_logs_days was replaced by binlog_expire_logs_seconds. While this variable doesn't server the same purpose it might be good to consider settings in seconds or hours instead of days. Another option would be to allow decimal values like 0.5 days.

Another option is to leave some of this work to the OS, like logrotate and journald. Sending this to a socket is another option. Some of these might make it easier to filter, compress, forward and de-duplicate log entries, especially when using JSON. However I don't think this is in scope for this PR.

xiongjiwei · 2021-10-26T06:12:39Z

please format the code and then the pr can be merge

db-will · 2021-10-27T01:30:54Z

@xiongjiwei May i merge this PR?

xiongjiwei · 2021-10-27T02:04:18Z

/merge

ti-chi-bot · 2021-10-27T02:04:22Z

This pull request has been accepted and is ready to merge.

Commit hash: 125887b

ti-chi-bot · 2021-10-27T02:04:31Z

@db-will: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.

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 ti-community-infra/tichi repository.

Add session var to update global logger max age

d756cef

ti-chi-bot added the release-note Denotes a PR that will be considered when it comes time to generate release notes. label Aug 26, 2021

ti-chi-bot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Aug 26, 2021

db-will changed the title ~~Add session var to update global logger max age~~ session: add session var to update global logger max age Aug 26, 2021

Fix fmt error

6324bf3

ti-chi-bot assigned morgo Aug 26, 2021

morgo self-requested a review August 26, 2021 23:29

morgo reviewed Aug 26, 2021

View reviewed changes

morgo removed their assignment Aug 27, 2021

db-will added 2 commits August 29, 2021 13:06

Init max days from config

3736b6a

Refactor max age to max days

185101b

db-will changed the title ~~session: add session var to update global logger max age~~ session: add session var to update global logger max days Aug 29, 2021

Merge branch 'master' into general-log-max-age

b08e472

Fix fmr error

be4b3d2

morgo self-requested a review August 29, 2021 19:14

morgo approved these changes Aug 29, 2021

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Aug 29, 2021

morgo requested a review from a team August 29, 2021 19:15

SabaPing reviewed Aug 30, 2021

View reviewed changes

Refactor to tidb_log_file_max_days

8a685d7

morgo requested a review from a team September 3, 2021 02:54

ti-srebot assigned bb7133 Sep 3, 2021

morgo requested a review from bb7133 September 3, 2021 03:04

ti-chi-bot assigned cfzjywxk, XuHuaiyu and yudongusa Sep 15, 2021

morgo requested a review from dveeden October 13, 2021 18:00

ti-chi-bot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Oct 22, 2021

xhebox approved these changes Oct 25, 2021

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Oct 25, 2021

Merge branch 'master' into general-log-max-age

52a25f4

db-will requested a review from a team as a code owner October 26, 2021 02:39

ti-chi-bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Oct 26, 2021

Merge branch 'master' into general-log-max-age

7c6982f

db-will and others added 2 commits October 26, 2021 13:21

Format tidb_vars.go

7507555

Merge branch 'master' into general-log-max-age

125887b

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Oct 27, 2021

Merge branch 'master' into general-log-max-age

0b0f290

ti-chi-bot merged commit c9f33cb into pingcap:master Oct 27, 2021

db-will deleted the general-log-max-age branch November 1, 2021 19:59

xhebox mentioned this pull request Nov 10, 2021

system variables: add tidb_log_file_max_days pingcap/docs#6773

Merged

14 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

session: add session var to update global logger max days #27595

session: add session var to update global logger max days #27595

db-will commented Aug 26, 2021 •

edited

Loading

ti-chi-bot commented Aug 26, 2021 •

edited

Loading

CLAassistant commented Aug 26, 2021 •

edited

Loading

sre-bot commented Aug 26, 2021

db-will commented Aug 26, 2021

db-will commented Aug 26, 2021

morgo Aug 26, 2021

db-will Aug 27, 2021

morgo Aug 27, 2021

morgo commented Aug 29, 2021

morgo left a comment

db-will commented Aug 30, 2021

ti-chi-bot commented Aug 30, 2021

bb7133 commented Aug 30, 2021

SabaPing left a comment

SabaPing Aug 30, 2021 •

edited

Loading

SabaPing Aug 30, 2021

db-will commented Aug 30, 2021

db-will commented Sep 3, 2021 •

edited

Loading

db-will commented Sep 15, 2021

dveeden commented Oct 14, 2021

xiongjiwei commented Oct 26, 2021

db-will commented Oct 27, 2021

xiongjiwei commented Oct 27, 2021

ti-chi-bot commented Oct 27, 2021

ti-chi-bot commented Oct 27, 2021

session: add session var to update global logger max days #27595

session: add session var to update global logger max days #27595

Conversation

db-will commented Aug 26, 2021 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Aug 26, 2021 • edited Loading

CLAassistant commented Aug 26, 2021 • edited Loading

sre-bot commented Aug 26, 2021

db-will commented Aug 26, 2021

db-will commented Aug 26, 2021

morgo Aug 26, 2021

Choose a reason for hiding this comment

db-will Aug 27, 2021

Choose a reason for hiding this comment

morgo Aug 27, 2021

Choose a reason for hiding this comment

morgo commented Aug 29, 2021

morgo left a comment

Choose a reason for hiding this comment

db-will commented Aug 30, 2021

ti-chi-bot commented Aug 30, 2021

bb7133 commented Aug 30, 2021

SabaPing left a comment

Choose a reason for hiding this comment

SabaPing Aug 30, 2021 • edited Loading

Choose a reason for hiding this comment

SabaPing Aug 30, 2021

Choose a reason for hiding this comment

db-will commented Aug 30, 2021

db-will commented Sep 3, 2021 • edited Loading

db-will commented Sep 15, 2021

dveeden commented Oct 14, 2021

xiongjiwei commented Oct 26, 2021

db-will commented Oct 27, 2021

xiongjiwei commented Oct 27, 2021

ti-chi-bot commented Oct 27, 2021

ti-chi-bot commented Oct 27, 2021

db-will commented Aug 26, 2021 •

edited

Loading

ti-chi-bot commented Aug 26, 2021 •

edited

Loading

CLAassistant commented Aug 26, 2021 •

edited

Loading

SabaPing Aug 30, 2021 •

edited

Loading

db-will commented Sep 3, 2021 •

edited

Loading