Когда вы измеряете вызовы базы данных из приложения или из базы данных, вы не видите полной картины, потому что они могут делать что-то еще, прежде чем записать это в журнал. Вот что я использую, чтобы точно знать, как долго мои запросы активны в базе данных или на клиенте. С помощью простого 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".
идентификация в клиенте
Из сессии я могу определить узел, к которому я подключен (потому что с 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 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]>, "Q 27select 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_sleep 10346 4377377377377 D n 1 C rSELECT 1 Z 5I", 16384, 0, NULL, NULL) = 65 <0.000109>
^Cstrace: Process 1915912 detached
С клиента, idle
— это время, когда база данных active
и наоборот. Если время не совпадает, посмотрите на свою сеть.
strace
может сделать гораздо больше, показывая другие системные вызовы, так что у вас есть эквивалент событий ожидания Oracle, чтобы понять время, не связанное с CPU. А если вы добавите -k
, то сможете получить полный стек вызовов, как здесь: