Stuck on select() syscall

[anayrat]

Hello,

I tried to replay log after a pgbench test. pgreplay had successfully parsed log files

Parse statistics
================

Log lines read: 50082
Total SQL statements processed: 50082
Simple SQL statements processed: 50082
Parametrized SQL statements processed: 0
Named prepared SQL statements executions processed: 0
Cancel requests processed: 0
Fast-path function calls ignored: 0

But when I replay, it seems stuck on do_select call:

postgres@pg11:~$ pgreplay -r -j -s1 /tmp/replay.log 
Execution is 10 seconds behind schedule
Execution is 30 seconds behind schedule

Here a perf report of specific pid:

  14.55%  [kernel]          [k] entry_SYSCALL_64
  12.12%  [kernel]          [k] syscall_return_via_sysret
  10.59%  [kernel]          [k] do_select

with gdb it seems stuck on

pgreplay/database.c

Line 146 in c9e93ea

rc = select(n, rfds, wfds, xfds, timeout);

I tried first with master and manually compiled version with archlinux and kernel 4.20.6-arch1-1-ARCH

Then I tried with debian stretch inside an lxc container (so, same kernel as above).

Maybe there is something wrong with this syscall under recent kernel? I read in this post that select perform worse than epoll : https://jvns.ca/blog/2017/06/03/async-io-on-linux--select--poll--and-epoll/

Note : my goal is to sample SQL workload with pg_sampletolog and replay it with pgreplay by adjusting speedfactor.

Thanks

[laurenz]

pgreplay doesn't block on select, unless it decides there is nothing to do for a while, in which case it it sleeps for a while. But I guess that in your gdb stack trace, do_select is called from poll_socket, which uses a timeout of 0 for a non-blocking poll of the socket.

I'd assume that the problem is not that the system call gets stuck or takes too long, but that there is no response from the PostgreSQL server. pgreplay just keeps running select in a tight loop if it is waiting for a response from the server, so it is normal for the system call to consume a lot of the CPU time.

Perhaps you are suffering from the following problem that is mentioned in the “limitations” section of the README:

While pgreplay makes sure that commands are sent to the server in the
order in which they were originally executed, there is no way to guarantee
that they will be executed in the same order during replay: Network
delay, processor contention and other factors may cause a later command
to "overtake" an earlier one. While this does not matter if the
commands don't affect each other, it can lead to SQL statements hitting
locks unexpectedly, causing replay to deadlock and "hang".
This is particularly likely if many different sessions change the same data
repeatedly in short intervals.

This can easily happen if many concurrent sessions change the same data concurrently, as can often happen in an artificial load test:

Session 1, time x: UPDATE t SET v = 1 WHERE id = 42;
Session 2, time x + 0.002ms: UPDATE t SET v = 1 WHERE id = 42;
Session 1, time x + 1ms: COMMIT
Session 2, time x + 1.5ms: COMMIT

Not pgreplay will faithfully replay the statements in that order and send the second statement 0.002 milliseconds after the first, then it waits for the first statement to return before it can send the third statement (because they use the same database session).

Now it can happen that the second statement gets executed first, since they get sent almost at the same time. Then session 2 has the row locked, and the update of session 1 is blocked. So pgreplay will wait in vain for the first statement to finish, and it won't send the fourth statement (which would remove the lock and allow processing to proceed) unless it has first sent the third statement.

In that situation, pgreplay has deadlocked with the database and is stuck. It has no way to detect that – it cannot tell the difference if the first statement is blocked or just takes a long time to complete. On the other hand, it cannot arbitrarily reorder the statements it sends, because they might depend on each other.

Here is a link to a thread on the (retired) mailing list that had that very problem. You could try the SQL statement mentioned there:

SELECT l.pid, pg_cancel_backend(l.pid)
FROM pg_locks l JOIN
     pg_stat_activity a ON (l.pid = a.procpid)
WHERE NOT l.granted
  AND current_timestamp - a.query_start > '3s'::interval;

If that gets replay unstuck, you are hitting this problem.

Unfortunately there is not much else that can be done about this, except to use a less artificial work load that does not modify the same table rows over and over in concurrent sessions...

[anayrat]

Thanks for your (long) explanation! As there is nothing that can be done, I close this issue.