Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Callbacks Hash in EventHandlerSubscription::Base gets longer randomly #52

Closed
grinser opened this Issue · 3 comments

2 participants

@grinser

I build a celluloid application running in JRuby utilizing the ZK gem with 5 pooled connections using mperham's connection_pool gem.
I'm using these connections within 5 celluloid actor threads that act as workers which process data.
Each worker uses 2 nested with_lock blocks with the same zookeeper connection from the above mentioned connection pool to lock its workload from being done simultaneously by another thread.
Everything seems to be working fine so far regarding my other zookeeper operations (task management) but I experienced one odd thing looking through the debug log that I wanted to share/discuss here:

Every now and then, I see the output of ZK::EventHandlerSubscription::Base like I attached below. I noticed that the @callbacks hash is growing with empty arrays over time after serving a few requests. This shouldn't be the case, right? Besides It should be okay to always use different lock names?

If you need more information, let me know. I could also try to nail this in a small sample application if requested.

#<ZK::EventHandlerSubscription::Base:0x1c122c7a @interests=#<Set: {:created, :deleted, :changed, :child}>,
@path="/_zklocking/task_lock:e7c74770-121b-11e2-8de4-82fc76d42e2c:mul_result_0/ex0000000003",
@mutex=#<ZK::Monitor:0x5cdcc3b8 @mon_count=0, @mon_mutex=#<Mutex:0x21b594a9>, @mon_owner=nil>,
@parent=#<ZK::EventHandler:0x329bbe66 @mutex=#<ZK::Monitor:0xef1347f @mon_count=0, @mon_mutex=#<Mutex:0x7dad8582>,
@mon_owner=nil>, @default_watcher_block=#<Proc:0xb185a44@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zk-1.7.2/lib/zk/event_handler.rb:250 (lambda)>,
@zk=#<ZK::Client::Threaded:5818 zk_session_id=0x13a4080816605ba ...>,
@callbacks={"state_3"=>[], :all_state_events=>[], "/_zklocking/task_lock:c6548120-121b-11e2-87cd-a5de314d1973:sum_result_0/ex0000000007"=>[],
 "state_-112"=>[ 
   #<ZK::EventHandlerSubscription::Base:0x1832f489 @interests=#<Set: {:created, :deleted, :changed, :child}>, @path="state_-112",
   @mutex=#<ZK::Monitor:0x51141ddf @mon_count=0, @mon_mutex=#<Mutex:0x7fb5450e>, @mon_owner=nil>,
   @parent=#<ZK::EventHandler:0x329bbe66 ...>,
   @callable=#<Proc:0x55c8dba2@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zk-1.7.2/lib/zk/node_deletion_watcher.rb:199 (lambda)>>],
   "state_1"=>[
     #<ZK::EventHandlerSubscription::Base:0x75cb94ad @interests=#<Set: {:created, :deleted, :changed, :child}>, @path="state_1",
     @mutex=#<ZK::Monitor:0x2c72c20d @mon_count=0, @mon_mutex=#<Mutex:0x2221fa47>, @mon_owner=nil>,
     @parent=#<ZK::EventHandler:0x329bbe66 ...>,
     @callable=#<Proc:0x64b65cd2@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zk-1.7.2/lib/zk/node_deletion_watcher.rb:199 (lambda)>>],
     "state_0"=>[ 
       #<ZK::EventHandlerSubscription::Base:0x8812a6 @interests=#<Set: {:created, :deleted, :changed, :child}>, @path="state_0",
       @mutex=#<ZK::Monitor:0x4b291058 @mon_count=0, @mon_mutex=#<Mutex:0x74f027f4>, @mon_owner=nil>, @parent=#<ZK::EventHandler:0x329bbe66 ...>,
       @callable=#<Proc:0x42cf4026@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zk-1.7.2/lib/zk/node_deletion_watcher.rb:199 (lambda)>>
     ], 
     :all_node_events=>[],
     "/_zklocking/task_lock:d225dd50-121b-11e2-9470-e74969dc6fb6:sum_result_0/ex0000000003"=>[],
     "/_zklocking/task_calculation_lock:calculation_task_3:user_1/ex0000000000"=>[],
     "/_zklocking/task_lock:dd5ca730-121b-11e2-9c91-1a29f145ecf1:mul_result_0/ex0000000005"=>[],
     "/_zklocking/task_lock:df2495f0-121b-11e2-9b18-221ea8a36fe9:mul_result_0/ex0000000002"=>[],
     "/_zklocking/task_lock:df643700-121b-11e2-92f2-37bbec17b37e:sum_result_0/ex0000000006"=>[],
     "/_zklocking/task_calculation_lock:calculation_task_2:user_1/ex0000000001"=>[],
     "/_zklocking/finish_lock:e148ae70-121b-11e2-999d-40dd7a593966/ex0000000000"=>[],
     "/_zklocking/task_lock:e7c74770-121b-11e2-8de4-82fc76d42e2c:mul_result_0/ex0000000003"=>[#<ZK::EventHandlerSubscription::Base:0x1c122c7a ...>]
  },
  @orig_pid=63595,
  @state=:running,
  @thread_opt=:single,
  @outstanding_watches={
    :data=>#<Set: {"/_zklocking/task_lock:dd5ca730-121b-11e2-9c91-1a29f145ecf1:mul_result_0/ex0000000005"}>,
     :child=>#<Set: {}>}
   >,
   @callable=#<Proc:0x6231b90d@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zk-1.7.2/lib/zk/node_deletion_watcher.rb:183 (lambda)>
> with [#<Zookeeper::Callbacks::WatcherCallback:0x5a4e3fa1 @context=nil, @path="/_zklocking/task_lock:e7c74770-121b-11e2-8de4-82fc76d42e2c:mul_result_0/ex0000000003", @state=3, @completed=true, @proc=#<Proc:0x47339158@/Users/grinser/.rvm/gems/jruby-1.6.8/gems/zookeeper-1.3.0-java/lib/zookeeper/callbacks.rb:24>, @type=2, @zk=#<ZK::Client::Threaded:5818 zk_session_id=0x13a4080816605ba ...>>]
@slyphon slyphon was assigned
@slyphon
Owner

Released a fix in gem 1.7.3.

Just a minor point, the callbacks hash doesn't get longer randomly, It gets longer deterministically :)

The keys are the path you registered for, the empty array held the callbacks for that path. The code that manages this hash is quite old, and well, I guess cleaning it up never got prioritized.

@slyphon
Owner

ok, gonna close this one out

@slyphon slyphon closed this
@grinser

Thanks for your swift reply and fix - Awesome support!
Works flawlessly for me now.

PS: Thanks for pointing out that the growth was not random ;-) It just looked random for me because I couldn't figure out the details :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.