Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1hSpc2-0005w1-Cm for pgsql-general@arkaria.postgresql.org; Mon, 20 May 2019 21:14:26 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1hSpbz-0006ap-Vl for pgsql-general@arkaria.postgresql.org; Mon, 20 May 2019 21:14:23 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1hSpbz-0006Zi-It for pgsql-general@lists.postgresql.org; Mon, 20 May 2019 21:14:23 +0000 Received: from mail-io1-xd42.google.com ([2607:f8b0:4864:20::d42]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1hSpbw-0001Gj-IR for pgsql-general@lists.postgresql.org; Mon, 20 May 2019 21:14:23 +0000 Received: by mail-io1-xd42.google.com with SMTP id e19so12240121iob.3 for ; Mon, 20 May 2019 14:14:19 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:subject:from:in-reply-to:date:cc:message-id:references :to; bh=MYYY4DiGI7i+zIY4IbXEnosY6OYL7141VGfTGYuGtiQ=; b=gh4vYr+88nXMdawIaKd8IBt/TxBTgQC/B2JwgItda1zwckVDQuMrwB+v8od2CDJ98F Uoyk/ZNPDJ0rEvVrAVQjOr3GWrk0mvJeNr2gXf3gAydXHcnNeo33RX3zZE4nQ0USGKj/ a3VeDZR4Sb8ARDzKBg6slIQRDe2dIW5FWlPjrAECrN+VjUQBiQPA8i+Duhy72+xAGruK vG89f9nKBKT+4pSX5LRLCc0/4fxodMmxWqEqCMlOFhmKrv7RX2L4PcReeXkB65gsq7hh nm1yGEfIHfMvrIZRekezqvu0ZUPf/eISahSq2FeJyC8SjOVYLsIyYl2ACLU/FJMh9H7Q lRnA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:subject:from:in-reply-to:date:cc :message-id:references:to; bh=MYYY4DiGI7i+zIY4IbXEnosY6OYL7141VGfTGYuGtiQ=; b=mvQK9gYIzcqUnJdh9vFzjVoT7+LfBGycTf4ZbR5ezZx0RLPeTGL3NrjdbjpFtZa2Ca iAuU1qn72baWiKBXHNTgp16DPkbTOszGYj8ojPtKqXx2lYAjErT4R1wmZ1qQH5yTqYJL 6J0uYQyoRrzFwauHXIoVgPIK1Gz7B/b8rvFL3BJx4pJCs++sLyUGINH2iIuFiSCssWrB JAzvmWyFLt4m2+F/K/8cVJu+8rNE8fK3820G8a0hfoVOINPJ9+JIYMswFwE35TUbd0Xn +nH475L6N/X8So0pb4utf8ut6Cz99TQjuXPxbYHeOvNKYKM6pBJd03bCI+G6pVqrPN8n gKyw== X-Gm-Message-State: APjAAAU0S3CfqrRXqIQHozwQQEaWBrsO0fpUEqfM/b2E00bRVyNvEVZO zz2dniomV6tT/lLk0ibAKVk= X-Google-Smtp-Source: APXvYqyzgBjfGzx3wg8JfZ6KOgRaz+ZFh8zY5GUqD/JKr4I3xcQUKCz64v8pI+OjjOqB40R/MzM+bQ== X-Received: by 2002:a6b:790a:: with SMTP id i10mr1623187iop.2.1558386858556; Mon, 20 May 2019 14:14:18 -0700 (PDT) Received: from [10.35.60.64] ([64.164.57.170]) by smtp.gmail.com with ESMTPSA id d75sm347217itd.10.2019.05.20.14.14.17 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Mon, 20 May 2019 14:14:17 -0700 (PDT) Content-Type: multipart/alternative; boundary="Apple-Mail=_0551F815-6DFB-4FF1-AF4E-5E070AC6F461" Mime-Version: 1.0 (Mac OS X Mail 9.3 \(3124\)) Subject: Re: Loading table with indexed jsonb field is stalling From: Will Hartung In-Reply-To: Date: Mon, 20 May 2019 14:14:16 -0700 Cc: Will Hartung , Tom Lane , pgsql-general@lists.postgresql.org Message-Id: <3A35A039-D8F5-4B40-9B41-42E70BEF2C2E@gmail.com> References: <20505.1558202555@sss.pgh.pa.us> <90835D2B-1FBA-4F26-8157-7C831C24B266@gmail.com> To: Adrian Klaver X-Mailer: Apple Mail (2.3124) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --Apple-Mail=_0551F815-6DFB-4FF1-AF4E-5E070AC6F461 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 > On May 20, 2019, at 11:13 AM, Adrian Klaver = wrote: > What do the below show: >=20 > 1) ps ax | grep postgres $ ps -ax | grep postgres 1171 ? S 0:04 /usr/lib/postgresql/10/bin/postgres -D = /var/lib/postgresql/10/main -c = config_file=3D/etc/postgresql/10/main/postgresql.conf 1420 ? Ds 0:21 postgres: 10/main: checkpointer process =20 1421 ? Ss 0:38 postgres: 10/main: writer process =20 1422 ? Ss 0:22 postgres: 10/main: wal writer process =20 1423 ? Ss 0:04 postgres: 10/main: autovacuum launcher = process =20 1424 ? Ss 0:04 postgres: 10/main: stats collector process =20= 1425 ? Ss 0:00 postgres: 10/main: bgworker: logical = replication launcher =20 15917 tty1 S 0:00 su - postgres 16300 ? Rs 10:39 postgres: 10/main: postgres willtest = 10.35.60.64(54594) COPY 16444 ? Ss 0:08 postgres: 10/main: autovacuum worker process = willtest waiting 16633 tty1 S+ 0:00 /usr/lib/postgresql/10/bin/psql 16641 ? Ss 0:00 postgres: 10/main: postgres postgres [local] = idle > 2) As superuser: > select * from pg_stat_activity ; datid | datname | pid | usesysid | usename | application_name | = client_addr | client_hostname | client_port | backend_start = | xact_start | query_start | = state_change | wait_event_type | wait_event | = state | backend_xid | backend_xmin | query = | backend_type =20 = -------+----------+-------+----------+----------+------------------+------= -------+-----------------+-------------+-------------------------------+--= -----------------------------+-------------------------------+------------= -------------------+-----------------+---------------------+--------+-----= --------+--------------+---------------------------------------+----------= ----------- | | 1425 | 10 | postgres | | = | | | 2019-05-17 12:00:17.659235-07 = | | | = | Activity | LogicalLauncherMain | = | | | | = background worker | | 1423 | | | | = | | | 2019-05-17 12:00:17.658936-07 = | | | = | Activity | AutoVacuumMain | = | | | | = autovacuum launcher 16384 | willtest | 16444 | | | | = | | | 2019-05-20 12:16:14.564982-07 = | 2019-05-20 12:16:14.641913-07 | 2019-05-20 12:16:14.641913-07 | = 2019-05-20 12:16:14.641914-07 | Lock | page | = active | 624 | 623 | autovacuum: ANALYZE = public.eis_entity | autovacuum worker 13051 | postgres | 16889 | 10 | postgres | psql | = | | -1 | 2019-05-20 13:44:50.84062-07 = | 2019-05-20 13:46:17.209382-07 | 2019-05-20 13:46:17.209382-07 | = 2019-05-20 13:46:17.209387-07 | | | = active | | 623 | select * from pg_stat_activity; = | client backend 16384 | willtest | 16300 | 10 | postgres | psql | = 10.35.60.64 | | 54594 | 2019-05-20 = 11:24:59.865383-07 | 2019-05-20 12:15:42.494372-07 | 2019-05-20 = 12:15:42.494372-07 | 2019-05-20 12:15:42.494378-07 | LWLock | = WALWriteLock | active | 623 | 612 | COPY = eis_entity FROM STDIN ; | client backend | | 1421 | | | | = | | | 2019-05-17 12:00:17.557683-07 = | | | = | Activity | BgWriterMain | = | | | | = background writer | | 1420 | | | | = | | | 2019-05-17 12:00:17.557992-07 = | | | = | | | = | | | | = checkpointer | | 1422 | | | | = | | | 2019-05-17 12:00:17.554268-07 = | | | = | | | = | | | | = walwriter (8 rows) It=E2=80=99s been running for about an hour and a half when I took = these. Also to note, I tried just loading the table with no indexes, and I was = getting a solid 22MB/s via iostat of just raw data load (just to proof = that I/O system, while certainly not extraordinary, was functional). Thanks. --Apple-Mail=_0551F815-6DFB-4FF1-AF4E-5E070AC6F461 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
On May 20, 2019, at 11:13 AM, Adrian Klaver <adrian.klaver@aklaver.com> wrote:

