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

*: refactor slow log format and parse slow query log to `SLOW_QUERY` table. #9290

Merged
merged 39 commits into from Mar 11, 2019

Conversation

@crazycs520
Copy link
Contributor

commented Feb 12, 2019

What problem does this PR solve?

  • refactor slow log format to compatible with mysql slow log.
  • Add INFORMATION_SCHEMA.SLOW_QUERY table, the table content is from parse slow log file.
  • Add tidb_slow_query_file seesion variable to control which slow log file to be parsed.

What is changed and how it works?

  • New slow log format is like below, this will be friendly to some utils like pt-query-digest.

    # Time: 2019-02-12-19:33:56.571953 +0800
    # Txn_start_ts: 406315658548871171
    # User: root@127.0.0.1
    # Conn_ID: 6
    # Query_time: 4.895492
    # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Processed_keys: 100000
    # DB: test
    # Is_internal: false
    select * from t_slim;
    
    • other information like statement digest, plan digest maybe add later.
    • If you need more information in slow log, please leave you comment.
  • Query INFORMATION_SCHEMA.SLOW_QUERY table.

    mysql> use INFORMATION_SCHEMA;
    Database changed
    mysql> set @@tidb_slow_query_file="tidb_slow.log";
    Query OK, 0 rows affected (0.00 sec)
    mysql> select * from `SLOW_QUERY`;
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | Time                       | Txn_start_ts       | User           | Conn_ID | Query_time | Process_time | Wait_time | Backoff_time | Request_count | Total_keys | Processed_keys | DB   | Is_internal | Query                                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | 2019-02-12 19:31:06.954777 | 406315605634056194 | root@127.0.0.1 |       1 |  37.142122 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | test |           0 | create table t1(y year NOT NULL DEFAULT '2155'); |
    | 2019-02-12 19:33:56.571953 | 406315658548871171 | root@127.0.0.1 |       6 |   4.895492 |        0.161 |      NULL |         NULL |             1 |     100001 |         100000 | test |           0 | select * from t_slim;                            |
    | 2019-02-12 19:34:33.257245 |                  0 | NULL           |    NULL |    0.51371 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | NULL |           1 | analyze table `test`.`t_slim`;                   |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    3 rows in set (0.00 sec)
    
    mysql> select * from `SLOW_QUERY` where `Is_internal`=false order by `Query_time` desc;
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | Time                       | Txn_start_ts       | User           | Conn_ID | Query_time | Process_time | Wait_time | Backoff_time | Request_count | Total_keys | Processed_keys | DB   | Is_internal | Query                                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    | 2019-02-12 19:31:06.954777 | 406315605634056194 | root@127.0.0.1 |       1 |  37.142122 |         NULL |      NULL |         NULL |          NULL |       NULL |           NULL | test |           0 | create table t1(y year NOT NULL DEFAULT '2155'); |
    | 2019-02-12 19:33:56.571953 | 406315658548871171 | root@127.0.0.1 |       6 |   4.895492 |        0.161 |      NULL |         NULL |             1 |     100001 |         100000 | test |           0 | select * from t_slim;                            |
    +----------------------------+--------------------+----------------+---------+------------+--------------+-----------+--------------+---------------+------------+----------------+------+-------------+--------------------------------------------------+
    2 rows in set (0.00 sec)

Check List

Tests

  • Unit test
  • Integration test

Code changes

  • Has exported function/method change

Side effects

Related changes

  • Need to update the documentation
@morgo

This comment has been minimized.

Copy link
Contributor

commented Feb 12, 2019

Assuming that a statement_digest function is added in pingcap/parser#32, it should be possible to group by digested form :-)

I myself will process the log file in a utility like pt-query-digest, but I can see the use case of presenting in the server (in the absense of pfs for this as in MySQL).

@jackysp

This comment has been minimized.

Copy link
Member

commented Feb 13, 2019

There may be some conflictions between this PR and #9279 .

@lysu

This comment has been minimized.

Copy link
Member

commented Feb 13, 2019

@crazycs520 I have a question, do we keep old slow-log in tidb.log file and put new format into new tidb-slow.log file? or just replace old format with the new one?

new format maybe friendly to pt but it seems not friendly to grep & awk script

@morgo

This comment has been minimized.

Copy link
Contributor

commented Feb 13, 2019

@crazycs520 I have a question, do we keep old slow-log in tidb.log file and put new format into new tidb-slow.log file? or just replace old format with the new one?

It is a good question. I would rather we don't have two formats. It feels wrong to ask a customer which slow log format they are using when we are suggesting tools to process it.

new format maybe friendly to pt but it seems not friendly to grep & awk script

I think medium term we should offer a pt-query-digest alternative based on https://github.com/Preetam/mysqllog + using our parser for normalization :-) It is quick to build, and will save users from installing perl.

crazycs520 added some commits Feb 27, 2019

