More on logger hang-ups

More on logger hang-ups

Post by Matthew Bl » Wed, 07 Apr 2010 07:16:14


Here's what I see in my program, two threads stuck on writing to the
same logger:

--> #0 MonitorMixin.mon_acquire(queue#Array)
at line /usr/lib/ruby/1.8/monitor.rb:286
#1 MonitorMixin.mon_enter at line /usr/lib/ruby/1.8/monitor.rb:214
#2 MonitorMixin.synchronize at line /usr/lib/ruby/1.8/monitor.rb:240
#3 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#4 Logger.initialize(severity#Fixnum, message#String,
progname#NilClass)
at line /usr/lib/ruby/1.8/logger.rb:327
#5 Logger.debug(progname#String) at
line /usr/lib/ruby/1.8/logger.rb:348
#6 Mauve::Alert.inspect(update#Mauve::Proto::AlertUp...)
at line /usr/lib/mauvealert/lib/mauve/alert.rb:322


--> #0 De *** .interrupt_last
at
line /usr/lib/ruby/gems/1.8/gems/ruby-debug-base-0.10.3/lib/ruby-debug-base.rb:89
#1 at
line /usr/lib/ruby/gems/1.8/gems/ruby-debug-0.10.3/bin/rdebug:351
#2 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#3 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#4 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#5 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#6 Logger.initialize(severity#Fixnum, message#String,
progname#NilClass)
at line /usr/lib/ruby/1.8/logger.rb:327
#7 Logger.debug(progname#String) at
line /usr/lib/ruby/1.8/logger.rb:348
#8 DataMapper::Adapters::DataObjectsAdapter.execute_reader
at
line /usr/lib/mauvealert/external/dm-core-0.10.2/lib/dm-core/adapters/data_objects_adapter.rb:140
....

Restarting the program from within rdebug, and re-interrupting leaves
these backtraces at the same point.

The most likely explanation is that the logger's output device (@dev) is
blocking for *minutes* at a time, but I've no idea why that might be
when it's just a file.

Will dive in and add some instrumentation / timeouts around that write
statement to see if I can work out why it is behaving that way.

--
Matthew
 
 
 

More on logger hang-ups

Post by Brian Cand » Wed, 07 Apr 2010 21:33:55


(1) Note line #4 calling MonitorMixin.write - this seems to imply that
@dev *is* a MonitorMixin??

(2) It looks like LogDevice.write is calling itself re-entrantly here?

Is it possible that you've called Logger.new() with an existing Logger
instance as an argument?

(3) Why is Logger.initialize in the backtrace? The source line number
suggests Logger#add (which makes a lot more sense). But if you are
really calling Logger.new() lots of times, that sounds like a problem. I
would have expected that you'd create a single global Logger instance at
the start of the app, and then pass this around everywhere.

Regards,

Brian.
--
Posted via http://www.yqcomputer.com/

 
 
 

More on logger hang-ups

Post by Matthew Bl » Thu, 08 Apr 2010 04:53:49


Hmm, yes it wasn't a file, it was another Logger::LogDevice - now
changed to a File...


Yup, by mistake, but not the same LogDevice (separate locks).


That is a bit of a mystery, no I've only created one Logger and there's
no Logger#new around.

That suggests the backtrace is wrong / elided somewhere. I'm now
waiting for it to happen again after removing the LogDevice confusion.

--
Matthew