Главная » SQL

⏳ Определение времени обращений к базе данных 🐘PostgreSQL или 🚀YugabyteDB (strace)

На чтение 5 мин. Просмотров 74 Опубликовано

Когда вы измеряете вызовы базы данных из приложения или из базы данных, вы не видите полной картины, потому что они могут делать что-то еще, прежде чем записать это в журнал. Вот что я использую, чтобы точно знать, как долго мои запросы активны в базе данных или на клиенте. С помощью простого strace в Linux, чтобы засечь время системных вызовов для обхода сети.

Я подключаюсь как:

yugabyte=> 
           c yugabyte franck

psql (13.7, server 11.2-YB-2.15.0.1-b0)
You are now connected to database "yugabyte" as user "franck".
Войти в полноэкранный режим Выход из полноэкранного режима
Содержание
  1. идентификация в клиенте
  2. идентификация на сервере
  3. strace

идентификация в клиенте

Из сессии я могу определить узел, к которому я подключен (потому что с YugabyteDB вы можете подключиться к любому узлу в кластере) и PID на этом узле:

yugabyte=> 

 select pg_backend_pid(), current_setting('listen_addresses') host
 , format(
  'postgres: %s %s %s(%s) %s'
  ,usename, datname, client_addr, client_port, state
 ) as cmd
 from pg_stat_activity where pid=pg_backend_pid();

 pg_backend_pid |   host    |                          cmd
----------------+-----------+-------------------------------------------------------
        1127372 | 10.0.0.61 | postgres: franck yugabyte 152.67.90.247(45330) active
(1 row)
Вход в полноэкранный режим Выход из полноэкранного режима

идентификация на сервере

Я также отобразил выше строку, которую вы должны найти в команде при перечислении процессов на хосте, совпадающую с тем, что вы видите из ps:

$ 

   ps -o cmd -p 1127372

CMD
postgres: franck yugabyte 152.67.90.247(45330) idle
Войти в полноэкранный режим Выйти из полноэкранного режима

Моя сессия была active, когда я выполнил запрос, и сейчас она idle в ожидании следующей команды.

Если вы не можете получить информацию из SQL, вы можете найти ее, перечислив PID с именем пользователя, именем базы данных, адресом клиента и портом:

$ 

   pgrep -a postgres | awk '
   /postgres: (.*) (.*) (.*)[(][0-9]+[)]/{sub(/ *$/,"");print}
   '

1038092 postgres: yugabyte yugabyte 152.67.90.247(42106) idle
1041807 postgres: yugabyte yugabyte 152.67.90.247(45638) idle
1127372 postgres: franck yugabyte 152.67.90.247(45330) idle
Вход в полноэкранный режим Выйти из полноэкранного режима

Вы также можете получить список всех PID PostgreSQL с помощью:

$ 

  pgrep -d, postgres

1031295,1031311,1031313,1031315,1031316,1031444,1031474,1031476,1031478,1031479,1031515,1031537,1031540,1031545,1031546,1038092,1041807,1127372
Войти в полноэкранный режим Выйти из полноэкранного режима

Это то же самое с YugabyteDB, поскольку YSQL API использует бэкенд PostgreSQL.

Вы также можете отследить последнее соединение с этим хостом:

$ 

  pgrep -n postgres

1127372
Войти в полноэкранный режим Выйти из полноэкранного режима

strace

Вот моя команда strace, использующая $(pgrep -n postgres) для трассировки последнего соединения и awk для подсчета времени, прошедшего между сетевыми вызовами:

