Datamapper freezes gtk

[solnic]

I'm using datamapper for persistence in this (http://github.com/Bolthar/rubydraulica/tree/master) application. The starts up smoothly then, after a couple of minutes after Datamapper.setup is been called, the ui freezes and the process' cpu % goes up to 100% (or 50% in dual core systems, 25% on quad). That means that the widgets don't get updated anymore, if i try to resize the window it doesn't get repainted, i can't focus on anything, the only fix is to kill the process and start it over again.
This actually happens only under unix, i've tried the same configuration (ruby 1.8.6, ruby-gnome 0.16) under both windows XP and ubuntu linux 9.04 and under windows everything works fine.

---

Created by Andrea Dallera - 2009-07-10 18:54:03 UTC

Original Lighthouse ticket: http://datamapper.lighthouseapp.com/projects/20609/tickets/966

[solnic]

@Andrea: Have you tried running with any of the other DO drivers, like MySQL or PostgreSQL? I just wanted to try to isolate whether or not the issue is with DataMapper or with the database drivers.

For now I’m going to assign this to dbussink, in case it is a driver problem, but if it turns out to be the same across other DB drivers, and the problem is in DM, then please assign it back to me.

by Dan Kubb (dkubb)

[solnic]

@dan: i’ve tried both mysql and postgres right now, same issue. If you want help troubleshooting I’m more than happy to lend you my time, just tell me what would be useful to try.
I’ve been looking at the source too, but very briefly. If you can give me some pointers maybe I can help you out fixing this.
Thanx in advance!

by Andrea Dallera

[solnic]

What exact Ruby version are you running? (patch level included). Are you able to backtrace where exactly it gobbling up cpu cycles? Like a ctrl^c that for example shows which method it’s in?

If you have a small test case I could run to verify, that would be even better for debugging purposes.

by Dirkjan Bussink

[solnic]

I’m running ruby 1.8.6 patchlevel287. I’ve tried 1.8.6 and 1.8.7 p72 too, same issue.
Unfortunately that’s pretty much the problem: i can’t see where this come from. A test case would be just running the application (http://github.com/Bolthar/rubydraulica/tree/master) and doing nothing but wait. After a while, if you keep the system monitor open, you’ll see cpu% skyrocket for no apparent reason. Note that i’m not polling or doing any kind of background operation, it’s just the gtk loop running. Breaking the application just returns the mail gtk loop as the running method, as expected.
If i don’t start datamapper (DataMapper.setup) everything goes fine, that’s the only hint that i’ve got up to now.

by Andrea Dallera

[solnic]

I prepared this test case. It’s the simplest i could come up with

require ’libglade2’
require ’rubygems’
require ’dm-core’

class Main
include GetText

def initialize()
window = Gtk::Window.new
window.visible = true
window.show
end
end

class Document
include DataMapper::Resource

property :id, Integer, :serial => true

property :number, Integer, :nullable => false
property :date, Date, :nullable => false
property :description, String

end

Main.new
DataMapper.setup(:default, {:adapter => :sqlite3, :database => ’test.db’})
DataMapper.auto_upgrade!
Gtk.main

by Andrea Dallera

[solnic]

Just one other question, what DataMapper version are you running? Last gem release or the DM next branch?

by Dirkjan Bussink

[solnic]

I’m running the latest gem version (0.9.11)

by Andrea Dallera

[solnic]

@Drikjan: do you need me to run any other tests? I started today looking at the source, it would be really helpful if you could tell me:
a) is there a quick way to log when and where (which thread) a transaction is opened?
b) when the issues manifests itself i’m not doing any kind of activity on the GUI so datamapper must be doing something in background. I haven’t explored the code already so, before i start tracing like crazy it would be really really helpful to know if there are some places where background operations (polling on loaded entities?) happen

Thanks in advance and, as i said already, don’t hesitate to contact me if you need some other test cases.

by Andrea Dallera

[solnic]

Sorry, but I haven’t really been able to dive into this. Could you check whether this still happens if you install DO and DM from the next branch on github? DO does have something that runs in a thread, that’s a scavenger that closes idle connections if they have been in the pool for over one minute. Other than that there is no threading activity in DO / DM that I’m aware of.

