SCM

[#1010779] Respect CommandTimeout in first function call w/ string parameter

View Trackers | Patches | Download .csv | Monitor

Date:
2010-03-16 07:02
Priority:
3
State:
Open
Submitted by:
Noah Misch (nmisch)
Assigned to:
Nobody (None)
Category:
Group:
Resolution:
None
 
Summary:
Respect CommandTimeout in first function call w/ string parameter

Detailed description
When a connection to a server with "standard_conforming_strings = off" first executes a command with a string parameter, we run "SHOW escape_string_warning"
internally. That internal command clobbers the user's CommandTimeout for the
execution of the main command. The effective CommandTimeout was 20 until NpgsqlCommand.cs revision 1.46 (2010-02-16), and lately 0 (unlimited). This
patch adds a CommandTimeout/SqlSent reset to NpgsqlCommand.GetCommandText, the
last NpgsqlCommand entry before we use the timeout value in ProcessBackendResponsesEnum. I have removed similar, existing resets in
GetCommandText callees. This is a bit of a hack; the right fix seemed to be to
push CommandTimeout through the call stack instead of through the mediator, but
that wasn't readily satisfying either. Thoughts? I've also added test cases.

Related discussion:
http://pgfoundry.org/forum/forum.php?thread_id=2514&forum_id=519

Thanks,
nm

Followup

Message
Date: 2010-04-08 15:33
Sender: Noah Misch

Francisco,

Thanks for retesting and applying the patch. I agree, the
way timeout handling has touched so many places shows the
need for a different strategy. I will put some more thought
into that.
Date: 2010-04-06 04:04
Sender: Francisco Figueiredo jr.


Hi, Noah!

Got it. Sorry for misunderstanding. I thought I had applied your patch, but I didn't. With your tests I could reproduce the problem and applied your patch correctly. At least, with all the other changes, I just had to add the relevant lines to GetCommandText.

Also, I'm noticing that this timeout issue is all spread in the code base. If you have suggestions to "clean" this up, they are very welcome.

We have to simplify that before it is too late.

Thanks again.
Date: 2010-04-05 03:09
Sender: Francisco Figueiredo jr.


Hi, Noah!

Didn't try it yet. I'm going to try it soon and will let you know.
Date: 2010-04-03 16:13
Sender: Noah Misch

Francisco, did you get a chance to try that instrumentation?
Date: 2010-03-22 01:38
Sender: Noah Misch

Hi Francisco,

Thank you for reviewing. I should have mentioned, the
second test does pass already; I just added it for
completeness. I'm not quite sure why we get different
results on the first test, though. I am attaching an
alternate patch, "debug-timeout.patch", that includes just
the test cases and some extra noise to show the timeouts
used for each query. Snip from the output in my setup:

Start timeout test 1
listening for response with timeout 15
Sending query: SET CLIENT_ENCODING TO UTF8 ... listening for
response with timeout 0
Sending query: set standard_conforming_strings=off ...
listening for response with timeout 20
Sending query: show escape_string_warning ... listening for
response with timeout 0
Sending query: SELECT ((E'foo')::text), pg_sleep(1.5) ...
listening for response with timeout 0
Sending query: unlisten * ... listening for response with
timeout 0
End timeout test 1

Here is the output after applying my proposed fix as well:

Start timeout test 1
listening for response with timeout 15
Sending query: SET CLIENT_ENCODING TO UTF8 ... listening for
response with timeout 0
Sending query: set standard_conforming_strings=off ...
listening for response with timeout 20
Sending query: show escape_string_warning ... listening for
response with timeout 0
Sending query: SELECT ((E'foo')::text), pg_sleep(1.5) ...
listening for response with timeout 1
listening for response with timeout 1
Caught exception (hopefully a timeout): Npgsql.NpgsqlException:
A timeout has occured. If you were establishing a
connection, increase Timeout value in ConnectionString. If
you were executing a command, increase the CommandTim\
eout value in ConnectionString or in your NpgsqlCommand object.
at
Npgsql.NpgsqlState.ProcessBackendResponsesEnum(NpgsqlConnector
context) in
c:\cygwin\home\noah.misch\src\npgsql\reprod\src\Npgsql\NpgsqlState.cs:line
383
at Npgsql.NpgsqlReadyState.QueryEnum(NpgsqlConnector
context, NpgsqlCommand command) in
c:\cygwin\home\noah.misch\src\npgsql\reprod\src\Npgsql\NpgsqlReadyState\
.cs:line 67
at Npgsql.NpgsqlConnector.QueryEnum(NpgsqlCommand
queryCommand) in
c:\cygwin\home\noah.misch\src\npgsql\reprod\src\Npgsql\NpgsqlConnector.cs:line
294
at Npgsql.NpgsqlCommand.GetReader(CommandBehavior cb) in
c:\cygwin\home\noah.misch\src\npgsql\reprod\src\Npgsql\NpgsqlCommand.cs:line
590
at Npgsql.NpgsqlCommand.ExecuteNonQuery() in
c:\cygwin\home\noah.misch\src\npgsql\reprod\src\Npgsql\NpgsqlCommand.cs:line
492
at NpgsqlTests.CommandTests.TimeoutFirstParameters() in
c:\cygwin\home\noah.misch\src\npgsql\reprod\testsuite\noninteractive\NUnit20\CommandTests.cs:line
3552
Sending query: unlisten * ... listening for response with
timeout 0
End timeout test 1

What output do you get?
Date: 2010-03-20 23:39
Sender: Francisco Figueiredo jr.


Hi!

I'm not being able to reproduce your problem.

As you noticed, I removed the command timeout reset the internal Npgsql command was doing.

I added your test cases and they all passed.

I set standard_conforming_strings = off too.

Attached Files:

Attachments:
npgsql-timeout-param.patch
debug-timeout.patch

Changes:

Field Old Value Date By
File Added462: debug-timeout.patch2010-03-22 01:39nmisch
File Added458: npgsql-timeout-param.patch2010-03-16 07:02nmisch
Powered By FusionForge