Bug #61290 for Net-ZooKeeper: Net::ZooKeeper consumes 100% cpu on wait

Sun Sep 12 21:00:00 2010 shyamx [...] gmail.com - Ticket created

Subject:	Net::ZooKeeper consumes 100% cpu on wait
Date:	Sun, 12 Sep 2010 17:59:49 -0700
To:	bug-Net-ZooKeeper [...] rt.cpan.org
From:	Syam <shyamx [...] gmail.com>

Net::ZooKeeper consumes 100% cpu when "wait" is used. At my initial inspection, it seems to be related to implementation mistake in pthread_cond_timedwait. The following patch fixes the issue. Please review and let me know if it looks correct. To reproduce: #!/usr/bin/perl use strict; use warnings; use Net::ZooKeeper qw/:errors :node_flags :acls/; my $zk_node = "localhost:2181"; my $zkh = Net::ZooKeeper::->new($zk_node) or die "$!"; my $watch = $zkh->watch(); my @locks = $zkh->exists('/foo',watch=>$watch); $watch->wait(timeout=>'10000'); The above script takes 100% cpu. Proposed patch: [syam@outercross]~/zookeeper-3.3.1/src/contrib/zkperl% diff -u ZooKeeper.xs zookeeper-3.3.1/contrib/zkperl/ZooKeeper.xs --- ZooKeeper.xs 2010-09-12 17:49:02.000000000 -0700 +++ zookeeper-3.3.1/contrib/zkperl/ZooKeeper.xs 2010-05-07 10:15:32.000000000 -0700 @@ -2638,7 +2638,7 @@ gettimeofday(&curr_timeval, NULL); - wait_timespec.tv_sec = end_timeval.tv_sec; + wait_timespec.tv_sec = end_timeval.tv_sec - curr_timeval.tv_sec; wait_timespec.tv_nsec = (end_timeval.tv_usec - curr_timeval.tv_usec) * 1000; @@ -2652,9 +2652,8 @@ break; } - if (pthread_cond_timedwait(&watch->cond, &watch->mutex, - &wait_timespec) == ETIMEDOUT) - break; + pthread_cond_timedwait(&watch->cond, &watch->mutex, + &wait_timespec); } done = watch->done;

Fri Sep 24 12:38:23 2010 bugs [...] syam.in - Correspondence added

