5

I want to know how to verify disk hits by a select query in PostgreSQL 9.4 on CentOS 6.5. Also please let me know how far enabling the log_statement_stats in the postgresql.conf will help me.

I need to understand the 'filesystem blocks in/out' value in the logs when I switch the above parameter to on.

For example, please check the log snippet:

2016-02-03 14:12:45 PST LOG:  statement: select * from test_stats_collect ;
2016-02-03 14:12:45 PST LOG:  QUERY STATISTICS
2016-02-03 14:12:45 PST DETAIL:  ! system usage stats:
        !       0.069489 elapsed 0.027995 user 0.002999 system sec
        !       [0.131979 user 0.146977 sys total]
        !       0/0 [3280/26440] filesystem blocks in/out
        !       0/5 [19/4866] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       20/116 [125/174] voluntary/involuntary context switches
3

The numbers reported by log_statement_stats come directly from the getrusage system call (assuming your OS has one). The numbers in square brackets are total for the session so far, the other numbers are deltas between the start and stop of the statement.

The filesystem block size is not normalized to be the same as the PostgresSQL block size. It is in whatever units of block size your OS reports in getrusage.

  • 1
    Hi , Thanks for your answer. But , could you please more specific i.e, when you said ," The numbers in square brackets are total for the session so far" are you saying that [3280/26440] filesystem blocks in/out those values are for session level ? if so, could you please help me to figure out file system block reads for above select query ? – Gowtham Kumar Feb 5 '16 at 2:08
  • 2
    Yes, those are for the backend (the process you are connected to) for its entire lifetime, which is the same lifetime as your session. Your specific query seems to have no reads or writes, "0/0". Everything it needed was already in memory. BTW, on my Linux machine, a block seems to be 512 bytes. – jjanes Feb 5 '16 at 16:12
  • ok , thanks for clarification . I got what am looking for . 0/0 is my query statistics and [3280/26440] filesystem blocks in/out indicates session level statistics . – Gowtham Kumar Feb 8 '16 at 8:56
  • Hi , I have a 'DDL' statement which is causing some file system in/out below are the logs: 2016-02-12 01:22:53 PST LOG: statement: create table test_sql_source (col1 numeric ); 2016-02-12 01:22:53 PST LOG: QUERY STATISTICS 2016-02-12 01:22:53 PST DETAIL: ! system usage stats: ! 0.005942 elapsed 0.001000 user 0.002000 system sec ! [0.017997 user 0.028995 sys total] ! 16/80 [1712/496] filesystem blocks in/out I am more interested to know about 16/80 what exactly this "in" value and out value means ? in the previous logs because in/out values are 0/0 , i did not understand it exactly. – Gowtham Kumar Feb 12 '16 at 9:52
  • To be more specific 'am seeing difference in the values of in/out for eg: 2016-02-12 01:54:21 PST LOG: statement: insert into test_sql_source values (1); is causing 0/32 [1712/528] filesystem blocks in/out and if i run the same query again (insert statement ) > 2016-02-12 01:54:21 PST STATEMENT: insert into test_sql_source values (1); is causing 0/16 [1712/544] filesystem blocks in/out – Gowtham Kumar Feb 12 '16 at 9:57
2

If you want to see the impact of a single query on I/O, you can also use EXPLAIN (ANALYZE, BUFFERS). Since disk reads are heavily dependent on what is already cached, results are obviously going to vary across runs.

Example on a table without index, where you can see 32 blocks were cached and 65562 blocks were read:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                QUERY PLAN                                                                                 
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Seq Scan on public.accesslog  (cost=0.00..94247.03 rows=9191 width=74) (actual time=483.209..558.841 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Filter: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Rows Removed by Filter: 1900894
   Buffers: shared hit=32 read=65562
 Planning time: 0.112 ms
 Execution time: 559.331 ms
(7 rows)

Same query, after I create a B-tree index on timestamp. Here you can see 6 blocks were cached and 311 were read:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                  QUERY PLAN                                                                                   
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Index Scan using accesslog_timestamp_idx on public.accesslog  (cost=0.43..607.15 rows=9186 width=74) (actual time=0.083..7.658 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Index Cond: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Buffers: shared hit=6 read=311
 Planning time: 0.640 ms
 Execution time: 8.348 ms
(6 rows)

And a repeat of same query shows that the second time all 317 blocks were cached:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                  QUERY PLAN                                                                                   
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Index Scan using accesslog_timestamp_idx on public.accesslog  (cost=0.43..607.15 rows=9186 width=74) (actual time=0.051..8.436 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Index Cond: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Buffers: shared hit=317
 Planning time: 0.154 ms
 Execution time: 9.454 ms
(6 rows)
  • 1
    How do you distinguish between the blocks read from disk or from the OS cache? – dezso Feb 6 '16 at 18:53
  • Thanks a lot for your explanation . Although am aware of explain (analyze , verbose , buffers) , your explanation adds more details . Only reasons why 'am going for logs is we can't predict and run explain plan of each and every query so , enabled the parameter in the postgres.conf file to log the details. Once again thanks for your time. – Gowtham Kumar Feb 8 '16 at 9:12

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.