Re: monitoring CREATE INDEX [CONCURRENTLY]

I added metrics for the validate_index phases; patch attached. This is
still a bit raw, but it looks much better now. Here's a sample
concurrent index build on a 100M tuple table. There are no concurrent
transactions, so phases that wait for lockers don't appear. I'm not
making any effort to report metrics during phase 6, note. In phase 7
I'm currently reporting only tuple counts; I think it'd be better to
report block numbers.

I don't show it here, but when an index is built on a partitioned table,
the "partitions done" number goes up all the way to "partitions total"
and the phases come and go for each partition.

One thing is clear: given the phase mechanics of varying durations, it
seems hard to use these numbers to predict total index build time.

now | phase | blocks total | blocks done | tuples total | tuples done | partitions total | partitions done
--------------+--------------------------------------------------------+--------------+-------------+--------------+-------------+------------------+-----------------
15:56:33.792 | building index (3 of 8): initializing (1/5) | 442478 | 32 | 0 | 0 | 0 | 0
15:56:33.805 | building index (3 of 8): initializing (1/5) | 442478 | 188 | 0 | 0 | 0 | 0
[snip about 500 lines]
15:56:41.345 | building index (3 of 8): initializing (1/5) | 442478 | 439855 | 0 | 0 | 0 | 0
15:56:41.356 | building index (3 of 8): initializing (1/5) | 442478 | 440288 | 0 | 0 | 0 | 0
15:56:41.367 | building index (3 of 8): initializing (1/5) | 442478 | 440778 | 0 | 0 | 0 | 0
15:56:41.378 | building index (3 of 8): initializing (1/5) | 442478 | 441706 | 0 | 0 | 0 | 0
15:56:41.389 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:41.4 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0

[snip 300 lines] ... I'm not sure what happened in this 3 seconds period. No metrics were being updated.

15:56:44.65 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:44.661 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:44.672 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:44.682 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:44.694 | building index (3 of 8): initializing (1/5) | 442478 | 442399 | 0 | 0 | 0 | 0
15:56:44.705 | building index (3 of 8): sorting tuples, spool 1 (3/5) | 442478 | 442399 | 100000000 | 0 | 0 | 0
15:56:44.716 | building index (3 of 8): sorting tuples, spool 1 (3/5) | 442478 | 442399 | 100000000 | 0 | 0 | 0
15:56:44.727 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 79057 | 0 | 0
15:56:44.738 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 217018 | 0 | 0
15:56:44.75 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 353804 | 0 | 0
15:56:44.761 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 487892 | 0 | 0
15:56:44.773 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 634136 | 0 | 0
[snip 660 lines]
15:56:52.47 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99111337 | 0 | 0
15:56:52.482 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99285701 | 0 | 0
15:56:52.493 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99444763 | 0 | 0
15:56:52.505 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99612313 | 0 | 0
15:56:52.516 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99782666 | 0 | 0
15:56:52.528 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 99937524 | 0 | 0
15:56:52.54 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.551 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.561 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.572 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.583 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.594 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.604 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.615 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.626 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.637 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.648 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.658 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.669 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.68 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.691 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.701 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.712 | building index (3 of 8): final btree sort & load (5/5) | 442478 | 442399 | 100000000 | 100000000 | 0 | 0
15:56:52.723 | validating index scan (phase 5 of 8) | 274194 | 1049 | 0 | 0 | 0 | 0
15:56:52.734 | validating index scan (phase 5 of 8) | 274194 | 2676 | 0 | 0 | 0 | 0
15:56:52.744 | validating index scan (phase 5 of 8) | 274194 | 2876 | 0 | 0 | 0 | 0
15:56:52.755 | validating index scan (phase 5 of 8) | 274194 | 4194 | 0 | 0 | 0 | 0
[snip 400 lines]
15:56:57.031 | validating index scan (phase 5 of 8) | 274194 | 268343 | 0 | 0 | 0 | 0
15:56:57.042 | validating index scan (phase 5 of 8) | 274194 | 268479 | 0 | 0 | 0 | 0
15:56:57.053 | validating index scan (phase 5 of 8) | 274194 | 270027 | 0 | 0 | 0 | 0
15:56:57.064 | validating index scan (phase 5 of 8) | 274194 | 271580 | 0 | 0 | 0 | 0
15:56:57.075 | validating index scan (phase 5 of 8) | 274194 | 273121 | 0 | 0 | 0 | 0
15:56:57.085 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.096 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.107 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.118 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.128 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.139 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.15 | sorting index scan results (phase 6 of 8) | 274194 | 274193 | 0 | 0 | 0 | 0
15:56:57.161 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 50152 | 0 | 0
15:56:57.172 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 175602 | 0 | 0
15:56:57.182 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 305326 | 0 | 0
15:56:57.193 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 430142 | 0 | 0
[snip 730 lines]
15:57:05.003 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99125556 | 0 | 0
15:57:05.013 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99276471 | 0 | 0
15:57:05.024 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99425041 | 0 | 0
15:57:05.035 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99580174 | 0 | 0
15:57:05.045 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99720505 | 0 | 0
15:57:05.056 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 99862311 | 0 | 0
15:57:05.067 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.077 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.088 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.099 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.109 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.12 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.131 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.142 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.152 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.163 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
15:57:05.174 | validate index heapscan (phase 7 of 8) | 0 | 0 | 100000000 | 100000000 | 0 | 0
(2862 filas)

and then it's done.

--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services