Re: monitoring CREATE INDEX [CONCURRENTLY] - Mailing list pgsql-hackers
| From | Alvaro Herrera |
|---|---|
| Subject | Re: monitoring CREATE INDEX [CONCURRENTLY] |
| Date | |
| Msg-id | 20190212191632.GA28036@alvherre.pgsql Whole thread Raw |
| In response to | Re: monitoring CREATE INDEX [CONCURRENTLY] (Alvaro Herrera <alvherre@2ndquadrant.com>) |
| Responses |
Re: monitoring CREATE INDEX [CONCURRENTLY]
Re: monitoring CREATE INDEX [CONCURRENTLY] |
| List | pgsql-hackers |
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 |
tuplesdone | 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
Attachment
pgsql-hackers by date: