[Serusers] threading weirdness?

[Greg Fausak]

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 at 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