Path: csiph.com!v102.xanadu-bbs.net!xanadu-bbs.net!feeder.erje.net!eu.feeder.erje.net!newsfeed.datemas.de!rt.uk.eu.org!newsfeed.xs4all.nl!newsfeed3a.news.xs4all.nl!xs4all!newsgate.cistron.nl!newsgate.news.xs4all.nl!post.news.xs4all.nl!not-for-mail
MIME-Version: 1.0
In-Reply-To: <bd29ac07-f93d-4b59-8c5b-78e5ce8b6e4c@googlegroups.com>
References: <d5d8cea5-c4c9-42c4-865f-9efe33b162ed@googlegroups.com> <mailman.11265.1403810111.18130.python-list@python.org> <bd29ac07-f93d-4b59-8c5b-78e5ce8b6e4c@googlegroups.com>
Date: Fri, 27 Jun 2014 12:06:54 +1000
Subject: Re: print statements and profiling a function slowed performance
From: Chris Angelico <rosuav@gmail.com>
Cc: "python-list@python.org" <python-list@python.org>
Content-Type: text/plain; charset=UTF-8
Precedence: list
Newsgroups: comp.lang.python
Message-ID: <mailman.11273.1403834817.18130.python-list@python.org>
Lines: 58
NNTP-Posting-Host: 2001:888:2000:d::a6
Xref: csiph.com comp.lang.python:73643

On Fri, Jun 27, 2014 at 6:36 AM, CM <cmpython@gmail.com> wrote:
>> Yes, it stands to reason that profiling code
>> is going to introduce a runtime cost.  How else
>> would we expect profiling to work?
>
> I think I was hoping for magic. :D

Thank you for being honest :) The fact is, though, that time-of-day
and console output take a lot more time than many people seem to
realize; this is especially true if you print something repeatedly on
the same line, such as:

num = len(x)
for i,foo in enumerate(x):
    print(i/num,end="\r")
    # perform processing

If x is, say, range(1000000), a simple "for foo in x: pass" will
complete fairly quickly (maybe 100ms on my computer), while the
progress-indicated loop will take much longer (about 30 seconds when I
tried it). Obviously you'll be doing more work than just "pass", but
it's easy to completely dwarf the actual processing with the display
to the user. (And yes, this can happen in production code, too. We had
an old Windows 3 program that, for some reason, completed its
processing in less time if someone moved the mouse around than if it
sat idle. Its stupid animation - not even a progress indication, just
"hi, I'm still working here" - interacted badly with idle
sensitivity.)

>>  What I do find Heisenbergian are bugs that show
>> up when debugging and profiling stuff are removed,
>> but completely gone when present.  IE profiling and
>> debugging slow it down enough that often subtle race
>> conditions are masked.
>
> Would never have occurred to me.  That *is* odd!

Race conditions are by their nature subtle. I've seen all sorts of
crazy things change their behaviour... refactoring a function can
appear to introduce or eliminate a bug (because the call/return
sequence adds a small delay), and occasionally, even a completely
benign change can influence something - renaming a file on the disk
can cause a cache miss and make the program work perfectly (or fail to
work) the one next time it's run. Yeah, that can be fun.

(Though not as much fun as debugging a refcount error, where a program
will crash if certain things are done *and then certain others*. The
actually-faulty code just plants a land mine [1], and until you tread
on it, nothing goes wrong. Depending on how many other references
there are to that object, the freeing could happen at any time; and
even after it's freed, there might be no apparent problem, until the
memory gets reused somewhere. Now THAT is fun to debug. Pretty much
*any* change to the code can affect whether or not it crashes.)

ChrisA

[1] Like this guy.
http://media.wizards.com/images/magic/tcg/products/m15/sf0JdVsk2/EN_42um78zriv.png