What do the below show:

1) ps ax | grep postgres

$ ps -ax | grep postgres
 1171 ?        S      = 0:04 /usr/lib/postgresql/10/bin/postgres -D = /var/lib/postgresql/10/main -c = config_file=3D/etc/postgresql/10/main/postgresql.conf
 1420 ?        Ds     0:21 = postgres: = 10/main: checkpointer process   
 1421 ?        Ss     0:38 = postgres: = 10/main: writer process   
 1422 ?        Ss     0:22 = postgres: = 10/main: wal writer process   
 1423 ?        Ss     0:04 = postgres: = 10/main: autovacuum launcher process   
 1424 ?        Ss     0:04 = postgres: = 10/main: stats collector process   
 1425 ?        Ss     0:00 = postgres: = 10/main: bgworker: logical replication launcher  =  
15917 tty1     S    =   0:00 su - postgres
16300 = ?        Rs    10:39 postgres: = 10/main: postgres willtest 10.35.60.64(54594) = COPY
16444 ?        Ss =     0:08 postgres: 10/main: autovacuum worker process =   willtest waiting
16633 = tty1     S+     0:00 /usr/lib/postgresql/10/bin/psql
16641 = ?        Ss     0:00 postgres: = 10/main: postgres postgres = [local] idle


2) As = superuser:
select * from pg_stat_activity = ;

 datid | datname  |  = pid  | usesysid | usename  | application_name | client_addr | = client_hostname | client_port |         = backend_start         |        =   xact_start           |    =       query_start          | =         state_change        =   | wait_event_type |     wait_event      = | state  | backend_xid | backend_xmin |         =         query           =       |    backend_type    =  
