the dreaded SQLError: Commands out of sync..

[Gary]

We upgraded to DM 1.1 a few weeks ago and since then have been
getting

#<DataObjects::SQLError: Commands out of sync; you can't run this
command now (code: 2014, sql state: HY000, query: ...)

more frequently. Worse, it seems to be unable to recover gracefully,
with subsequent DB calls failing in a similar manner.

The mechanism for failure seems to be from sustained high DB load,
which we will try to address by the standard tricks of memcaching,
enlarging the db instance, etc.

However it seems like a bug to me that all subsequent commands are in
error, like DO has forgotten that it still has a buffer remaining that
needs to be freed.

I'd appreciate any pointers on how to further spelunk this, as I
really haven't ventured over into the DO world yet.

Thanks,
Gary

[Dirkjan Bussink]

On 3 Nov 2009, at 19:08, Gary wrote:

> #<DataObjects::SQLError: Commands out of sync; you can't run this
> command now (code: 2014, sql state: HY000, query: ...)
>
> more frequently. Worse, it seems to be unable to recover gracefully,
> with subsequent DB calls failing in a similar manner.

What kind of application do you have where you get these errors? Is
this in a Merb, Sinatra or another app? Are you doing things
multithreaded or not?

And do you have a strack trace to see where it occurs? Whether it's
always when reading data, when writing, both or any other regularity
that you can find.

One idea that springs to mind is that perhaps forking could be an
issue. If a main process connects to the database and then the child
processes fork, they could be sharing a connection perhaps and run
queries on that out of sync.

--
Regards,

Dirkjan Bussink

[Jordan Ritter]

Ditto here: in the past I've forgotten to set Phusion Passenger's
framework "spawn method" to conservative, which -- based on when my
app initializes its DB connection -- yielded shared file descriptors
across processes, resulting in that sort of error you just saw.

cheers,
--jordan

[Gary]

We have a Merb app, but it's a bin/rake task that's running. No
forking within the rake task, but it is a few green threads running,
which should be sleeping more often than not. One thought is a green
thread might fail to yield politely. But that would be ok if it just
caused a single DB query to timeout and I could then recover.

We actually run two of the tasks at overlapping times on the same
machine in separate directories and separate environments, though
using the same DB uri.

A stack trace is:

         :exception: !ruby/exception:DataObjects::SQLError
           message: Commands out of sync; you can''t run this command
now
         :backtrace:
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/adapters/
data_objects_adapter.rb:88:in `execute_reader''
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/adapters/
data_objects_adapter.rb:88:in `read''
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/adapters/
data_objects_adapter.rb:266:in `with_connection''
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/adapters/
data_objects_adapter.rb:84:in `read''
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
repository.rb:141:in `read''        
/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
collection.rb:1001:in `lazy_load''
/mnt/indexer/framework/gems/gems/extlib-0.9.14/lib/extlib/
lazy_array.rb:451:in `map''

... in my app below

It then fails again on a write

/mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/adapters/
data_objects_adapter.rb:162:in `execute_non_query'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
adapters/data_objects_adapter.rb:162:in `execute'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
adapters/data_objects_adapter.rb:266:in `with_connection'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
adapters/data_objects_adapter.rb:160:in `execute'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
adapters/data_objects_adapter.rb:134:in `update'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
repository.rb:159:in `update'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
resource.rb:841:in `_update'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
resource.rb:631:in `hookable__update_hook_nan_before_advised'
- /mnt/indexer/framework/gems/gems/extlib-0.9.14/lib/extlib/
hook.rb:299:in `update_hook'
- /mnt/indexer/framework/gems/gems/extlib-0.9.14/lib/extlib/
hook.rb:297:in `catch'
- /mnt/indexer/framework/gems/gems/extlib-0.9.14/lib/extlib/
hook.rb:297:in `update_hook'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
resource.rb:554:in `save_self'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations.rb:55:in `save_self'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
resource.rb:343:in `save'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations.rb:48:in `save'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations/support/context.rb:29:in `validation_context'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations.rb:48:in `save'
- /mnt/indexer/framework/gems/gems/dm-core-0.10.1/lib/dm-core/
resource.rb:316:in `update'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations.rb:61:in `update'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations/support/context.rb:29:in `validation_context'
- /mnt/indexer/framework/gems/gems/dm-validations-0.10.1/lib/dm-
validations.rb:61:in `update'
... in my app below

Thanks,
Gary

[Dirkjan Bussink]

On 3 Nov 2009, at 19:58, Gary wrote:

> We have a Merb app, but it's a bin/rake task that's running. No
> forking within the rake task, but it is a few green threads running,
> which should be sleeping more often than not. One thought is a green
> thread might fail to yield politely. But that would be ok if it just
> caused a single DB query to timeout and I could then recover.

Merb actually also forks for rake tasks, depending on the
configuration. Could you please check whether it really doesn't do this?

Another issue could pop up if you have multiple green threads that use
the same DO connection, so that could also be an issue.

--
Regards,

Dirkjan

[Gary]

After some more experimentation, I noticed that having Merb.logger on
debug with several threads dumping to it simultaneously added extra
stresses. Switching off debug mode seems to have reduced the
likelihood of the sql errors.
I am still not sure if merb is forking or not for rake, but I should
only be doing db ops in the child, if that's the case.