*: refine commit txn slow log

[lysu]

What problem does this PR solve?

1) commit slow log info is hard to find question:

run this script:

create table tb (a int, b int);
insert into tb (a, b) values (1, 1), (2, 2)...;  // x47100
begin;
update tb set b =  0;
commit;

will got commit log like this:

2018/12/18 15:11:04.482 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.530186968s succ:true con:1 user:root@127.0.0.1 txn_start_ts:405043163388706817 database:test sql:commit

we are hard to know the real reason make this slow.

2) no latch wait metric

From metric, we can't known how long time used in wait local latch, and we need add it to metrics

What is changed and how it works?

1) refine commit txn slow log

add more detail info in commit slow log, just like this:

2018/12/18 15:11:04.482 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.530186968s prewrite_time:2.284130378s commit_time:83.495155ms get_commit_ts_time:153.792µs write_keys:47100 write_size:1457201 prewrite_region:1 succ:true con:1 user:root@127.0.0.1 txn_start_ts:405043163388706817 database:test sql:commitTxn

we can got detail info:

• GetCommitTsTime: get commit_ts time for this txn
• PrewriteTime: prewrite time for this txn
• CommitTime: commit time for this txn
• LocalLatchTime: wait tidb local latch time
• TotalBackoffTime: total time waste in backoff operation
• ResolveLockTime: time used to resolve lock
• WriteKeys: keys be writen in this txn
• WriteSize: data bytes be writen in this txn
• PrewriteRegionNum: prewrite region count
• TxnRetry: auto transaction retried count, so if txn be retried above item is first txn commit value

so we can see TxnRetry to known whether slow by txn-retry, or no retry just slow in caused by latch, prewrite, getTs, commit or resolve; and we also can get write key count, data size and requested region count info which are missed in previous log.

2) add latch wait to metric

Add a prometheus metric item, local_latch_wait_seconds:

TiKVLocalLatchWaitTimeHistogram = prometheus.NewHistogram(
		prometheus.HistogramOpts{
			Namespace: "tidb",
			Subsystem: "tikvclient",
			Name:      "local_latch_wait_seconds",
			Help:      "Wait time of a get local latch.",
			Buckets:   prometheus.ExponentialBuckets(0.0005, 2, 20),
		})

to record the time that wait latch when txn could not acquire lock success.

Check List

Tests

• Exists Test

Code changes

• Collect stats in 2pc
• Add log
• Add metric

Side effects

• N/A

Related changes

• Need to cherry-pick to the release branch
• Need to update the documentation
• Need to be included in the release note

---

This change is 

@tiancaiamao @jackysp PTAL thx~

[lysu]

/run-all-tests

[lysu]

/run-all-tests

[shenli]

@tiancaiamao PTAL

[lysu]

/run-all-tests

[shenli]

The metrics is not mentioned in "What is changed and how it works?" section. Please refine the description.

[lysu]

/rebuild

[lysu]

/run-all-tests

[lysu]

@tiancaiamao @jackysp @winkyao PTAL

[jackysp]

LGTM

[lysu]

@tiancaiamao @tiancaiamao

[tiancaiamao]

Why pointer of pointer? is it better to use commitDetail ?

[lysu]

direct use commitDetail will copy on withValue call and couldn't get modification by callled method,
use pointer of commitDetail can get change result, but hard to distinguish "has commitDetail" and "no commitDetail"

[tiancaiamao]

LGTM