by Dirkjan Bussink

[solnic]

I’ve installed DO and DM from source. There’s a little problem in DO’ s rakefiles: Dir[’tasks/*.rake’].each { |f| import f } doesn’t import gem.rake as the first file so GEM_SPEC is undefined for the other tasks, I brutally inserted import ’tasks/gem.rake’ before and it works. Now the problem is that dm-core needs do_sqlite3 (or do_mysql, or do_postgres) version 0.10 which i couldn’t find (Do they exist?). What can i do about that?

Did you run the snippet i posted before? If yes, does it behave as i told? Anyway i think the problem is connected to what you said, because i tried measuring the time it takes to crash and it’s always really close to 60 secs.

Also (if they’re actually broken, which i think is unlikely to be, maybe there’s something wrong about my machine) I’d be glad to fix the rakefiles (NOT with the hack i mentioned of course :-). If that’s the case, how can i send you a patch?

by Andrea Dallera

[solnic]

For DO you also need the do/next branch on github, that holds DO 0.10. I haven’t run the example myself but if it’s around 60 secs it could very well be related then.

by Dirkjan Bussink

[solnic]

Extlib::Polling has a scavenger with 60 secs interval, i thought the problem was there but after removing all threading from the module i still got the weird freeze after exactly 60 seconds. Anyway you can close this issue by me, i’m switching to AR.

by Andrea Dallera

[solnic]

I would recommend not closing this ticket if we can help it. It’s very likely that the DataObjects drivers will become the default database drivers for ActiveRecord at some point -- possibly sooner rather than later -- so this problem will continue to affect others if it is an actual bug in DO.

The only case I would recommend closing this ticket is if it was only reproducible by the submitter, and/or we don’t have enough information to continue on our own.

by Dan Kubb (dkubb)

[solnic]

What platform are you running this on (Linux (+distro), FreeBSD (+version) etc)? I’m currently seeing a "library routine called out of sequence (DataObjects::SQLError)" error on my Macbook when trying to run this. It looks like there is some concurrency issue here, I wonder whether your bug is another manifestation of the same concurrency issue.

by Dirkjan Bussink

[solnic]

I’ve encountered this issue running ubuntu 9.04 , ubuntu 8.10 and debian 5.0.2. As i said in the first post everything goes fine under windows XP.

by Andrea Dallera

[solnic]

With ruby-gnome2-0.16.0 and dm-core-0.9.11 (and older) I did not have this problem. Upgrading to ruby-gnome2-0.19.0 caused this problem to appear with both dm-core-0.9.11 and dm-core-0.10.0. This is on a gentoo ~x86 system (updated 2-3 times a week). My test app is similar to Andrea’s (http://gist.github.com/156815).

After reading this report I did confirm that my test app pegs one of the cores (quad core) at 100%, with the core changing about every minute.

$ cat /proc/version
Linux version 2.6.30-gentoo-r1 (root@royw-gentoo) (gcc version 4.3.3 (Gentoo 4.3.3-r2 p1.2, pie-10.1.5) ) #1 SMP Thu Jul 2 15:17:56 CDT 2009

Installed gtk+:

[I] x11-libs/gtk+
Installed versions: 1.2.10-r12(1)(07:10:35 PM 03/07/2009)(nls -debug -linguas_az -linguas_ca -linguas_cs -linguas_da -linguas_de -linguas_el -linguas_es -linguas_et -linguas_eu -linguas_fi -linguas_fr -linguas_ga -linguas_gl -linguas_hr -linguas_hu -linguas_it -linguas_ja -linguas_ko -linguas_lt -linguas_nl -linguas_nn -linguas_no -linguas_pl -linguas_pt -linguas_pt_BR -linguas_ro -linguas_ru -linguas_sk -linguas_sl -linguas_sr -linguas_sv -linguas_tr -linguas_uk -linguas_vi)
2.16.5(2)(04:09:25 AM 07/21/2009)(X cups doc jpeg jpeg2k tiff vim-syntax -debug -test -xinerama)

by Roy Wright

[solnic]

@roy: Can you also try this with the DataMapper In-Memory and/or the YAML adapters? If the problem persists, then it is something wrong in DataMapper, but if it goes away then we can be reasonably certain it is something in DataObjects.

by Dan Kubb (dkubb)

[solnic]

It took a little effort, but did get dm-c0re-0.9.11 to run the test code successfully using dm-yaml-adapter-0.7. Switching back to sqlite::memory still caused the test code to be unsuccessful.

dm-core-0.10.0 (from http://gems.datamapper.org) does not support auto_migrate! so could not get it to work with the test code using the yaml adapter (get a "undefined method `auto_migrate!’ for DataMapper:Module (NoMethodError)" error message).

Updated test code (using yaml adapter) at: http://gist.github.com/158985

by Roy Wright

[solnic]

I’m not seeing a hang on OS X, but I do get the following error message:

dm-core/lib/dm-core/adapters/data_objects_adapter.rb:167:in `execute_reader’: library routine called out of sequence (DataObjects::SQLError)

Could you try using do_mysql and / or do_postgres? They seem to not have this issue for me on OS X. It could be that the hang on Linux is a different result of the same issue that shows up for me on OS X.

I guess it’s related to sqlite3 not being thread safe and that that causes something to trip up somewhere.

by Dirkjan Bussink

[solnic]

Did a new install of postgresql-8.3 and using do_postgres-0.9.12 saw the same problem as with sqlite3 (for the record, do_sqlite3-0.9.12).

That’s implying it’s data_object dependent instead of adapter dependent.

I ran with the ruby -W flag and saved the log messages at http://gist.github.com/159170 (along with the diffs between the logs).

$ ruby --version
ruby 1.8.7 (2009-06-12 patchlevel 174) [i686-linux]

Complete toolchain info at: http://gist.github.com/159171

by Roy Wright

[solnic]

Could you try with using both DO’s next branch and DM’s next branch? You can clone them from github and switch to the branch and then install it as a gem.

I would like to confirm that upgrading to next still exposes the issue. I find it weird that it doesn’t show up on OS X though, so i probably need to try this in a virtual machine.

by Dirkjan Bussink

[solnic]

BTW, what exact sqlite3 version are you running?

by Dirkjan Bussink

[solnic]

I’ll give the next branches a try. I’m also trying to install a recent bug fix release to ruby-gnome2 (0.19.1). I’m running sqlite-3.6.16 compiled with doc, tcl, and threadsafe options, but not with debug or soundex options.

Thank you.

by Roy Wright

[solnic]

Got a response from Kou on the ruby-gnome2 mailing list:

It will relate to Thread.

You can find ’Person.auto_upgrade!’ creates a new
thread. (FYI: Thread.list)

Could someone look into the problem? I don’t have time to
look into the problem. :<
glib/src/rbglib_maincontext.c will help you.

by Roy Wright

[solnic]

I believe I’ve run into the same underlying problem as well, albeit from a different angle -- sinatra & rack. (Thanks to dbussink for referring me to this thread.)

I recently (re)wrote a ::Rack::Session::DataMapper module. When I was testing it, I noticed that every time I exited Sinatra (with ^C), it would "hang" waiting for a (mongrel) worker thread to release. The first worker thread, to be precise. When I disabled the module, it would exit fine. In Sinatra w/ Mongrel, each request spawns a new Thread, and since my Sinatra app didn’t do any DB accesses before my Rack module was invoked (beyond logging and adapter setup), DataMapper’s first real invocation was from within a short-lived Mongrel handler thread.

I haven’t looked at dm-core yet, but I theorize that the intializing thread (Thread.current) stores some shared objects that get used outside the Thread’s context, thus bumping their reference counts. That worker thread then delays exit until its objects are released; conceivably those objects are either referenced by the Main thread (which upon ^C is waiting for the worker Thread to exit), or by another worker Thread that already died (potentially suggesting a lost refcount decrement?). Either way, both threads end up waiting for the other to exit, thus the hang.

If I’m not far off the mark, the solution may be as simple as forcing any lazy initialization stuff to occur inside ::DataMapper.setup().

Gist with Rack plugin, small Sinatra app and related stuff: http://gist.github.com/164587

FWIW, this repros on Ruby 1.8.6 (OSX) & 1.8.7 (linux), Sinatra 0.9.2 && 0.10.1, dm-core 0.9.11 and dm-core.git (latest).

by Jordan Ritter

[solnic]

WRT my issue, looks like this is due to ::Extlib::Pooling.scavenger, which creates a new thread if it hasn’t been already. Since the hang only seems to happen to DO-derived adapters (:in_memory doesn’t seem to suffer), I simply added the scavenger call to DataObjectsAdapter#initialize - called through ::DataMapper.setup() - thereby eliminating the hang.

It’s not immediately obvious to me that this fixes the GTK issue, but it might.

1-liner fix: http://github.com/jpr5/dm-core/commit/3379acf9ad12a154eabb9fcd3148a09f6fbc1a55

by Jordan Ritter

[solnic]

Just tried the ::Extlib::Pooling.scavenger change on dm-core-0.9.11 and it did not resolve the gtk problem.

by Roy Wright

[solnic]

Is this still a problem, or is it safe to close this ticket? I see no activity or discussion for almost 9 or 10 months now.

by Dan Kubb (dkubb)

[solnic]

The issue’s been resolved, I think this is safe to close.

by Andrea Dallera

[solnic]

Someone reported that this ticket has not been resolved on IRC this afternoon:

CathalMagus
4:11 PM I think I’ve run into bug #966 again (http://datamapper.lighthouseapp.com/projects/20609/tickets/966-datamapper-freezes-gtk)
4:12 PM I ran across it using DataMapper 0.10.1 with Ruby/Gtk, and then upgraded to the 1.0.0.rc2 gems but have the same problem was causing my Gtk interface to become unresponsive as soon as I did any lookup with DataMapper (sqlite3). I also tried the dm-mysql-adapter. It can be triggered with the sample script from the #966 bug report.
4:14 PM I’m using: ruby 1.8.7 (2009-06-12 patchlevel 174) [x86_64-linux]
4:15 PM and I can look up the db via DataMapper fine via scripts which don’t interact with Gtk.

Hopefully this person will respond to this ticket so that more information can be gathered from them, and when this bug is resolved they can confirm it.

by Dan Kubb (dkubb)

[solnic]

It was I who mentioned this on IRC. I’m happy to run through various tests to help resolve this. Andrea didn’t mention which specific change "resolved" the issue for him. Perhaps the interaction on the libgnome2-ruby side has been fixed (I’m using 0.17.0~rc2 which is not the most up-to-date).

by CathalMagus

[solnic]

The issue was fixed on the ruby/gnome2 side, in version 0.19.2. If you update to a new version you won’t be experiencing the problem anymore.

On the side, the problem was caused by a lock here http://github.com/datamapper/extlib/blob/master/lib/extlib/pooling.rb so maybe it should be useful to check that for thread safety.

by Andrea Dallera

[solnic]

Thanks Andrea, I upgraded to ruby-gnome2 0.19.3 and the issue is indeed resolved there. (I can also confirm that it was still present in version 0.19.0, which my new distro came with).

by CathalMagus

[solnic]

While the freeze behaviour is fixed with ruby-gnome2 0.19.3, the rogue CPU usage seems to be a problem still. My ruby-gnome2 app, Palatina, loads data from DataMapper and then sits there displaying it in a list. I’m using adapter.select queries, no Resource objects are instantiated. After one minute the ruby process starts to consume 90-99% of CPU (on my Ubuntu-like system on x86_64). Another user of Palatina (running Ubuntu on i686) found "between 80 to 95% of CPU" consumed.

Anyone on a Debian-like system can install Palatina from my repository to test the issue.

Much easier, I’ve updated Andreas’ simplest script which shows the problem and attached it as simplest.rb - it demonstrates the problem at around 60 seconds.

by CathalMagus