Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nD1l3-0006ws-Rs for pgsql-bugs@arkaria.postgresql.org; Thu, 27 Jan 2022 10:12:02 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1nD1l2-0000iG-60 for pgsql-bugs@arkaria.postgresql.org; Thu, 27 Jan 2022 10:12:00 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nD1l1-0000i7-PD for pgsql-bugs@lists.postgresql.org; Thu, 27 Jan 2022 10:11:59 +0000 Received: from mail1.dalibo.net ([212.83.143.11] helo=mail.dalibo.com) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nD1kw-0002ag-Nn for pgsql-bugs@postgresql.org; Thu, 27 Jan 2022 10:11:58 +0000 Received: from [192.168.74.150] (82-64-99-9.subs.proxad.net [82.64.99.9]) by mail.dalibo.com (Postfix) with ESMTPSA id 339411F842 for ; Thu, 27 Jan 2022 11:11:51 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=simple/simple; d=dalibo.com; s=a; t=1643278311; bh=FjOZU2xe5Tqhz2OapU2/XvnWLKRffzQ7h5rQByMV9gg=; h=Date:From:Subject:To:From; b=OUXvxHtnuYyqdeKJOh59Dj60EvNhkGulluDl05OeAaDmEYAIsGdq2wYQ0XU4jzqqf 6VRBo1vFdB+oEZgs8Uj8MeThcsKdGhhgb9naqekySTI+obSjgKJk/+gTWoqPRAglHO aFQdb9XmeYzHQ3n3sR3tP+xWnsT0Awpf4OvF1ujY= Content-Type: multipart/mixed; boundary="------------ycKQ0wmGY1B4grm0Q1uK4YE8" Message-ID: Date: Thu, 27 Jan 2022 11:11:50 +0100 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.5.0 From: Christophe Courtois Subject: No access to TOAST tables shown in EXPLAIN ( ANALYZE, BUFFERS ) To: pgsql-bugs Content-Language: fr-FR Organization: Dalibo List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multi-part message in MIME format. --------------ycKQ0wmGY1B4grm0Q1uK4YE8 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Hi, I've found that EXPLAIN (ANALYZE,BUFFERS) does not show any access to the TOAST tables when a toasted column is only SELECTed and not used in any way in the query. pg_statio_all_tables only shows access to the heap. I imagine that some optimization does not bother to go into the TOAST table, as its content is neither printed neither used. As a consequence, EXPLAIN plans can show huge differences against the actual query results, in buffers count and query time. As EXPLAIN is supposed to "display the true row counts and true run time accumulated within each plan node", I think there may be a problem. I didn't see any related caveats in https://www.postgresql.org/docs/14/using-explain.html#USING-EXPLAIN-CAVEATS For example, a simple "SELECT" from my one-column table takes ~ 20 ms and reads 9000 buffers, but the EXPLAIN ANALYZE is much much quicker: QUERY PLAN ------------------------------------------------------------------------ Seq Scan on public.noises (actual time=0.025..0.393 rows=3000 loops=1) Output: noise Buffers: shared hit=20 Query Identifier: 2512658633781838584 Planning Time: 0.030 ms Execution Time: 0.689 ms If I force the use of the result in the query (concatenation, length…), I see the 9000 missing hits again in the EXPLAIN plan. This seems to be this way since 9.1 at least. I'm wondering if this can be changed, or at least documented. SQL script for a full demo is joined. The main parts of the output are below (I hope this is readable): "8 MB test table" List of relations Schema | Name | Type | Owner | Persistence | Access method | Size | Description --------+--------+-------+----------+-------------+---------------+---------+------------- public | noises | table | postgres | unlogged | heap | 8384 kB | "** Reset stats **" "**" "** Query : SELECT noise FROM noises : ~ about 10-20 ms **" "**" Time: 16.350 ms relid | schemaname | relname | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit ---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+--------------- 4697174 | public | noises | 0 | 20 | | | 0 | 3000 | 0 | 6001 4697177 | pg_toast | pg_toast_4697174 | 0 | 3000 | 0 | 6001 | | | | "** Reset stats **" "**" "** Same query + EXPLAIN ANALYZE : < 1 ms , 20 hits **" "**" QUERY PLAN ------------------------------------------------------------------------ Seq Scan on public.noises (actual time=0.006..0.199 rows=3000 loops=1) Output: noise Buffers: shared hit=20 Query Identifier: 1313741123942831781 Planning Time: 0.028 ms Execution Time: 0.334 ms pg_sleep ---------- relid | schemaname | relname | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit ---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+--------------- 4697174 | public | noises | 0 | 20 | | | 0 | 0 | 0 | 0 4697177 | pg_toast | pg_toast_4697174 | 0 | 0 | 0 | 0 | | | | "** Reset stats **" "**" "** Force use of toast data + EXPLAIN ANALYZE : 10-20 ms, 9020 hits **" "**" QUERY PLAN ------------------------------------------------------------------------ Seq Scan on public.noises (actual time=0.023..9.679 rows=3000 loops=1) Output: (noise || ''::text) Buffers: shared hit=9020 Query Identifier: -6122032322937607654 Planning Time: 0.026 ms Execution Time: 9.843 ms relid | schemaname | relname | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit ---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+--------------- 4697174 | public | noises | 0 | 20 | | | 0 | 3000 | 0 | 6000 4697177 | pg_toast | pg_toast_4697174 | 0 | 3000 | 0 | 6000 | | | | -- Christophe Courtois Consultant Dalibo https://dalibo.com/ --------------ycKQ0wmGY1B4grm0Q1uK4YE8 Content-Type: text/plain; charset=UTF-8; name="explain_court-circuite_toasts.sql.txt" Content-Disposition: attachment; filename="explain_court-circuite_toasts.sql.txt" Content-Transfer-Encoding: base64 LS0gVGFibGUgZGUgZMOpbW8KXHBzZXQgcGFnZXIgb2ZmClxwc2V0IGZvb3RlciBvZmYKClNF VCB0cmFja19pb190aW1pbmcgVE8gb247CgotLSBzb21lIHVuY29tcHJlc3NpYmxlIG5vaXNl CkNSRUFURSBPUiBSRVBMQUNFIEZVTkNUSU9OIHJhbmRvbV9zdHJpbmdfcGF2ZWwoaW50KSBS RVRVUk5TIHRleHQgQVMgJCQgCiAgU0VMRUNUIGFycmF5X3RvX3N0cmluZygKICAgIEFSUkFZ IChTRUxFQ1Qgc3Vic3RyaW5nKCcwMTIzNDU2Nzg5QUJDREVGR0hJSktMTU5PUFFSU1RVVldY WVonIEZST00gKHJhbmRvbSgpICozNik6OmludCBGT1IgMSkgRlJPTSBnZW5lcmF0ZV9zZXJp ZXMoMSwgJDEpICksICcnICkgCiQkIExBTkdVQUdFIHNxbDsKClxlY2hvICI4IE1CIHRlc3Qg dGFibGUiCkRST1AgVEFCTEUgSUYgRVhJU1RTIG5vaXNlcyA7CkNSRUFURSBVTkxPR0dFRCBU QUJMRSBub2lzZXMgQVMgU0VMRUNUIHJhbmRvbV9zdHJpbmdfcGF2ZWwgKDI1MDApIEFTIG5v aXNlIEZST00gZ2VuZXJhdGVfc2VyaWVzICgxLCAzMDAwKSBqIDsKVkFDVVVNIG5vaXNlcyA7 CgpcZHQrIG5vaXNlcwoKU0VMRUNUICdub2lzZXMnOjpyZWdjbGFzczo6b2lkOjp0ZXh0IEFT IGhvaWQgXGdzZXQKU0VMRUNUIHJlbHRvYXN0cmVsaWQgQVMgdG9pZCBGUk9NIHBnX2NsYXNz IFdIRVJFIG9pZD06aG9pZCBcZ3NldApTRUxFQ1QgaW5kZXhyZWxpZDo6dGV4dCBBUyB0eG9p ZCBGUk9NIHBnX2luZGV4IFdIRVJFIGluZHJlbGlkPTp0b2lkIFxnc2V0CgpcZWNobyAiKiog UmVzZXQgc3RhdHMgKioiClNFTEVDVCBwZ19zbGVlcCgxKTsgIC0tIHN0YXRzIGFyZSBub3Qg dXBkYXRlZCBpbnN0YW50bHkKU0VMRUNUIHBnX3N0YXRfcmVzZXRfc2luZ2xlX3RhYmxlX2Nv dW50ZXJzICg6aG9pZCkscGdfc3RhdF9yZXNldF9zaW5nbGVfdGFibGVfY291bnRlcnMgKDp0 b2lkKSxwZ19zdGF0X3Jlc2V0X3NpbmdsZV90YWJsZV9jb3VudGVycyAoOnR4b2lkKTsKU0VM RUNUIHBnX3NsZWVwKDEpOyAgLS0gc3RhdHMgYXJlIG5vdCB1cGRhdGVkIGluc3RhbnRseQoK XGVjaG8gIioqIgpcZWNobyAiKiogUXVlcnkgOiBTRUxFQ1Qgbm9pc2VzICA6IH4gYWJvdXQg MTAtMjAgbXMgKioiClxlY2hvICIqKiIKXHRpbWluZyBvbgpcbyAvZGV2L251bGwKU0VMRUNU IG5vaXNlIEZST00gbm9pc2VzIDsKXHRpbWluZyBvZmYKXG8KClNFTEVDVCBwZ19zbGVlcCgx KTsKU0VMRUNUICogRlJPTSBwZ19zdGF0aW9fYWxsX3RhYmxlcyBXSEVSRSByZWxpZCBJTiAo OmhvaWQsIDp0b2lkKTsKXGVjaG8gIioqIFJlc2V0IHN0YXRzICoqIgpTRUxFQ1QgcGdfc3Rh dF9yZXNldF9zaW5nbGVfdGFibGVfY291bnRlcnMgKDpob2lkKSxwZ19zdGF0X3Jlc2V0X3Np bmdsZV90YWJsZV9jb3VudGVycyAoOnRvaWQpLHBnX3N0YXRfcmVzZXRfc2luZ2xlX3RhYmxl X2NvdW50ZXJzICg6dHhvaWQpOwpTRUxFQ1QgcGdfc2xlZXAoMSk7CgpcZWNobyAiKioiClxl Y2hvICIqKiBTYW1lIHF1ZXJ5ICsgRVhQTEFJTiBBTkFMWVpFIDogPCAxIG1zICwgMjAgaGl0 cyAqKiIKXGVjaG8gIioqIgoKRVhQTEFJTiAoQU5BTFlaRSxCVUZGRVJTLFZFUkJPU0UsIENP U1RTIE9GRikKU0VMRUNUIG5vaXNlIEZST00gbm9pc2VzIDsKClNFTEVDVCBwZ19zbGVlcCgx KTsKU0VMRUNUICogRlJPTSBwZ19zdGF0aW9fYWxsX3RhYmxlcyBXSEVSRSByZWxpZCBJTiAo OmhvaWQsIDp0b2lkKTsKXGVjaG8gIioqIFJlc2V0IHN0YXRzICoqIgpTRUxFQ1QgcGdfc3Rh dF9yZXNldF9zaW5nbGVfdGFibGVfY291bnRlcnMgKDpob2lkKSxwZ19zdGF0X3Jlc2V0X3Np bmdsZV90YWJsZV9jb3VudGVycyAoOnRvaWQpLHBnX3N0YXRfcmVzZXRfc2luZ2xlX3RhYmxl X2NvdW50ZXJzICg6dHhvaWQpOwpTRUxFQ1QgcGdfc2xlZXAoMSk7CgpcZWNobyAiKioiClxl Y2hvICIqKiBGb3JjZSB1c2Ugb2YgdG9hc3QgZGF0YSArIEVYUExBSU4gQU5BTFlaRSA6IDEw LTIwIG1zLCA5MDIwIGhpdHMgKioiClxlY2hvICIqKiIKCkVYUExBSU4gKEFOQUxZWkUsQlVG RkVSUyxWRVJCT1NFLENPU1RTIE9GRikKU0VMRUNUIG5vaXNlfHwnJyBGUk9NIG5vaXNlcyA7 CgpTRUxFQ1QgcGdfc2xlZXAoMSk7ClNFTEVDVCAqIEZST00gcGdfc3RhdGlvX2FsbF90YWJs ZXMgV0hFUkUgcmVsaWQgSU4gKDpob2lkLCA6dG9pZCk7CgpEUk9QIFRBQkxFIG5vaXNlcyA7 Cg== --------------ycKQ0wmGY1B4grm0Q1uK4YE8--