Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1bjS2e-0000oG-RY for pgsql-performance@arkaria.postgresql.org; Mon, 12 Sep 2016 14:17:01 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1bjS2e-0006Wi-E4 for pgsql-performance@arkaria.postgresql.org; Mon, 12 Sep 2016 14:17:00 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1bjS0x-0004e8-QG for pgsql-performance@postgresql.org; Mon, 12 Sep 2016 14:15:16 +0000 Received: from smtp5-g21.free.fr ([212.27.42.5]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1bjS0r-0001oS-MQ for pgsql-performance@postgresql.org; Mon, 12 Sep 2016 14:15:14 +0000 Received: from [192.168.1.17] (unknown [82.233.212.24]) by smtp5-g21.free.fr (Postfix) with ESMTP id 13D005FF8A for ; Mon, 12 Sep 2016 16:15:05 +0200 (CEST) Subject: Strange nested loop for an INSERT References: From: phb07 To: pgsql-performance@postgresql.org X-Forwarded-Message-Id: Message-ID: <1f22a3fa-dcc5-eeac-a708-7f10fada4674@apra.asso.fr> Date: Mon, 12 Sep 2016 16:15:05 +0200 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/mixed; boundary="------------36ADE0DF788E9D8EB5E1718C" X-Pg-Spam-Score: -2.6 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org This is a multi-part message in MIME format. --------------36ADE0DF788E9D8EB5E1718C Content-Type: multipart/alternative; boundary="------------621D5F6EA4E2787426A9CBCB" --------------621D5F6EA4E2787426A9CBCB Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit Hi all, One of my customer has reported to me a performance problem when using the E-Maj extension. It is a tool that allows to log updates performed on application tables, with the capability to cancel them. It is based on classic triggers with a log table associated to each application table. The performance issue, encountered in very specific situations, is the time needed to cancel a significant number of insertions. I have build a simple test case that reproduces the problem without the need of the extension. It just mimics the behaviour. Attached is the psql script and its result. The updates cancellation operation is done in 3 steps: - create a temporary table that holds each primary key to process - delete from the application table all rows that are no longer wished (previously inserted rows and new values of updated rows) - insert into the application table old rows we want to see again (previously deleted rows or old values of updated rows) The performance problem only concerns the third statement (the INSERT). I have run this test case in various recent postgres versions, from 9.1 to 9.6, with the same results. The problem appears when: - the application table has a primary key with a large number of columns (at least 7 columns in this test case) - and nothing but INSERT statements have been executed on the application table - and the log trigger remains active (to provide a nice feature: cancel the cancellation !) In the test case, I create a table and populate it with 100,000 rows, create the log mechanism, then insert 10,000 rows and finaly cancel these 10,000 rows insertion. The faulting INSERT statement has the following explain: explain analyze INSERT INTO t1 SELECT t1_log.c1,t1_log.c2,t1_log.c3,t1_log.c4,t1_log.c5,t1_log.c6,t1_log.c7,t1_log.c8 FROM t1_log, tmp WHERE t1_log.c1 = tmp.c1 AND t1_log.c2 = tmp.c2 AND t1_log.c3 = tmp.c3 AND t1_log.c4 = tmp.c4 AND t1_log.c5 = tmp.c5 AND t1_log.c6 = tmp.c6 AND t1_log.c7 = tmp.c7 AND t1_log.gid = tmp.gid AND t1_log.tuple = 'OLD'; QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ Insert on t1 (cost=0.00..890.90 rows=1 width=32) (actual time=434571.193..434571.193 rows=0 loops=1) -> Nested Loop (cost=0.00..890.90 rows=1 width=32) (actual time=434571.187..434571.187 rows=0 loops=1) Join Filter: ((t1_log.c1 = tmp.c1) AND (t1_log.c2 = tmp.c2) AND (t1_log.c3 = tmp.c3) AND (t1_log.c4 = tmp.c4) AND (t1_log.c5 = tmp.c5) AND (t1_log.c6 = tmp.c6) AND (t1_log.c7 = tmp.c7) AND (t1_log.gid = tmp.gid)) Rows Removed by Join Filter: 100000000 -> Index Scan using t1_log_gid_tuple_idx on t1_log (cost=0.00..423.22 rows=1 width=40) (actual time=0.378..69.594 rows=10000 loops=1) Index Cond: ((tuple)::text = 'OLD'::text) -> Seq Scan on tmp (cost=0.00..176.17 rows=9717 width=36) (actual time=0.006..21.678 rows=10000 loops=10000) Total runtime: 434571.243 ms (8 rows) Time: 434572,146 ms When the conditions are not exactly met, I get: explain analyze INSERT INTO t1 SELECT t1_log.c1,t1_log.c2,t1_log.c3,t1_log.c4,t1_log.c5,t1_log.c6,t1_log.c7,t1_log.c8 FROM t1_log, tmp WHERE t1_log.c1 = tmp.c1 AND t1_log.c2 = tmp.c2 AND t1_log.c3 = tmp.c3 AND t1_log.c4 = tmp.c4 AND t1_log.c5 = tmp.c5 AND t1_log.c6 = tmp.c6 AND t1_log.c7 = tmp.c7 AND t1_log.gid = tmp.gid AND t1_log.tuple = 'OLD'; QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Insert on t1 (cost=438.65..906.34 rows=1 width=32) (actual time=111.526..111.526 rows=0 loops=1) -> Hash Join (cost=438.65..906.34 rows=1 width=32) (actual time=111.521..111.521 rows=0 loops=1) Hash Cond: ((tmp.c1 = t1_log.c1) AND (tmp.c2 = t1_log.c2) AND (tmp.c3 = t1_log.c3) AND (tmp.c4 = t1_log.c4) AND (tmp.c5 = t1_log.c5) AND (tmp.c6 = t1_log.c6) AND (tmp.c7 = t1_log.c7) AND (tmp.gid = t1_log.gid)) -> Seq Scan on tmp (cost=0.00..176.17 rows=9717 width=36) (actual time=0.007..22.444 rows=10000 loops=1) -> Hash (cost=435.68..435.68 rows=99 width=40) (actual time=58.300..58.300 rows=10000 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 586kB -> Seq Scan on t1_log (cost=0.00..435.68 rows=99 width=40) (actual time=2.281..28.430 rows=10000 loops=1) Filter: ((tuple)::text = 'OLD'::text) Rows Removed by Filter: 10000 Total runtime: 111.603 ms (10 rows) So we get a nested loop in the bad case, instead of a hash join. But what looks strange to me in this nested loop is that the seq scan on the tmp table is executed 10000 times (once for each t1_log row) while no row matches the "t1_log.tuple = 'OLD'" condition, leading to a dramatic O^2 behaviour. I have also remarked that the problem disappears when: - an index is added on the temporary table, - or the log trigger is disabled, - or the enable_nestloop is disabled (bringing what is currenlty my favourite workaround), - or when I delete from pg_statistics the row concerning the "tuple" column of the log table (that presently says that there is nothing but 'NEW' values). Thanks by advance for any explanation about this case. Best regards. Philippe. --------------621D5F6EA4E2787426A9CBCB Content-Type: text/html; charset=windows-1252 Content-Transfer-Encoding: 8bit
Hi all,
 
One of my customer has reported to me a performance problem when using the E-Maj extension.
It is a tool that allows to log updates performed on application tables, with the capability to cancel them.
It is based on classic triggers with a log table associated to each application table.
The performance issue, encountered in very specific situations, is the time needed to cancel a significant number of insertions.
 
I have build a simple test case that reproduces the problem without the need of the extension. It just mimics the behaviour.
Attached is the psql script and its result.
 
The updates cancellation operation is done in 3 steps:
- create a temporary table that holds each primary key to process
- delete from the application table all rows that are no longer wished (previously inserted rows and new values of updated rows)
- insert into the application table old rows we want to see again (previously deleted rows or old values of updated rows)
 
The performance problem only concerns the third statement (the INSERT).
I have run this test case in various recent postgres versions, from 9.1 to 9.6, with the same results.
 
The problem appears when:
- the application table has a primary key with a large number of columns (at least 7 columns in this test case)
- and nothing but INSERT statements have been executed on the application table
- and the log trigger remains active (to provide a nice feature: cancel the cancellation !)
 
In the test case, I create a table and populate it with 100,000 rows, create the log mechanism, then insert 10,000 rows and finaly cancel these 10,000 rows insertion.
 
The faulting INSERT statement has the following explain:
explain analyze
INSERT INTO t1
  SELECT t1_log.c1,t1_log.c2,t1_log.c3,t1_log.c4,t1_log.c5,t1_log.c6,t1_log.c7,t1_log.c8
    FROM t1_log, tmp
    WHERE t1_log.c1 = tmp.c1 AND t1_log.c2 = tmp.c2 AND t1_log.c3 = tmp.c3
      AND t1_log.c4 = tmp.c4 AND t1_log.c5 = tmp.c5 AND t1_log.c6 = tmp.c6
      AND t1_log.c7 = tmp.c7
      AND t1_log.gid = tmp.gid AND t1_log.tuple = 'OLD';
                                                                                                          QUERY PLAN                                                                                                         
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Insert on t1  (cost=0.00..890.90 rows=1 width=32) (actual time=434571.193..434571.193 rows=0 loops=1)
   ->  Nested Loop  (cost=0.00..890.90 rows=1 width=32) (actual time=434571.187..434571.187 rows=0 loops=1)
         Join Filter: ((t1_log.c1 = tmp.c1) AND (t1_log.c2 = tmp.c2) AND (t1_log.c3 = tmp.c3) AND (t1_log.c4 = tmp.c4) AND (t1_log.c5 = tmp.c5) AND (t1_log.c6 = tmp.c6) AND (t1_log.c7 = tmp.c7) AND (t1_log.gid = tmp.gid))
         Rows Removed by Join Filter: 100000000
         ->  Index Scan using t1_log_gid_tuple_idx on t1_log  (cost=0.00..423.22 rows=1 width=40) (actual time=0.378..69.594 rows=10000 loops=1)
               Index Cond: ((tuple)::text = 'OLD'::text)
         ->  Seq Scan on tmp  (cost=0.00..176.17 rows=9717 width=36) (actual time=0.006..21.678 rows=10000 loops=10000)
Total runtime: 434571.243 ms
(8 rows)
 
Time: 434572,146 ms
 
When the conditions are not exactly met, I get:
explain analyze
INSERT INTO t1
  SELECT t1_log.c1,t1_log.c2,t1_log.c3,t1_log.c4,t1_log.c5,t1_log.c6,t1_log.c7,t1_log.c8
    FROM t1_log, tmp
    WHERE t1_log.c1 = tmp.c1 AND t1_log.c2 = tmp.c2 AND t1_log.c3 = tmp.c3
      AND t1_log.c4 = tmp.c4 AND t1_log.c5 = tmp.c5 AND t1_log.c6 = tmp.c6
      AND t1_log.c7 = tmp.c7
      AND t1_log.gid = tmp.gid AND t1_log.tuple = 'OLD';
                                                                                                         QUERY PLAN                                                                                                        
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Insert on t1  (cost=438.65..906.34 rows=1 width=32) (actual time=111.526..111.526 rows=0 loops=1)
   ->  Hash Join  (cost=438.65..906.34 rows=1 width=32) (actual time=111.521..111.521 rows=0 loops=1)
         Hash Cond: ((tmp.c1 = t1_log.c1) AND (tmp.c2 = t1_log.c2) AND (tmp.c3 = t1_log.c3) AND (tmp.c4 = t1_log.c4) AND (tmp.c5 = t1_log.c5) AND (tmp.c6 = t1_log.c6) AND (tmp.c7 = t1_log.c7) AND (tmp.gid = t1_log.gid))
         ->  Seq Scan on tmp  (cost=0.00..176.17 rows=9717 width=36) (actual time=0.007..22.444 rows=10000 loops=1)
         ->  Hash  (cost=435.68..435.68 rows=99 width=40) (actual time=58.300..58.300 rows=10000 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 586kB
               ->  Seq Scan on t1_log  (cost=0.00..435.68 rows=99 width=40) (actual time=2.281..28.430 rows=10000 loops=1)
                     Filter: ((tuple)::text = 'OLD'::text)
                     Rows Removed by Filter: 10000
Total runtime: 111.603 ms
(10 rows)
 
So we get a nested loop in the bad case, instead of a hash join.
But what looks strange to me in this nested loop is that the seq scan on the tmp table is executed 10000 times (once for each t1_log row) while no row matches the "t1_log.tuple = 'OLD'" condition, leading to a dramatic O^2 behaviour.
 
I have also remarked that the problem disappears when:
- an index is added on the temporary table,
- or the log trigger is disabled,
- or the enable_nestloop is disabled (bringing what is currenlty my favourite workaround),
- or when I delete from pg_statistics the row concerning the "tuple" column of the log table (that presently says that there is nothing but 'NEW' values).
 
Thanks by advance for any explanation about this case.
Best regards.
Philippe.
--------------621D5F6EA4E2787426A9CBCB-- --------------36ADE0DF788E9D8EB5E1718C Content-Type: application/octet-stream; name="test.sql" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="test.sql" XHRpbWluZyBvbgpzZWxlY3QgdmVyc2lvbigpOwpzZXQgd29ya19tZW0gPSAn NDBNQic7ClxzZXQgT05fRVJST1JfU1RPUAoKLS0gQ3JlYXRlIGFuZCBwb3B1 bGF0ZSB0aGUgdGFibGUKLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0KZHJvcCB0YWJsZSBpZiBleGlzdHMgdDEgY2FzY2FkZTsKY3JlYXRlIHRh YmxlIHQxICgKICBjMSAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGMyICAg IGludGVnZXIgICAgbm90IG51bGwsCiAgYzMgICAgaW50ZWdlciAgICBub3Qg bnVsbCwKICBjNCAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM1ICAgIGlu dGVnZXIgICAgbm90IG51bGwsCiAgYzYgICAgaW50ZWdlciAgICBub3QgbnVs bCwKICBjNyAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM4ICAgIGludGVn ZXIgICAgbm90IG51bGwsCnByaW1hcnkga2V5IChjMSxjMixjMyxjNCxjNSxj NixjNykgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIC0tIGxp bmUgdG8gY29tbWVudCBmb3IgNiBjb2x1bW5zIHBrZXkKLS1wcmltYXJ5IGtl eSAoYzEsYzIsYzMsYzQsYzUsYzYpICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgLS0gbGluZSB0byB1bmNvbW1lbnQgZm9yIDYgY29sdW1u cyBwa2V5Cik7Cmluc2VydCBpbnRvIHQxCiAgc2VsZWN0IGksIDIsIDMsIDQs IDUsIDYsIDcsIDgKICAgIGZyb20gZ2VuZXJhdGVfc2VyaWVzICgxLDEwMDAw MCkgaTsKCi0tIFNldHVwIHRoZSBsb2dnaW5nIG1lY2hhbmlzbQotLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0KZHJvcCB0YWJsZSBpZiBleGlzdHMg dDFfbG9nIGNhc2NhZGU7CmNyZWF0ZSB0YWJsZSB0MV9sb2cgKAogIGMxICAg IGludGVnZXIgICAgbm90IG51bGwsCiAgYzIgICAgaW50ZWdlciAgICBub3Qg bnVsbCwKICBjMyAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM0ICAgIGlu dGVnZXIgICAgbm90IG51bGwsCiAgYzUgICAgaW50ZWdlciAgICBub3QgbnVs bCwKICBjNiAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM3ICAgIGludGVn ZXIgICAgbm90IG51bGwsCiAgYzggICAgaW50ZWdlciAgICBub3QgbnVsbCwK ICB2ZXJiICB2YXJjaGFyKDMpIG5vdCBudWxsLCAKICB0dXBsZSB2YXJjaGFy KDMpIG5vdCBudWxsLAogIGdpZCAgIGJpZ3NlcmlhbCAgbm90IG51bGwKKTsK Y3JlYXRlIHVuaXF1ZSBpbmRleCBvbiB0MV9sb2coZ2lkLCB0dXBsZSk7CgpD UkVBVEUgT1IgUkVQTEFDRSBGVU5DVElPTiB0MV9sb2dfZm5jdCgpIFJFVFVS TlMgVFJJR0dFUiBBUyAkJApCRUdJTgogIElGIChUR19PUCA9ICdERUxFVEUn KSBUSEVOCiAgICBJTlNFUlQgSU5UTyB0MV9sb2cgU0VMRUNUIE9MRC4qLCAn REVMJywgJ09MRCc7CiAgICBSRVRVUk4gT0xEOwogIEVMU0lGIChUR19PUCA9 ICdVUERBVEUnKSBUSEVOCiAgICBJTlNFUlQgSU5UTyB0MV9sb2cgU0VMRUNU IE9MRC4qLCAnVVBEJywgJ09MRCc7CiAgICBJTlNFUlQgSU5UTyB0MV9sb2cg U0VMRUNUIE5FVy4qLCAnVVBEJywgJ05FVycsIGxhc3R2YWwoKTsKICAgIFJF VFVSTiBORVc7CiAgRUxTSUYgKFRHX09QID0gJ0lOU0VSVCcpIFRIRU4KICAg IElOU0VSVCBJTlRPIHQxX2xvZyBTRUxFQ1QgTkVXLiosICdJTlMnLCAnTkVX JzsKICAgIFJFVFVSTiBORVc7CiAgRU5EIElGOwogIFJFVFVSTiBOVUxMOwpF TkQ7CiQkIExBTkdVQUdFIHBscGdzcWwgU0VDVVJJVFkgREVGSU5FUjsKCkNS RUFURSBUUklHR0VSIHQxX2xvZ190cmcKICBBRlRFUiBJTlNFUlQgT1IgVVBE QVRFIE9SIERFTEVURSBPTiB0MQogIEZPUiBFQUNIIFJPVyBFWEVDVVRFIFBS T0NFRFVSRSB0MV9sb2dfZm5jdCgpOwoKLS0gR2VuZXJhdGUgdGFibGUgY2hh bmdlcwotLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tCmluc2VydCBpbnRvIHQx CiAgc2VsZWN0IGMxLCAwLCBjMywgYzQsIGM1LCBjNiwgYzcsIGM4CiAgICBm cm9tIHQxIHdoZXJlIGMxICUgMTAgPSAwOwoKLS0gMyBjYXNlcyB3aGVuIHRo ZSBwcm9ibGVtIGRpc2FwcGVhcnMKLS1kZWxldGUgZnJvbSB0MSB3aGVyZSBj MSA9IDE7Ci0tdXBkYXRlIHQxIHNldCBjMiA9IC0yIHdoZXJlIGMxID0gMjsK LS1hbHRlciB0YWJsZSB0MSBkaXNhYmxlIHRyaWdnZXIgdDFfbG9nX3RyZzsK CnZhY3V1bSBhbmFseXplOwoKc2VsZWN0IHR1cGxlLCBjb3VudCgqKSBmcm9t IHQxX2xvZyBncm91cCBieSAxOwpzZWxlY3QgKiBmcm9tIHBnX3N0YXRzIHdo ZXJlIHRhYmxlbmFtZSA9ICd0MV9sb2cnIGFuZCBhdHRuYW1lID0gJ3R1cGxl JzsKCi0tIENhbmNlbCB0YWJsZSdzIHVwZGF0ZXMKLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLQoKQ1JFQVRFIFRFTVAgVEFCTEUgdG1wIEFTCiAgU0VMRUNU IGMxLGMyLGMzLGM0LGM1LGM2LAogICAgICAgICBjNywgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAt LSBsaW5lIHRvIGNvbW1lbnQgZm9yIDYgY29sdW1ucyBwa2V5CiAgICAgICAg IG1pbihnaWQpIGFzIGdpZAogICAgRlJPTSB0MV9sb2cKICAgIFdIRVJFIGdp ZCA+IDAKICAgIEdST1VQIEJZIGMxLGMyLGMzLGM0LGM1LGM2CiAgICAgICAg ICAgICxjNyAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgIC0tIGxpbmUgdG8gY29tbWVudCBmb3IgNiBjb2x1 bW5zIHBrZXkKOwoKREVMRVRFIEZST00gT05MWSB0MSBVU0lORyB0bXAKICAg IFdIRVJFIHQxLmMxID0gdG1wLmMxIEFORCB0MS5jMiA9IHRtcC5jMiBBTkQg dDEuYzMgPSB0bXAuYzMKICAgICAgQU5EIHQxLmM0ID0gdG1wLmM0IEFORCB0 MS5jNSA9IHRtcC5jNSBBTkQgdDEuYzYgPSB0bXAuYzYKICAgICAgQU5EIHQx LmM3ID0gdG1wLmM3ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgLS0gbGluZSB0byBjb21tZW50IGZvciA2IGNvbHVtbnMg cGtleQo7CgotLSAzIGlkZW50aWZpZWQgd29ya2Fyb3VuZHMKLS1jcmVhdGUg aW5kZXggb24gdG1wKGdpZCk7Ci0tZGVsZXRlIGZyb20gcGdfc3RhdGlzdGlj IHMgCi0tICB1c2luZyBwZ19jbGFzcyBjLCBwZ19uYW1lc3BhY2UgbiwgcGdf YXR0cmlidXRlIGEgCi0tICB3aGVyZSBzdGFyZWxpZCA9IGMub2lkIGFuZCBj LnJlbG5hbWVzcGFjZSA9IG4ub2lkIGFuZCBzdGFhdHRudW0gPSBhLmF0dG51 bSBhbmQgYXR0cmVsaWQgPSBjLm9pZAotLSAgICBhbmQgcmVsbmFtZSA9ICd0 MV9sb2cnIGFuZCBuc3BuYW1lID0gJ3B1YmxpYycgYW5kIGF0dG5hbWUgPSAn dHVwbGUnOwpzZXQgZW5hYmxlX25lc3Rsb29wICA9IGZhbHNlOwoKc2VsZWN0 ICogZnJvbSBwZ19zdGF0cyB3aGVyZSB0YWJsZW5hbWUgPSAndDFfbG9nJyBh bmQgYXR0bmFtZSA9ICd0dXBsZSc7CgotLSBUaGUgZmF1bHRpbmcgc3RhdGVt ZW50CmV4cGxhaW4gYW5hbHl6ZQpJTlNFUlQgSU5UTyB0MQogIFNFTEVDVCB0 MV9sb2cuYzEsdDFfbG9nLmMyLHQxX2xvZy5jMyx0MV9sb2cuYzQsdDFfbG9n LmM1LHQxX2xvZy5jNix0MV9sb2cuYzcsdDFfbG9nLmM4CiAgICBGUk9NIHQx X2xvZywgdG1wCiAgICBXSEVSRSB0MV9sb2cuYzEgPSB0bXAuYzEgQU5EIHQx X2xvZy5jMiA9IHRtcC5jMiBBTkQgdDFfbG9nLmMzID0gdG1wLmMzCiAgICAg IEFORCB0MV9sb2cuYzQgPSB0bXAuYzQgQU5EIHQxX2xvZy5jNSA9IHRtcC5j NSBBTkQgdDFfbG9nLmM2ID0gdG1wLmM2CiAgICAgIEFORCB0MV9sb2cuYzcg PSB0bXAuYzcgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgIC0tIGxpbmUgdG8gY29tbWVudCBmb3IgNiBjb2x1bW5zIHBrZXkKICAg ICAgQU5EIHQxX2xvZy5naWQgPSB0bXAuZ2lkIEFORCB0MV9sb2cudHVwbGUg PSAnT0xEJzsKCg== --------------36ADE0DF788E9D8EB5E1718C Content-Type: application/octet-stream; name="test_ko1.log" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="test_ko1.log" XHRpbWluZyBvbgpUaW1pbmcgaXMgb24uCnNlbGVjdCB2ZXJzaW9uKCk7CiAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgdmVy c2lvbiAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgIAotLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0KIFBvc3RncmVTUUwgOS4yLjE2IG9uIGk2ODYtcGMtbGlu dXgtZ251LCBjb21waWxlZCBieSBnY2MgKFVidW50dSA0LjguMi0xOXVidW50 dTEpIDQuOC4yLCAzMi1iaXQKKDEgcm93KQoKVGltZTogMiwzNzIgbXMKc2V0 IHdvcmtfbWVtID0gJzQwTUInOwpTRVQKVGltZTogMCwyMzcgbXMKXHNldCBP Tl9FUlJPUl9TVE9QCi0tIENyZWF0ZSBhbmQgcG9wdWxhdGUgdGhlIHRhYmxl Ci0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tCmRyb3AgdGFibGUg aWYgZXhpc3RzIHQxIGNhc2NhZGU7CkRST1AgVEFCTEUKVGltZTogMTEsNzg5 IG1zCmNyZWF0ZSB0YWJsZSB0MSAoCiAgYzEgICAgaW50ZWdlciAgICBub3Qg bnVsbCwKICBjMiAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGMzICAgIGlu dGVnZXIgICAgbm90IG51bGwsCiAgYzQgICAgaW50ZWdlciAgICBub3QgbnVs bCwKICBjNSAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM2ICAgIGludGVn ZXIgICAgbm90IG51bGwsCiAgYzcgICAgaW50ZWdlciAgICBub3QgbnVsbCwK ICBjOCAgICBpbnRlZ2VyICAgIG5vdCBudWxsLApwcmltYXJ5IGtleSAoYzEs YzIsYzMsYzQsYzUsYzYsYzcpICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAtLSBsaW5lIHRvIGNvbW1lbnQgZm9yIDYgY29sdW1ucyBwa2V5 Ci0tcHJpbWFyeSBrZXkgKGMxLGMyLGMzLGM0LGM1LGM2KSAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgIC0tIGxpbmUgdG8gdW5jb21tZW50 IGZvciA2IGNvbHVtbnMgcGtleQopOwpDUkVBVEUgVEFCTEUKVGltZTogNywy MDMgbXMKaW5zZXJ0IGludG8gdDEKICBzZWxlY3QgaSwgMiwgMywgNCwgNSwg NiwgNywgOAogICAgZnJvbSBnZW5lcmF0ZV9zZXJpZXMgKDEsMTAwMDAwKSBp OwpJTlNFUlQgMCAxMDAwMDAKVGltZTogMzk3LDAxOCBtcwotLSBzZXR1cCB0 aGUgbG9nZ2luZyBtZWNoYW5pc20KLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tCmRyb3AgdGFibGUgaWYgZXhpc3RzIHQxX2xvZyBjYXNjYWRlOwpE Uk9QIFRBQkxFClRpbWU6IDEsOTE1IG1zCmNyZWF0ZSB0YWJsZSB0MV9sb2cg KAogIGMxICAgIGludGVnZXIgICAgbm90IG51bGwsCiAgYzIgICAgaW50ZWdl ciAgICBub3QgbnVsbCwKICBjMyAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAog IGM0ICAgIGludGVnZXIgICAgbm90IG51bGwsCiAgYzUgICAgaW50ZWdlciAg ICBub3QgbnVsbCwKICBjNiAgICBpbnRlZ2VyICAgIG5vdCBudWxsLAogIGM3 ICAgIGludGVnZXIgICAgbm90IG51bGwsCiAgYzggICAgaW50ZWdlciAgICBu b3QgbnVsbCwKICB2ZXJiICB2YXJjaGFyKDMpIG5vdCBudWxsLCAKICB0dXBs ZSB2YXJjaGFyKDMpIG5vdCBudWxsLAogIGdpZCAgIGJpZ3NlcmlhbCAgbm90 IG51bGwKKTsKQ1JFQVRFIFRBQkxFClRpbWU6IDEsNzk4IG1zCmNyZWF0ZSB1 bmlxdWUgaW5kZXggb24gdDFfbG9nKGdpZCwgdHVwbGUpOwpDUkVBVEUgSU5E RVgKVGltZTogMiwxOTAgbXMKQ1JFQVRFIE9SIFJFUExBQ0UgRlVOQ1RJT04g dDFfbG9nX2ZuY3QoKSBSRVRVUk5TIFRSSUdHRVIgQVMgJCQKQkVHSU4KICBJ RiAoVEdfT1AgPSAnREVMRVRFJykgVEhFTgogICAgSU5TRVJUIElOVE8gdDFf bG9nIFNFTEVDVCBPTEQuKiwgJ0RFTCcsICdPTEQnOwogICAgUkVUVVJOIE9M RDsKICBFTFNJRiAoVEdfT1AgPSAnVVBEQVRFJykgVEhFTgogICAgSU5TRVJU IElOVE8gdDFfbG9nIFNFTEVDVCBPTEQuKiwgJ1VQRCcsICdPTEQnOwogICAg SU5TRVJUIElOVE8gdDFfbG9nIFNFTEVDVCBORVcuKiwgJ1VQRCcsICdORVcn LCBsYXN0dmFsKCk7CiAgICBSRVRVUk4gTkVXOwogIEVMU0lGIChUR19PUCA9 ICdJTlNFUlQnKSBUSEVOCiAgICBJTlNFUlQgSU5UTyB0MV9sb2cgU0VMRUNU IE5FVy4qLCAnSU5TJywgJ05FVyc7CiAgICBSRVRVUk4gTkVXOwogIEVORCBJ RjsKICBSRVRVUk4gTlVMTDsKRU5EOwokJCBMQU5HVUFHRSBwbHBnc3FsIFNF Q1VSSVRZIERFRklORVI7CkNSRUFURSBGVU5DVElPTgpUaW1lOiAxLDMzMSBt cwpDUkVBVEUgVFJJR0dFUiB0MV9sb2dfdHJnCiAgQUZURVIgSU5TRVJUIE9S IFVQREFURSBPUiBERUxFVEUgT04gdDEKICBGT1IgRUFDSCBST1cgRVhFQ1VU RSBQUk9DRURVUkUgdDFfbG9nX2ZuY3QoKTsKQ1JFQVRFIFRSSUdHRVIKVGlt ZTogMCw2ODcgbXMKLS0gR2VuZXJhdGUgdGFibGUgY2hhbmdlcwotLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tCmluc2VydCBpbnRvIHQxCiAgc2VsZWN0IGMx LCAwLCBjMywgYzQsIGM1LCBjNiwgYzcsIGM4CiAgICBmcm9tIHQxIHdoZXJl IGMxICUgMTAgPSAwOwpJTlNFUlQgMCAxMDAwMApUaW1lOiAzNDUsNTg2IG1z Ci0tIDMgY2FzZXMgd2hlbiB0aGUgcHJvYmxlbSBkaXNhcHBlYXJzCi0tZGVs ZXRlIGZyb20gdDEgd2hlcmUgYzEgPSAxOwotLXVwZGF0ZSB0MSBzZXQgYzIg PSAtMiB3aGVyZSBjMSA9IDI7Ci0tYWx0ZXIgdGFibGUgdDEgZGlzYWJsZSB0 cmlnZ2VyIHQxX2xvZ190cmc7CnZhY3V1bSBhbmFseXplOwpWQUNVVU0KVGlt ZTogODIyLDUwMCBtcwpzZWxlY3QgdHVwbGUsIGNvdW50KCopIGZyb20gdDFf bG9nIGdyb3VwIGJ5IDE7CiB0dXBsZSB8IGNvdW50IAotLS0tLS0tKy0tLS0t LS0KIE5FVyAgIHwgMTAwMDAKKDEgcm93KQoKVGltZTogNCwxOTcgbXMKc2Vs ZWN0ICogZnJvbSBwZ19zdGF0cyB3aGVyZSB0YWJsZW5hbWUgPSAndDFfbG9n JyBhbmQgYXR0bmFtZSA9ICd0dXBsZSc7CiBzY2hlbWFuYW1lIHwgdGFibGVu YW1lIHwgYXR0bmFtZSB8IGluaGVyaXRlZCB8IG51bGxfZnJhYyB8IGF2Z193 aWR0aCB8IG5fZGlzdGluY3QgfCBtb3N0X2NvbW1vbl92YWxzIHwgbW9zdF9j b21tb25fZnJlcXMgfCBoaXN0b2dyYW1fYm91bmRzIHwgY29ycmVsYXRpb24g fCBtb3N0X2NvbW1vbl9lbGVtcyB8IG1vc3RfY29tbW9uX2VsZW1fZnJlcXMg fCBlbGVtX2NvdW50X2hpc3RvZ3JhbSAKLS0tLS0tLS0tLS0tKy0tLS0tLS0t LS0tKy0tLS0tLS0tLSstLS0tLS0tLS0tLSstLS0tLS0tLS0tLSstLS0tLS0t LS0tLSstLS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0tLS0tKy0tLS0tLS0t LS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0tLS0tKy0tLS0tLS0tLS0tLS0r LS0tLS0tLS0tLS0tLS0tLS0tLSstLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0r LS0tLS0tLS0tLS0tLS0tLS0tLS0tLQogcHVibGljICAgICB8IHQxX2xvZyAg ICB8IHR1cGxlICAgfCBmICAgICAgICAgfCAgICAgICAgIDAgfCAgICAgICAg IDQgfCAgICAgICAgICAxIHwge05FV30gICAgICAgICAgICB8IHsxfSAgICAg ICAgICAgICAgIHwgICAgICAgICAgICAgICAgICB8ICAgICAgICAgICAxIHwg ICAgICAgICAgICAgICAgICAgfCAgICAgICAgICAgICAgICAgICAgICAgIHwg CigxIHJvdykKClRpbWU6IDEsNjQxIG1zCi0tIENhbmNlbCB0YWJsZSdzIHVw ZGF0ZXMKLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLQpDUkVBVEUgVEVNUCBU QUJMRSB0bXAgQVMKICBTRUxFQ1QgYzEsYzIsYzMsYzQsYzUsYzYsCiAgICAg ICAgIGM3LCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgIC0tIGxpbmUgdG8gY29tbWVudCBmb3IgNiBj b2x1bW5zIHBrZXkKICAgICAgICAgbWluKGdpZCkgYXMgZ2lkCiAgICBGUk9N IHQxX2xvZwogICAgV0hFUkUgZ2lkID4gMAogICAgR1JPVVAgQlkgYzEsYzIs YzMsYzQsYzUsYzYKICAgICAgICAgICAgLGM3ICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgLS0gbGluZSB0 byBjb21tZW50IGZvciA2IGNvbHVtbnMgcGtleQo7ClNFTEVDVCAxMDAwMApU aW1lOiAxMyw1ODAgbXMKREVMRVRFIEZST00gT05MWSB0MSBVU0lORyB0bXAK ICAgIFdIRVJFIHQxLmMxID0gdG1wLmMxIEFORCB0MS5jMiA9IHRtcC5jMiBB TkQgdDEuYzMgPSB0bXAuYzMKICAgICAgQU5EIHQxLmM0ID0gdG1wLmM0IEFO RCB0MS5jNSA9IHRtcC5jNSBBTkQgdDEuYzYgPSB0bXAuYzYKICAgICAgQU5E IHQxLmM3ID0gdG1wLmM3ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgLS0gbGluZSB0byBjb21tZW50IGZvciA2IGNvbHVt bnMgcGtleQo7CkRFTEVURSAxMDAwMApUaW1lOiAyOTEsNzI3IG1zCi0tIDEg Y2FzZSB0aGF0IG1pdGlnYXRlcyB0aGUgcHJvYmxlbQotLWNyZWF0ZSBpbmRl eCBvbiB0bXAoZ2lkKTsKc2VsZWN0ICogZnJvbSBwZ19zdGF0cyB3aGVyZSB0 YWJsZW5hbWUgPSAndDFfbG9nJyBhbmQgYXR0bmFtZSA9ICd0dXBsZSc7CiBz Y2hlbWFuYW1lIHwgdGFibGVuYW1lIHwgYXR0bmFtZSB8IGluaGVyaXRlZCB8 IG51bGxfZnJhYyB8IGF2Z193aWR0aCB8IG5fZGlzdGluY3QgfCBtb3N0X2Nv bW1vbl92YWxzIHwgbW9zdF9jb21tb25fZnJlcXMgfCBoaXN0b2dyYW1fYm91 bmRzIHwgY29ycmVsYXRpb24gfCBtb3N0X2NvbW1vbl9lbGVtcyB8IG1vc3Rf Y29tbW9uX2VsZW1fZnJlcXMgfCBlbGVtX2NvdW50X2hpc3RvZ3JhbSAKLS0t LS0tLS0tLS0tKy0tLS0tLS0tLS0tKy0tLS0tLS0tLSstLS0tLS0tLS0tLSst LS0tLS0tLS0tLSstLS0tLS0tLS0tLSstLS0tLS0tLS0tLS0rLS0tLS0tLS0t LS0tLS0tLS0tKy0tLS0tLS0tLS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0t LS0tKy0tLS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0tLS0tLSstLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0tLS0tLS0tLQogcHVi bGljICAgICB8IHQxX2xvZyAgICB8IHR1cGxlICAgfCBmICAgICAgICAgfCAg ICAgICAgIDAgfCAgICAgICAgIDQgfCAgICAgICAgICAxIHwge05FV30gICAg ICAgICAgICB8IHsxfSAgICAgICAgICAgICAgIHwgICAgICAgICAgICAgICAg ICB8ICAgICAgICAgICAxIHwgICAgICAgICAgICAgICAgICAgfCAgICAgICAg ICAgICAgICAgICAgICAgIHwgCigxIHJvdykKClRpbWU6IDEsOTczIG1zCmV4 cGxhaW4gYW5hbHl6ZQpJTlNFUlQgSU5UTyB0MQogIFNFTEVDVCB0MV9sb2cu YzEsdDFfbG9nLmMyLHQxX2xvZy5jMyx0MV9sb2cuYzQsdDFfbG9nLmM1LHQx X2xvZy5jNix0MV9sb2cuYzcsdDFfbG9nLmM4CiAgICBGUk9NIHQxX2xvZywg dG1wCiAgICBXSEVSRSB0MV9sb2cuYzEgPSB0bXAuYzEgQU5EIHQxX2xvZy5j MiA9IHRtcC5jMiBBTkQgdDFfbG9nLmMzID0gdG1wLmMzCiAgICAgIEFORCB0 MV9sb2cuYzQgPSB0bXAuYzQgQU5EIHQxX2xvZy5jNSA9IHRtcC5jNSBBTkQg dDFfbG9nLmM2ID0gdG1wLmM2CiAgICAgIEFORCB0MV9sb2cuYzcgPSB0bXAu YzcgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIC0t IGxpbmUgdG8gY29tbWVudCBmb3IgNiBjb2x1bW5zIHBrZXkKICAgICAgQU5E IHQxX2xvZy5naWQgPSB0bXAuZ2lkIEFORCB0MV9sb2cudHVwbGUgPSAnT0xE JzsKICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgIFFVRVJZIFBMQU4gICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg Ci0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLQog SW5zZXJ0IG9uIHQxICAoY29zdD0wLjAwLi44OTAuOTAgcm93cz0xIHdpZHRo PTMyKSAoYWN0dWFsIHRpbWU9NDM0NTcxLjE5My4uNDM0NTcxLjE5MyByb3dz PTAgbG9vcHM9MSkKICAgLT4gIE5lc3RlZCBMb29wICAoY29zdD0wLjAwLi44 OTAuOTAgcm93cz0xIHdpZHRoPTMyKSAoYWN0dWFsIHRpbWU9NDM0NTcxLjE4 Ny4uNDM0NTcxLjE4NyByb3dzPTAgbG9vcHM9MSkKICAgICAgICAgSm9pbiBG aWx0ZXI6ICgodDFfbG9nLmMxID0gdG1wLmMxKSBBTkQgKHQxX2xvZy5jMiA9 IHRtcC5jMikgQU5EICh0MV9sb2cuYzMgPSB0bXAuYzMpIEFORCAodDFfbG9n LmM0ID0gdG1wLmM0KSBBTkQgKHQxX2xvZy5jNSA9IHRtcC5jNSkgQU5EICh0 MV9sb2cuYzYgPSB0bXAuYzYpIEFORCAodDFfbG9nLmM3ID0gdG1wLmM3KSBB TkQgKHQxX2xvZy5naWQgPSB0bXAuZ2lkKSkKICAgICAgICAgUm93cyBSZW1v dmVkIGJ5IEpvaW4gRmlsdGVyOiAxMDAwMDAwMDAKICAgICAgICAgLT4gIElu ZGV4IFNjYW4gdXNpbmcgdDFfbG9nX2dpZF90dXBsZV9pZHggb24gdDFfbG9n ICAoY29zdD0wLjAwLi40MjMuMjIgcm93cz0xIHdpZHRoPTQwKSAoYWN0dWFs IHRpbWU9MC4zNzguLjY5LjU5NCByb3dzPTEwMDAwIGxvb3BzPTEpCiAgICAg ICAgICAgICAgIEluZGV4IENvbmQ6ICgodHVwbGUpOjp0ZXh0ID0gJ09MRCc6 OnRleHQpCiAgICAgICAgIC0+ICBTZXEgU2NhbiBvbiB0bXAgIChjb3N0PTAu MDAuLjE3Ni4xNyByb3dzPTk3MTcgd2lkdGg9MzYpIChhY3R1YWwgdGltZT0w LjAwNi4uMjEuNjc4IHJvd3M9MTAwMDAgbG9vcHM9MTAwMDApCiBUb3RhbCBy dW50aW1lOiA0MzQ1NzEuMjQzIG1zCig4IHJvd3MpCgpUaW1lOiA0MzQ1NzIs MTQ2IG1zCg== --------------36ADE0DF788E9D8EB5E1718C Content-Type: text/plain Content-Disposition: inline Content-Transfer-Encoding: 8bit MIME-Version: 1.0 -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance --------------36ADE0DF788E9D8EB5E1718C--