Subject:	Re: [rt.cpan.org #61290] AutoReply: Net::ZooKeeper consumes 100% cpu on wait
Date:	Fri, 24 Sep 2010 09:38:10 -0700
To:	bug-Net-ZooKeeper [...] rt.cpan.org
From:	Syam <bugs [...] syam.in>

On Sun, Sep 12, 2010 at 6:00 PM, Bugs in Net-ZooKeeper via RT < bug-Net-ZooKeeper@rt.cpan.org> wrote: Show quoted text

> > Greetings, > > This message has been automatically generated in response to the > creation of a trouble ticket regarding: > "Net::ZooKeeper consumes 100% cpu on wait", > a summary of which appears below. > > There is no need to reply to this message right now. Your ticket has been > assigned an ID of [rt.cpan.org #61290]. Your ticket is accessible > on the web at: > > https://rt.cpan.org/Ticket/Display.html?id=61290 > > Please include the string: > > [rt.cpan.org #61290] > > in the subject line of all future correspondence about this issue. To do > so, > you may reply to this message. > > Thank you, > bug-Net-ZooKeeper@rt.cpan.org > > ------------------------------------------------------------------------- > Net::ZooKeeper consumes 100% cpu when "wait" is used. At my > initial inspection, it seems to be related to implementation mistake > in pthread_cond_timedwait. The following patch fixes the issue. > > Please review and let me know if it looks correct. > > To reproduce: > > #!/usr/bin/perl > > use strict; > use warnings; > > use Net::ZooKeeper qw/:errors :node_flags :acls/; > my $zk_node = "localhost:2181"; > my $zkh = Net::ZooKeeper::->new($zk_node) or die "$!"; > my $watch = $zkh->watch(); > my @locks = $zkh->exists('/foo',watch=>$watch); > $watch->wait(timeout=>'10000'); > > The above script takes 100% cpu. > > > Proposed patch: > > [syam@outercross]~/zookeeper-3.3.1/src/contrib/zkperl% diff -u > ZooKeeper.xs > zookeeper-3.3.1/contrib/zkperl/ZooKeeper.xs > --- ZooKeeper.xs 2010-09-12 17:49:02.000000000 -0700 > +++ zookeeper-3.3.1/contrib/zkperl/ZooKeeper.xs 2010-05-07 > 10:15:32.000000000 -0700 > @@ -2638,7 +2638,7 @@ > > gettimeofday(&curr_timeval, NULL); > > - wait_timespec.tv_sec = end_timeval.tv_sec; > + wait_timespec.tv_sec = end_timeval.tv_sec - > curr_timeval.tv_sec; > wait_timespec.tv_nsec = > (end_timeval.tv_usec - curr_timeval.tv_usec) * 1000; > > @@ -2652,9 +2652,8 @@ > break; > } > > - if (pthread_cond_timedwait(&watch->cond, &watch->mutex, > - &wait_timespec) == ETIMEDOUT) > - break; > + pthread_cond_timedwait(&watch->cond, &watch->mutex, > + &wait_timespec); > } > > done = watch->done; > >

Fri Sep 24 12:38:24 2010 The RT System itself - Status changed from 'new' to 'open'

Mon Sep 30 17:42:34 2013 dburke [...] addictmud.org - Correspondence added

I still experience the 100% cpu usage with the previously suggested patch. After some work, I was able to fix it with the below patch. The problem being that pthread_cond_timedwait() takes an absolute time, instead of an interval, so it is looping hard-core for the wait time instead of sleeping. diff -Naur ./ZooKeeper.xs /opt/zookeeper/contrib/zkperl/ZooKeeper.xs --- ./ZooKeeper.xs 2012-09-30 13:53:29.000000000 -0400 +++ /opt/zookeeper/contrib/zkperl/ZooKeeper.xs 2013-09-27 16:44:49.104000150 -0400 @@ -2604,6 +2604,7 @@ unsigned int timeout; struct timeval end_timeval; int i, done; + struct timespec wait_timespec; PPCODE: watch = _zkw_get_handle_outer(aTHX_ zkwh, NULL); @@ -2630,27 +2631,25 @@ end_timeval.tv_sec += timeout / 1000; end_timeval.tv_usec += (timeout % 1000) * 1000; + wait_timespec.tv_sec = end_timeval.tv_sec; + wait_timespec.tv_nsec = end_timeval.tv_usec * 1000; + pthread_mutex_lock(&watch->mutex); while (!watch->done) { struct timeval curr_timeval; - struct timespec wait_timespec; gettimeofday(&curr_timeval, NULL); - wait_timespec.tv_sec = end_timeval.tv_sec - curr_timeval.tv_sec; - wait_timespec.tv_nsec = - (end_timeval.tv_usec - curr_timeval.tv_usec) * 1000; - - if (wait_timespec.tv_nsec < 0) { - --wait_timespec.tv_sec; - wait_timespec.tv_nsec += 1000000000; - } - - if (wait_timespec.tv_sec < 0 || - (wait_timespec.tv_sec == 0 && wait_timespec.tv_nsec <= 0)) { - break; - } + if (end_timeval.tv_sec < curr_timeval.tv_sec) { + break; + } + + if (end_timeval.tv_sec == curr_timeval.tv_sec) { + if (end_timeval.tv_usec <= curr_timeval.tv_usec) { + break; + } + } pthread_cond_timedwait(&watch->cond, &watch->mutex, &wait_timespec);

Subject:

zkperl_zookeeper_xs.patch

diff -Naur ./ZooKeeper.xs /opt/zookeeper/contrib/zkperl/ZooKeeper.xs --- ./ZooKeeper.xs 2012-09-30 13:53:29.000000000 -0400 +++ /opt/zookeeper/contrib/zkperl/ZooKeeper.xs 2013-09-27 16:44:49.104000150 -0400 @@ -2604,6 +2604,7 @@ unsigned int timeout; struct timeval end_timeval; int i, done; + struct timespec wait_timespec; PPCODE: watch = _zkw_get_handle_outer(aTHX_ zkwh, NULL); @@ -2630,27 +2631,25 @@ end_timeval.tv_sec += timeout / 1000; end_timeval.tv_usec += (timeout % 1000) * 1000; + wait_timespec.tv_sec = end_timeval.tv_sec; + wait_timespec.tv_nsec = end_timeval.tv_usec * 1000; + pthread_mutex_lock(&watch->mutex); while (!watch->done) { struct timeval curr_timeval; - struct timespec wait_timespec; gettimeofday(&curr_timeval, NULL); - wait_timespec.tv_sec = end_timeval.tv_sec - curr_timeval.tv_sec; - wait_timespec.tv_nsec = - (end_timeval.tv_usec - curr_timeval.tv_usec) * 1000; - - if (wait_timespec.tv_nsec < 0) { - --wait_timespec.tv_sec; - wait_timespec.tv_nsec += 1000000000; - } - - if (wait_timespec.tv_sec < 0 || - (wait_timespec.tv_sec == 0 && wait_timespec.tv_nsec <= 0)) { - break; - } + if (end_timeval.tv_sec < curr_timeval.tv_sec) { + break; + } + + if (end_timeval.tv_sec == curr_timeval.tv_sec) { + if (end_timeval.tv_usec <= curr_timeval.tv_usec) { + break; + } + } pthread_cond_timedwait(&watch->cond, &watch->mutex, &wait_timespec);

Sat Oct 04 20:59:26 2014 MAF [...] cpan.org - Correspondence added

Fixed in 0.36. See https://issues.apache.org/jira/browse/ZOOKEEPER-1062 for more details.

Sat Oct 04 20:59:28 2014 MAF [...] cpan.org - Status changed from 'open' to 'resolved'

Sat Oct 04 22:11:23 2014 MAF [...] cpan.org - Fixed in 0.36 added

Bug #61290 for Net-ZooKeeper: Net::ZooKeeper consumes 100% cpu on wait

Preferred bug tracker