FreeTDS Development Group

["Sokol, Ryan - 244" <ryans AT HA.com>]

Which PHP functions are you using (mssql, odbc, Sybase)?

-----Original Message-----
From: freetds-bounces AT lists.ibiblio.org
[mailto:freetds-bounces AT lists.ibiblio.org] On Behalf Of Locke Berkebile
Sent: Friday, February 02, 2007 11:30 AM
To: FreeTDS Development Group
Subject: [freetds] Freezes on certain queries under load


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:

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.

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.

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


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.=..|

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

_______________________________________________
FreeTDS mailing list
FreeTDS AT lists.ibiblio.org
http://lists.ibiblio.org/mailman/listinfo/freetds