Path: csiph.com!usenet.pasdenom.info!weretis.net!feeder4.news.weretis.net!rt.uk.eu.org!newsfeed.xs4all.nl!newsfeed1a.news.xs4all.nl!xs4all!newsgate.cistron.nl!newsgate.news.xs4all.nl!post.news.xs4all.nl!not-for-mail
Return-Path: <skip.montanaro@gmail.com>
X-Original-To: python-list@python.org
Delivered-To: python-list@mail.python.org
X-Spam-Status: OK 0.001
X-Spam-Evidence: '*H*': 1.00; '*S*': 0.00; 'python.': 0.02; '(at': 0.04; 'essentially': 0.04; 'base.': 0.05; 'activity.': 0.09; 'broke': 0.09; 'wrapped': 0.09; 'cc:addr:python-list': 0.11; 'wrote': 0.14; 'thread': 0.14; 'times,': 0.14; '4:35': 0.16; 'does,': 0.16; 'finish.': 0.16; 'from:addr:pobox.com': 0.16; 'from:addr:skip': 0.16; 'maintainer': 0.16; "module's": 0.16; 'python-based': 0.16; 'underlying': 0.16; 'written.': 0.16; 'followed': 0.16; 'sender:addr:gmail.com': 0.17; 'wrote:': 0.18; 'looked': 0.18; 'bit': 0.19; 'module': 0.19; 'basically': 0.19; 'cc:addr:python.org': 0.22; 'print': 0.22; 'bytes': 0.24; 'passes': 0.24; 'simpler': 0.24; 'skip': 0.24; "haven't": 0.24; 'cc:2**0': 0.24; 'handling': 0.26; 'logging': 0.26; 'least': 0.26; 'header:In-Reply-To:1': 0.27; 'on,': 0.29; 'compared': 0.30; 'moved': 0.30; 'message-id:@mail.gmail.com': 0.30; 'code': 0.31; 'stuff': 0.32; 'fri,': 0.33; 'programmers': 0.33; 'raw': 0.33; 'skip:t 40': 0.33; 'actual': 0.34; 'but': 0.35; 'received:google.com': 0.35; 'version': 0.36; 'c++': 0.36; 'disk': 0.36; 'responsible': 0.36; 'operating': 0.37; 'performance': 0.37; 'tired': 0.38; 'needed': 0.38; 'whatever': 0.38; 'pm,': 0.38; 'little': 0.38; 'does': 0.39; 'system.': 0.39; 'how': 0.40; 'eventually': 0.60; 'guy': 0.60; 'ian': 0.60; 'first': 0.61; 'back': 0.62; 'our': 0.64; 'became': 0.64; 'more': 0.64; 'finally': 0.65; 'to:addr:gmail.com': 0.65; 'sole': 0.78; 'awhile': 0.84; 'hit.': 0.84
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:sender:in-reply-to:references:date:message-id:subject :from:to:cc:content-type; bh=wBA5PVVVdNAEmXJiYSWYSDlilAyizQoaGzUIsyvCrZU=; b=SeEO6+st1URB7of8HwUa3ksw79UUc8hAJRrfU9VXuoNodhrWQ9CMQf2iaK2rrd+JJY tKdyjSuyFLm820tqw0epNU0TOmkZe9T/TkaA+W3SjeZcDxTZOuWesZjoDX8QByyXTCKX n7Gxc79yfat7Q6hGBkEf7WZhB8TwSpScGvWmNvwGtsYmQoMRoPOPRkxwKeBWwStQfFx+ WMX8A0SCOWoFZbIjT7IDhz8fyc26DBVWo6kk9GnQT1fjd7GNwj7LfT3NRPKzsWvI95s/ j67colOdNvxVBMUaGoCnmoGlZ+j37LcIlZzqeYFcSVzEa2Y+LrdPMuVrrEog+AIKtTrX BEfg==
MIME-Version: 1.0
X-Received: by 10.50.13.102 with SMTP id g6mr11685664igc.20.1403914364386; Fri, 27 Jun 2014 17:12:44 -0700 (PDT)
Sender: skip.montanaro@gmail.com
In-Reply-To: <CALwzidnkQyeQ5qBawFj=6DYBTySHc9VAcTSno7i5pNbH8KKHFQ@mail.gmail.com>
References: <d5d8cea5-c4c9-42c4-865f-9efe33b162ed@googlegroups.com> <mailman.11266.1403810884.18130.python-list@python.org> <d1dbc61a-ed09-4a10-b4d5-deb40cb54430@googlegroups.com> <53acdd24$0$29985$c3e8da3$5496439d@news.astraweb.com> <lok45f$45v$1@ger.gmane.org> <CANc-5UxS9O=yPphCGzr=cbX-_SLTKLq28FbxwC2FVwLPrbqXqw@mail.gmail.com> <CALwzidnkQyeQ5qBawFj=6DYBTySHc9VAcTSno7i5pNbH8KKHFQ@mail.gmail.com>
Date: Fri, 27 Jun 2014 19:12:44 -0500
X-Google-Sender-Auth: fiP8D7WpA2S5tfB9Xn0T8zlUK2M
Subject: Re: print statements and profiling a function slowed performance
From: Skip Montanaro <skip@pobox.com>
To: Ian Kelly <ian.g.kelly@gmail.com>
Content-Type: text/plain; charset=UTF-8
Cc: Python <python-list@python.org>
X-BeenThere: python-list@python.org
X-Mailman-Version: 2.1.15
Precedence: list
List-Id: General discussion list for the Python programming language <python-list.python.org>
List-Unsubscribe: <https://mail.python.org/mailman/options/python-list>, <mailto:python-list-request@python.org?subject=unsubscribe>
List-Archive: <http://mail.python.org/pipermail/python-list/>
List-Post: <mailto:python-list@python.org>
List-Help: <mailto:python-list-request@python.org?subject=help>
List-Subscribe: <https://mail.python.org/mailman/listinfo/python-list>, <mailto:python-list-request@python.org?subject=subscribe>
Newsgroups: comp.lang.python
Message-ID: <mailman.11297.1403914701.18130.python-list@python.org>
Lines: 29
NNTP-Posting-Host: 2001:888:2000:d::a6
X-Trace: 1403914701 news.xs4all.nl 2962 [2001:888:2000:d::a6]:39299
X-Complaints-To: abuse@xs4all.nl
Xref: csiph.com comp.lang.python:73681

