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

*: log each com_stmt_fetch separately #11987

Merged
merged 6 commits into from
Sep 25, 2019
Merged

*: log each com_stmt_fetch separately #11987

merged 6 commits into from
Sep 25, 2019

Conversation

lysu
Copy link
Contributor

@lysu lysu commented Sep 2, 2019

What problem does this PR solve?

to slow log:

In the current master code, slow log will be wrong value(last fetch time(or new start execute time) - last cmd time)
In 2.1 code, slow log will be incompatible value(last fetch time(or new start execute time) - first com_stmt_execute time)
but mysql record com_stmt_exec and com_stmt_fetch for each request.

this pr will change the behavior as MySQL does, although TiDB and MySQL use very different way to handle cursor:

  • MySQL execute sql and save the result in temp table(memory or myisam), then fetch the tmp table
  • TiDB cache the executor-tree and execute when fetch command came and cache partial result in memory(now TiDB-server node is stateless and doesn't write any data in local disk)

so, you may see mysql stmt_execute is slow but fetch super fast, and TiDB both execute and fetch is slow in log.

What is changed and how it works?

  • add LogParitialSlow to recordset
  • Fix stmt_reset should clean up opened cursor in stmt(but pay attention both libmysql c API and jdbc, close ResultSet shouldn't send stmt_reset in current client impl, but mysql server will handle stmt_reset like this)
  • log InPreapre and HasMoreResult in slow log too(help find question)
  • log Parse_time and Compile_time in slow log(it seems miss those two fields)

Check List

Tests

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

Code changes

  • Has exported function/method change
  • Has exported variable/fields change
  • Has interface methods change
  • Has persistent data change

Side effects

  • Possible performance regression
  • Increased code complexity
  • Breaking backward compatibility

Related changes

  • Need to cherry-pick to the release branch
  • Need to update the documentation
  • Need to update the tidb-ansible repository

Release note

  • Write release note for bug-fix or new feature.

This change is Reviewable

@lysu
Copy link
Contributor Author

lysu commented Sep 2, 2019

/run-all-tests

@codecov
Copy link

codecov bot commented Sep 2, 2019

Codecov Report

❗ No coverage uploaded for pull request base (master@4891e18). Click here to learn what that means.
The diff coverage is 93.75%.

@@            Coverage Diff             @@
##             master    #11987   +/-   ##
==========================================
  Coverage          ?   80.745%           
==========================================
  Files             ?       454           
  Lines             ?     99403           
  Branches          ?         0           
==========================================
  Hits              ?     80263           
  Misses            ?     13346           
  Partials          ?      5794

@lonng
Copy link
Contributor

lonng commented Sep 3, 2019

IMO, I don't like this way to fix the slow query misinformation (the extra LogPartialSlow method is not an elegant way). Prefer to change the query cost time to an accumulative time and accumulate it every com_stmt_fetch.

Copy link
Member

@jackysp jackysp left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@lysu
Copy link
Contributor Author

lysu commented Sep 3, 2019

IMO, I don't like this way to fix the slow query misinformation (the extra LogPartialSlow method is not an elegant way). Prefer to change the query cost time to an accumulative time and accumulate it every com_stmt_fetch.

mysql record slow log for each comand time, should keep compatible with that?

https://github.com/mysql/mysql-server/blob/2f553f258daa213c710bc56d4fd7b8faeb7c4631/sql/sql_parse.cc#L1458

https://github.com/mysql/mysql-server/blob/2f553f258daa213c710bc56d4fd7b8faeb7c4631/sql/sql_parse.cc#L1738

@jackysp
Copy link
Member

jackysp commented Sep 24, 2019

PTAL @lonng .
Please resolve the conflicts, @lysu .

@lysu lysu requested a review from coocood September 25, 2019 03:32
@lysu lysu added the priority/release-blocker This issue blocks a release. Please solve it ASAP. label Sep 25, 2019

// LogPartialSlow logs the slow log for partial result.
// it will be used in server-side cursor or multi-queries.
LogPartialSlow()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The method name is too specific.
Something like OnFetchDone would be better.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried remove this method out of that interface and give a new name now~ PTAL if free

@lysu
Copy link
Contributor Author

lysu commented Sep 25, 2019

/run-all-tests

@lysu
Copy link
Contributor Author

lysu commented Sep 25, 2019

@coocood @tiancaiamao PTAL

@lysu lysu removed the priority/release-blocker This issue blocks a release. Please solve it ASAP. label Sep 25, 2019
@coocood
Copy link
Member

coocood commented Sep 25, 2019

LGTM

Copy link
Member

@jackysp jackysp left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@jackysp jackysp added the status/can-merge Indicates a PR has been approved by a committer. label Sep 25, 2019
@lysu lysu added the status/LGT2 Indicates that a PR has LGTM 2. label Sep 25, 2019
@sre-bot
Copy link
Contributor

sre-bot commented Sep 25, 2019

/run-all-tests

@sre-bot sre-bot merged commit 74eaf32 into pingcap:master Sep 25, 2019
@sre-bot
Copy link
Contributor

sre-bot commented Sep 25, 2019

cherry pick to release-3.1 failed

@sre-bot
Copy link
Contributor

sre-bot commented Sep 25, 2019

cherry pick to release-3.0 in PR #12392

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
component/server status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. type/usability
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants