Skip to content

Instantly share code, notes, and snippets.

@ancoron

ancoron/summary.txt Secret

Last active July 25, 2019 02:38
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save ancoron/d5114b0907e8974b6808077e02f8d109 to your computer and use it in GitHub Desktop.
Save ancoron/d5114b0907e8974b6808077e02f8d109 to your computer and use it in GitHub Desktop.
Download ZIP
Test results from UUID load tests (with extension)
Raw
summary.txt
-- https://github.com/ancoron/pg-uuid-ext
CREATE EXTENSION IF NOT EXISTS uuid_ext;
-- https://github.com/ancoron/pg-uuid-v1
CREATE EXTENSION IF NOT EXISTS uuid_v1;
Tables:
CREATE TABLE t_uuid (id uuid PRIMARY KEY USING INDEX TABLESPACE faster) TABLESPACE fast;
CREATE TABLE t_uuid_serial (id uuid PRIMARY KEY USING INDEX TABLESPACE faster) TABLESPACE fast;
CREATE TABLE t_uuid_ext (id uuid) TABLESPACE fast;
CREATE UNIQUE INDEX idx_uuid_ext ON t_uuid_ext (id uuid_timestamp_ops) TABLESPACE faster;
CREATE TABLE t_uuid_v1 (id uuid_v1 PRIMARY KEY USING INDEX TABLESPACE faster) TABLESPACE fast;
1.) COPY 200M rows from file into table:
t_uuid: 2499875.629 ms (41:39.876) 100.0 %
t_uuid_serial: 360743.053 ms (06:00.743) 14.4 %
t_uuid_ext: 362321.035 ms (06:02.321) 14.5 %
t_uuid_v1: 320795.305 ms (05:20.795) 12.8 %
2.) DELETE first 7M rows:
t_uuid: 78906.383 ms (01:18.906) 100.0 %
t_uuid_serial: 7054.232 ms (00:07.054) 8.9 %
t_uuid_ext: 7018.438 ms (00:07.018) 8.9 %
t_uuid_v1: 6986.633 ms (00:06.987) 8.9 %
3.) VACUUM (VERBOSE, ANALYZE):
t_uuid: 296490.419 ms (04:56.490) 100.0 %
t_uuid_serial: 97587.985 ms (01:37.588) 32.9 %
t_uuid_ext: 86050.850 ms (01:26.051) 29.0 %
t_uuid_v1: 76356.344 ms (01:16.356) 25.8 %
4.) DELETE another 5M rows:
t_uuid: 29378.067 ms (00:29.378) 100.0 %
t_uuid_serial: 4897.380 ms (00:04.897) 16.7 %
t_uuid_ext: 4890.844 ms (00:04.891) 16.6 %
t_uuid_v1: 4885.595 ms (00:04.886) 16.6 %
5.) COPY 17M additional rows from file into table:
t_uuid: 651976.685 ms (10:51.977) 100.0 %
t_uuid_serial: 31094.804 ms (00:31.095) 4.8 %
t_uuid_ext: 31129.127 ms (00:31.129) 4.8 %
t_uuid_v1: 27497.356 ms (00:27.497) 4.2 %
6.) VACUUM (VERBOSE, ANALYZE):
t_uuid: 217983.576 ms (03:37.984) 100.0 %
t_uuid_serial: 48780.509 ms (00:48.781) 22.4 %
t_uuid_ext: 48472.868 ms (00:48.473) 22.2 %
t_uuid_v1: 47442.738 ms (00:47.443) 21.8 %
7.) REINDEX (VERBOSE):
t_uuid: 92387.364 ms (01:32.387) 100.0 %
t_uuid_serial: 72567.831 ms (01:12.568) 78.5 %
t_uuid_ext: 79104.090 ms (01:19.104) 85.6 %
t_uuid_v1: 78544.865 ms (01:18.545) 85.0 %
Raw
test-postgresql.log
SET application_name TO 'uuid-ext-test';
SET
SELECT pg_backend_pid();
pg_backend_pid
----------------
29091
(1 row)
SELECT pg_sleep(15);
pg_sleep
----------
(1 row)
\timing on
Timing is on.
-- INSERT 80M rows...
COPY t_uuid FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.a.txt' WITH ( FORMAT text );
COPY 200000000
Time: 2499875.629 ms (41:39.876)
CHECKPOINT;
CHECKPOINT
Time: 25235.641 ms (00:25.236)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.670 ms (00:05.006)
COPY t_uuid_serial FROM '/srv/dev/github/ancoron/pg-uuid-test/data.serial.a.txt' WITH ( FORMAT text );
COPY 200000000
Time: 360743.053 ms (06:00.743)
CHECKPOINT;
CHECKPOINT
Time: 3806.264 ms (00:03.806)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5006.338 ms (00:05.006)
COPY t_uuid_ext FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.a.txt' WITH ( FORMAT text );
COPY 200000000
Time: 362321.035 ms (06:02.321)
CHECKPOINT;
CHECKPOINT
Time: 3407.506 ms (00:03.408)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5009.477 ms (00:05.009)
COPY t_uuid_v1 FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.a.txt' WITH ( FORMAT text );
COPY 200000000
Time: 320795.305 ms (05:20.795)
CHECKPOINT;
CHECKPOINT
Time: 4012.433 ms (00:04.012)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.982 ms (00:05.006)
-- ANALYZE...
ANALYZE VERBOSE t_uuid;
psql:/tmp/tmp.t7yxnLer28:28: INFO: analyzing "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:28: INFO: "t_uuid": scanned 150000 of 1081082 pages, containing 27750000 live rows and 0 dead rows; 150000 rows in sample, 200000170 estimated total rows
ANALYZE
Time: 37872.384 ms (00:37.872)
ANALYZE VERBOSE t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:29: INFO: analyzing "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:29: INFO: "t_uuid_serial": scanned 150000 of 1081082 pages, containing 27750000 live rows and 0 dead rows; 150000 rows in sample, 200000170 estimated total rows
ANALYZE
Time: 37463.966 ms (00:37.464)
ANALYZE VERBOSE t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:30: INFO: analyzing "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:30: INFO: "t_uuid_ext": scanned 150000 of 1081082 pages, containing 27750000 live rows and 0 dead rows; 150000 rows in sample, 200000170 estimated total rows
ANALYZE
Time: 37531.453 ms (00:37.531)
ANALYZE VERBOSE t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:31: INFO: analyzing "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:31: INFO: "t_uuid_v1": scanned 150000 of 1081082 pages, containing 27749830 live rows and 0 dead rows; 150000 rows in sample, 199998945 estimated total rows
ANALYZE
Time: 26091.001 ms (00:26.091)
CHECKPOINT;
CHECKPOINT
Time: 300.717 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.425 ms (00:05.005)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+-----------------+----------+----------
t_uuid | t_uuid_pkey | 2472 MiB (32 %) | 7828.484 | 8445.953
t_uuid_ext | idx_uuid_ext | 660 MiB (11 %) | 6016.094 | 8445.953
t_uuid_serial | t_uuid_serial_pkey | 660 MiB (11 %) | 6016.094 | 8445.953
t_uuid_v1 | t_uuid_v1_pkey | 660 MiB (11 %) | 6016.094 | 8445.953
(4 rows)
Time: 387.411 ms
-- DELETE first 20M rows...
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid WHERE uuid_v1_timestamp(id) < '2018-08-04 06:16:53.124261+02';
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid (cost=0.00..4081084.64 rows=66666725 width=6) (actual time=78898.778..78898.778 rows=0 loops=1)
Buffers: shared hit=7000032 read=1081050 dirtied=936363 written=898560
I/O Timings: read=47547.983 write=4261.954
-> Seq Scan on public.t_uuid (cost=0.00..4081084.64 rows=66666725 width=6) (actual time=0.235..73664.810 rows=7000000 loops=1)
Output: ctid
Filter: (uuid_v1_timestamp(t_uuid.id) < '2018-08-04 06:16:53.124261+02'::timestamp with time zone)
Rows Removed by Filter: 193000000
Buffers: shared hit=32 read=1081050 dirtied=931082 written=898560
I/O Timings: read=47547.983 write=4261.954
Planning Time: 0.801 ms
Execution Time: 78898.848 ms
(11 rows)
Time: 78906.383 ms (01:18.906)
CHECKPOINT;
CHECKPOINT
Time: 1001.681 ms (00:01.002)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.619 ms (00:05.005)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_serial WHERE id < '1e8979d3-769b-1ba3-b10d-e03f49d672fb';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_serial (cost=0.57..200844.08 rows=7400006 width=6) (actual time=6976.195..6976.195 rows=0 loops=1)
Buffers: shared hit=7037627 read=64661 dirtied=37838
I/O Timings: read=347.544
-> Index Scan using t_uuid_serial_pkey on public.t_uuid_serial (cost=0.57..200844.08 rows=7400006 width=6) (actual time=5.308..1709.849 rows=6999999 loops=1)
Output: ctid
Index Cond: (t_uuid_serial.id < '1e8979d3-769b-1ba3-b10d-e03f49d672fb'::uuid)
Buffers: shared hit=37628 read=64661 dirtied=32548
I/O Timings: read=347.544
Planning Time: 1.152 ms
Execution Time: 6976.230 ms
(10 rows)
Time: 7054.232 ms (00:07.054)
CHECKPOINT;
CHECKPOINT
Time: 1202.235 ms (00:01.202)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5002.399 ms (00:05.002)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_ext WHERE id <* '377a9e7b-979d-11e8-b5d4-e03f49d672fb';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_ext (cost=0.57..4480.47 rows=4000 width=6) (actual time=6944.515..6944.515 rows=0 loops=1)
Buffers: shared hit=7054966 read=64661 dirtied=37838
I/O Timings: read=351.216
-> Index Scan using idx_uuid_ext on public.t_uuid_ext (cost=0.57..4480.47 rows=4000 width=6) (actual time=0.553..1736.594 rows=7000000 loops=1)
Output: ctid
Index Cond: (t_uuid_ext.id <* '377a9e7b-979d-11e8-b5d4-e03f49d672fb'::uuid)
Buffers: shared hit=54966 read=64661 dirtied=32590
I/O Timings: read=351.216
Planning Time: 1.416 ms
Execution Time: 6949.827 ms
(10 rows)
Time: 7018.438 ms (00:07.018)
CHECKPOINT;
CHECKPOINT
Time: 1201.928 ms (00:01.202)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.110 ms (00:05.004)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_v1 WHERE id < '377a9e7b-979d-11e8-b5d4-e03f49d672fb';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_v1 (cost=0.57..189986.31 rows=6999962 width=6) (actual time=6921.011..6921.011 rows=0 loops=1)
Buffers: shared hit=7054967 read=64660 dirtied=37838
I/O Timings: read=344.154
-> Index Scan using t_uuid_v1_pkey on public.t_uuid_v1 (cost=0.57..189986.31 rows=6999962 width=6) (actual time=5.125..1702.851 rows=7000000 loops=1)
Output: ctid
Index Cond: (t_uuid_v1.id < '377a9e7b-979d-11e8-b5d4-e03f49d672fb'::uuid_v1)
Buffers: shared hit=54967 read=64660 dirtied=32555
I/O Timings: read=344.154
Planning Time: 1.202 ms
Execution Time: 6921.047 ms
(10 rows)
Time: 6986.633 ms (00:06.987)
CHECKPOINT;
CHECKPOINT
Time: 1202.071 ms (00:01.202)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.614 ms (00:05.006)
-- ANALYZE...
ANALYZE VERBOSE t_uuid;
psql:/tmp/tmp.t7yxnLer28:57: INFO: analyzing "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:57: INFO: "t_uuid": scanned 150000 of 1081082 pages, containing 26766355 live rows and 983645 dead rows; 150000 rows in sample, 192910831 estimated total rows
ANALYZE
Time: 2554.076 ms (00:02.554)
ANALYZE VERBOSE t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:58: INFO: analyzing "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:58: INFO: "t_uuid_serial": scanned 150000 of 1081082 pages, containing 26780430 live rows and 969400 dead rows; 150000 rows in sample, 193012272 estimated total rows
ANALYZE
Time: 33504.563 ms (00:33.505)
ANALYZE VERBOSE t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:59: INFO: analyzing "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:59: INFO: "t_uuid_ext": scanned 150000 of 1081082 pages, containing 26788000 live rows and 962000 dead rows; 150000 rows in sample, 193066831 estimated total rows
ANALYZE
Time: 35432.534 ms (00:35.433)
ANALYZE VERBOSE t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:60: INFO: analyzing "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:60: INFO: "t_uuid_v1": scanned 150000 of 1081082 pages, containing 26788000 live rows and 962000 dead rows; 150000 rows in sample, 193066831 estimated total rows
ANALYZE
Time: 32898.973 ms (00:32.899)
CHECKPOINT;
CHECKPOINT
Time: 400.847 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.781 ms (00:05.005)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+-----------------+----------+----------
t_uuid | t_uuid_pkey | 2662 MiB (34 %) | 7828.484 | 8445.953
t_uuid_ext | idx_uuid_ext | 845 MiB (14 %) | 6016.094 | 8445.953
t_uuid_serial | t_uuid_serial_pkey | 847 MiB (14 %) | 6016.094 | 8445.953
t_uuid_v1 | t_uuid_v1_pkey | 845 MiB (14 %) | 6016.094 | 8445.953
(4 rows)
Time: 256.496 ms
VACUUM (VERBOSE, ANALYZE) t_uuid;
psql:/tmp/tmp.t7yxnLer28:66: INFO: vacuuming "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:66: INFO: scanned index "t_uuid_pkey" to remove 7000000 row versions
DETAIL: CPU: user: 55.69 s, system: 18.89 s, elapsed: 214.25 s
psql:/tmp/tmp.t7yxnLer28:66: INFO: "t_uuid": removed 7000000 row versions in 37838 pages
DETAIL: CPU: user: 0.09 s, system: 0.02 s, elapsed: 0.81 s
psql:/tmp/tmp.t7yxnLer28:66: INFO: index "t_uuid_pkey" now contains 193000000 row versions in 1002046 pages
DETAIL: 7000000 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:66: INFO: "t_uuid": found 7000000 removable, 193000000 nonremovable row versions in 1081082 out of 1081082 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220005
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 74.03 s, system: 28.76 s, elapsed: 294.54 s.
psql:/tmp/tmp.t7yxnLer28:66: INFO: analyzing "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:66: INFO: "t_uuid": scanned 150000 of 1081082 pages, containing 26783560 live rows and 0 dead rows; 150000 rows in sample, 193034831 estimated total rows
VACUUM
Time: 296490.419 ms (04:56.490)
CHECKPOINT;
CHECKPOINT
Time: 1303.946 ms (00:01.304)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.673 ms (00:05.005)
VACUUM (VERBOSE, ANALYZE) t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:70: INFO: vacuuming "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:70: INFO: scanned index "t_uuid_serial_pkey" to remove 6999999 row versions
DETAIL: CPU: user: 10.02 s, system: 2.38 s, elapsed: 13.62 s
psql:/tmp/tmp.t7yxnLer28:70: INFO: "t_uuid_serial": removed 6999999 row versions in 37838 pages
DETAIL: CPU: user: 0.08 s, system: 0.00 s, elapsed: 0.09 s
psql:/tmp/tmp.t7yxnLer28:70: INFO: index "t_uuid_serial_pkey" now contains 193000001 row versions in 770060 pages
DETAIL: 6999999 index row versions were removed.
26819 index pages have been deleted, 0 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:70: INFO: "t_uuid_serial": found 6999999 removable, 193000001 nonremovable row versions in 1081082 out of 1081082 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220006
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 31.34 s, system: 11.45 s, elapsed: 84.23 s.
psql:/tmp/tmp.t7yxnLer28:70: INFO: analyzing "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:70: INFO: "t_uuid_serial": scanned 150000 of 1081082 pages, containing 26806885 live rows and 0 dead rows; 150000 rows in sample, 193202939 estimated total rows
VACUUM
Time: 97587.985 ms (01:37.588)
CHECKPOINT;
CHECKPOINT
Time: 801.320 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5001.661 ms (00:05.002)
VACUUM (VERBOSE, ANALYZE) t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:74: INFO: vacuuming "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:74: INFO: scanned index "idx_uuid_ext" to remove 7000000 row versions
DETAIL: CPU: user: 10.22 s, system: 2.43 s, elapsed: 13.68 s
psql:/tmp/tmp.t7yxnLer28:74: INFO: "t_uuid_ext": removed 7000000 row versions in 37838 pages
DETAIL: CPU: user: 0.08 s, system: 0.00 s, elapsed: 0.16 s
psql:/tmp/tmp.t7yxnLer28:74: INFO: index "idx_uuid_ext" now contains 193000000 row versions in 770060 pages
DETAIL: 7000000 index row versions were removed.
26819 index pages have been deleted, 0 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:74: INFO: "t_uuid_ext": found 7000000 removable, 193000000 nonremovable row versions in 1081082 out of 1081082 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220007
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 30.04 s, system: 10.09 s, elapsed: 74.58 s.
psql:/tmp/tmp.t7yxnLer28:74: INFO: analyzing "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:74: INFO: "t_uuid_ext": scanned 150000 of 1081082 pages, containing 26787445 live rows and 0 dead rows; 150000 rows in sample, 193062831 estimated total rows
VACUUM
Time: 86050.850 ms (01:26.051)
CHECKPOINT;
CHECKPOINT
Time: 901.531 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.610 ms (00:05.006)
VACUUM (VERBOSE, ANALYZE) t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:78: INFO: vacuuming "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:78: INFO: scanned index "t_uuid_v1_pkey" to remove 7000000 row versions
DETAIL: CPU: user: 9.49 s, system: 1.55 s, elapsed: 12.07 s
psql:/tmp/tmp.t7yxnLer28:78: INFO: "t_uuid_v1": removed 7000000 row versions in 37838 pages
DETAIL: CPU: user: 0.09 s, system: 0.00 s, elapsed: 0.16 s
psql:/tmp/tmp.t7yxnLer28:78: INFO: index "t_uuid_v1_pkey" now contains 193000000 row versions in 770060 pages
DETAIL: 7000000 index row versions were removed.
26819 index pages have been deleted, 0 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:78: INFO: "t_uuid_v1": found 7000000 removable, 193000000 nonremovable row versions in 1081082 out of 1081082 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220008
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 29.22 s, system: 9.54 s, elapsed: 70.41 s.
psql:/tmp/tmp.t7yxnLer28:78: INFO: analyzing "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:78: INFO: "t_uuid_v1": scanned 150000 of 1081082 pages, containing 26773015 live rows and 0 dead rows; 150000 rows in sample, 192958831 estimated total rows
VACUUM
Time: 76356.344 ms (01:16.356)
CHECKPOINT;
CHECKPOINT
Time: 1001.684 ms (00:01.002)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.175 ms (00:05.004)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+-----------------+----------+----------
t_uuid | t_uuid_pkey | 2660 MiB (34 %) | 7828.484 | 8445.953
t_uuid_ext | idx_uuid_ext | 847 MiB (14 %) | 6016.094 | 8445.953
t_uuid_serial | t_uuid_serial_pkey | 847 MiB (14 %) | 6016.094 | 8445.953
t_uuid_v1 | t_uuid_v1_pkey | 847 MiB (14 %) | 6016.094 | 8445.953
(4 rows)
Time: 257.550 ms
-- DELETE first 20M rows...
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid WHERE uuid_v1_timestamp(id) < '2018-08-12 16:07:29.502713+02';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid (cost=0.00..3976604.48 rows=64344944 width=6) (actual time=29375.486..29375.486 rows=0 loops=1)
Buffers: shared hit=5064925 read=1043183 dirtied=27029 written=24
I/O Timings: read=12451.795 write=0.313
-> Seq Scan on public.t_uuid (cost=0.00..3976604.48 rows=64344944 width=6) (actual time=30.618..25733.233 rows=4999998 loops=1)
Output: ctid
Filter: (uuid_v1_timestamp(t_uuid.id) < '2018-08-12 16:07:29.502713+02'::timestamp with time zone)
Rows Removed by Filter: 188000002
Buffers: shared hit=37899 read=1043183 written=24
I/O Timings: read=12451.795 write=0.313
Planning Time: 0.174 ms
Execution Time: 29375.511 ms
(11 rows)
Time: 29378.067 ms (00:29.378)
CHECKPOINT;
CHECKPOINT
Time: 701.270 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5001.990 ms (00:05.002)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_serial WHERE id < '1e89e390-c87b-1404-95bd-e03f49667533';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_serial (cost=0.57..132732.15 rows=4830073 width=6) (actual time=4816.148..4816.148 rows=0 loops=1)
Buffers: shared hit=5052764 read=46185 dirtied=27029
I/O Timings: read=264.166
-> Index Scan using t_uuid_serial_pkey on public.t_uuid_serial (cost=0.57..132732.15 rows=4830073 width=6) (actual time=0.020..1137.500 rows=4999999 loops=1)
Output: ctid
Index Cond: (t_uuid_serial.id < '1e89e390-c87b-1404-95bd-e03f49667533'::uuid)
Buffers: shared hit=25737 read=46185
I/O Timings: read=264.166
Planning Time: 0.482 ms
Execution Time: 4816.190 ms
(10 rows)
Time: 4897.380 ms (00:04.897)
CHECKPOINT;
CHECKPOINT
Time: 701.331 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.176 ms (00:05.003)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_ext WHERE id <~ '2018-08-12 16:07:29.502713+02';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_ext (cost=0.57..4326.24 rows=3861 width=6) (actual time=4803.523..4803.523 rows=0 loops=1)
Buffers: shared hit=5084069 read=46185 dirtied=27029
I/O Timings: read=238.174
-> Index Scan using idx_uuid_ext on public.t_uuid_ext (cost=0.57..4326.24 rows=3861 width=6) (actual time=0.020..1119.440 rows=4999998 loops=1)
Output: ctid
Index Cond: (t_uuid_ext.id <~ '2018-08-12 16:07:29.502713+02'::timestamp with time zone)
Buffers: shared hit=57043 read=46185
I/O Timings: read=238.174
Planning Time: 1.732 ms
Execution Time: 4803.578 ms
(10 rows)
Time: 4890.844 ms (00:04.891)
CHECKPOINT;
CHECKPOINT
Time: 701.385 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.658 ms (00:05.006)
EXPLAIN (ANALYZE, BUFFERS, VERBOSE) DELETE FROM t_uuid_v1 WHERE id < '0c82dbba-9e39-11e8-aeeb-e03f49667533';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Delete on public.t_uuid_v1 (cost=0.57..143234.89 rows=5209887 width=6) (actual time=4806.230..4806.230 rows=0 loops=1)
Buffers: shared hit=5084069 read=46185 dirtied=27029
I/O Timings: read=248.417
-> Index Scan using t_uuid_v1_pkey on public.t_uuid_v1 (cost=0.57..143234.89 rows=5209887 width=6) (actual time=0.023..1121.336 rows=4999998 loops=1)
Output: ctid
Index Cond: (t_uuid_v1.id < '0c82dbba-9e39-11e8-aeeb-e03f49667533'::uuid_v1)
Buffers: shared hit=57043 read=46185
I/O Timings: read=248.417
Planning Time: 0.497 ms
Execution Time: 4806.275 ms
(10 rows)
Time: 4885.595 ms (00:04.886)
CHECKPOINT;
CHECKPOINT
Time: 701.157 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.155 ms (00:05.005)
-- INSERT additional 20M rows...
COPY t_uuid FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.b.txt' WITH ( FORMAT text );
COPY 17000000
Time: 651976.685 ms (10:51.977)
CHECKPOINT;
CHECKPOINT
Time: 26637.761 ms (00:26.638)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.759 ms (00:05.004)
COPY t_uuid_serial FROM '/srv/dev/github/ancoron/pg-uuid-test/data.serial.b.txt' WITH ( FORMAT text );
COPY 17000000
Time: 31094.804 ms (00:31.095)
CHECKPOINT;
CHECKPOINT
Time: 1702.569 ms (00:01.703)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.680 ms (00:05.006)
COPY t_uuid_ext FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.b.txt' WITH ( FORMAT text );
COPY 17000000
Time: 31129.127 ms (00:31.129)
CHECKPOINT;
CHECKPOINT
Time: 1802.881 ms (00:01.803)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.721 ms (00:05.004)
COPY t_uuid_v1 FROM '/srv/dev/github/ancoron/pg-uuid-test/data.v1.b.txt' WITH ( FORMAT text );
COPY 17000000
Time: 27497.356 ms (00:27.497)
CHECKPOINT;
CHECKPOINT
Time: 1802.897 ms (00:01.803)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.365 ms (00:05.004)
-- ANALYZE...
ANALYZE VERBOSE t_uuid;
psql:/tmp/tmp.t7yxnLer28:122: INFO: analyzing "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:122: INFO: "t_uuid": scanned 150000 of 1135136 pages, containing 27096025 live rows and 653975 dead rows; 150000 rows in sample, 205051156 estimated total rows
ANALYZE
Time: 26345.195 ms (00:26.345)
ANALYZE VERBOSE t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:123: INFO: analyzing "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:123: INFO: "t_uuid_serial": scanned 150000 of 1135136 pages, containing 27081590 live rows and 668251 dead rows; 150000 rows in sample, 204941918 estimated total rows
ANALYZE
Time: 23655.392 ms (00:23.655)
ANALYZE VERBOSE t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:124: INFO: analyzing "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:124: INFO: "t_uuid_ext": scanned 150000 of 1135136 pages, containing 27097690 live rows and 652310 dead rows; 150000 rows in sample, 205063756 estimated total rows
ANALYZE
Time: 22408.195 ms (00:22.408)
ANALYZE VERBOSE t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:125: INFO: analyzing "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:125: INFO: "t_uuid_v1": scanned 150000 of 1135136 pages, containing 27080855 live rows and 669145 dead rows; 150000 rows in sample, 204936356 estimated total rows
ANALYZE
Time: 23076.556 ms (00:23.077)
CHECKPOINT;
CHECKPOINT
Time: 200.526 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.425 ms (00:05.005)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+-----------------+----------+----------
t_uuid | t_uuid_pkey | 2754 MiB (33 %) | 8245.375 | 8868.250
t_uuid_ext | idx_uuid_ext | 1036 MiB (16 %) | 6527.469 | 8868.250
t_uuid_serial | t_uuid_serial_pkey | 1039 MiB (16 %) | 6527.469 | 8868.250
t_uuid_v1 | t_uuid_v1_pkey | 1039 MiB (16 %) | 6527.469 | 8868.250
(4 rows)
Time: 345.171 ms
VACUUM (VERBOSE, ANALYZE) t_uuid;
psql:/tmp/tmp.t7yxnLer28:131: INFO: vacuuming "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:131: INFO: scanned index "t_uuid_pkey" to remove 4999998 row versions
DETAIL: CPU: user: 49.10 s, system: 12.45 s, elapsed: 183.30 s
psql:/tmp/tmp.t7yxnLer28:131: INFO: "t_uuid": removed 4999998 row versions in 27028 pages
DETAIL: CPU: user: 0.27 s, system: 0.42 s, elapsed: 3.79 s
psql:/tmp/tmp.t7yxnLer28:131: INFO: index "t_uuid_pkey" now contains 205000002 row versions in 1055408 pages
DETAIL: 4999998 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:131: INFO: "t_uuid": found 4999998 removable, 17000042 nonremovable row versions in 118920 out of 1135136 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220021
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 52.06 s, system: 14.03 s, elapsed: 197.10 s.
psql:/tmp/tmp.t7yxnLer28:131: INFO: analyzing "public.t_uuid"
psql:/tmp/tmp.t7yxnLer28:131: INFO: "t_uuid": scanned 150000 of 1135136 pages, containing 27083655 live rows and 0 dead rows; 150000 rows in sample, 204957545 estimated total rows
VACUUM
Time: 217983.576 ms (03:37.984)
CHECKPOINT;
CHECKPOINT
Time: 2403.808 ms (00:02.404)
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5000.602 ms (00:05.001)
VACUUM (VERBOSE, ANALYZE) t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:135: INFO: vacuuming "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:135: INFO: scanned index "t_uuid_serial_pkey" to remove 4999999 row versions
DETAIL: CPU: user: 10.39 s, system: 2.37 s, elapsed: 14.18 s
psql:/tmp/tmp.t7yxnLer28:135: INFO: "t_uuid_serial": removed 4999999 row versions in 27028 pages
DETAIL: CPU: user: 0.35 s, system: 0.30 s, elapsed: 2.63 s
psql:/tmp/tmp.t7yxnLer28:135: INFO: index "t_uuid_serial_pkey" now contains 205000002 row versions in 835516 pages
DETAIL: 4999999 index row versions were removed.
46108 index pages have been deleted, 26950 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:135: INFO: "t_uuid_serial": found 4999999 removable, 17000042 nonremovable row versions in 118920 out of 1135136 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220022
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 13.27 s, system: 3.84 s, elapsed: 26.09 s.
psql:/tmp/tmp.t7yxnLer28:135: INFO: analyzing "public.t_uuid_serial"
psql:/tmp/tmp.t7yxnLer28:135: INFO: "t_uuid_serial": scanned 150000 of 1135136 pages, containing 27084925 live rows and 0 dead rows; 150000 rows in sample, 204967156 estimated total rows
VACUUM
Time: 48780.509 ms (00:48.781)
CHECKPOINT;
CHECKPOINT
Time: 500.988 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.985 ms (00:05.004)
VACUUM (VERBOSE, ANALYZE) t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:139: INFO: vacuuming "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:139: INFO: scanned index "idx_uuid_ext" to remove 4999998 row versions
DETAIL: CPU: user: 10.38 s, system: 2.46 s, elapsed: 14.07 s
psql:/tmp/tmp.t7yxnLer28:139: INFO: "t_uuid_ext": removed 4999998 row versions in 27028 pages
DETAIL: CPU: user: 0.23 s, system: 0.38 s, elapsed: 2.55 s
psql:/tmp/tmp.t7yxnLer28:139: INFO: index "idx_uuid_ext" now contains 205000002 row versions in 835516 pages
DETAIL: 4999998 index row versions were removed.
46108 index pages have been deleted, 26950 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:139: INFO: "t_uuid_ext": found 4999998 removable, 17000042 nonremovable row versions in 118920 out of 1135136 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220023
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 13.05 s, system: 4.01 s, elapsed: 25.44 s.
psql:/tmp/tmp.t7yxnLer28:139: INFO: analyzing "public.t_uuid_ext"
psql:/tmp/tmp.t7yxnLer28:139: INFO: "t_uuid_ext": scanned 150000 of 1135136 pages, containing 27104905 live rows and 0 dead rows; 150000 rows in sample, 205118356 estimated total rows
VACUUM
Time: 48472.868 ms (00:48.473)
CHECKPOINT;
CHECKPOINT
Time: 501.038 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5002.189 ms (00:05.002)
VACUUM (VERBOSE, ANALYZE) t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:143: INFO: vacuuming "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:143: INFO: scanned index "t_uuid_v1_pkey" to remove 4999998 row versions
DETAIL: CPU: user: 10.13 s, system: 2.59 s, elapsed: 14.03 s
psql:/tmp/tmp.t7yxnLer28:143: INFO: "t_uuid_v1": removed 4999998 row versions in 27028 pages
DETAIL: CPU: user: 0.22 s, system: 0.18 s, elapsed: 2.32 s
psql:/tmp/tmp.t7yxnLer28:143: INFO: index "t_uuid_v1_pkey" now contains 205000002 row versions in 835516 pages
DETAIL: 4999998 index row versions were removed.
46108 index pages have been deleted, 26950 are currently reusable.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
psql:/tmp/tmp.t7yxnLer28:143: INFO: "t_uuid_v1": found 4999998 removable, 17000042 nonremovable row versions in 118920 out of 1135136 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 1220024
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins, 0 frozen pages.
0 pages are entirely empty.
CPU: user: 12.62 s, system: 3.90 s, elapsed: 24.30 s.
psql:/tmp/tmp.t7yxnLer28:143: INFO: analyzing "public.t_uuid_v1"
psql:/tmp/tmp.t7yxnLer28:143: INFO: "t_uuid_v1": scanned 150000 of 1135136 pages, containing 27085110 live rows and 0 dead rows; 150000 rows in sample, 204968556 estimated total rows
VACUUM
Time: 47442.738 ms (00:47.443)
CHECKPOINT;
CHECKPOINT
Time: 500.817 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.826 ms (00:05.004)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+-----------------+----------+----------
t_uuid | t_uuid_pkey | 2755 MiB (33 %) | 8245.375 | 8868.250
t_uuid_ext | idx_uuid_ext | 1037 MiB (16 %) | 6527.469 | 8868.250
t_uuid_serial | t_uuid_serial_pkey | 1037 MiB (16 %) | 6527.469 | 8868.250
t_uuid_v1 | t_uuid_v1_pkey | 1037 MiB (16 %) | 6527.469 | 8868.250
(4 rows)
Time: 259.391 ms
REINDEX (VERBOSE) TABLE t_uuid;
psql:/tmp/tmp.t7yxnLer28:150: INFO: index "t_uuid_pkey" was reindexed
DETAIL: CPU: user: 62.03 s, system: 10.24 s, elapsed: 91.83 s
REINDEX
Time: 92387.364 ms (01:32.387)
CHECKPOINT;
CHECKPOINT
Time: 300.715 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5003.770 ms (00:05.004)
REINDEX (VERBOSE) TABLE t_uuid_serial;
psql:/tmp/tmp.t7yxnLer28:154: INFO: index "t_uuid_serial_pkey" was reindexed
DETAIL: CPU: user: 45.22 s, system: 9.27 s, elapsed: 72.42 s
REINDEX
Time: 72567.831 ms (01:12.568)
CHECKPOINT;
CHECKPOINT
Time: 200.472 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5004.477 ms (00:05.004)
REINDEX (VERBOSE) TABLE t_uuid_ext;
psql:/tmp/tmp.t7yxnLer28:158: INFO: index "idx_uuid_ext" was reindexed
DETAIL: CPU: user: 57.99 s, system: 9.35 s, elapsed: 78.95 s
REINDEX
Time: 79104.090 ms (01:19.104)
CHECKPOINT;
CHECKPOINT
Time: 300.645 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5001.869 ms (00:05.002)
REINDEX (VERBOSE) TABLE t_uuid_v1;
psql:/tmp/tmp.t7yxnLer28:162: INFO: index "t_uuid_v1_pkey" was reindexed
DETAIL: CPU: user: 55.72 s, system: 9.48 s, elapsed: 78.39 s
REINDEX
Time: 78544.865 ms (01:18.545)
CHECKPOINT;
CHECKPOINT
Time: 300.691 ms
SELECT pg_sleep(5);
pg_sleep
----------
(1 row)
Time: 5005.560 ms (00:05.006)
SELECT table_name, index_name, concat(bloat_mb, ' MiB (', bloat_pct, ' %)') AS bloat, index_mb, table_mb FROM view_index_bloat WHERE table_name LIKE 't_uuid%' ORDER BY table_name, index_name DESC;
table_name | index_name | bloat | index_mb | table_mb
---------------+--------------------+----------------+----------+----------
t_uuid | t_uuid_pkey | 676 MiB (11 %) | 6166.664 | 8868.250
t_uuid_ext | idx_uuid_ext | 676 MiB (11 %) | 6166.664 | 8868.250
t_uuid_serial | t_uuid_serial_pkey | 676 MiB (11 %) | 6166.664 | 8868.250
t_uuid_v1 | t_uuid_v1_pkey | 676 MiB (11 %) | 6166.664 | 8868.250
(4 rows)
Time: 245.284 ms
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment