From: Tom Lane <tgl@sss.pgh.pa.us>
To: "David G. Johnston" <david.g.johnston@gmail.com>
cc: Justin Pryzby <pryzby@telsasoft.com>,
 Lars Bergeson <larsavatar@gmail.com>,
        "pgsql-performance@lists.postgresql.org"
 <pgsql-performance@lists.postgresql.org>
Subject: Re: Query is slower with a large proportion of NULLs in several
 columns
In-reply-to: 
 <CAKFQuwZ==D+f656wsZcctpChQ2xWx5t2fjEhr8+VQWCSCWaWgQ@mail.gmail.com>
References: 
 <CAK66RGYim22Sd8-NvmufcxEQ_P99=UTAyJ9agnwDyEbCiVGEQg@mail.gmail.com>
 <2688019.1640051519@sss.pgh.pa.us>
 <CAK66RGbd8n46xEp3fTKOa3pO3eC=NT8tEHHZYjuNZq4Y0SQHTw@mail.gmail.com>
 <20211221045138.GZ17618@telsasoft.com> <2704544.1640062888@sss.pgh.pa.us>
 <CAKFQuwZ==D+f656wsZcctpChQ2xWx5t2fjEhr8+VQWCSCWaWgQ@mail.gmail.com>
Comments: In-reply-to "David G. Johnston" <david.g.johnston@gmail.com>
	message dated "Mon, 20 Dec 2021 22:08:59 -0700"
MIME-Version: 1.0
Content-Type: text/plain; charset="UTF-8"
Content-ID: <2707816.1640064786.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Tue, 21 Dec 2021 00:33:06 -0500
Message-ID: <2707817.1640064786@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/2707817.1640064786%40sss.pgh.pa.us>
Precedence: bulk

"David G. Johnston" <david.g.johnston@gmail.com> writes:
> On Monday, December 20, 2021, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> It would help if somebody had labeled the units of I/O Time
>> ... but I'm guessing those are microsec vs. the millisec
>> of the other times, because otherwise it's completely wrong.

> Related to my preceding observation, from the explain (buffers) docs:
> =E2=80=9C=E2=80=A6and the time spent reading and writing data file block=
s (in milliseconds)
> if track_io_timing
> <https://www.postgresql.org/docs/current/runtime-config-statistics.html#=
GUC-TRACK-IO-TIMING>
> is enabled.=E2=80=9C

Hmm ... the code sure looks like it's supposed to be millisec:

            appendStringInfoString(es->str, "I/O Timings:");
            if (!INSTR_TIME_IS_ZERO(usage->blk_read_time))
                appendStringInfo(es->str, " read=3D%0.3f",
                                 INSTR_TIME_GET_MILLISEC(usage->blk_read_t=
ime));
            if (!INSTR_TIME_IS_ZERO(usage->blk_write_time))
                appendStringInfo(es->str, " write=3D%0.3f",
                                 INSTR_TIME_GET_MILLISEC(usage->blk_write_=
time));

And when I try some cases here, I get I/O timing numbers that are
consistent with the overall time reported by EXPLAIN, for example

 Seq Scan on foo  (cost=3D0.00..843334.10 rows=3D11000010 width=3D508) (ac=
tual time=3D0.
015..1897.492 rows=3D11000000 loops=3D1)
   Buffers: shared hit=3D15874 read=3D717460
   I/O Timings: read=3D1184.638
 Planning:
   Buffers: shared hit=3D5 read=3D2
   I/O Timings: read=3D0.025
 Planning Time: 0.229 ms
 Execution Time: 2151.529 ms

So now we have a real mystery about what is happening on Lars'
system.  Those numbers can't be right.

			regards, tom lane