From mboxrd@z Thu Jan 1 00:00:00 1970 X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on dcvr.yhbt.net X-Spam-Level: X-Spam-ASN: AS14383 205.234.109.0/24 X-Spam-Status: No, score=0.0 required=3.0 tests=none shortcircuit=no autolearn=unavailable version=3.3.2 Path: news.gmane.org!not-for-mail From: chris mckenzie Newsgroups: gmane.comp.lang.ruby.rainbows.general Subject: Re: Page request roundtrip time increases substantially after a bit of use Date: Mon, 24 Jan 2011 18:55:03 -0800 (PST) Message-ID: <288407.18061.qm@web63303.mail.re1.yahoo.com> References: <571697.98064.qm@web63303.mail.re1.yahoo.com> <20110124215440.GA25489@dcvr.yhbt.net> <20110125001107.GA1921@dcvr.yhbt.net> NNTP-Posting-Host: lo.gmane.org Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit X-Trace: dough.gmane.org 1295924524 23034 80.91.229.12 (25 Jan 2011 03:02:04 GMT) X-Complaints-To: usenet@dough.gmane.org NNTP-Posting-Date: Tue, 25 Jan 2011 03:02:04 +0000 (UTC) To: Rainbows! list Original-X-From: rainbows-talk-bounces-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org Tue Jan 25 04:01:59 2011 Return-path: Envelope-to: gclrrg-rainbows-talk@m.gmane.org X-Original-To: rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org Delivered-To: rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1295924104; bh=/O68ZdJEUzWMIKnM0lJfm2asLHNf24YtoCtfO6nd9wc=; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=4EByTlqJE/+ju5TA4Ee6Hg7b7KAL84oavGf2RuqgAe6DZxBA20yLwO1PAXK2++ZXIgZlkQfEHPjHQJfpZFLwMcRPf0trlBMcUjVzKOBjvu/OOJTPLxnWckz+ukdYjEWmQCNYsToxum3ul0ETHMDkfcMcoZlwG+pn16IMeJgbvWY= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=XKQgbPH53Dmbfe9wGQuUobqb6JaiUoA/KbBElVHCp7xoIcpfDHygeizC4ylz0wbBIDTjxMgw30qBD1lCB89Tw5yyJZwtmrnoadIYTd7cNAg8vAsK96Y+/SOaDNohkS+VSMb1VI/Lbl1unk3aydnQIpcj9YnADM8l9O8PdmZBWWQ=; X-YMail-OSG: 0tU3MiIVM1nKASU1vs6hoiehxO.PLXJp.dHRa6x31zTAx.R V5xifpNe_MPUWAxZSM7Yp97estMYbr66UyYCHEiB.bpUlejxBuuET_f2Z5yq tG6nngK6f1Uz2ImtietQZHuSg0q5T95dTP1zvXoD75dKx9_ChxXosAMDzI0S LET4SGklxxcGNHP_KYCvPVpQ2JhtjhEBzo0sW5aT1mWrz540LUS29AzVR1t2 hf6H7shar0RB1MS6k69LtAcERppgOGKReQ5XLbkJ5xX85wuJtYyQAMp1_0dy 1ItOEvdO701W5LIi94TqaAoSBdg-- X-Mailer: YahooMailRC/555 YahooMailWebService/0.8.107.285259 In-Reply-To: <20110125001107.GA1921-yBiyF41qdooeIZ0/mPfg9Q@public.gmane.org> X-BeenThere: rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Original-Sender: rainbows-talk-bounces-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org Errors-To: rainbows-talk-bounces-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org Xref: news.gmane.org gmane.comp.lang.ruby.rainbows.general:200 Archived-At: Received: from rubyforge.org ([205.234.109.19]) by lo.gmane.org with esmtp (Exim 4.69) (envelope-from ) id 1PhZAK-0001Lo-Qb for gclrrg-rainbows-talk@m.gmane.org; Tue, 25 Jan 2011 04:01:57 +0100 Received: from rubyforge.org (rubyforge.org [127.0.0.1]) by rubyforge.org (Postfix) with ESMTP id 053EA18583AE; Mon, 24 Jan 2011 22:01:53 -0500 (EST) Received: from web63303.mail.re1.yahoo.com (web63303.mail.re1.yahoo.com [69.147.97.28]) by rubyforge.org (Postfix) with SMTP id 99B1418583AE for ; Mon, 24 Jan 2011 21:55:04 -0500 (EST) Received: (qmail 18281 invoked by uid 60001); 25 Jan 2011 02:55:04 -0000 Received: from [173.243.145.79] by web63303.mail.re1.yahoo.com via HTTP; Mon, 24 Jan 2011 18:55:03 PST chris mckenzie wrote: > Hi Eric, > > I'll prepare a more formal response in a bit, but here is my test run: > rainbows -c config.rb rackup.ru >Thanks, I'm trying to reproduce it now. Are you able to reproduce it >more quickly by throwing some ab or httperf runs in the mix to make more >requests? Reducing worker_processes usually help reproduce issues more >quickly, too, especially if it's a resource leak. It's a finicky bug. That data below was perfect; exactly what I was experiencing; but now it refuses to show its face again. Just to be sure; it's the plateau that concerns me,not the occasional GC spikes ... not even those few huge ones. Another interesting note is that when I use the full stack that I have, the bitrate throughput goes to the tube too. It may be a problem with chunked transfer? I don't know really; probably ethtool and wireshark would tell us. Here's the basic pattern though... My application load pulls down < 100k JS. Usually it's about 60ms or so. When the plateau hits, curl reports that the throughput goes from 10.9M/s to 32K/s ... however, this could be an unrelated problem. If it's not, however, and If this problem was scarce resource acquisition entirely, then I would probably think that a 10 byte file and an 80k file would take about the same time ... say 2 seconds + however long it took to transfer. > Also, do you have any iptables/firewall/QoS settings on that machine > that could be interfering? No. This is a vanilla install. It's a desktop linux system and so it has X and firefox and a few terminals; some minimal window manager; nothing extraordinary; htop reveals 9GB ram free, although I just noticed that ruby is taking up double digit cpu per core; perhaps it's just the nature of ruby but I'll see what I can do about graphing that during a lifecycle. > I haven't noticed anything in CLOSE_WAIT since I started testing it a > few minutes ago. Maybe it takes longer, but CLOSE_WAIT has always been > a rarity to see in my years of working with TCP client/servers... We are looking at "TIME_WAIT" for a lot of them ... but after the browser is down and the thread has been idling for 10 minutes ... it falls into "CLOSE_WAIT" until I bring it down and back up. > The (CSV) output of the test can be seen here: > http://qaa.ath.cx/single-request.csv.gz > Just covering all my bases here, you don't have a super slow > disk/filesystem that bogs down your entire system once your logs grow to > a certain size, right? I *thought* about this ... truly. I haven't factored it out to be honest but no, the await from iostat is good, the machine itself is still responsive to my cp and mv commands for the data during the tests and there is no noticable slowdown of anything else. It's a two way quad core xeon with 12GB of memory (t7500) so I don't think that the physical hardware is to blame (although it could be memory related; who knows!) > For those of you without any visualization software, I made a rudimentary graph > > > from the data here: > > http://qaa.ath.cx/single-request.png > > You can clearly see how the delay increases and then doesn't ever go back down > to previous levels. > Very strange. > I'm testing on my 32-bit machine with ruby 1.8.7 (2010-12-23 patchlevel > 330) [i686-linux] straight off of ruby-lang.org . I usually use > Rainbows! with 1.9.2-p136 and will try that if I can reproduce the bug > under 1.8.7, too. Let me upgrade my ruby to that today or early tomorrow ... I'm just using the one that ubuntu gives me after apt-get update/upgrade (which is patch 72). I probably can't go too custom as this has to be part of a deployable sdk; but it's worth a shot. Thanks again. ~chris. > I'll research answers to your previous questions now. Thanks for looking into > this! Alright, thanks! -- Eric Wong _______________________________________________ Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org http://rubyforge.org/mailman/listinfo/rainbows-talk Do not quote signatures (like this one) or top post when replying