$ 

  strace -p $(pgrep -n postgres) 
  -e recvfrom,sendto -Ttttryys 100 -o /dev/stdout | awk '
  # keep last timing in t to show the difference
  t>0{T=$1-t}
  # recvfrom are after idle session, sendto are after active one
  {e="idle"}/sendto/{e="active"}
  # print time in second in front
  />, ".\/{
   printf "%10.3f seconds %6s: %-sn",T,e,$0;t=$1
  }
  # show stack if -k is used
  !/^ *>/{stack=""}
  /[(]PostgresMain[+]/{print "",stack" PostgresMain"}
  /^ *>/{sub(/.*[(]/," ");sub(/[+].*/,"");stack=$(NF-1)"<"stack}
  '
Войти в полноэкранный режим Выйти из полноэкранного режима

Объяснение аргументов:

Завершить с помощью Control-C

Вот мои трассировки после выполнения select pg_sleep(5)watch 3:

strace: Process 1127372 attached
     0.000 seconds active: 1658132400.777489 (+     0.000401) sendto(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 65, 0, NULL, 0) = 65 <0.000126>
     3.034 seconds   idle: 1658132403.811221 (+     3.032812) recvfrom(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "Q27select pg_sleep(5)", 8192, 0, NULL, NULL) = 24 <0.000027>
     5.006 seconds active: 1658132408.817043 (+     0.000218) sendto(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 65, 0, NULL, 0) = 65 <0.000174>
     3.033 seconds   idle: 1658132411.849789 (+     3.032513) recvfrom(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "Q27select pg_sleep(5)", 8192, 0, NULL, NULL) = 24 <0.000028>
     5.005 seconds active: 1658132416.855284 (+     0.000219) sendto(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 65, 0, NULL, 0) = 65 <0.000063>
     3.032 seconds   idle: 1658132419.887601 (+     3.032207) recvfrom(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "Q27select pg_sleep(5)", 8192, 0, NULL, NULL) = 24 <0.000034>
     5.006 seconds active: 1658132424.893134 (+     0.000225) sendto(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 65, 0, NULL, 0) = 65 <0.000143>
     3.031 seconds   idle: 1658132427.924617 (+     3.031141) recvfrom(10<TCP:[10.0.0.61:5433->152.67.90.247:45330]>, "Q27select pg_sleep(5)", 8192, 0, NULL, NULL) = 24 <0.000043>
^Cstrace: Process 1127372 detached
Вход в полноэкранный режим Выход из полноэкранного режима

Вы можете видеть, как сессия простаивает 3 секунды, затем получает вызов (Q — простой запрос) на pg_sleep и получает через 5 секунд строку (T — описание строки).

Конечно, вы можете выполнить то же самое на стороне клиента. Вот что я получил в то же время с той же командой, за исключением того, что PID в -p — это psql:

strace: Process 1915912 attached
     0.000 seconds   idle: 1658132400.793259 (+     0.000000) recvfrom(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 16384, 0, NULL, NULL) = 65 <0.000049>
     3.005 seconds active: 1658132403.797932 (+     3.004631) sendto(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "Q27select pg_sleep(5)", 24, MSG_NOSIGNAL, NULL, 0) = 24 <0.000070>
     5.034 seconds   idle: 1658132408.831439 (+     5.033590) recvfrom(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 16384, 0, NULL, NULL) = 65 <0.000533>
     3.005 seconds active: 1658132411.836482 (+     3.004959) sendto(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "Q27select pg_sleep(5)", 24, MSG_NOSIGNAL, NULL, 0) = 24 <0.000067>
     5.034 seconds   idle: 1658132416.870051 (+     5.033576) recvfrom(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 16384, 0, NULL, NULL) = 65 <0.000118>
     3.004 seconds active: 1658132419.874207 (+     3.004159) sendto(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "Q27select pg_sleep(5)", 24, MSG_NOSIGNAL, NULL, 0) = 24 <0.000135>
     5.033 seconds   idle: 1658132424.907636 (+     5.033427) recvfrom(6<TCP:[10.0.3.176:45330->132.226.128.168:5433]>, "T!1pg_sleep103464377377377377Dn1CrSELECT 1Z5I", 16384, 0, NULL, NULL) = 65 <0.000109>
^Cstrace: Process 1915912 detached
Войти в полноэкранный режим Выйти из полноэкранного режима

С клиента, idle — это время, когда база данных active и наоборот. Если время не совпадает, посмотрите на свою сеть.

strace может сделать гораздо больше, показывая другие системные вызовы, так что у вас есть эквивалент событий ожидания Oracle, чтобы понять время, не связанное с CPU. А если вы добавите -k, то сможете получить полный стек вызовов, как здесь:

Оцените статью
devanswers.ru
Добавить комментарий