Skip to content

I/O Timings: Read / Write times not obvious enough #477

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
Krysztophe opened this issue Apr 8, 2022 · 6 comments · May be fixed by #708
Open

I/O Timings: Read / Write times not obvious enough #477

Krysztophe opened this issue Apr 8, 2022 · 6 comments · May be fixed by #708

Comments

@Krysztophe
Copy link
Contributor

The I/O Timings information are not really visible, as in:

Screenshot_20220408_152744

I would expect them to appear in the array , above "Read" and "Written". And perhaps in color if they are a big part of the total query time.

Examples:
@pgiraud
Copy link
Member

pgiraud commented Oct 10, 2024

Is this what you have in mind for the location?

Screenshot from 2024-10-10 14-53-13

@Krysztophe
Copy link
Contributor Author

Nice!

Et si je n'abuse pas : perhaps the same colors as here ? (for the number of blocs and GB only? the title ? Just the bullet points ?)

image

@pgiraud
Copy link
Member

pgiraud commented Mar 14, 2025

@Krysztophe Is it correct that in the plan, for "I/O Timings" we can only have "read" and "write" and that the values for these correspond to respectively "Buffers shared read" and "Buffers shared written"?

@pgiraud pgiraud mentioned this issue Mar 14, 2025
Closed
pgiraud added a commit that referenced this issue Mar 14, 2025
@pgiraud
Move IO timings the buffers grid in node detail
d183147 
Fixes #477
@pgiraud pgiraud linked a pull request Mar 14, 2025 that will close this issue
Draft
@Krysztophe
Copy link
Contributor Author

It seems to depends on the version and the cache effect. If running again my example in https://explain.dalibo.com/plan/mZe#plan/node/1 , twice, I get the sharedkeyword for I/O timings now.
This is in src/backend/commands/explain.c ; I'll look after lunch.

 EXPLAIN (ANALYZE,VERBOSE,BUFFERS) UPDATE pgbench_accounts SET  filler = 'e'  ;
 
                                                                  QUERY PLAN                                                                   
-----------------------------------------------------------------------------------------------------------------------------------------------
 Update on public.pgbench_accounts  (cost=0.00..263935.35 rows=0 width=0) (actual time=61836.928..61836.929 rows=0 loops=1)
   Buffers: shared hit=70792108 read=27430 dirtied=382757 written=191392
   I/O Timings: shared read=326.400 write=1473.914
   ->  Seq Scan on public.pgbench_accounts  (cost=0.00..263935.35 rows=10000035 width=346) (actual time=0.019..1075.525 rows=10000000 loops=1)
         Output: 'e                                                                                   '::character(84), ctid
         Buffers: shared hit=163935
 Query Identifier: 3677610296251216147
 Planning:
   Buffers: shared hit=47 read=3
   I/O Timings: shared read=0.407
 Planning Time: 0.692 ms
 Execution Time: 61837.468 ms

[17002](3686198)postgres@pgbench_100_ssd=#* EXPLAIN (ANALYZE,VERBOSE,BUFFERS) UPDATE pgbench_accounts SET  filler = 'e'  ;

                                                                   QUERY PLAN                                                                    
-------------------------------------------------------------------------------------------------------------------------------------------------
 Update on public.pgbench_accounts  (cost=0.00..527869.09 rows=0 width=0) (actual time=55680.592..55680.593 rows=0 loops=1)
   Buffers: shared hit=80983466 dirtied=191393 written=191393
   I/O Timings: shared write=1278.325
   ->  Seq Scan on public.pgbench_accounts  (cost=0.00..527869.09 rows=20000009 width=346) (actual time=267.844..1482.712 rows=10000000 loops=1)
         Output: 'e                                                                                   '::character(84), ctid
         Buffers: shared hit=327869
 Query Identifier: 3677610296251216147
 Planning Time: 0.030 ms
 Execution Time: 55680.613 ms

@Krysztophe
Copy link
Contributor Author

@Krysztophe Is it correct that in the plan, for "I/O Timings" we can only have "read" and "write" and that the values for these correspond to respectively "Buffers shared read" and "Buffers shared written"?

On PG17: https://explain.dalibo.com/plan/40ed3a382gah1b44#plan

   I/O Timings: shared read=60857.349 write=2075.348, temp read=190561.144 write=20711.103

@pgiraud pgiraud mentioned this issue Mar 21, 2025
Open
@Krysztophe
Copy link
Contributor Author

Seems a bit more complicated with JSON & PG17 : #733

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Move IO timings the buffers grid in node detail dalibo/pev2
2 participants
@pgiraud @Krysztophe