@zz-jason zz-jason requested review from lysu, winkyao and XuHuaiyu Feb 27, 2019

Show resolved Hide resolved executor/adapter.go Outdated
Show resolved Hide resolved util/execdetails/execdetails.go Outdated
Show resolved Hide resolved sessionctx/variable/session.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log_test.go
Show resolved Hide resolved sessionctx/variable/session.go Outdated

crazycs520 added some commits Feb 27, 2019

@crazycs520

This comment has been minimized.

Copy link
Contributor Author

commented Mar 6, 2019

@crazycs520

This comment has been minimized.

Copy link
Contributor Author

commented Mar 6, 2019

/run-all-tests

@winkyao
Copy link
Member

left a comment

LGTM

Show resolved Hide resolved sessionctx/variable/session.go
Show resolved Hide resolved util/execdetails/execdetails.go Outdated
Show resolved Hide resolved util/execdetails/execdetails.go Outdated
Show resolved Hide resolved infoschema/tables_test.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go Outdated

zz-jason and others added some commits Mar 7, 2019

Update util/execdetails/execdetails.go
Co-Authored-By: crazycs520 <crazycs520@gmail.com>
Update infoschema/slow_log.go
Co-Authored-By: crazycs520 <crazycs520@gmail.com>
@crazycs520

This comment has been minimized.

Copy link
Contributor Author

commented Mar 8, 2019

@zz-jason PTAL.

Show resolved Hide resolved infoschema/slow_log.go
Show resolved Hide resolved infoschema/slow_log.go
Show resolved Hide resolved infoschema/slow_log.go
Show resolved Hide resolved infoschema/slow_log.go Outdated
Show resolved Hide resolved infoschema/slow_log.go
Show resolved Hide resolved util/execdetails/execdetails.go Outdated
Show resolved Hide resolved sessionctx/variable/session.go
Show resolved Hide resolved sessionctx/variable/session_test.go Outdated
Show resolved Hide resolved util/execdetails/execdetails.go Outdated
buf.WriteString(SlowLogPrefixStr + SlowLogIndexNamesStr + SlowLogSpaceMarkStr + indexIDs + "\n")
}
buf.WriteString(SlowLogPrefixStr + SlowLogIsInternalStr + SlowLogSpaceMarkStr + strconv.FormatBool(s.InRestrictedSQL) + "\n")
if len(sql) > 0 {

This comment has been minimized.

Copy link
@zimulala

zimulala Mar 11, 2019

Member

Under what circumstances will encounter the situation of len(sql) == 0 ?

This comment has been minimized.

Copy link
@crazycs520

crazycs520 Mar 11, 2019

Author Contributor

Normally It won't be len(sql) = 0, but just in case, we should also print ";" when len(sql)=0. Parser need ";" to indicate the end of slow log.

Show resolved Hide resolved sessionctx/variable/session.go Outdated
Show resolved Hide resolved executor/adapter.go

crazycs520 added some commits Mar 11, 2019

@crazycs520

This comment has been minimized.

Copy link
Contributor Author

commented Mar 11, 2019

@zz-jason @zimulala PTAL again. Thanks.

@zz-jason
Copy link
Member

left a comment

LGTM

@zz-jason

This comment has been minimized.

Copy link
Member

commented Mar 11, 2019

/run-all-tests

@zz-jason zz-jason removed the request for review from XuHuaiyu Mar 11, 2019

@zz-jason zz-jason merged commit 80110fb into pingcap:master Mar 11, 2019

16 checks passed

ci/circleci Your tests passed on CircleCI!
Details
codecov/patch 75.1269% of diff hit (target 0%)
Details
codecov/project 67.3959% (+0.0028%) compared to a968f91
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
idc-jenkins-ci-tidb/build Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/check_dev Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/code_coverage Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/common-test job succeeded
Details
idc-jenkins-ci-tidb/integration-common-test Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/integration-compatibility-test Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/integration-ddl-test Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/mybatis-test job succeeded
Details
idc-jenkins-ci-tidb/sqllogic-test-1 Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/sqllogic-test-2 Jenkins job succeeded.
Details
idc-jenkins-ci-tidb/unit-test Jenkins job succeeded.
Details
license/cla Contributor License Agreement is signed.
Details
}
defer func() {
if err = file.Close(); err != nil {
log.Error(err)

This comment has been minimized.

Copy link
@zimulala

zimulala Mar 11, 2019

Member

Please add more information to this log.


const (
// SlowLogPrefixStr is slow log row prefix.
SlowLogPrefixStr = "# "

This comment has been minimized.

Copy link
@zimulala

zimulala Mar 11, 2019

Member

Could we rename it to SlowLogFieldPrefixStr or SlowLogRowPrefixStr?

totalKeys uint64
processKeys uint64
db string
indexNames string

This comment has been minimized.

Copy link
@zimulala

zimulala Mar 11, 2019

Member

Do we need to update this field name?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
9 participants
You can’t perform that action at this time.