FreeTDS Development Group

["ZIGLIO, Frediano, VF-IT" <Frediano.Ziglio AT vodafone.com>]

> 
> 
> We recently migrated our application servers from Windows Server 2003
> to FreeBSD to boost performance of our PHP application.  We are using
> FreeTDS to connect to our existing SQL Server 2000 database server.
> 
> FreeTDS was easy to setup and it works very well up to a point.  Under
> moderate load (where "moderate" is a load average of about 14 
> and above)
> we begin to see failures.  On investigation, we the following patten
> emerges:
> 

What do you mean with "load average 14" ?

> Occasionally (not always or even usually), selecting with 
> XLOCK causes 
> a freeze in the TDS connection to SQL Server.   The log with 
> timestamps
> included below shows an example of this behavior.
> 

I think that sql server is just waiting for lock. The log you sent
confirm this. FreeTDS was just waiting for server. I suspect that this
is a small problem caused by a small difference in token handling. It
seems that our dblib wait to process some tokens  so perhaps it keeps
locking for a bit more time. Note however that this happens only if last
done token (which is very small) got not read from client ip stack
(which is very unlikely). Are you sure that there are no pending
transaction waiting? This can happen for instance if you use persistent
connections and you forgot to commit/rollback transactions.
Try also to check processes running on server when it hangs.

> We tested with FreeTDS .63 (bundled in the current FreeBSD ports 
> collection), FreeTDS .64 and current (.65).  We also tested with
> protocol version 7.0 and 8.0.  Both produced the same behavior.
> .63 and .64 produced the same behavior.  .65 current produced
> many more connection errors, which we didn't pursue further.
> 

Mmm... perhaps CVS HEAD produce more errors cause it better handle
timeouts. It seems that sql server just refuse connections when it's too
busy. Which type of error occurs?

> Can anyone provide clues to resolving this behavior?
> 
> Locke Berkebile
> San Francisco
> 
> 
> Details follow:
> 
> 1) freetds.conf for our server:
> 
> [taz]
>       host = 192.168.10.7
>       port = 1433
>       tds version = 8.0
> 

Does global section contain timeouts?

> 
> 2) The head of the tds log file (showing the FreeTDS version
>    and the TDS protocol version):
> 
> 11:22:31.629409 Starting log file for FreeTDS 0.63
>     on 2007-01-24 11:22:31 with debug level 99.
> 11:22:31.629633 names for ISO-8859-1: ISO-8859-1
> 11:22:31.629645 names for UTF-8: UTF-8
> 11:22:31.629654 names for UCS-2LE: UCS-2LE
> 11:22:31.629661 names for UCS-2BE: UCS-2BE
> 11:22:31.629669 iconv to convert client-side data to the 
> "ISO-8859-1" character set
> 11:22:31.629691 tds_iconv_info_init: converting 
> "ISO-8859-1"->"UCS-2LE"
> 11:22:31.629708 tds_iconv_info_init: converting 
> "ISO-8859-1"->"UCS-2LE"
> 11:22:31.629759 Connecting to 192.168.10.7 port 1433, TDS 7.0.
> 11:22:31.630629 tds_put_string converting 16 bytes of 
> "bsdbanks1.ja.org"
> 11:22:31.630745 tds_put_string wrote 32 bytes
> 11:22:31.630756 tds_put_string converting 11 bytes of "Banks_User2"
> 11:22:31.630766 tds_put_string wrote 22 bytes
> 11:22:31.630798 tds_put_string converting 5 bytes of "PHP 5"
> 11:22:31.630809 tds_put_string wrote 10 bytes
> 11:22:31.630817 tds_put_string converting 3 bytes of "taz"
> 11:22:31.630826 tds_put_string wrote 6 bytes
> 11:22:31.630834 tds_put_string converting 10 bytes of "DB-Library"
> 11:22:31.630843 tds_put_string wrote 20 bytes
> 11:22:31.630852 tds_put_string converting 10 bytes of "us_english"
> 11:22:31.630861 tds_put_string wrote 20 bytes
> 11:22:31.630869 tds_put_string wrote 0 bytes
> 11:22:31.631023 tds_process_login_tokens()
> 
> 
> 3) The portion of the tds log exhibiting the freezing 
> behavior.  Note that 
>    the timestamps jump from 11:23:44.041544 to 
> 11:24:35.541649.  During this
>    window, we receive connection failure errors in our php 
> application:
> 
> 11:23:44.041234 tds_process_end() state set to TDS_IDLE
> 11:23:44.041244 dbsqlok() end status was success
> 11:23:44.041255 dbresults()
> 11:23:44.041267 tds_process_row_tokens() state is COMPLETED
> 11:23:44.041321 dbcmd() bufsz = 20
> 11:23:44.041332 in dbfreebuf()
> 11:23:44.041345 in dbsqlexec()
> 11:23:44.041355 in dbsqlsend()
> 11:23:44.041366 tds_free_all_results()
> 11:23:44.041378 tds_put_string converting 117 bytes of "
>       SELECT lock_state, set_stamp
>       FROM gamelock_table
>       WITH (XLOCK)
>       WHERE game_id = '25318'
>       "
> 11:23:44.041393 tds_put_string wrote 234 bytes
> 11:23:44.041404 Sending packet
> 0000 01 01 00 f2 00 00 01 00-0a 00 20 00 20 00 20 00 
> |........ .. . . .|
> 0010 20 00 20 00 20 00 53 00-45 00 4c 00 45 00 43 00 | . . 
> .S. E.L.E.C.|
> 0020 54 00 20 00 6c 00 6f 00-63 00 6b 00 5f 00 73 00 |T. 
> .l.o. c.k._.s.|
> 0030 74 00 61 00 74 00 65 00-2c 00 20 00 73 00 65 00 
> |t.a.t.e. ,. .s.e.|
> 0040 74 00 5f 00 73 00 74 00-61 00 6d 00 70 00 0a 00 
> |t._.s.t. a.m.p...|
> 0050 20 00 20 00 20 00 20 00-20 00 20 00 46 00 52 00 | . . . 
> .  . .F.R.|
> 0060 4f 00 4d 00 20 00 67 00-61 00 6d 00 65 00 6c 00 |O.M. 
> .g. a.m.e.l.|
> 0070 6f 00 63 00 6b 00 5f 00-74 00 61 00 62 00 6c 00 
> |o.c.k._. t.a.b.l.|
> 0080 65 00 0a 00 20 00 20 00-20 00 20 00 20 00 20 00 |e... . 
> .  . . . .|
> 0090 57 00 49 00 54 00 48 00-20 00 28 00 58 00 4c 00 
> |W.I.T.H.  .(.X.L.|
> 00a0 4f 00 43 00 4b 00 29 00-0a 00 20 00 20 00 20 00 
> |O.C.K.). .. . . .|
> 00b0 20 00 20 00 20 00 57 00-48 00 45 00 52 00 45 00 | . . 
> .W. H.E.R.E.|
> 00c0 20 00 67 00 61 00 6d 00-65 00 5f 00 69 00 64 00 | 
> .g.a.m. e._.i.d.|
> 00d0 20 00 3d 00 20 00 27 00-32 00 35 00 33 00 31 00 | .=. 
> .'. 2.5.3.1.|
> 00e0 38 00 27 00 0a 00 20 00-20 00 20 00 20 00 20 00 |8.'... 
> .  . . . .|
> 00f0 20 00                  -                        | .|
> 
> 11:23:44.041544 in dbsqlok() 
> 11:24:35.541649 Received header
> 0000 04 01 00 53 00 3d 01 00-                        |...S.=..|
> 

