{"id":362130,"date":"2024-05-21T01:28:27","date_gmt":"2024-05-21T01:28:27","guid":{"rendered":"http:\/\/savepearlharbor.com\/?p=362130"},"modified":"-0001-11-30T00:00:00","modified_gmt":"-0001-11-29T21:00:00","slug":"","status":"publish","type":"post","link":"https:\/\/savepearlharbor.com\/?p=362130","title":{"rendered":"Timed wait events in PostgreSQL<\/span>"},"content":{"rendered":"
<\/div>\n
\n
\n
\n
\n

\u042d\u0442\u0430 \u043f\u0443\u0431\u043b\u0438\u043a\u0430\u0446\u0438\u044f \u2014 \u043f\u0435\u0440\u0435\u0432\u043e\u0434 \u0432\u0442\u043e\u0440\u043e\u0439 \u0441\u0442\u0430\u0442\u044c\u0438 \u0438\u0437\u0432\u0435\u0441\u0442\u043d\u043e\u0433\u043e \u0441\u043f\u0435\u0446\u0438\u0430\u043b\u0438\u0441\u0442\u0430 \u0432 \u043e\u0431\u043b\u0430\u0441\u0442\u0438 Oracle \u0424\u0440\u0438\u0446\u0430 \u0425\u0443\u0433\u043b\u0430\u043d\u0434\u0430 \u043d\u0430 \u0437\u0430\u0434\u0430\u043d\u043d\u0443\u044e \u0442\u0435\u043c\u0443 (\u043f\u0435\u0440\u0432\u0443\u044e \u0441\u0442\u0430\u0442\u044c\u044e \u044f \u043f\u0435\u0440\u0435\u0432\u0451\u043b \u0440\u0430\u043d\u0435\u0435 \u0441\u043c. <\/em>\u0418\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u043d\u0438\u0435 bpftrace \u0434\u043b\u044f \u0442\u0440\u0430\u0441\u0441\u0438\u0440\u043e\u0432\u043a\u0438 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u0437\u0430\u043f\u0440\u043e\u0441\u043e\u0432 \u0432 postgres<\/em><\/a>)<\/em><\/p>\n

\u042d\u0442\u043e \u0442\u043e, \u0447\u0435\u0433\u043e \u043d\u0435 \u0441\u0443\u0449\u0435\u0441\u0442\u0432\u0443\u0435\u0442 \u0432 PostgreSQL \u043d\u0430 \u043c\u043e\u043c\u0435\u043d\u0442 \u043d\u0430\u043f\u0438\u0441\u0430\u043d\u0438\u044f \u0441\u0442\u0430\u0442\u044c\u0438. \u041e\u0434\u043d\u0430\u043a\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u044d\u0442\u043e (timed wait events) \u0447\u0440\u0435\u0437\u0432\u044b\u0447\u0430\u0439\u043d\u043e \u043f\u0440\u043e\u0441\u0442\u043e, \u043f\u0440\u0438\u0447\u0435\u043c \u0441 \u043d\u0435\u0437\u043d\u0430\u0447\u0438\u0442\u0435\u043b\u044c\u043d\u044b\u043c\u0438 \u043d\u0430\u043a\u043b\u0430\u0434\u043d\u044b\u043c\u0438 \u0440\u0430\u0441\u0445\u043e\u0434\u0430\u043c\u0438. \u041d\u0430\u043a\u043b\u0430\u0434\u043d\u044b\u0435 \u0440\u0430\u0441\u0445\u043e\u0434\u044b \u2014 \u044d\u0442\u043e \u043a\u043b\u0430\u0441\u0441\u0438\u0447\u0435\u0441\u043a\u0430\u044f \u043f\u0440\u0438\u0447\u0438\u043d\u0430, \u043f\u043e \u043a\u043e\u0442\u043e\u0440\u043e\u0439 PostgreSQL \u043d\u0435 \u0434\u043e\u0431\u0430\u0432\u043b\u044f\u0435\u0442 «Timed wait events».<\/p>\n

\u041c\u044b \u043c\u043e\u0436\u0435\u043c \u043a\u043e\u0441\u0432\u0435\u043d\u043d\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u044d\u0442\u0438 \u0432\u0440\u0435\u043c\u0435\u043d\u0430 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u0434\u043e\u0431\u0430\u0432\u0438\u0432 \u043f\u0440\u043e\u0431\u0443 (probe) \u043a \u0444\u0443\u043d\u043a\u0446\u0438\u044f\u043c \u0437\u0430\u043f\u0443\u0441\u043a\u0430 \u0438 \u0437\u0430\u0432\u0435\u0440\u0448\u0435\u043d\u0438\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f (\u0444\u0443\u043d\u043a\u0446\u0438\u0438 pgstat_report_wait_start() \u0438 pgstat_report_wait_end()), \u043f\u0435\u0440\u0435\u0434 \u043a\u043e\u043c\u043f\u0438\u043b\u044f\u0446\u0438\u0435\u0439 \u0438 \u043b\u0438\u043d\u043a\u043e\u0432\u043a\u043e\u0439 \u0438\u0441\u0445\u043e\u0434\u043d\u043e\u0433\u043e \u043a\u043e\u0434\u0430. \u0418\u043c\u0435\u044f \u0442\u0430\u043a\u0443\u044e \u043f\u0440\u043e\u0431\u0443, \u043c\u044b \u043c\u043e\u0436\u0435\u043c \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c bpftrace (\u0438\u043b\u0438 SystemTap), \u0447\u0442\u043e\u0431\u044b \u043e\u0442\u0441\u043b\u0435\u0436\u0438\u0432\u0430\u0442\u044c \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043d\u0430\u0447\u0430\u043b\u0430 \u0438 \u043e\u043a\u043e\u043d\u0447\u0430\u043d\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u0430 \u0442\u0430\u043a\u0436\u0435 \u043f\u0440\u043e\u0441\u043c\u0430\u0442\u0440\u0438\u0432\u0430\u0442\u044c \u0438 \u0437\u0430\u0441\u0435\u043a\u0430\u0442\u044c \u0432\u0440\u0435\u043c\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u0439 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f.<\/p>\n

\u0414\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u0442\u0430\u043a\u0438\u0435 \u043f\u0440\u043e\u0431\u044b \u043f\u0440\u043e\u0441\u0442\u043e. \u041d\u0435\u043e\u0431\u0445\u043e\u0434\u0438\u043c\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u0432\u0441\u0435\u0433\u043e 5 \u043b\u0438\u043d\u0438\u0439 \u043a\u043e\u0434\u0430 \u0432 \u0438\u0441\u0445\u043e\u0434\u043d\u044b\u0439 \u043a\u043e\u0434 PostgreSQL, \u0447\u0442\u043e\u0431\u044b \u043f\u043e\u044f\u0432\u0438\u043b\u0438\u0441\u044c 2 \u043d\u043e\u0432\u044b\u0435 \u043f\u0440\u043e\u0431\u044b: \u043d\u0430\u0447\u0430\u043b\u0430 \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u043e\u043a\u043e\u043d\u0447\u0430\u043d\u0438\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f (wait event start and wait event end).<\/p>\n

\u0414\u043e\u0431\u0430\u0432\u044c\u0442\u0435 \u043f\u0440\u043e\u0431\u044b \u0432 \u0444\u0430\u0439\u043b, \u043a\u043e\u0442\u043e\u0440\u044b\u0439 \u0441\u043e\u0434\u0435\u0440\u0436\u0438\u0442 \u0444\u0443\u043d\u043a\u0446\u0438\u0438 pgstat_report_wait_start() and pgstat_report_wait_end(); (\u044d\u0442\u043e \u0444\u0430\u0439\u043b \u2014 src\/include\/utils\/wait_event.h<\/code>)<\/p>\n

diff --git a\/src\/include\/utils\/wait_event.h b\/src\/include\/utils\/wait_event.h index 009b03a520..f3b06113e9 100644 --- a\/src\/include\/utils\/wait_event.h +++ b\/src\/include\/utils\/wait_event.h @@ -28,6 +28,9 @@  \/* enums for wait events *\/  #include \"utils\/wait_event_types.h\"  +\/* pg_trace for TRACE_POSTGRESQL macros *\/ +#include \"pg_trace.h\" +  extern const char *pgstat_get_wait_event(uint32 wait_event_info);  extern const char *pgstat_get_wait_event_type(uint32 wait_event_info);  static inline void pgstat_report_wait_start(uint32 wait_event_info);  <\/code><\/pre>\n
@@ -87,6 +90,7 @@ extern char **GetWaitEventExtensionNames(int *nwaitevents);  static inline void  pgstat_report_wait_start(uint32 wait_event_info)  { +       TRACE_POSTGRESQL_WAIT_EVENT_START(wait_event_info);         \/*          * Since this is a four-byte field which is always read and written as          * four-bytes, updates are atomic.  <\/code><\/pre>\n
@@ -103,6 +107,7 @@ pgstat_report_wait_start(uint32 wait_event_info)  static inline void  pgstat_report_wait_end(void)  { +       TRACE_POSTGRESQL_WAIT_EVENT_END();         \/* see pgstat_report_wait_start() *\/         *(volatile uint32 *) my_wait_event_info = 0;  }  <\/code><\/pre>\n
\u0414\u043e\u0431\u0430\u0432\u044c\u0442\u0435 \u044d\u0442\u0438 \u043f\u0440\u043e\u0431\u044b \u0432 \u0441\u043f\u0438\u0441\u043e\u043a \u043f\u0440\u043e\u0431 \u0432 \u0444\u0430\u0439\u043b\u0435 src\/backend\/utils\/probes.d<\/code>:<\/p>\n
diff --git a\/src\/backend\/utils\/probes.d b\/src\/backend\/utils\/probes.d index 0af275587b..a1e53e8e24 100644 --- a\/src\/backend\/utils\/probes.d +++ b\/src\/backend\/utils\/probes.d @@ -91,4 +91,8 @@ provider postgresql {         probe wal__switch();         probe wal__buffer__write__dirty__start();         probe wal__buffer__write__dirty__done(); + +        probe wait__event__start(uint32); +        probe wait__event__end(); +  };  <\/code><\/pre>\n
\u0414\u0430\u043b\u0435\u0435 \u043d\u0435\u043e\u0431\u0445\u043e\u0434\u0438\u043c\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u043e\u043f\u0446\u0438\u044e(\u043a\u043b\u044e\u0447) \u0434\u043b\u044f \u0432\u043a\u043b\u044e\u0447\u0435\u043d\u0438\u044f dtrace \u043f\u0440\u0438 \u043a\u043e\u043c\u043f\u0438\u043b\u044f\u0446\u0438\u0438 (\u043f\u0440\u0438\u043c. \u043f\u0435\u0440\u0435\u0432\u043e\u0434\u0447\u0438\u043a\u0430 configure --enable-dtrace ...<\/code>), \u0430 \u0442\u0430\u043a\u0436\u0435 \u0441\u043a\u043e\u043c\u043f\u0438\u043b\u0438\u0440\u043e\u0432\u0430\u0442\u044c \u0438 \u0441\u043b\u0438\u043d\u043a\u043e\u0432\u0430\u0442\u044c \u0438\u0441\u0445\u043e\u0434\u043d\u044b\u0439 \u043a\u043e\u0434 PostgreSQL.<\/p>\n
\u0427\u0442\u043e\u0431\u044b \u043f\u043e\u0434\u0442\u0432\u0435\u0440\u0434\u0438\u0442\u044c \u0434\u043e\u0431\u0430\u0432\u043b\u0435\u043d\u0438\u0435 \u043d\u043e\u0432\u044b\u0445 \u043f\u0440\u043e\u0431, \u0432\u044b \u043c\u043e\u0436\u0435\u0442\u0435 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c \u043a\u043e\u043c\u0430\u043d\u0434\u0443 bpftrace -l<\/code> \u0434\u043b\u044f \u0432\u044b\u0432\u043e\u0434\u0430 \u0441\u043f\u0438\u0441\u043a\u0430 \u043f\u0440\u043e\u0431:<\/p>\n
bpftrace -l 'usdt:\/usr\/local\/pgsql\/bin\/postgres:wait*' usdt:\/usr\/local\/pgsql\/bin\/postgres:postgresql:wait__event__end usdt:\/usr\/local\/pgsql\/bin\/postgres:postgresql:wait__event__start  <\/code><\/pre>\n
\u0412\u043e\u0442 \u043e\u043d\u0438!<\/p>\n
\u042f \u0440\u0430\u0441\u0448\u0438\u0440\u0438\u043b \u0441\u043a\u0440\u0438\u043f\u0442 query-analyzer.bt<\/code> \u0441 \u043f\u043e\u043c\u043e\u0449\u044c\u044e \u0441\u043e\u0431\u044b\u0442\u0438\u0439 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u043f\u043e\u043b\u0443\u0447\u0438\u043b: query-analyzer-waits.bt<\/a>.<\/p>\n
\u0422\u0435\u043f\u0435\u0440\u044c \u044f \u043c\u043e\u0433\u0443 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c bpftrace \u0438 \u043f\u0440\u043e\u0431\u044b, \u0447\u0442\u043e\u0431\u044b \u0443\u0432\u0438\u0434\u0435\u0442\u044c, \u043d\u0430 \u0447\u0442\u043e \u0440\u0430\u0441\u0445\u043e\u0434\u0443\u0435\u0442\u0441\u044f \u0432\u0440\u0435\u043c\u044f, \u0432\u043a\u043b\u044e\u0447\u0430\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f:<\/p>\n
root@84fe326249c0:\/postgres-bpftrace# .\/query-analyzer-waits.bt -p 18183 Attaching 200 probes... PostgreSQL statement execution analyzer. Time in microseconds (us). pid   :Phase      :time to phase :time in phase : query ------|-----------|--------------|--------------|------ [21964] WAIT      : (          ) :    3878097701: . [21964]Query start:              :              : select now(); [21964] parse     : (       113) :           318: select now(); [21964] rewrite   : (       199) :           302: select now(); [21964] plan      : (       102) :           488: select now(); [21964] execute   : (       647) :           294: select now(); [21964]Query done : (       505) :          2972: select now(); <\/code><\/pre>\n
\u042f \u0432\u044b\u043f\u043e\u043b\u043d\u0438\u043b select now(); \u0432 psql, \u043c\u044b \u043c\u043e\u0436\u0435\u043c \u0432\u0438\u0434\u0435\u0442\u044c, \u0447\u0442\u043e \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u0443\u0435\u0442\u0441\u044f simple query protocol (Query start\/Query done). \u0412\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u0435 \u0437\u0430\u0432\u0435\u0440\u0448\u0438\u043b\u043e\u0441\u044c \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435\u043c, \u043d\u043e \u043f\u043e\u0441\u043a\u043e\u043b\u044c\u043a\u0443 \u0438\u043d\u0444\u043e\u0440\u043c\u0430\u0446\u0438\u044f \u043e \u043a\u043b\u0430\u0441\u0441\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u0438\u043c\u0435\u043d\u0438 \u0434\u043e\u0441\u0442\u0443\u043f\u043d\u0430 \u0442\u043e\u043b\u044c\u043a\u043e \u043f\u0440\u0438 \u0437\u0430\u043f\u0443\u0441\u043a\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u044f \u043d\u0435 \u043c\u043e\u0433\u0443 \u0443\u0432\u0438\u0434\u0435\u0442\u044c \u044d\u0442\u043e \u0437\u0434\u0435\u0441\u044c. \u042d\u0442\u043e client.CLIENT_READ<\/code> \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435.<\/p>\n
\u0414\u043b\u044f \u0442\u0430\u043a\u043e\u0433\u043e \u043d\u0435\u0431\u043e\u043b\u044c\u0448\u043e\u0433\u043e, \u043f\u0440\u043e\u0441\u0442\u043e\u0433\u043e \u0437\u0430\u043f\u0440\u043e\u0441\u0430 \u0432\u043e\u043e\u0431\u0449\u0435 \u043d\u0435 \u0432\u043e\u0437\u043d\u0438\u043a\u0430\u0435\u0442 \u0441\u043e\u0431\u044b\u0442\u0438\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f. \u042d\u0442\u043e \u043d\u0435\u043c\u043d\u043e\u0433\u043e \u0441\u0442\u0440\u0430\u043d\u043d\u043e. \u042f \u0443\u0432\u0435\u0440\u0435\u043d, \u0447\u0442\u043e \u0440\u0435\u0437\u0443\u043b\u044c\u0442\u0430\u0442 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u043e\u0442\u043f\u0440\u0430\u0432\u043b\u044f\u0435\u0442\u0441\u044f \u043e\u0431\u0440\u0430\u0442\u043d\u043e \u043c\u043e\u0435\u043c\u0443 \u043a\u043b\u0438\u0435\u043d\u0442\u0443 (psql). \u041f\u043e\u043b\u0443\u0447\u0430\u0435\u0442\u0441\u044f, \u0447\u0442\u043e \u044d\u0442\u0430 \u043e\u0442\u043f\u0440\u0430\u0432\u043a\u0430 \u043d\u0435 \u043f\u043e\u0441\u0447\u0438\u0442\u0430\u043d\u0430?<\/p>\n
\u042f \u043f\u043e\u0447\u0442\u0438 \u0443\u0432\u0435\u0440\u0435\u043d, \u0447\u0442\u043e \u044d\u0442\u043e \u0441\u0434\u0435\u043b\u0430\u043d\u043e \u043d\u0430\u043c\u0435\u0440\u0435\u043d\u043d\u043e, \u043f\u043e\u0442\u043e\u043c\u0443 \u0447\u0442\u043e \u0435\u0441\u043b\u0438 \u044f \u043e\u0442\u043f\u0440\u0430\u0432\u043b\u044e \u043a\u043b\u0438\u0435\u043d\u0442\u0443 \u043c\u043d\u043e\u0433\u043e \u0434\u0430\u043d\u043d\u044b\u0445, \u043c\u043e\u0436\u043d\u043e \u0441\u0433\u0435\u043d\u0435\u0440\u0438\u0440\u043e\u0432\u0430\u0442\u044c client.CLIENT_WRITE<\/code> \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435. \u0421\u043e\u0431\u044b\u0442\u0438\u0435 \u043a\u043b\u0438\u0435\u043d\u0442.CLIENT_WRITE<\/code>, \u043f\u043e-\u0432\u0438\u0434\u0438\u043c\u043e\u043c\u0443, \u044f\u0432\u043b\u044f\u0435\u0442\u0441\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u0435\u043c, \u043a\u043e\u0442\u043e\u0440\u043e\u0435 \u043f\u043e\u043a\u0430\u0437\u044b\u0432\u0430\u0435\u0442 \u0432\u0440\u0435\u043c\u044f, \u0437\u0430\u0442\u0440\u0430\u0447\u0435\u043d\u043d\u043e\u0435 \u043d\u0430 \u043e\u0442\u043f\u0440\u0430\u0432\u043a\u0443 \u0434\u0430\u043d\u043d\u044b\u0445 \u043a\u043b\u0438\u0435\u043d\u0442\u0443 (\u0434\u043b\u044f \u044d\u0442\u043e\u0433\u043e \u043e\u0442\u043a\u043b\u044e\u0447\u0438\u0442\u0435 \u043f\u0435\u0439\u0434\u0436\u0438\u043d\u0433 \u0432 psql<\/code>: \\pset pager off<\/code>):<\/p>\n
[21964] WAIT      : (          ) :      22160788: client.CLIENT_READ [21964]Query start:              :              : select repeat('x',1000000); [21964] parse     : (        90) :            49: select repeat('x',1000000); [21964] rewrite   : (       422) :            48: select repeat('x',1000000); [21964] plan      : (       669) :          5788: select repeat('x',1000000); [21964] WAIT      : (          ) :           444: client.CLIENT_WRITE [21964] WAIT      : (          ) :           119: client.CLIENT_WRITE [21964] WAIT      : (          ) :           266: client.CLIENT_WRITE [21964] execute   : (        98) :          1776: select repeat('x',1000000); [21964]Query done : (       166) :          9109: select repeat('x',1000000);  <\/code><\/pre>\n
\u0422\u0430\u043a\u0436\u0435 \u0438\u043d\u0442\u0435\u0440\u0435\u0441\u043d\u043e: \u043a\u043e\u0433\u0434\u0430 \u044f \u0441\u043e\u0437\u0434\u0430\u044e \u0442\u0430\u0431\u043b\u0438\u0446\u0443, \u0432\u044b\u0437\u043e\u0432 WAL write(io.WAL_WRITE<\/code>) \u0438 fsync() (io.WAL_SYNC<\/code>) \u043f\u0440\u043e\u0438\u0441\u0445\u043e\u0434\u0438\u0442, \u043a\u043e\u0433\u0434\u0430 \u0444\u0430\u0437\u0430 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u0437\u0430\u0432\u0435\u0440\u0448\u0435\u043d\u0430 (\u0444\u0430\u0437\u0430 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f [execute] \u0441\u043e\u043e\u0431\u0449\u0430\u0435\u0442 \u043e \u0441\u0432\u043e\u0435\u043c \u0432\u0440\u0435\u043c\u0435\u043d\u0438 \u0434\u043e io.WAL_WRITE<\/code> \u0438 io.WAL_SYNC<\/code>):<\/p>\n
[21964] WAIT      : (          ) :      11254040: client.CLIENT_READ [21964]Query start:              :              : create table t(id int, f1 text); [21964] parse     : (        71) :            83: create table t(id int, f1 text); [21964] rewrite   : (       283) :             8: create table t(id int, f1 text); [21964] WAIT      : (          ) :           292: io.DATA_FILE_EXTEND [21964] WAIT      : (          ) :           116: io.DATA_FILE_EXTEND [21964] WAIT      : (          ) :          4512: io.DATA_FILE_IMMEDIATE_SYNC [21964] execute   : (         0) :         12127: create table t(id int, f1 text); [21964] WAIT      : (          ) :            67: io.WAL_WRITE [21964] WAIT      : (          ) :          1778: io.WAL_SYNC [21964]Query done : (      2425) :         15252: create table t(id int, f1 text); <\/code><\/pre>\n
\u0418 \u0435\u0441\u043b\u0438 \u044f \u0432\u0441\u0442\u0430\u0432\u043b\u044f\u044e \u0434\u0430\u043d\u043d\u044b\u0435, \u0444\u0443\u043d\u043a\u0446\u0438\u044f fsync() \u0442\u0430\u043a\u0436\u0435 \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u0435\u0442\u0441\u044f \u0432\u043d\u0435 \u0444\u0430\u0437\u044b \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f:<\/p>\n
[21964] WAIT      : (          ) :      45872174: client.CLIENT_READ [21964]Query start:              :              : insert into t select id, repeat('x',10) from generate_series(1, [21964] parse     : (       361) :           645: insert into t select id, repeat('x',10) from generate_series(1, [21964] rewrite   : (       935) :          1296: insert into t select id, repeat('x',10) from generate_series(1, [21964] plan      : (        97) :          2486: insert into t select id, repeat('x',10) from generate_series(1, [21964] WAIT      : (          ) :           638: io.DATA_FILE_EXTEND [21964] execute   : (         0) :          1969: insert into t select id, repeat('x',10) from generate_series(1, [21964] execute   : (         0) :          2131: insert into t select id, repeat('x',10) from generate_series(1, [21964] WAIT      : (          ) :            98: io.WAL_WRITE [21964] WAIT      : (          ) :          2448: io.WAL_SYNC [21964]Query done : (      3401) :         11518: insert into t select id, repeat('x',10) from generate_series(1, <\/code><\/pre>\n
\u0410 \u0432\u043e\u0442 \u043a\u0430\u043a \u0432\u044b\u0433\u043b\u044f\u0434\u0438\u0442 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u043d\u0438\u0435 TEMP’a:<\/p>\n
[21964] WAIT      : (          ) :       5325897: client.CLIENT_READ [21964]Query start:              :              : select count(*) from generate_series(1,85_350); [21964] parse     : (        94) :            41: select count(*) from generate_series(1,85_350); [21964] rewrite   : (       115) :            58: select count(*) from generate_series(1,85_350); [21964] plan      : (        49) :            62: select count(*) from generate_series(1,85_350); [21964] WAIT      : (          ) :            33: io.BUFFILE_WRITE [21964] WAIT      : (          ) :             8: io.BUFFILE_WRITE [21964] WAIT      : (          ) :            12: io.BUFFILE_WRITE [21964] WAIT      : (          ) :            12: io.BUFFILE_WRITE [21964] WAIT      : (          ) :             7: io.BUFFILE_WRITE ...many more io.BUFFILE_WRITEs... [21964] WAIT      : (          ) :            10: io.BUFFILE_READ [21964] WAIT      : (          ) :             6: io.BUFFILE_READ [21964] WAIT      : (          ) :             6: io.BUFFILE_READ [21964] WAIT      : (          ) :             4: io.BUFFILE_READ [21964] WAIT      : (          ) :             4: io.BUFFILE_READ ...many more io.BUFFILE_READs... [21964] execute   : (        67) :         35538: select count(*) from generate_series(1,85_350); [21964]Query done : (       275) :         36303: select count(*) from generate_series(1,85_350); <\/code><\/pre>\n
\u041f\u043e\u0447\u0442\u0438 \u0442\u0430\u043a\u043e\u0435 \u0436\u0435 \u043a\u043e\u043b\u0438\u0447\u0435\u0441\u0442\u0432\u043e Temp IO \u043c\u043e\u0436\u043d\u043e \u0443\u0432\u0438\u0434\u0435\u0442\u044c \u0441 \u043f\u043e\u043c\u043e\u0449\u044c\u044e explain analyse (buffers).<\/p>\n
\u041f\u0435\u0440\u0432\u044b\u0439 \u0441\u0435\u0430\u043d\u0441 \u0434\u043b\u044f \u0432\u0445\u043e\u0434\u0430 \u0432 \u0431\u0430\u0437\u0443 \u0434\u0430\u043d\u043d\u044b\u0445 \u0434\u043e\u043b\u0436\u0435\u043d (\u043f\u043e\u0432\u0442\u043e\u0440\u043d\u043e) \u0441\u043e\u0437\u0434\u0430\u0442\u044c relcache. \u042d\u0442\u043e \u0434\u0435\u043b\u0430\u0435\u0442\u0441\u044f \u0434\u043e \u0442\u043e\u0433\u043e, \u043a\u0430\u043a \u0441\u0435\u0430\u043d\u0441 \u043d\u0430\u0447\u043d\u0435\u0442 \u0447\u0442\u043e-\u043b\u0438\u0431\u043e \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u0442\u044c. \u0412\u043e\u0442 \u043a\u0430\u043a \u044d\u0442\u043e \u0432\u044b\u0433\u043b\u044f\u0434\u0438\u0442 \u0432 \u043c\u043e\u0435\u0439 \u0431\u0430\u0437\u0435 \u0434\u0430\u043d\u043d\u044b\u0445:<\/p>\n
[14454] WAIT      : (          ) :            32: io.RELATION_MAP_READ [14454] WAIT      : (          ) :            66: io.DATA_FILE_READ [14454] WAIT      : (          ) :            10: io.RELATION_MAP_READ [14454] WAIT      : (          ) :            68: io.DATA_FILE_READ [14454] WAIT      : (          ) :            45: io.DATA_FILE_READ [14454] WAIT      : (          ) :            21: io.DATA_FILE_READ [14454] WAIT      : (          ) :            42: io.DATA_FILE_READ [14454] WAIT      : (          ) :            77: io.DATA_FILE_READ [14454] WAIT      : (          ) :            39: io.DATA_FILE_READ [14454] WAIT      : (          ) :            19: io.DATA_FILE_READ [14454] WAIT      : (          ) :            49: io.DATA_FILE_READ [14454] WAIT      : (          ) :            14: io.DATA_FILE_READ [14454] WAIT      : (          ) :           120: io.DATA_FILE_READ [14454] WAIT      : (          ) :            16: io.DATA_FILE_READ ...more io.DATA_FILE_READs  <\/code><\/pre>\n
\u0412 \u043c\u043e\u0435\u0439 \u0431\u0430\u0437\u0435 \u0434\u0430\u043d\u043d\u044b\u0445 \u0431\u0435\u0437 \u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u0435\u043b\u044c\u0441\u043a\u0438\u0445 \u0442\u0430\u0431\u043b\u0438\u0446 \u044d\u0442\u043e \u0433\u0435\u043d\u0435\u0440\u0438\u0440\u0443\u0435\u0442 2 \u0441\u043e\u0431\u044b\u0442\u0438\u044f io.RELATION_MAP_READ<\/code> \u0438 71 \u0441\u043e\u0431\u044b\u0442\u0438\u0435 io.DATA_FILE_READ<\/code>. \u041e\u043d\u0438 \u043a\u0435\u0448\u0438\u0440\u0443\u044e\u0442\u0441\u044f \u0432 \u043e\u043f\u0435\u0440\u0430\u0446\u0438\u043e\u043d\u043d\u043e\u0439 \u0441\u0438\u0441\u0442\u0435\u043c\u0435, \u0438 \u043f\u043e\u044d\u0442\u043e\u043c\u0443 \u0443 \u043d\u0438\u0445 \u0443\u043a\u0430\u0437\u0430\u043d\u043d\u0430\u044f \u0432\u044b\u0448\u0435 \u043c\u0438\u0437\u0435\u0440\u043d\u0430\u044f \u0437\u0430\u0434\u0435\u0440\u0436\u043a\u0430 (\u0437\u0430\u0434\u0435\u0440\u0436\u043a\u0430 \u0443\u043a\u0430\u0437\u0430\u043d\u0430 \u0432 \u043c\u0438\u043a\u0440\u043e\u0441\u0435\u043a\u0443\u043d\u0434\u0430\u0445!).<\/p>\n
\u0412\u043f\u043e\u043b\u043d\u0435 \u0432\u0435\u0440\u043e\u044f\u0442\u043d\u043e, \u0447\u0442\u043e \u044d\u0442\u043e \u043f\u0440\u043e\u0438\u0441\u0445\u043e\u0434\u0438\u0442 \u043d\u0435 \u0442\u043e\u043b\u044c\u043a\u043e \u043f\u0440\u0438 \u043f\u0435\u0440\u0432\u043e\u043c \u0432\u0445\u043e\u0434\u0435 \u0432 \u0441\u0438\u0441\u0442\u0435\u043c\u0443, \u043d\u043e \u0438 \u043f\u0440\u0438 \u0438\u0437\u043c\u0435\u043d\u0435\u043d\u0438\u0438 \u0442\u0430\u0431\u043b\u0438\u0446, \u0442\u0440\u0435\u0431\u0443\u044e\u0449\u0435\u043c \u043e\u0431\u043d\u043e\u0432\u043b\u0435\u043d\u0438\u044f relcaches, \u043a\u043e\u0442\u043e\u0440\u044b\u0435 \u044f\u0432\u043b\u044f\u044e\u0442\u0441\u044f \u0444\u0430\u0439\u043b\u0430\u043c\u0438. \u0421\u043a\u043e\u0440\u0435\u0435 \u0432\u0441\u0435\u0433\u043e, \u043e\u043d\u0438 \u043d\u0430\u0445\u043e\u0434\u044f\u0442\u0441\u044f \u0437\u0430 \u043f\u0440\u0435\u0434\u0435\u043b\u0430\u043c\u0438 \u0444\u0430\u0437\u044b \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u0438, \u0441\u043b\u0435\u0434\u043e\u0432\u0430\u0442\u0435\u043b\u044c\u043d\u043e, \u044d\u0442\u0438 \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043f\u043e\u0442\u0435\u043d\u0446\u0438\u0430\u043b\u044c\u043d\u043e \u0442\u0440\u0443\u0434\u043d\u043e \u043e\u0431\u043d\u0430\u0440\u0443\u0436\u0438\u0442\u044c.<\/p>\n
\u0424\u0430\u043a\u0442\u0438\u0447\u0435\u0441\u043a\u0438, \u043e\u043f\u0435\u0440\u0430\u0446\u0438\u0438 \u0447\u0442\u0435\u043d\u0438\u044f relcache \u0442\u0430\u043a\u0436\u0435 \u0437\u0430\u043f\u0438\u0441\u044b\u0432\u0430\u044e\u0442 init-\u0444\u0430\u0439\u043b\u044b relcache \u043f\u0440\u0438 \u043f\u0435\u0440\u0432\u043e\u043c \u043e\u0431\u0440\u0430\u0449\u0435\u043d\u0438\u0438 \u043a \u0431\u0430\u0437\u0435 \u0434\u0430\u043d\u043d\u044b\u0445. \u041e\u0434\u043d\u0430\u043a\u043e \u043d\u0435\u0442 \u0441\u043e\u0431\u044b\u0442\u0438\u044f io.RELATION_MAP_WRITE<\/code>. \u041c\u043d\u0435 \u0431\u044b\u043b\u043e \u0438\u043d\u0442\u0435\u0440\u0435\u0441\u043d\u043e, \u0435\u0441\u0442\u044c \u043b\u0438 \u043a\u0430\u043a\u043e\u0439-\u0442\u043e \u043c\u0435\u0445\u0430\u043d\u0438\u0437\u043c \u0434\u043b\u044f \u043f\u0440\u043e\u0432\u0435\u0440\u043a\u0438 \u0442\u043e\u0433\u043e, \u0447\u0442\u043e \u0441\u0443\u0449\u0435\u0441\u0442\u0432\u0443\u044e\u0449\u0438\u0435 \u0444\u0430\u0439\u043b\u044b \u0432\u0441\u0435 \u0435\u0449\u0435 \u0434\u0435\u0439\u0441\u0442\u0432\u0438\u0442\u0435\u043b\u044c\u043d\u044b, \u043d\u043e \u0431\u044b\u0441\u0442\u0440\u043e\u0435 \u0438\u0441\u0441\u043b\u0435\u0434\u043e\u0432\u0430\u043d\u0438\u0435 \u043f\u0440\u0438 \u043f\u043e\u043c\u043e\u0449\u0438 strace -fp \u043f\u043e\u043a\u0430\u0437\u044b\u0432\u0430\u0435\u0442, \u0447\u0442\u043e \u0444\u0430\u0439\u043b\u044b \u0438\u043d\u0438\u0446\u0438\u0430\u043b\u0438\u0437\u0430\u0446\u0438\u0438 relcache \u0437\u0430\u043f\u0438\u0441\u044b\u0432\u0430\u044e\u0442\u0441\u044f, \u0442\u043e\u043b\u044c\u043a\u043e \u043d\u0435\u0437\u0430\u043c\u0435\u0442\u043d\u043e (\u0438\u0437-\u0437\u0430 \u043e\u0442\u0441\u0443\u0442\u0441\u0442\u0432\u0438\u044f io.RELATION_MAP_WRITE<\/code>).<\/p>\n
\u041a\u043e\u0433\u0434\u0430 \u044f \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u044e \u043f\u0435\u0440\u0432\u044b\u0439 \u0437\u0430\u043f\u0440\u043e\u0441, \u0441\u0435\u0440\u0432\u0435\u0440\u043d\u0430\u044f \u0447\u0430\u0441\u0442\u044c \u0434\u043e\u043b\u0436\u043d\u0430 \u0437\u0430\u043f\u043e\u043b\u043d\u0438\u0442\u044c \u0441\u0432\u043e\u0439 \u043a\u0430\u0442\u0430\u043b\u043e\u0433, \u043a\u043e\u0442\u043e\u0440\u044b\u0439 \u0442\u0430\u043a\u0436\u0435 \u0433\u0435\u043d\u0435\u0440\u0438\u0440\u0443\u0435\u0442 \u043d\u0435\u043a\u043e\u0442\u043e\u0440\u044b\u0435 \u0441\u043e\u0431\u044b\u0442\u0438\u044f io.DATA_FILE_READ<\/code>:<\/p>\n
[14454]Query start:              :              : select now(); [14454] parse     : (       316) :           811: select now(); [14454] WAIT      : (          ) :           200: io.DATA_FILE_READ [14454] WAIT      : (          ) :           105: io.DATA_FILE_READ [14454] WAIT      : (          ) :            95: io.DATA_FILE_READ [14454] WAIT      : (          ) :            42: io.DATA_FILE_READ [14454] WAIT      : (          ) :            57: io.DATA_FILE_READ [14454] WAIT      : (          ) :           140: io.DATA_FILE_READ [14454] WAIT      : (          ) :            46: io.DATA_FILE_READ [14454] WAIT      : (          ) :            60: io.DATA_FILE_READ [14454] WAIT      : (          ) :            36: io.DATA_FILE_READ [14454] WAIT      : (          ) :            57: io.DATA_FILE_READ [14454] WAIT      : (          ) :            65: io.DATA_FILE_READ [14454] WAIT      : (          ) :            66: io.DATA_FILE_READ [14454] WAIT      : (          ) :            30: io.DATA_FILE_READ [14454] WAIT      : (          ) :            89: io.DATA_FILE_READ [14454] rewrite   : (       510) :          7532: select now(); [14454] plan      : (       502) :           612: select now(); [14454] execute   : (       453) :           134: select now(); [14454]Query done : (       322) :         11197: select now();  <\/code><\/pre>\n
\u0412\u0430\u0436\u043d\u043e, \u0447\u0442\u043e \u043e\u043d\u0438 \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u044e\u0442\u0441\u044f \u043d\u0430 \u044d\u0442\u0430\u043f\u0435 rewrite. \u0421\u043b\u0435\u0434\u043e\u0432\u0430\u0442\u0435\u043b\u044c\u043d\u043e, \u0444\u0430\u0437\u0430 rewrite \u0437\u0430\u043d\u0438\u043c\u0430\u0435\u0442 \u0431\u043e\u043b\u044c\u0448\u0435 \u0432\u0440\u0435\u043c\u0435\u043d\u0438. \u042d\u0442\u0430 \u0444\u0430\u0437\u0430 \u0432 \u043e\u0441\u043d\u043e\u0432\u043d\u043e\u043c \u043d\u0435 \u043f\u043e\u043f\u0430\u0434\u0430\u0435\u0442 \u0432 \u043e\u0442\u0447\u0451\u0442\u044b \u043f\u043e \u043f\u0440\u043e\u0438\u0437\u0432\u043e\u0434\u0438\u0442\u0435\u043b\u044c\u043d\u043e\u0441\u0442\u0438 \u0438 \u043d\u0435 \u0432\u0438\u0434\u043d\u0430 \u0432 pg_stat_statements.<\/p>\n<\/div>\n<\/div>\n<\/div>\n
<\/div>\n

 \u0441\u0441\u044b\u043b\u043a\u0430 \u043d\u0430 \u043e\u0440\u0438\u0433\u0438\u043d\u0430\u043b \u0441\u0442\u0430\u0442\u044c\u0438  https:\/\/habr.com\/ru\/articles\/778670\/<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"
<\/div>\n
\n
\n
\n
\n
\u042d\u0442\u0430 \u043f\u0443\u0431\u043b\u0438\u043a\u0430\u0446\u0438\u044f \u2014 \u043f\u0435\u0440\u0435\u0432\u043e\u0434 \u0432\u0442\u043e\u0440\u043e\u0439 \u0441\u0442\u0430\u0442\u044c\u0438 \u0438\u0437\u0432\u0435\u0441\u0442\u043d\u043e\u0433\u043e \u0441\u043f\u0435\u0446\u0438\u0430\u043b\u0438\u0441\u0442\u0430 \u0432 \u043e\u0431\u043b\u0430\u0441\u0442\u0438 Oracle \u0424\u0440\u0438\u0446\u0430 \u0425\u0443\u0433\u043b\u0430\u043d\u0434\u0430 \u043d\u0430 \u0437\u0430\u0434\u0430\u043d\u043d\u0443\u044e \u0442\u0435\u043c\u0443 (\u043f\u0435\u0440\u0432\u0443\u044e \u0441\u0442\u0430\u0442\u044c\u044e \u044f \u043f\u0435\u0440\u0435\u0432\u0451\u043b \u0440\u0430\u043d\u0435\u0435 \u0441\u043c. <\/em>\u0418\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u043d\u0438\u0435 bpftrace \u0434\u043b\u044f \u0442\u0440\u0430\u0441\u0441\u0438\u0440\u043e\u0432\u043a\u0438 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u0437\u0430\u043f\u0440\u043e\u0441\u043e\u0432 \u0432 postgres<\/em><\/a>)<\/em><\/p>\n
\u042d\u0442\u043e \u0442\u043e, \u0447\u0435\u0433\u043e \u043d\u0435 \u0441\u0443\u0449\u0435\u0441\u0442\u0432\u0443\u0435\u0442 \u0432 PostgreSQL \u043d\u0430 \u043c\u043e\u043c\u0435\u043d\u0442 \u043d\u0430\u043f\u0438\u0441\u0430\u043d\u0438\u044f \u0441\u0442\u0430\u0442\u044c\u0438. \u041e\u0434\u043d\u0430\u043a\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u044d\u0442\u043e (timed wait events) \u0447\u0440\u0435\u0437\u0432\u044b\u0447\u0430\u0439\u043d\u043e \u043f\u0440\u043e\u0441\u0442\u043e, \u043f\u0440\u0438\u0447\u0435\u043c \u0441 \u043d\u0435\u0437\u043d\u0430\u0447\u0438\u0442\u0435\u043b\u044c\u043d\u044b\u043c\u0438 \u043d\u0430\u043a\u043b\u0430\u0434\u043d\u044b\u043c\u0438 \u0440\u0430\u0441\u0445\u043e\u0434\u0430\u043c\u0438. \u041d\u0430\u043a\u043b\u0430\u0434\u043d\u044b\u0435 \u0440\u0430\u0441\u0445\u043e\u0434\u044b \u2014 \u044d\u0442\u043e \u043a\u043b\u0430\u0441\u0441\u0438\u0447\u0435\u0441\u043a\u0430\u044f \u043f\u0440\u0438\u0447\u0438\u043d\u0430, \u043f\u043e \u043a\u043e\u0442\u043e\u0440\u043e\u0439 PostgreSQL \u043d\u0435 \u0434\u043e\u0431\u0430\u0432\u043b\u044f\u0435\u0442 «Timed wait events».<\/p>\n
\u041c\u044b \u043c\u043e\u0436\u0435\u043c \u043a\u043e\u0441\u0432\u0435\u043d\u043d\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u044d\u0442\u0438 \u0432\u0440\u0435\u043c\u0435\u043d\u0430 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u0434\u043e\u0431\u0430\u0432\u0438\u0432 \u043f\u0440\u043e\u0431\u0443 (probe) \u043a \u0444\u0443\u043d\u043a\u0446\u0438\u044f\u043c \u0437\u0430\u043f\u0443\u0441\u043a\u0430 \u0438 \u0437\u0430\u0432\u0435\u0440\u0448\u0435\u043d\u0438\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f (\u0444\u0443\u043d\u043a\u0446\u0438\u0438 pgstat_report_wait_start() \u0438 pgstat_report_wait_end()), \u043f\u0435\u0440\u0435\u0434 \u043a\u043e\u043c\u043f\u0438\u043b\u044f\u0446\u0438\u0435\u0439 \u0438 \u043b\u0438\u043d\u043a\u043e\u0432\u043a\u043e\u0439 \u0438\u0441\u0445\u043e\u0434\u043d\u043e\u0433\u043e \u043a\u043e\u0434\u0430. \u0418\u043c\u0435\u044f \u0442\u0430\u043a\u0443\u044e \u043f\u0440\u043e\u0431\u0443, \u043c\u044b \u043c\u043e\u0436\u0435\u043c \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c bpftrace (\u0438\u043b\u0438 SystemTap), \u0447\u0442\u043e\u0431\u044b \u043e\u0442\u0441\u043b\u0435\u0436\u0438\u0432\u0430\u0442\u044c \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043d\u0430\u0447\u0430\u043b\u0430 \u0438 \u043e\u043a\u043e\u043d\u0447\u0430\u043d\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u0430 \u0442\u0430\u043a\u0436\u0435 \u043f\u0440\u043e\u0441\u043c\u0430\u0442\u0440\u0438\u0432\u0430\u0442\u044c \u0438 \u0437\u0430\u0441\u0435\u043a\u0430\u0442\u044c \u0432\u0440\u0435\u043c\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u0439 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f.<\/p>\n
\u0414\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u0442\u0430\u043a\u0438\u0435 \u043f\u0440\u043e\u0431\u044b \u043f\u0440\u043e\u0441\u0442\u043e. \u041d\u0435\u043e\u0431\u0445\u043e\u0434\u0438\u043c\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u0432\u0441\u0435\u0433\u043e 5 \u043b\u0438\u043d\u0438\u0439 \u043a\u043e\u0434\u0430 \u0432 \u0438\u0441\u0445\u043e\u0434\u043d\u044b\u0439 \u043a\u043e\u0434 PostgreSQL, \u0447\u0442\u043e\u0431\u044b \u043f\u043e\u044f\u0432\u0438\u043b\u0438\u0441\u044c 2 \u043d\u043e\u0432\u044b\u0435 \u043f\u0440\u043e\u0431\u044b: \u043d\u0430\u0447\u0430\u043b\u0430 \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u043e\u043a\u043e\u043d\u0447\u0430\u043d\u0438\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f (wait event start and wait event end).<\/p>\n
\u0414\u043e\u0431\u0430\u0432\u044c\u0442\u0435 \u043f\u0440\u043e\u0431\u044b \u0432 \u0444\u0430\u0439\u043b, \u043a\u043e\u0442\u043e\u0440\u044b\u0439 \u0441\u043e\u0434\u0435\u0440\u0436\u0438\u0442 \u0444\u0443\u043d\u043a\u0446\u0438\u0438 pgstat_report_wait_start() and pgstat_report_wait_end(); (\u044d\u0442\u043e \u0444\u0430\u0439\u043b \u2014 src\/include\/utils\/wait_event.h<\/code>)<\/p>\n
diff --git a\/src\/include\/utils\/wait_event.h b\/src\/include\/utils\/wait_event.h index 009b03a520..f3b06113e9 100644 --- a\/src\/include\/utils\/wait_event.h +++ b\/src\/include\/utils\/wait_event.h @@ -28,6 +28,9 @@  \/* enums for wait events *\/  #include \"utils\/wait_event_types.h\"  +\/* pg_trace for TRACE_POSTGRESQL macros *\/ +#include \"pg_trace.h\" +  extern const char *pgstat_get_wait_event(uint32 wait_event_info);  extern const char *pgstat_get_wait_event_type(uint32 wait_event_info);  static inline void pgstat_report_wait_start(uint32 wait_event_info);  <\/code><\/pre>\n
@@ -87,6 +90,7 @@ extern char **GetWaitEventExtensionNames(int *nwaitevents);  static inline void  pgstat_report_wait_start(uint32 wait_event_info)  { +       TRACE_POSTGRESQL_WAIT_EVENT_START(wait_event_info);         \/*          * Since this is a four-byte field which is always read and written as          * four-bytes, updates are atomic.  <\/code><\/pre>\n
@@ -103,6 +107,7 @@ pgstat_report_wait_start(uint32 wait_event_info)  static inline void  pgstat_report_wait_end(void)  { +       TRACE_POSTGRESQL_WAIT_EVENT_END();         \/* see pgstat_report_wait_start() *\/         *(volatile uint32 *) my_wait_event_info = 0;  }  <\/code><\/pre>\n
\u0414\u043e\u0431\u0430\u0432\u044c\u0442\u0435 \u044d\u0442\u0438 \u043f\u0440\u043e\u0431\u044b \u0432 \u0441\u043f\u0438\u0441\u043e\u043a \u043f\u0440\u043e\u0431 \u0432 \u0444\u0430\u0439\u043b\u0435 src\/backend\/utils\/probes.d<\/code>:<\/p>\n
diff --git a\/src\/backend\/utils\/probes.d b\/src\/backend\/utils\/probes.d index 0af275587b..a1e53e8e24 100644 --- a\/src\/backend\/utils\/probes.d +++ b\/src\/backend\/utils\/probes.d @@ -91,4 +91,8 @@ provider postgresql {         probe wal__switch();         probe wal__buffer__write__dirty__start();         probe wal__buffer__write__dirty__done(); + +        probe wait__event__start(uint32); +        probe wait__event__end(); +  };  <\/code><\/pre>\n
\u0414\u0430\u043b\u0435\u0435 \u043d\u0435\u043e\u0431\u0445\u043e\u0434\u0438\u043c\u043e \u0434\u043e\u0431\u0430\u0432\u0438\u0442\u044c \u043e\u043f\u0446\u0438\u044e(\u043a\u043b\u044e\u0447) \u0434\u043b\u044f \u0432\u043a\u043b\u044e\u0447\u0435\u043d\u0438\u044f dtrace \u043f\u0440\u0438 \u043a\u043e\u043c\u043f\u0438\u043b\u044f\u0446\u0438\u0438 (\u043f\u0440\u0438\u043c. \u043f\u0435\u0440\u0435\u0432\u043e\u0434\u0447\u0438\u043a\u0430 configure --enable-dtrace ...<\/code>), \u0430 \u0442\u0430\u043a\u0436\u0435 \u0441\u043a\u043e\u043c\u043f\u0438\u043b\u0438\u0440\u043e\u0432\u0430\u0442\u044c \u0438 \u0441\u043b\u0438\u043d\u043a\u043e\u0432\u0430\u0442\u044c \u0438\u0441\u0445\u043e\u0434\u043d\u044b\u0439 \u043a\u043e\u0434 PostgreSQL.<\/p>\n
\u0427\u0442\u043e\u0431\u044b \u043f\u043e\u0434\u0442\u0432\u0435\u0440\u0434\u0438\u0442\u044c \u0434\u043e\u0431\u0430\u0432\u043b\u0435\u043d\u0438\u0435 \u043d\u043e\u0432\u044b\u0445 \u043f\u0440\u043e\u0431, \u0432\u044b \u043c\u043e\u0436\u0435\u0442\u0435 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c \u043a\u043e\u043c\u0430\u043d\u0434\u0443 bpftrace -l<\/code> \u0434\u043b\u044f \u0432\u044b\u0432\u043e\u0434\u0430 \u0441\u043f\u0438\u0441\u043a\u0430 \u043f\u0440\u043e\u0431:<\/p>\n
bpftrace -l 'usdt:\/usr\/local\/pgsql\/bin\/postgres:wait*' usdt:\/usr\/local\/pgsql\/bin\/postgres:postgresql:wait__event__end usdt:\/usr\/local\/pgsql\/bin\/postgres:postgresql:wait__event__start  <\/code><\/pre>\n
\u0412\u043e\u0442 \u043e\u043d\u0438!<\/p>\n
\u042f \u0440\u0430\u0441\u0448\u0438\u0440\u0438\u043b \u0441\u043a\u0440\u0438\u043f\u0442 query-analyzer.bt<\/code> \u0441 \u043f\u043e\u043c\u043e\u0449\u044c\u044e \u0441\u043e\u0431\u044b\u0442\u0438\u0439 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u043f\u043e\u043b\u0443\u0447\u0438\u043b: query-analyzer-waits.bt<\/a>.<\/p>\n
\u0422\u0435\u043f\u0435\u0440\u044c \u044f \u043c\u043e\u0433\u0443 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u0442\u044c bpftrace \u0438 \u043f\u0440\u043e\u0431\u044b, \u0447\u0442\u043e\u0431\u044b \u0443\u0432\u0438\u0434\u0435\u0442\u044c, \u043d\u0430 \u0447\u0442\u043e \u0440\u0430\u0441\u0445\u043e\u0434\u0443\u0435\u0442\u0441\u044f \u0432\u0440\u0435\u043c\u044f, \u0432\u043a\u043b\u044e\u0447\u0430\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u044f \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f:<\/p>\n
root@84fe326249c0:\/postgres-bpftrace# .\/query-analyzer-waits.bt -p 18183 Attaching 200 probes... PostgreSQL statement execution analyzer. Time in microseconds (us). pid   :Phase      :time to phase :time in phase : query ------|-----------|--------------|--------------|------ [21964] WAIT      : (          ) :    3878097701: . [21964]Query start:              :              : select now(); [21964] parse     : (       113) :           318: select now(); [21964] rewrite   : (       199) :           302: select now(); [21964] plan      : (       102) :           488: select now(); [21964] execute   : (       647) :           294: select now(); [21964]Query done : (       505) :          2972: select now(); <\/code><\/pre>\n
\u042f \u0432\u044b\u043f\u043e\u043b\u043d\u0438\u043b select now(); \u0432 psql, \u043c\u044b \u043c\u043e\u0436\u0435\u043c \u0432\u0438\u0434\u0435\u0442\u044c, \u0447\u0442\u043e \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u0443\u0435\u0442\u0441\u044f simple query protocol (Query start\/Query done). \u0412\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u0435 \u0437\u0430\u0432\u0435\u0440\u0448\u0438\u043b\u043e\u0441\u044c \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435\u043c, \u043d\u043e \u043f\u043e\u0441\u043a\u043e\u043b\u044c\u043a\u0443 \u0438\u043d\u0444\u043e\u0440\u043c\u0430\u0446\u0438\u044f \u043e \u043a\u043b\u0430\u0441\u0441\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f \u0438 \u0438\u043c\u0435\u043d\u0438 \u0434\u043e\u0441\u0442\u0443\u043f\u043d\u0430 \u0442\u043e\u043b\u044c\u043a\u043e \u043f\u0440\u0438 \u0437\u0430\u043f\u0443\u0441\u043a\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f, \u044f \u043d\u0435 \u043c\u043e\u0433\u0443 \u0443\u0432\u0438\u0434\u0435\u0442\u044c \u044d\u0442\u043e \u0437\u0434\u0435\u0441\u044c. \u042d\u0442\u043e client.CLIENT_READ<\/code> \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435.<\/p>\n
\u0414\u043b\u044f \u0442\u0430\u043a\u043e\u0433\u043e \u043d\u0435\u0431\u043e\u043b\u044c\u0448\u043e\u0433\u043e, \u043f\u0440\u043e\u0441\u0442\u043e\u0433\u043e \u0437\u0430\u043f\u0440\u043e\u0441\u0430 \u0432\u043e\u043e\u0431\u0449\u0435 \u043d\u0435 \u0432\u043e\u0437\u043d\u0438\u043a\u0430\u0435\u0442 \u0441\u043e\u0431\u044b\u0442\u0438\u0435 \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u044f. \u042d\u0442\u043e \u043d\u0435\u043c\u043d\u043e\u0433\u043e \u0441\u0442\u0440\u0430\u043d\u043d\u043e. \u042f \u0443\u0432\u0435\u0440\u0435\u043d, \u0447\u0442\u043e \u0440\u0435\u0437\u0443\u043b\u044c\u0442\u0430\u0442 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u043e\u0442\u043f\u0440\u0430\u0432\u043b\u044f\u0435\u0442\u0441\u044f \u043e\u0431\u0440\u0430\u0442\u043d\u043e \u043c\u043e\u0435\u043c\u0443 \u043a\u043b\u0438\u0435\u043d\u0442\u0443 (psql). \u041f\u043e\u043b\u0443\u0447\u0430\u0435\u0442\u0441\u044f, \u0447\u0442\u043e \u044d\u0442\u0430 \u043e\u0442\u043f\u0440\u0430\u0432\u043a\u0430 \u043d\u0435 \u043f\u043e\u0441\u0447\u0438\u0442\u0430\u043d\u0430?<\/p>\n
\u042f \u043f\u043e\u0447\u0442\u0438 \u0443\u0432\u0435\u0440\u0435\u043d, \u0447\u0442\u043e \u044d\u0442\u043e \u0441\u0434\u0435\u043b\u0430\u043d\u043e \u043d\u0430\u043c\u0435\u0440\u0435\u043d\u043d\u043e, \u043f\u043e\u0442\u043e\u043c\u0443 \u0447\u0442\u043e \u0435\u0441\u043b\u0438 \u044f \u043e\u0442\u043f\u0440\u0430\u0432\u043b\u044e \u043a\u043b\u0438\u0435\u043d\u0442\u0443 \u043c\u043d\u043e\u0433\u043e \u0434\u0430\u043d\u043d\u044b\u0445, \u043c\u043e\u0436\u043d\u043e \u0441\u0433\u0435\u043d\u0435\u0440\u0438\u0440\u043e\u0432\u0430\u0442\u044c client.CLIENT_WRITE<\/code> \u043e\u0436\u0438\u0434\u0430\u043d\u0438\u0435. \u0421\u043e\u0431\u044b\u0442\u0438\u0435 \u043a\u043b\u0438\u0435\u043d\u0442.CLIENT_WRITE<\/code>, \u043f\u043e-\u0432\u0438\u0434\u0438\u043c\u043e\u043c\u0443, \u044f\u0432\u043b\u044f\u0435\u0442\u0441\u044f \u0441\u043e\u0431\u044b\u0442\u0438\u0435\u043c, \u043a\u043e\u0442\u043e\u0440\u043e\u0435 \u043f\u043e\u043a\u0430\u0437\u044b\u0432\u0430\u0435\u0442 \u0432\u0440\u0435\u043c\u044f, \u0437\u0430\u0442\u0440\u0430\u0447\u0435\u043d\u043d\u043e\u0435 \u043d\u0430 \u043e\u0442\u043f\u0440\u0430\u0432\u043a\u0443 \u0434\u0430\u043d\u043d\u044b\u0445 \u043a\u043b\u0438\u0435\u043d\u0442\u0443 (\u0434\u043b\u044f \u044d\u0442\u043e\u0433\u043e \u043e\u0442\u043a\u043b\u044e\u0447\u0438\u0442\u0435 \u043f\u0435\u0439\u0434\u0436\u0438\u043d\u0433 \u0432 psql<\/code>: \\pset pager off<\/code>):<\/p>\n
[21964] WAIT      : (          ) :      22160788: client.CLIENT_READ [21964]Query start:              :              : select repeat('x',1000000); [21964] parse     : (        90) :            49: select repeat('x',1000000); [21964] rewrite   : (       422) :            48: select repeat('x',1000000); [21964] plan      : (       669) :          5788: select repeat('x',1000000); [21964] WAIT      : (          ) :           444: client.CLIENT_WRITE [21964] WAIT      : (          ) :           119: client.CLIENT_WRITE [21964] WAIT      : (          ) :           266: client.CLIENT_WRITE [21964] execute   : (        98) :          1776: select repeat('x',1000000); [21964]Query done : (       166) :          9109: select repeat('x',1000000);  <\/code><\/pre>\n
\u0422\u0430\u043a\u0436\u0435 \u0438\u043d\u0442\u0435\u0440\u0435\u0441\u043d\u043e: \u043a\u043e\u0433\u0434\u0430 \u044f \u0441\u043e\u0437\u0434\u0430\u044e \u0442\u0430\u0431\u043b\u0438\u0446\u0443, \u0432\u044b\u0437\u043e\u0432 WAL write(io.WAL_WRITE<\/code>) \u0438 fsync() (io.WAL_SYNC<\/code>) \u043f\u0440\u043e\u0438\u0441\u0445\u043e\u0434\u0438\u0442, \u043a\u043e\u0433\u0434\u0430 \u0444\u0430\u0437\u0430 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f \u0437\u0430\u0432\u0435\u0440\u0448\u0435\u043d\u0430 (\u0444\u0430\u0437\u0430 \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f [execute] \u0441\u043e\u043e\u0431\u0449\u0430\u0435\u0442 \u043e \u0441\u0432\u043e\u0435\u043c \u0432\u0440\u0435\u043c\u0435\u043d\u0438 \u0434\u043e io.WAL_WRITE<\/code> \u0438 io.WAL_SYNC<\/code>):<\/p>\n
[21964] WAIT      : (          ) :      11254040: client.CLIENT_READ [21964]Query start:              :              : create table t(id int, f1 text); [21964] parse     : (        71) :            83: create table t(id int, f1 text); [21964] rewrite   : (       283) :             8: create table t(id int, f1 text); [21964] WAIT      : (          ) :           292: io.DATA_FILE_EXTEND [21964] WAIT      : (          ) :           116: io.DATA_FILE_EXTEND [21964] WAIT      : (          ) :          4512: io.DATA_FILE_IMMEDIATE_SYNC [21964] execute   : (         0) :         12127: create table t(id int, f1 text); [21964] WAIT      : (          ) :            67: io.WAL_WRITE [21964] WAIT      : (          ) :          1778: io.WAL_SYNC [21964]Query done : (      2425) :         15252: create table t(id int, f1 text); <\/code><\/pre>\n
\u0418 \u0435\u0441\u043b\u0438 \u044f \u0432\u0441\u0442\u0430\u0432\u043b\u044f\u044e \u0434\u0430\u043d\u043d\u044b\u0435, \u0444\u0443\u043d\u043a\u0446\u0438\u044f fsync() \u0442\u0430\u043a\u0436\u0435 \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u0435\u0442\u0441\u044f \u0432\u043d\u0435 \u0444\u0430\u0437\u044b \u0432\u044b\u043f\u043e\u043b\u043d\u0435\u043d\u0438\u044f:<\/p>\n
[21964] WAIT      : (          ) :      45872174: client.CLIENT_READ [21964]Query start:              :              : insert into t select id, repeat('x',10) from generate_series(1, [21964] parse     : (       361) :           645: insert into t select id, repeat('x',10) from generate_series(1, [21964] rewrite   : (       935) :          1296: insert into t select id, repeat('x',10) from generate_series(1, [21964] plan      : (        97) :          2486: insert into t select id, repeat('x',10) from generate_series(1, [21964] WAIT      : (          ) :           638: io.DATA_FILE_EXTEND [21964] execute   : (         0) :          1969: insert into t select id, repeat('x',10) from generate_series(1, [21964] execute   : (         0) :          2131: insert into t select id, repeat('x',10) from generate_series(1, [21964] WAIT      : (          ) :            98: io.WAL_WRITE [21964] WAIT      : (          ) :          2448: io.WAL_SYNC [21964]Query done : (      3401) :         11518: insert into t select id, repeat('x',10) from generate_series(1, <\/code><\/pre>\n
\u0410 \u0432\u043e\u0442 \u043a\u0430\u043a \u0432\u044b\u0433\u043b\u044f\u0434\u0438\u0442 \u0438\u0441\u043f\u043e\u043b\u044c\u0437\u043e\u0432\u0430\u043d\u0438\u0435 TEMP’a:<\/p>\n
[21964] WAIT      : (          ) :       5325897: client.CLIENT_READ [21964]Query start:              :              : select count(*) from generate_series(1,85_350); [21964] parse     : (        94) :            41: select count(*) from generate_series(1,85_350); [21964] rewrite   : (       115) :            58: select count(*) from generate_series(1,85_350); [21964] plan      : (        49) :            62: select count(*) from generate_series(1,85_350); [21964] WAIT      : (          ) :            33: io.BUFFILE_WRITE [21964] WAIT      : (          ) :             8: io.BUFFILE_WRITE [21964] WAIT      : (          ) :            12: io.BUFFILE_WRITE [21964] WAIT      : (          ) :            12: io.BUFFILE_WRITE [21964] WAIT      : (          ) :             7: io.BUFFILE_WRITE ...many more io.BUFFILE_WRITEs... [21964] WAIT      : (          ) :            10: io.BUFFILE_READ [21964] WAIT      : (          ) :             6: io.BUFFILE_READ [21964] WAIT      : (          ) :             6: io.BUFFILE_READ [21964] WAIT      : (          ) :             4: io.BUFFILE_READ [21964] WAIT      : (          ) :             4: io.BUFFILE_READ ...many more io.BUFFILE_READs... [21964] execute   : (        67) :         35538: select count(*) from generate_series(1,85_350); [21964]Query done : (       275) :         36303: select count(*) from generate_series(1,85_350); <\/code><\/pre>\n
\u041f\u043e\u0447\u0442\u0438 \u0442\u0430\u043a\u043e\u0435 \u0436\u0435 \u043a\u043e\u043b\u0438\u0447\u0435\u0441\u0442\u0432\u043e Temp IO \u043c\u043e\u0436\u043d\u043e \u0443\u0432\u0438\u0434\u0435\u0442\u044c \u0441 \u043f\u043e\u043c\u043e\u0449\u044c\u044e explain analyse (buffers).<\/p>\n
\u041f\u0435\u0440\u0432\u044b\u0439 \u0441\u0435\u0430\u043d\u0441 \u0434\u043b\u044f \u0432\u0445\u043e\u0434\u0430 \u0432 \u0431\u0430\u0437\u0443 \u0434\u0430\u043d\u043d\u044b\u0445 \u0434\u043e\u043b\u0436\u0435\u043d (\u043f\u043e\u0432\u0442\u043e\u0440\u043d\u043e) \u0441\u043e\u0437\u0434\u0430\u0442\u044c relcache. \u042d\u0442\u043e \u0434\u0435\u043b\u0430\u0435\u0442\u0441\u044f \u0434\u043e \u0442\u043e\u0433\u043e, \u043a\u0430\u043a \u0441\u0435\u0430\u043d\u0441 \u043d\u0430\u0447\u043d\u0435\u0442 \u0447\u0442\u043e-\u043b\u0438\u0431\u043e \u0432\u044b\u043f\u043e\u043b\u043d\u044f\u0442\u044c. \u0412\u043e\u0442 \u043a\u0430\u043a \u044d\u0442\u043e \u0432\u044b\u0433\u043b\u044f\u0434\u0438\u0442 \u0432 \u043c\u043e\u0435\u0439 \u0431\u0430\u0437\u0435 \u0434\u0430\u043d\u043d\u044b\u0445:<\/p>\n
[14454] WAIT      : (          ) :            32: io.RELATION_MAP_READ [14454] WAIT      : (          ) :            66: io.DATA_FILE_READ [14454] WAIT      : (          ) :            10:<\/code><\/pre>\n<\/div>\n<\/div>\n<\/div>\n<\/div>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[],"tags":[],"class_list":["post-362130","post","type-post","status-publish","format-standard","hentry"],"_links":{"self":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/362130","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=362130"}],"version-history":[{"count":0,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/362130\/revisions"}],"wp:attachment":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=362130"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=362130"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=362130"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}