On Fri, Jun 27, 2014 at 4:35 PM, Ian Kelly <ian.g.kelly@gmail.com> wrote:
> That's got to count for
> something, compared to a raw print that has to wait for the I/O to
> finish.

A raw print basically just tosses some bytes in a stdio buffer (at
least in Unix-land). Stdio does whatever little it does, then passes
the bytes off to the operating system. The underlying OS is then
responsible to see that the bytes get to disk or syslog, or wherever.
It's hard for me to see how that process would be any more time
consuming than the necessary thread switching, followed by what is
essentially the same activity. I haven't looked at the logging module
in awhile (I eventually just rolled my own much simpler version which
only supports what I need), but I don't think it used threads to
perform the actual I/O when it was first written.

Aside... The actual straw that broke the camel's back was that at
work...  One of our C++ programmers wrote a threaded logging module
(to speed up logging by handling it in a thread  - hmmm... sounds
familiar) then wrapped it for use in our Python-based platform. Time
passed, that guy moved on, and I became the sole maintainer of this
particular code base. Finally tired of our applications deadlocking at
inopportune times, I tossed out the threaded stuff and rewrote just
the small bit of the logging module's features I needed in Python. No
performance hit. No deadlocks.

threading-doesn't-always-speed-things-up-ly, y'rs,

Skip