This confirm that FreeTDS is waiting for server.

> 11:24:35.541679 Received packet
> 0000 81 02 00 00 00 08 00 38-0a 6c 00 6f 00 63 00 6b 
> |.......8 .l.o.c.k|
> 0010 00 5f 00 73 00 74 00 61-00 74 00 65 00 00 00 08 
> |._.s.t.a .t.e....|
> 0020 00 3d 09 73 00 65 00 74-00 5f 00 73 00 74 00 61 
> |.=.s.e.t ._.s.t.a|
> 0030 00 6d 00 70 00 d1 00 00-00 00 c0 98 00 00 2c 7f 
> |.m.p.... ......,.|
> 0040 cc 00 fd 10 00 c1 00 01-00 00 00                |........ ...|
> 
> 11:24:35.541709 dbsqlok() marker is 81
> 11:24:35.541745 dbsqlok() found result token
> 11:24:35.541757 dbresults()
> 11:24:35.541767 tds_free_all_results()
> 11:24:35.541778 processing result tokens.  marker is  81(TDS7_RESULT)
> 11:24:35.542015 tds_free_all_results()
> 11:24:35.542032 processing TDS7 result. set current_results 
> to tds->res_info
> 11:24:35.542044 tds_get_string: reading 20 from wire to give 
> 10 to client.
> 11:24:35.542057 tds7_get_data_info:1558: 
>       colname = lock_state (10 bytes)
>       type = 56 (int)
>       server's type = 56 (int)
>       column_varint_size = 0
>       column_size = 4 (4 on server)
> 11:24:35.542071 tds_get_string: reading 18 from wire to give 
> 9 to client.
> 11:24:35.542082 tds7_get_data_info:1558: 
>       colname = set_stamp (9 bytes)
>       type = 61 (datetime)
>       server's type = 61 (datetime)
>       column_varint_size = 0
>       column_size = 8 (8 on server)
> 11:24:35.542096 dbresults() process_result_tokens returned 
> result_type = 4049 retcode = 1
> 11:24:35.542107 processing result tokens.  marker is  d1(ROW)
> 11:24:35.542118 dbresults() process_result_tokens returned 
> result_type = 4040 retcode = 1
> 11:24:35.542129 dbnextrow()
> 11:24:35.542138 dbnextrow() dbresults_state = 2
> 11:24:35.542149 processing row tokens.  marker is  d1(ROW)
> 11:24:35.542168 processing row.  column is 0 varint size = 0
> 11:24:35.542179 processing row.  column size is 4 
> 11:24:35.542188 clearing column 0 NULL bit
> 11:24:35.542198 processing row.  column is 1 varint size = 0
> 11:24:35.542208 processing row.  column size is 8 
> 11:24:35.542218 clearing column 1 NULL bit
> 11:24:35.542229 leaving dbnextrow() returning -1
> 11:24:35.542245 dbdatlen() type = 56
> 11:24:35.542255 leaving dbdatlen() returning 4
> 11:24:35.542266 dbdatlen() type = 61
> 11:24:35.542276 leaving dbdatlen() returning 8
> 11:24:35.542285 tds_willconvert()
> 11:24:35.542297 tds_willconvert() 61 47 1
> 11:24:35.542335 dbdatlen() type = 61
> 11:24:35.542347 leaving dbdatlen() returning 8
> 11:24:35.542361 dbnextrow()
> 11:24:35.542370 dbnextrow() dbresults_state = 2
> 11:24:35.542380 processing row tokens.  marker is  fd(DONE)
> 11:24:35.542390 tds_process_end: more_results = 0
>               was_cancelled = 0
>               error = 0
>               done_count_valid = 1
> 11:24:35.542401 tds_process_end() state set to TDS_IDLE
> 

freddy77