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.

Sign up for GitHub

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

Jump to bottom

add more time field for slow query detail page #810

Merged
merged 32 commits into from
Nov 26, 2020
Merged

add more time field for slow query detail page #810

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
32 commits
Select commit Hold shift + click to select a range
fe1c1a9
add more time field for slow query detail page
crazycs520 Nov 24, 2020
1729986
add exec retry time
crazycs520 Nov 24, 2020
043467d
refine
crazycs520 Nov 24, 2020
4ce951f
add wait ts
crazycs520 Nov 25, 2020
6d022e0
refine display
crazycs520 Nov 25, 2020
9c424c7
add more comment
crazycs520 Nov 25, 2020
c43ecdf
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
a3aad95
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
c005bb2
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
fea6b6b
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
10de098
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
cf9daa9
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
5607611
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
46b54a2
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
d90c6cf
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
71e6c8f
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
5e3d883
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
8f8d00b
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
dd40265
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
26bcd44
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
6626815
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
453c127
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
4190910
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
f38822e
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
a4e88e0
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
b08e954
Update ui/lib/apps/SlowQuery/translations/en.yaml
crazycs520 Nov 26, 2020
388aecc
refine time model
crazycs520 Nov 26, 2020
f66d54d
address comment
crazycs520 Nov 26, 2020
949f991
refine comment
crazycs520 Nov 26, 2020
cb2decc
Apply suggestions from code review
breezewish Nov 26, 2020
fd85096
Merge branch 'master' into add-more-time-field
breezewish Nov 26, 2020
cd56b4f
Apply suggestions from code review
breezewish Nov 26, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 28 additions & 19 deletions pkg/apiserver/slowquery/queries.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,11 +37,18 @@ type SlowQuery struct {
ConnectionID string `gorm:"column:Conn_ID" json:"connection_id"`
Success int `gorm:"column:Succ" json:"success"`

Timestamp float64 `gorm:"column:timestamp" proj:"(UNIX_TIMESTAMP(Time) + 0E0)" json:"timestamp"` // finish time
QueryTime float64 `gorm:"column:Query_time" json:"query_time"` // latency
ParseTime float64 `gorm:"column:Parse_time" json:"parse_time"`
CompileTime float64 `gorm:"column:Compile_time" json:"compile_time"`
ProcessTime float64 `gorm:"column:Process_time" json:"process_time"`
Timestamp float64 `gorm:"column:timestamp" proj:"(UNIX_TIMESTAMP(Time) + 0E0)" json:"timestamp"` // finish time
QueryTime float64 `gorm:"column:Query_time" json:"query_time"` // latency
ParseTime float64 `gorm:"column:Parse_time" json:"parse_time"`
CompileTime float64 `gorm:"column:Compile_time" json:"compile_time"`
RewriteTime float64 `gorm:"column:Rewrite_time" json:"rewrite_time"`
PreprocSubqueriesTime float64 `gorm:"column:Preproc_subqueries_time" json:"preproc_subqueries_time"`
OptimizeTime float64 `gorm:"column:Optimize_time" json:"optimize_time"`
WaitTSTime float64 `gorm:"column:Wait_TS" json:"wait_ts"`
CopTime float64 `gorm:"column:Cop_time" json:"cop_time"`
LockKeysTime float64 `gorm:"column:LockKeys_time" json:"lock_keys_time"`
WriteRespTime float64 `gorm:"column:Write_sql_response_total" json:"write_sql_response_total"`
ExecRetryTime float64 `gorm:"column:Exec_retry_time" json:"exec_retry_time"`

MemoryMax int `gorm:"column:Mem_max" json:"memory_max"`
DiskMax int `gorm:"column:Disk_max" json:"disk_max"`
Expand All @@ -63,20 +70,22 @@ type SlowQuery struct {
Host string `gorm:"column:Host" json:"host"`

// Time
WaitTime float64 `gorm:"column:Wait_time" json:"wait_time"`
BackoffTime float64 `gorm:"column:Backoff_time" json:"backoff_time"`
GetCommitTSTime float64 `gorm:"column:Get_commit_ts_time" json:"get_commit_ts_time"`
LocalLatchWaitTime float64 `gorm:"column:Local_latch_wait_time" json:"local_latch_wait_time"`
ResolveLockTime float64 `gorm:"column:Resolve_lock_time" json:"resolve_lock_time"`
PrewriteTime float64 `gorm:"column:Prewrite_time" json:"prewrite_time"`
CommitTime float64 `gorm:"column:Commit_time" json:"commit_time"`
CommitBackoffTime float64 `gorm:"column:Commit_backoff_time" json:"commit_backoff_time"`
CopProcAvg float64 `gorm:"column:Cop_proc_avg" json:"cop_proc_avg"`
CopProcP90 float64 `gorm:"column:Cop_proc_p90" json:"cop_proc_p90"`
CopProcMax float64 `gorm:"column:Cop_proc_max" json:"cop_proc_max"`
CopWaitAvg float64 `gorm:"column:Cop_wait_avg" json:"cop_wait_avg"`
CopWaitP90 float64 `gorm:"column:Cop_wait_p90" json:"cop_wait_p90"`
CopWaitMax float64 `gorm:"column:Cop_wait_max" json:"cop_wait_max"`
ProcessTime float64 `gorm:"column:Process_time" json:"process_time"`
WaitTime float64 `gorm:"column:Wait_time" json:"wait_time"`
BackoffTime float64 `gorm:"column:Backoff_time" json:"backoff_time"`
GetCommitTSTime float64 `gorm:"column:Get_commit_ts_time" json:"get_commit_ts_time"`
LocalLatchWaitTime float64 `gorm:"column:Local_latch_wait_time" json:"local_latch_wait_time"`
ResolveLockTime float64 `gorm:"column:Resolve_lock_time" json:"resolve_lock_time"`
PrewriteTime float64 `gorm:"column:Prewrite_time" json:"prewrite_time"`
WaitPreWriteBinlogTime float64 `gorm:"column:Wait_prewrite_binlog_time" json:"wait_prewrite_binlog_time"`
CommitTime float64 `gorm:"column:Commit_time" json:"commit_time"`
CommitBackoffTime float64 `gorm:"column:Commit_backoff_time" json:"commit_backoff_time"`
CopProcAvg float64 `gorm:"column:Cop_proc_avg" json:"cop_proc_avg"`
CopProcP90 float64 `gorm:"column:Cop_proc_p90" json:"cop_proc_p90"`
CopProcMax float64 `gorm:"column:Cop_proc_max" json:"cop_proc_max"`
CopWaitAvg float64 `gorm:"column:Cop_wait_avg" json:"cop_wait_avg"`
CopWaitP90 float64 `gorm:"column:Cop_wait_p90" json:"cop_wait_p90"`
CopWaitMax float64 `gorm:"column:Cop_wait_max" json:"cop_wait_max"`

// Transaction
WriteKeys int `gorm:"column:Write_keys" json:"write_keys"`
Expand Down
66 changes: 51 additions & 15 deletions ui/lib/apps/SlowQuery/pages/Detail/DetailTabTime.tsx
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,23 @@ export interface ITabTimeProps {
export default function TabBasic({ data }: ITabTimeProps) {
const { t } = useTranslation()
const items = [
{
key: 'write_sql_response_total',
value: data.write_sql_response_total! * 10e8,
},
{
key: 'exec_retry_time',
value: data.exec_retry_time! * 10e8,
},
{
key: 'query_time2',
keyDisplay: (
<Typography.Text strong>
{t('slow_query.fields.query_time2')}
</Typography.Text>
),
value: data.query_time! * 10e8,
},
{
key: 'parse_time',
value: data.parse_time! * 10e8,
Expand All @@ -20,6 +37,26 @@ export default function TabBasic({ data }: ITabTimeProps) {
key: 'compile_time',
value: data.compile_time! * 10e8,
},
{
key: 'rewrite_time',
value: data.rewrite_time! * 10e8,
},
{
key: 'preproc_subqueries_time',
value: data.preproc_subqueries_time! * 10e8,
},
{
key: 'optimize_time',
value: data.optimize_time! * 10e8,
},
{
key: 'wait_ts',
value: data.wait_ts! * 10e8,
},
{
key: 'cop_time',
value: data.cop_time! * 10e8,
},
{
key: 'wait_time',
value: data.wait_time! * 10e8,
Expand All @@ -28,42 +65,41 @@ export default function TabBasic({ data }: ITabTimeProps) {
key: 'process_time',
value: data.process_time! * 10e8,
},
{
key: 'lock_keys_time',
value: data.lock_keys_time! * 10e8,
},
{
key: 'backoff_time',
value: data.backoff_time! * 10e8,
},
{
key: 'get_commit_ts_time',
value: data.get_commit_ts_time! * 10e8,
key: 'prewrite_time',
value: data.prewrite_time! * 10e8,
},
{
key: 'local_latch_wait_time',
value: data.local_latch_wait_time! * 10e8,
},
{
key: 'resolve_lock_time',
value: data.resolve_lock_time! * 10e8,
key: 'wait_prewrite_binlog_time',
value: data.wait_prewrite_binlog_time! * 10e8,
},
{
key: 'prewrite_time',
value: data.prewrite_time! * 10e8,
key: 'get_commit_ts_time',
value: data.get_commit_ts_time! * 10e8,
},
{
key: 'commit_time',
value: data.commit_time! * 10e8,
},
{
key: 'commit_backoff_time',
value: data.commit_backoff_time! * 10e8,
key: 'resolve_lock_time',
value: data.resolve_lock_time! * 10e8,
},
{
key: 'query_time2',
keyDisplay: (
<Typography.Text strong>
{t('slow_query.fields.query_time2')}
</Typography.Text>
),
value: data.query_time! * 10e8,
key: 'commit_backoff_time',
value: data.commit_backoff_time! * 10e8,
},
]
const columns = timeValueColumns('slow_query.fields.', items)
Expand Down
52 changes: 38 additions & 14 deletions ui/lib/apps/SlowQuery/translations/en.yaml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,22 +34,46 @@ slow_query:
db: Execution Database
db_tooltip: The database used to execute the query

parse_time: Parse Time
query_time2: Query Time
query_time2_tooltip: The execution time of a query (due to the parallel execution, it may be significantly smaller than the following time)
breezewish marked this conversation as resolved.
Show resolved Hide resolved
parse_time: 　　Parse Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
parse_time_tooltip: Time consumed when parsing the query
compile_time: Compile Time
compile_time_tooltip: Time consumed when optimizing the query
wait_time: Coprocessor Wait Time
process_time: Coprocessor Process Time
backoff_time: Backoff Retry Time
compile_time: 　　Generate plan Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
compile_time_tooltip: Time consumed when generating plan of the query
Copy link
Member

Choose a reason for hiding this comment

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

This tooltip does not provide new information, so that it can be either removed, or make it more detailed.

crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
rewrite_time: 　　　　Rewrite plan Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
preproc_subqueries_time: 　　　　　　Preprocess subquery Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
preproc_subqueries_time_tooltip: The time consumed of pre-process the subquery during the rewrite plan phase
breezewish marked this conversation as resolved.
Show resolved Hide resolved
optimize_time: 　　　　Optimize plan Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
wait_ts: 　　Wait Txn StartTS Time
wait_ts_tooltip: Time consumed of waiting transaction start ts
Copy link
Member

Choose a reason for hiding this comment

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

what is wait startTs? Is it the time of retrieving a StartTs?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

wait for retrieving a StartTs finish?

Since retrieving StartTs is asynchronous, when we need the startTs, we need wait for retrieving a StartTs finish first.

crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
cop_time: 　　Coprocessor request Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
cop_time_tooltip: Time consumed of TiDB sending cop request
Copy link
Member

Choose a reason for hiding this comment

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

Is this a total time or P99 time or AVG time? As we know that there can be multiple Copr requests.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

The time model is below:

start := time.Now()

for _, cop := range tasks {
    go sendAndRecvCopRequestResult();
} 
waitCopRequestFinish()

cop_time := time.Since(start)    // This is the cop_time.

wait_time: 　　　　Coprocessor Wait Time
wait_time_tooltip: The total waiting time of cop request in TiKV. Because the Coprocessor of TiKV runs a limited number of threads, cop requests might queue up when all threads of Coprocessor are working
Copy link
Member

Choose a reason for hiding this comment

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

In 4.0 "cop requests might queue up" is not true, every requests will be processed in parallel. I recommend to not write this misleading information.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Ok, this is copy from the documents.

Copy link
Member

Choose a reason for hiding this comment

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

Looks like we need to update documents as well.. LOL

crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
process_time: 　　　　Coprocessor Process Time
process_time_tooltip: The total processing time of a SQL statement in TiKV. Because data is sent to TiKV concurrently, this value might exceed the query time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
backoff_time: 　　Backoff Retry Time
backoff_time_tooltip: The waiting time before retry when a query encounters errors that require a retry
breezewish marked this conversation as resolved.
Show resolved Hide resolved
get_commit_ts_time: Get Commit Ts Time
local_latch_wait_time: Local Latch Wait Time
resolve_lock_time: Resolve Lock Time
prewrite_time: Prewrite Time
commit_time: Commit Time
commit_backoff_time: Commit Backoff Time
query_time2: Query Time
query_time2_tooltip: The execution time of a query (due to the parallel execution, it may be significantly smaller than the above time)
lock_keys_time: 　　Lock keys Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
lock_keys_time_tooltip: Time consumed when locking keys in pessimistic transaction
get_commit_ts_time: 　　Get Commit Ts Time
get_commit_ts_time_tooltip: The time spent on getting commit_ts during the second phase (commit) of the two-phase transaction commit
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
local_latch_wait_time: 　　Local Latch Wait Time
local_latch_wait_time_tooltip: The time that TiDB spends on waiting for the lock before the second phase (commit) of the two-phase transaction commit
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
resolve_lock_time: 　　Resolve Lock Time
resolve_lock_time_tooltip: The time that TiDB resolves locks when prewrite encounters locks.
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
prewrite_time: 　　Prewrite Time
prewrite_time_tooltip: The duration of the first phase (prewrite) of the two-phase transaction commit
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
wait_prewrite_binlog_time: 　　Wait binlog prewrite Time
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
wait_prewrite_binlog_time_tooltip: The duration of waiting prewrite binlog finish
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
commit_time: 　　Commit Time
commit_time_tooltip: The duration of the second phase (commit) of the two-phase transaction commit
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
commit_backoff_time: 　　Commit Backoff Time
commit_backoff_time_tooltip: The waiting time when the two-phase transaction commit encounters errors
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
write_sql_response_total: Send response Time
write_sql_response_total_tooltip: Time consumed when sending response to the client
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
exec_retry_time: Retry execution Time
exec_retry_time_tooltip: Time consumed of retry execution that cause by locks or errors.
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

request_count: Request Count
process_keys: Process Keys
Expand Down
56 changes: 39 additions & 17 deletions ui/lib/apps/SlowQuery/translations/zh.yaml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,25 +34,47 @@ slow_query:
db: 执行数据库
db_tooltip: 执行该 SQL 查询时使用的数据库名称

parse_time: 解析耗时
query_time2: SQL 执行时间
query_time2_tooltip: 由于存在并行执行，因此 SQL 执行时间可能远小于以下各项时间
breezewish marked this conversation as resolved.
Show resolved Hide resolved
parse_time: 　　解析耗时
parse_time_tooltip: 解析该 SQL 查询的耗时
compile_time: 优化耗时
compile_time_tooltip: 优化该 SQL 查询的耗时
wait_time: Coprocessor 累计等待耗时
process_time: Coprocessor 累计执行耗时
process_time_tooltip: Coprocessor 累计执行耗时
backoff_time: 累计重试等待耗时
get_commit_ts_time: 取 Commit Ts 耗时
get_commit_ts_time_tooltip: 从 PD 取递交时间戳（事务号）步骤的耗时
local_latch_wait_time: Local Latch Wait 耗时
compile_time: 　　生成执行计划耗时
compile_time_tooltip: 生成该 SQL 的执行计划的耗时
rewrite_time: 　　　　重写执行计划耗时
rewrite_time_tooltip: 重写执行计划的耗时，例如常量折叠等
preproc_subqueries_time: 　　　　　　子查询预处理耗时
optimize_time: 　　　　优化执行计划耗时
optimize_time_tooltip: 优化器寻找执行计划的耗时，包括规则优化和物理优化的耗时
wait_ts: 　　等待事务开始时间戳耗时
wait_ts_tooltip: 从 PD 取事务开始时间戳步骤的耗时
cop_time: 　　Coprocessor 请求耗时
cop_time_tooltip: TiDB 发送 cop 请求的耗时
wait_time: 　　　　Coprocessor 累计等待耗时
wait_time_tooltip: 在 TiKV Coprocessor 的等待时间之和，因为 TiKV 的 Coprocessor 线程数是有限的，当所有的 Coprocessor 线程都在工作的时候，cop 请求会排队；
process_time: 　　　　Coprocessor 累计执行耗时
process_time_tooltip: 在 TiKV Coprocessor 的处理时间之和，因为请求会并行的发到 TiKV 执行，这个值可能会超过 SQL 执行时间
breezewish marked this conversation as resolved.
Show resolved Hide resolved
lock_keys_time: 　　上锁耗时
lock_keys_time_tooltip: 悲观事务中对相关行数据进行上锁的耗时
backoff_time: 　　累计重试等待耗时
backoff_time_tooltip: 执行过程中遇到锁或者错误后的等待耗时
breezewish marked this conversation as resolved.
Show resolved Hide resolved
get_commit_ts_time: 　　取 Commit Ts 耗时
get_commit_ts_time_tooltip: 从 PD 取提交时间戳（事务号）步骤的耗时
local_latch_wait_time: 　　Local Latch Wait 耗时
local_latch_wait_time_tooltip: 事务在 TiDB 本地与其他事务产生了锁冲突并等待的耗时
resolve_lock_time: Resolve Lock 耗时
resolve_lock_time_tooltip: 事务在 TiKV 与其他事务产生了锁冲突并处理锁冲突的耗时
prewrite_time: Prewrite 阶段耗时
commit_time: Commit 阶段耗时
commit_backoff_time: Commit 重试等待耗时
query_time2: SQL 执行时间
query_time2_tooltip: 由于存在并行执行，因此 SQL 执行时间可能远小于上述各项时间
resolve_lock_time: 　　Resolve Lock 耗时
resolve_lock_time_tooltip: 事务在提交过程中与其他事务产生了锁冲突并处理锁冲突的耗时
prewrite_time: 　　Prewrite 阶段耗时
prewrite_time_tooltip: 事务两阶段提交中第一阶段（prewrite 阶段）的耗时
wait_prewrite_binlog_time: 　　等 binlog Prewrite 耗时
breezewish marked this conversation as resolved.
Show resolved Hide resolved
wait_prewrite_binlog_time_tooltip: 等待 binlog prewrite 完成的耗时
breezewish marked this conversation as resolved.
Show resolved Hide resolved
commit_time: 　　Commit 阶段耗时
commit_time_tooltip: 事务两阶段提交中第二阶段（commit 阶段）的耗时
commit_backoff_time: 　　Commit 重试等待耗时
commit_backoff_time_tooltip: 事务两阶段提交过程中遇到锁或者错误后的等待耗时
write_sql_response_total: 发送结果耗时
write_sql_response_total_tooltip: 发送 SQL 结果给客户端的耗时
exec_retry_time: 执行重试耗时
exec_retry_time_tooltip: 由于锁冲突或者某些错误导致执行失败的执行耗时

request_count: Coprocessor 请求数
process_keys: 可见版本数
Expand Down