-------+----------+-------+----------+----------+--------------= ----+-------------+-----------------+-------------+-----------------------= --------+-------------------------------+-------------------------------+-= ------------------------------+-----------------+---------------------+---= -----+-------------+--------------+---------------------------------------= +---------------------
       |        =   |  1425 |       10 | postgres |    =               |       =       |               =   |             | 2019-05-17 = 12:00:17.659235-07 |               =                 |     =                     =       |               =                 | Activity  =       | LogicalLauncherMain |        = |             |        =       |               =                     =     | background worker
       |        =   |  1423 |          |    =       |              =     |             |   =               |       =       | 2019-05-17 12:00:17.658936-07 |     =                     =       |               =                 |     =                     =       | Activity        | = AutoVacuumMain      |        |   =           |          =     |                 =                     =   | autovacuum launcher
 16384 | willtest | 16444 |        =   |          |        =           |           =   |                 | =             | 2019-05-20 = 12:16:14.564982-07 | 2019-05-20 12:16:14.641913-07 | 2019-05-20 = 12:16:14.641913-07 | 2019-05-20 12:16:14.641914-07 | Lock    =         | page          =       | active |         624 |  =         623 | autovacuum: ANALYZE public.eis_entity = | autovacuum worker
 13051 | postgres | 16889 |       10 | = postgres | psql             |   =           |           =       |          -1 | 2019-05-20 = 13:44:50.84062-07  | 2019-05-20 13:46:17.209382-07 | 2019-05-20 = 13:46:17.209382-07 | 2019-05-20 13:46:17.209387-07 |     =             |         =             | active |     =         |          623 | = select * from pg_stat_activity;       | client = backend
 16384 | willtest | 16300 |   =     10 | postgres | psql           =   | 10.35.60.64 |               =   |       54594 | 2019-05-20 11:24:59.865383-07 | = 2019-05-20 12:15:42.494372-07 | 2019-05-20 12:15:42.494372-07 | = 2019-05-20 12:15:42.494378-07 | LWLock          = | WALWriteLock        | active |     =     623 |          612 | COPY  = eis_entity FROM STDIN ;         | client = backend
       |  =         |  1421 |        =   |          |        =           |           =   |                 | =             | 2019-05-17 = 12:00:17.557683-07 |               =                 |     =                     =       |               =                 | Activity  =       | BgWriterMain        |  =       |             |  =             |         =                     =           | background writer
       |        =   |  1420 |          |    =       |              =     |             |   =               |       =       | 2019-05-17 12:00:17.557992-07 |     =                     =       |               =                 |     =                     =       |               =   |                   =   |        |           =   |              |     =                     =               | = checkpointer
       |  =         |  1422 |        =   |          |        =           |           =   |                 | =             | 2019-05-17 = 12:00:17.554268-07 |               =                 |     =                     =       |               =                 |     =             |         =             |        | =             |        =       |               =                     =     | walwriter
(8 = rows)


It=E2=80=99s been running for about an hour and a = half when I took these.

Also to = note, I tried just loading the table with no indexes, and I was getting = a solid 22MB/s via iostat of just raw data load (just to proof that I/O = system, while certainly not extraordinary, was = functional).

Thanks.

= --Apple-Mail=_0551F815-6DFB-4FF1-AF4E-5E070AC6F461--