Hi,
I've been working on a problem which I thought was a postgres driver problem, but now I'm not so sure.
I put a bunch of debug statements in the driver functions. I've grepped the debugs for db_init|db_close|connect_db|disconnect_db and here is what I have: -----------cut------------ Mar 1 23:59:49 rave ser[1803]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1803]: connect_db(): here we go Mar 1 23:59:49 rave ser[1803]: connect_db(): we are connected /tmp/debug.1803.out Mar 1 23:59:49 rave ser[1804]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1804]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1804]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1804]: db_close(): free self Mar 1 23:59:49 rave ser[1804]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1804]: connect_db(): here we go Mar 1 23:59:49 rave ser[1805]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1805]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1805]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1805]: db_close(): free self Mar 1 23:59:49 rave ser[1805]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1805]: connect_db(): here we go Mar 1 23:59:49 rave ser[1806]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1806]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1806]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1806]: db_close(): free self Mar 1 23:59:49 rave ser[1804]: connect_db(): we are connected /tmp/debug.1804.out Mar 1 23:59:49 rave ser[1806]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1804]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1806]: connect_db(): here we go Mar 1 23:59:49 rave ser[1804]: connect_db(): here we go Mar 1 23:59:49 rave ser[1805]: connect_db(): we are connected /tmp/debug.1805.out Mar 1 23:59:49 rave ser[1805]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1805]: connect_db(): here we go Mar 1 23:59:49 rave ser[1804]: connect_db(): we are connected /tmp/debug.1804.out Mar 1 23:59:50 rave ser[1805]: connect_db(): we are connected /tmp/debug.1805.out Mar 1 23:59:50 rave ser[1806]: connect_db(): we are connected /tmp/debug.1806.out Mar 1 23:59:50 rave ser[1806]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:50 rave ser[1806]: connect_db(): here we go Mar 1 23:59:50 rave ser[1806]: connect_db(): we are connected /tmp/debug.1806.out Mar 2 00:00:50 rave ser[1807]: begin_transaction(): BEGIN error server closed the connection unexpectedly ^IThis probably means the server terminated abnormally ^Ibefore or while processing the request.
-----------------cut-------------- The current processes that are running are: [root@rave sip_router]# ps -ax | grep ser 30060 ? S 0:00 /bin/sh bin/safe_mysqld --user=mysql 1803 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg 1804 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg 1805 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg 1806 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg 1807 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg 1808 ? S 0:00 ser -f /usr/local/etc/ser/serpost.cfg -----------------cut------------------ Here is the top of my ser.cfg file: ---------------- debug=2 # debug level (cmd line: -dddddddddd) fork=yes log_stderror=no # (cmd line: -E) check_via=no # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R) listen=216.87.144.203 port=5060 children=2 fifo="/tmp/ser_fifo" alias="augustvoice.net"
loadmodule "/usr/local/lib/ser/modules/sl.so" loadmodule "/usr/local/lib/ser/modules/tm.so" loadmodule "/usr/local/lib/ser/modules/acc.so" loadmodule "/usr/local/lib/ser/modules/rr.so" loadmodule "/usr/local/lib/ser/modules/maxfwd.so" loadmodule "/usr/local/lib/ser/modules/postgres.so" loadmodule "/usr/local/lib/ser/modules/usrloc.so" loadmodule "/usr/local/lib/ser/modules/registrar.so" loadmodule "/usr/local/lib/ser/modules/exec.so" loadmodule "/usr/local/lib/ser/modules/auth.so" loadmodule "/usr/local/lib/ser/modules/textops.so"
modparam("usrloc","db_mode",2) modparam("usrloc","db_url", "sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME")
modparam("tm","retr_timer1p1", 2) # increase retry timeout modparam("tm","retr_timer1p2", 3) # increase retry timeout modparam("tm","retr_timer1p3", 6) # increase retry timeout
modparam("acc", "log_level", 1) modparam("acc", "acc_flag", 1 ) modparam("acc", "report_ack", 0 ) modparam("auth","db_url", "sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME") # # this is the main routing block for augustvoice.net # this block can handle any routing request, local or foreign #
route { #
... ---------------------------
A couple of questions: 1) I state 'children=2', but I see 6 'processes'. I think linux does threads with processes, so am I seeing 2 'processes' with 3 threads per process??? 2) the debug output has the process ID and the action being performed. Either it is way out of order, or the postgres db driver is being asked to do things out of order. 3) Why is there all of the db_init(), db_close() stuff?? All of this stuff happens in the first second on startup. Surely that many opens and closes aren't really needed are they? 4) select statements seem to happen in one thread, and insert/delete statements seem to happen in another thread. What is that about?
---greg Greg Fausak
Hi Greg,
On Sunday 02 March 2003 07:59, Greg Fausak wrote:
Hi, Mar 1 23:59:49 rave ser[1803]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1803]: connect_db(): here we go Mar 1 23:59:49 rave ser[1803]: connect_db(): we are connected /tmp/debug.1803.out Mar 1 23:59:49 rave ser[1804]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1804]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1804]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1804]: db_close(): free self Mar 1 23:59:49 rave ser[1804]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1804]: connect_db(): here we go Mar 1 23:59:49 rave ser[1805]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1805]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1805]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1805]: db_close(): free self Mar 1 23:59:49 rave ser[1805]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1805]: connect_db(): here we go Mar 1 23:59:49 rave ser[1806]: db_close(): disconnect_db() Mar 1 23:59:49 rave ser[1806]: disconnect_db(): entry Mar 1 23:59:49 rave ser[1806]: disconnect_db(): PQfinish() Mar 1 23:59:49 rave ser[1806]: db_close(): free self Mar 1 23:59:49 rave ser[1804]: connect_db(): we are connected /tmp/debug.1804.out Mar 1 23:59:49 rave ser[1806]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1804]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1806]: connect_db(): here we go Mar 1 23:59:49 rave ser[1804]: connect_db(): here we go Mar 1 23:59:49 rave ser[1805]: connect_db(): we are connected /tmp/debug.1805.out Mar 1 23:59:49 rave ser[1805]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:49 rave ser[1805]: connect_db(): here we go Mar 1 23:59:49 rave ser[1804]: connect_db(): we are connected /tmp/debug.1804.out Mar 1 23:59:50 rave ser[1805]: connect_db(): we are connected /tmp/debug.1805.out Mar 1 23:59:50 rave ser[1806]: connect_db(): we are connected /tmp/debug.1806.out Mar 1 23:59:50 rave ser[1806]: db_init(): sql://USER:PASSWORD@humpty.august.net:5432/THEDBNAME Mar 1 23:59:50 rave ser[1806]: connect_db(): here we go Mar 1 23:59:50 rave ser[1806]: connect_db(): we are connected /tmp/debug.1806.out Mar 2 00:00:50 rave ser[1807]: begin_transaction(): BEGIN error server closed the connection unexpectedly ^IThis probably means the server terminated abnormally ^Ibefore or while processing the request.
I think the problem is that a transaction is made from a process which do not initalized it's database connection. See below.
A couple of questions:
- I state 'children=2', but I see 6 'processes'. I think linux does threads with processes, so am I seeing 2 'processes' with 3 threads per process???
Children means only how many processes are doing the main work: listening on the interfaces and porccesing request. Their is also one timer process which runs regular commands. And you have fifo activate in your config, this results in another process for listening on the fifo. With 'serctl ps' you can see which process is for what. We don't use threads AFAIK. The linux thread scheme isn't very portable.
- the debug output has the process ID and the action being performed. Either it is way out of order, or the postgres db driver is being asked to do things out of order.
Sorry i don't understand what you mean.
- Why is there all of the db_init(), db_close() stuff?? All of this stuff happens in the first second on startup. Surely that many opens and closes aren't really needed are they?
Every ser process have to open its own db connection. With this way every process can access the db if it needs to. Otherwise we would need one db communication process, which would require interprocess communication. Or we had to share one connection between multiple processes, which would require a lot of locking.
- select statements seem to happen in one thread, and insert/delete
statements seem to happen in another thread. What is that about?
I can only think of the initial usrloc load from database at ser startup as process which only selects. After this only inserts and deletes should happen. But maybe i'm overseeing here something. Jan?
Greetings Nils
-
lgfausakļ¼ august.net -
Nils Ohlmeier