Speed in progress in post-processing is misleading

[morgo]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do? If possible, provide a recipe for reproducing the error.

I imported 1 80GiB table with TiDB lightning. It worked as expected, but there was something in the logs that could be misleading:

2019/04/19 10:57:24.508  [info] progress: 288/314 chunks (91.7%), 0/1 tables (0.0%), speed 59.42 MiB/s, remaining 1m48s
2019/04/19 10:58:15.035  [info] [`ontime`.`ontime`:0] restore chunk #288 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000290.sql:0) takes 1m6.786456701s (read: 16.399068996s, encode: 46.956198114s, deliver: 26.986902394s, size: 365724609, kvs: 587359)
2019/04/19 10:58:15.924  [info] [`ontime`.`ontime`:0] restore chunk #289 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000291.sql:0) takes 1m7.308596365s (read: 16.592581554s, encode: 47.53086694s, deliver: 26.885925253s, size: 365842044, kvs: 588326)
2019/04/19 10:58:17.092  [info] [`ontime`.`ontime`:0] restore chunk #290 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000292.sql:0) takes 1m7.909898107s (read: 16.6468798s, encode: 47.976796893s, deliver: 27.531606735s, size: 366548691, kvs: 589641)
2019/04/19 10:58:18.002  [info] [`ontime`.`ontime`:0] restore chunk #291 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000293.sql:0) takes 1m7.370414962s (read: 16.596332265s, encode: 47.452088895s, deliver: 27.378736932s, size: 366442580, kvs: 589587)
2019/04/19 10:58:18.551  [info] [`ontime`.`ontime`:0] restore chunk #292 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000294.sql:0) takes 1m7.276636804s (read: 16.654740381s, encode: 47.383267823s, deliver: 27.353697896s, size: 366748822, kvs: 590417)
2019/04/19 10:58:19.278  [info] [`ontime`.`ontime`:0] restore chunk #293 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000295.sql:0) takes 1m7.483649827s (read: 16.836955554s, encode: 47.4216458s, deliver: 27.177977163s, size: 366565528, kvs: 590363)
2019/04/19 10:58:19.346  [info] [`ontime`.`ontime`:0] restore chunk #294 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000296.sql:0) takes 1m7.214924554s (read: 16.676707627s, encode: 47.333561636s, deliver: 27.288494748s, size: 365748469, kvs: 587515)
2019/04/19 10:58:19.496  [info] [`ontime`.`ontime`:0] restore chunk #297 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000299.sql:0) takes 1m6.847181108s (read: 16.794947935s, encode: 46.822892583s, deliver: 27.542620217s, size: 364553156, kvs: 583875)
2019/04/19 10:58:19.739  [info] [`ontime`.`ontime`:0] restore chunk #296 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000298.sql:0) takes 1m7.346982713s (read: 16.50881386s, encode: 47.765438811s, deliver: 26.720869217s, size: 363710758, kvs: 581874)
2019/04/19 10:58:19.770  [info] [`ontime`.`ontime`:0] restore chunk #298 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000300.sql:0) takes 1m6.965520634s (read: 16.600162769s, encode: 47.249858277s, deliver: 26.964208405s, size: 363796329, kvs: 581389)
2019/04/19 10:58:19.823  [info] [`ontime`.`ontime`:0] restore chunk #295 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000297.sql:0) takes 1m7.486180866s (read: 16.75539177s, encode: 47.662811344s, deliver: 26.975854933s, size: 364985011, kvs: 586013)
2019/04/19 10:58:20.153  [info] [`ontime`.`ontime`:0] restore chunk #299 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000301.sql:0) takes 1m7.143061626s (read: 16.634920628s, encode: 47.393688964s, deliver: 27.30845416s, size: 364444900, kvs: 583960)
2019/04/19 10:58:20.832  [info] [`ontime`.`ontime`:0] restore chunk #300 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000302.sql:0) takes 1m7.086168968s (read: 16.669206333s, encode: 47.236513242s, deliver: 26.907263486s, size: 364217460, kvs: 583248)
2019/04/19 10:58:20.884  [info] [`ontime`.`ontime`:0] restore chunk #301 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000303.sql:0) takes 1m6.543379601s (read: 16.573656478s, encode: 46.790259167s, deliver: 26.609936692s, size: 364065013, kvs: 582580)
2019/04/19 10:58:23.653  [info] [`ontime`.`ontime`:0] restore chunk #303 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000305.sql:0) takes 1m7.074397327s (read: 16.522003924s, encode: 47.51934977s, deliver: 26.092176823s, size: 364322952, kvs: 584096)
2019/04/19 10:58:23.679  [info] [`ontime`.`ontime`:0] restore chunk #302 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000304.sql:0) takes 1m7.145327601s (read: 16.673329281s, encode: 47.378547845s, deliver: 25.859322236s, size: 364273786, kvs: 583360)
2019/04/19 10:58:44.349  [info] [`ontime`.`ontime`:0] restore chunk #312 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000314.sql:0) takes 24.609683888s (read: 6.566946196s, encode: 17.401519162s, deliver: 3.243461405s, size: 164967753, kvs: 265477)
2019/04/19 10:59:08.546  [info] [`ontime`.`ontime`:0] restore chunk #304 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000306.sql:0) takes 53.510622966s (read: 14.210565472s, encode: 37.813905703s, deliver: 7.562855261s, size: 364593196, kvs: 584383)
2019/04/19 10:59:09.243  [info] [`ontime`.`ontime`:0] restore chunk #305 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000307.sql:0) takes 53.318288989s (read: 14.143962845s, encode: 37.755656104s, deliver: 7.169037636s, size: 364482504, kvs: 583659)
2019/04/19 10:59:10.369  [info] [`ontime`.`ontime`:0] restore chunk #306 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000308.sql:0) takes 53.276026626s (read: 14.063708065s, encode: 37.782428554s, deliver: 6.855892683s, size: 364380421, kvs: 583487)
2019/04/19 10:59:11.140  [info] [`ontime`.`ontime`:0] restore chunk #307 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000309.sql:0) takes 53.137725106s (read: 14.031394057s, encode: 37.755501518s, deliver: 6.446930186s, size: 364286151, kvs: 583787)
2019/04/19 10:59:11.377  [info] [`ontime`.`ontime`:0] restore chunk #308 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000310.sql:0) takes 52.825191191s (read: 14.087666875s, encode: 37.352905982s, deliver: 6.288371376s, size: 364729869, kvs: 584423)
2019/04/19 10:59:11.632  [info] [`ontime`.`ontime`:0] restore chunk #310 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000312.sql:0) takes 52.285204777s (read: 13.954230642s, encode: 36.975168395s, deliver: 6.1849906s, size: 365445973, kvs: 586356)
2019/04/19 10:59:11.653  [info] [`ontime`.`ontime`:0] restore chunk #309 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000311.sql:0) takes 52.374601681s (read: 14.040815033s, encode: 37.009166342s, deliver: 6.12540251s, size: 365396877, kvs: 586466)
2019/04/19 10:59:11.861  [info] [`ontime`.`ontime`:0] restore chunk #311 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.000000313.sql:0) takes 52.36530689s (read: 13.969956401s, encode: 37.046355277s, deliver: 6.077134501s, size: 365602922, kvs: 587464)
2019/04/19 10:59:12.162  [info] [`ontime`.`ontime`:0] restore chunk #313 (/mnt/evo970/data-sets/ontime-data/ontime.ontime.00001.sql:0) takes 52.391710917s (read: 14.034153272s, encode: 36.999025501s, deliver: 5.998670794s, size: 365583895, kvs: 587544)
2019/04/19 10:59:12.162  [info] [`ontime`.`ontime`:0] encode kv data and write takes 21m47.596367835s (read 80539338461, written 114560022511)
2019/04/19 10:59:12.164  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] engine close
2019/04/19 10:59:16.075  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] engine close takes 3.910884297s
2019/04/19 10:59:16.075  [info] [`ontime`.`ontime`:0] flush kv deliver ...
2019/04/19 10:59:16.075  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] import
2019/04/19 11:02:24.499  [info] switch to tikv Import mode takes 4.435986ms
2019/04/19 11:02:24.499  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 51.21 MiB/s, post-processing
2019/04/19 11:04:31.921  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] import takes 5m15.845531805s
2019/04/19 11:04:31.921  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] cleanup 
2019/04/19 11:04:34.165  [info] [`ontime`.`ontime`:0] [9d2626e1-dca4-5efb-a07a-8336c493a62a] cleanup takes 2.244043243s
2019/04/19 11:04:34.165  [info] [`ontime`.`ontime`:0] kv deliver all flushed, takes 5m18.090368706s
2019/04/19 11:04:34.165  [info] [`ontime`.`ontime`] import whole table takes 27m9.599757383s
2019/04/19 11:04:34.165  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] engine close
2019/04/19 11:04:34.175  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] engine close takes 9.106235ms
2019/04/19 11:04:34.175  [info] [`ontime`.`ontime`:-1] flush kv deliver ...
2019/04/19 11:04:34.175  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] import
2019/04/19 11:04:34.235  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] import takes 60.051593ms
2019/04/19 11:04:34.235  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] cleanup 
2019/04/19 11:04:34.236  [info] [`ontime`.`ontime`:-1] [c5fdba2b-e6e3-5ace-b2f0-60ab8205cdd9] cleanup takes 689.512µs
2019/04/19 11:04:34.236  [info] [`ontime`.`ontime`:-1] kv deliver all flushed, takes 60.87098ms
2019/04/19 11:04:34.244  [info] [ontime.ontime] ALTER TABLE `ontime`.`ontime` AUTO_INCREMENT=725579472
2019/04/19 11:04:34.424  [info] [`ontime`.`ontime`] alter table set auto_id takes 179.78494ms
2019/04/19 11:04:34.424  [info] [`ontime`.`ontime`] local checksum [sum:17109095500510594957, kvs:183953732, size:114560022511]
2019/04/19 11:04:34.444  [info] [`ontime`.`ontime`] doing remote checksum
2019/04/19 11:07:24.501  [info] switch to tikv Import mode takes 6.442484ms
2019/04/19 11:07:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 42.67 MiB/s, post-processing
2019/04/19 11:10:05.558  [warning] query ADMIN CHECKSUM TABLE `ontime`.`ontime` [error] Error 9005: Region is unavailable[try again later]
2019/04/19 11:10:05.559  [warning] query ADMIN CHECKSUM TABLE `ontime`.`ontime` retry 1
2019/04/19 11:11:32.870  [info] [`ontime`.`ontime`] do checksum takes 6m58.44575803s
2019/04/19 11:11:32.895  [info] [`ontime`.`ontime`] checksum pass, {bytes:114560022511 kvs:183953732 checksum:17109095500510594957} takes 6m58.469971683s
2019/04/19 11:11:32.895  [info] [`ontime`.`ontime`] analyze
2019/04/19 11:12:24.500  [info] switch to tikv Import mode takes 5.617193ms
2019/04/19 11:12:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 36.58 MiB/s, post-processing
2019/04/19 11:17:24.501  [info] switch to tikv Import mode takes 6.383353ms
2019/04/19 11:17:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 32.00 MiB/s, post-processing
2019/04/19 11:22:24.501  [info] switch to tikv Import mode takes 6.408816ms
2019/04/19 11:22:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 28.45 MiB/s, post-processing

2. What did you expect to see?

This status line becomes less useful when in post-processing mode:

2019/04/19 11:22:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 28.45 MiB/s, post-processing

It looks like the speed is averaged out, and so it looks like things are slowing. It would be nice to either omit this line in post processing or at least remove the speed column.

3. What did you see instead?

2019/04/19 11:22:24.501  [info] progress: 314/314 chunks (100.0%), 0/1 tables (0.0%), speed 28.45 MiB/s, post-processing

4. Versions of the cluster

Release Version: v2.1.8-4-gea3b27e
Git Commit Hash: ea3b27e616ee33a74c216cf4d295782a01124ebf
Git Branch: master
UTC Build Time: 2019-04-17 05:22:40
Go Version: go version go1.12 linux/amd64

[glorv]

the newest progress log format is as follows:

[2020/08/18 17:15:38.048 +08:00] [INFO] [restore.go:523] [progress] [files="304/337 (90.2%)"] [tables="7/9 (77.8%)"] [speed(MiB/s)=115.4747196733547] [state=writing] [remaining=1m5s]

So this issue is outdated now.