Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > comp.lang.python > #73628 > unrolled thread

print statements and profiling a function slowed performance

Back to article view | Back to comp.lang.python

Contents

  print statements and profiling a function slowed performance CM <cmpython@gmail.com> - 2014-06-26 11:44 -0700
    Re: print statements and profiling a function slowed performance Michael Torrie <torriem@gmail.com> - 2014-06-26 13:14 -0600
      Re: print statements and profiling a function slowed performance CM <cmpython@gmail.com> - 2014-06-26 13:36 -0700
        Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-27 12:06 +1000
        Re: print statements and profiling a function slowed performance Michael Torrie <torriem@gmail.com> - 2014-06-26 19:59 -0600
        Re: print statements and profiling a function slowed performance Dennis Lee Bieber <wlfraed@ix.netcom.com> - 2014-06-28 09:41 -0400
        Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-28 23:50 +1000
        Re: print statements and profiling a function slowed performance Dennis Lee Bieber <wlfraed@ix.netcom.com> - 2014-06-29 02:14 -0400
        Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-29 17:14 +1000
    Re: print statements and profiling a function slowed performance Mark Lawrence <breamoreboy@yahoo.co.uk> - 2014-06-26 20:27 +0100
      Re: print statements and profiling a function slowed performance CM <cmpython@gmail.com> - 2014-06-26 13:37 -0700
        Re: print statements and profiling a function slowed performance Steven D'Aprano <steve+comp.lang.python@pearwood.info> - 2014-06-27 02:55 +0000
          Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-27 13:14 +1000
          Re: print statements and profiling a function slowed performance Mark Lawrence <breamoreboy@yahoo.co.uk> - 2014-06-27 16:55 +0100
          Re: print statements and profiling a function slowed performance Skip Montanaro <skip@pobox.com> - 2014-06-27 11:05 -0500
          Re: print statements and profiling a function slowed performance Ian Kelly <ian.g.kelly@gmail.com> - 2014-06-27 15:35 -0600
          Re: print statements and profiling a function slowed performance Skip Montanaro <skip@pobox.com> - 2014-06-27 19:12 -0500
          Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-28 10:29 +1000
            Re: print statements and profiling a function slowed performance Marko Rauhamaa <marko@pacujo.net> - 2014-06-28 22:20 +0300
              Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-29 09:30 +1000
              Re: print statements and profiling a function slowed performance Rustom Mody <rustompmody@gmail.com> - 2014-06-28 19:25 -0700
                Re: print statements and profiling a function slowed performance Chris Angelico <rosuav@gmail.com> - 2014-06-29 12:32 +1000
          Re: print statements and profiling a function slowed performance Mark Lawrence <breamoreboy@yahoo.co.uk> - 2014-06-28 02:06 +0100
    Re: print statements and profiling a function slowed performance Dennis Lee Bieber <wlfraed@ix.netcom.com> - 2014-06-26 22:11 -0400

Page 1 of 2  [1] 2  Next page →

#73628 — print statements and profiling a function slowed performance

Huh. I learned two new Python facts this week:

1. print statements were slowing down my code enough to
really notice a particular transition. It went from about
2-3 seconds to a bit under 1 second. What at first seemed
unresponsive now seems almost snappy. The only difference
was removing a lot of print statements I had used for
debugging (Python 2.5, on a single core 1.97 Ghz machine).

2. Merely having a cPython decorator for profiling a 
function significantly slowed down performance...again,
from a about 2 seconds to just under a second (~1 second
doesn't seem much but these sorts of delays do affect 
user experience).  There is something ironic or 
Heisenbergian about that.

[toc] | [next] | [standalone]

#73632

On 06/26/2014 12:44 PM, CM wrote:
> Huh. I learned two new Python facts this week:
> 
> 1. print statements were slowing down my code enough to
> really notice a particular transition. It went from about
> 2-3 seconds to a bit under 1 second. What at first seemed
> unresponsive now seems almost snappy. The only difference
> was removing a lot of print statements I had used for
> debugging (Python 2.5, on a single core 1.97 Ghz machine).

Yes print statements are very useful, but you have to be careful with
them.  In Uni I remember working on a project where we coded up an
algorithm, and then attempted to work out by timing the O() runtime of
the algorithm.  Wanting to be fancy and print out a progress report, I
added an entire term to the O() runtime!  Instead of O(log n), it became
closer to O(n).  Oops!

Seems like over the years good old fashioned debugging skills have been
lost.  In the earliest days of IDEs (Turbo BASIC and QuickBASIC) I
regularly would employ debuggers with break points, watches, and step
through my code.  Nowadays it seems we loath to fire up the debugger.  I
imagine the currently available debugger frontends like ddd or kdbg
support pdb.  Not sure though.

> 2. Merely having a cPython decorator for profiling a 
> function significantly slowed down performance...again,
> from a about 2 seconds to just under a second (~1 second
> doesn't seem much but these sorts of delays do affect 
> user experience).  There is something ironic or 
> Heisenbergian about that.

Yes, it stands to reason that profiling code is going to introduce a
runtime cost.  How else would we expect profiling to work?  That's why a
production "release" is done with debugging and profiling stuff removed.
 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.

[toc] | [prev] | [next] | [standalone]

#73636

> Seems like over the years good old fashioned 
> debugging skills have been lost.  In the earliest 
> days of IDEs (Turbo BASIC and QuickBASIC) I 
> regularly would employ debuggers with break 
> points, watches, and step through my code.  

I do also use a debugger, but lazily use print 
statements, too.  When I use the debugger (in
my case, in the IDE I use, Boa Constructor), I
do use break points and step through my code, 
but I have never used watches.  How do you use
them?

> 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
 
>  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!

[toc] | [prev] | [next] | [standalone]

#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

[toc] | [prev] | [next] | [standalone]

#73645

On 06/26/2014 02:36 PM, CM wrote:
>>  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!

If you never work with threads then you probably won't encounter this issue.

[toc] | [prev] | [next] | [standalone]

#73704

On Fri, 27 Jun 2014 12:06:54 +1000, Chris Angelico <rosuav@gmail.com>
declaimed the following:

>
>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

	I take it those are subjective feelings of time...


C:\Users\Wulfraed\Documents>script1.py
Executed in: 0.0352086402164
Executed in: 57.0624450629

C:\Users\Wulfraed\Documents>type script1.py
import sys
import time

#   Python 2.7, Windows 7-64, Core i7-3770 3.4GHz, 12GB

x = range(1000000)

start = time.clock()
for i in x:
    pass
took = time.clock() - start
print "Executed in: %s" % (took)

start = time.clock()
for i in x:
    sys.stdout.write("%s\r" % i)
took = time.clock() - start
print "Executed in: %s" % (took)
C:\Users\Wulfraed\Documents>


	35mSec vs 57Sec

-- 
	Wulfraed                 Dennis Lee Bieber         AF6VN
    wlfraed@ix.netcom.com    HTTP://wlfraed.home.netcom.com/

[toc] | [prev] | [next] | [standalone]

#73705

On Sat, Jun 28, 2014 at 11:41 PM, Dennis Lee Bieber
<wlfraed@ix.netcom.com> wrote:
> On Fri, 27 Jun 2014 12:06:54 +1000, Chris Angelico <rosuav@gmail.com>
> declaimed the following:
>
>>
>>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
>
>         I take it those are subjective feelings of time...

No, they were measured; but the exact difference will depend on Python
version, console, OS, etc, etc, etc, etc, etc, which is why I said
"maybe 100ms" - on one run it was about that (rounded aggressively to
make for convenient figures), but if I ran the test again, it might
come out at 50ms or 200ms. For what it's worth, I did the test on
Python 3.5(ish) on Linux; since you tested it on Python 2, a closer
comparison would be to use xrange rather than range, to avoid the RAM
overhead.

ChrisA

[toc] | [prev] | [next] | [standalone]

#73722

On Sat, 28 Jun 2014 23:50:26 +1000, Chris Angelico <rosuav@gmail.com>
declaimed the following:

>No, they were measured; but the exact difference will depend on Python
>version, console, OS, etc, etc, etc, etc, etc, which is why I said
>"maybe 100ms" - on one run it was about that (rounded aggressively to
>make for convenient figures), but if I ran the test again, it might
>come out at 50ms or 200ms. For what it's worth, I did the test on
>Python 3.5(ish) on Linux; since you tested it on Python 2, a closer
>comparison would be to use xrange rather than range, to avoid the RAM
>overhead.
>

	I chose range() in order to reuse the list (generated outside the
timing), rather than include the time of the iterator on both loops.

	Ran it three times and only had differences in the noise.

	The main incentive for my "subjective" comment is that I was getting a
do-nothing loop that was ~half the time you reported, while the print #
loop was ~twice your reported times.
-- 
	Wulfraed                 Dennis Lee Bieber         AF6VN
    wlfraed@ix.netcom.com    HTTP://wlfraed.home.netcom.com/

[toc] | [prev] | [next] | [standalone]

#73725

On Sun, Jun 29, 2014 at 4:14 PM, Dennis Lee Bieber
<wlfraed@ix.netcom.com> wrote:
> On Sat, 28 Jun 2014 23:50:26 +1000, Chris Angelico <rosuav@gmail.com>
> declaimed the following:
>
>>No, they were measured; but the exact difference will depend on Python
>>version, console, OS, etc, etc, etc, etc, etc, which is why I said
>>"maybe 100ms" - on one run it was about that (rounded aggressively to
>>make for convenient figures), but if I ran the test again, it might
>>come out at 50ms or 200ms. For what it's worth, I did the test on
>>Python 3.5(ish) on Linux; since you tested it on Python 2, a closer
>>comparison would be to use xrange rather than range, to avoid the RAM
>>overhead.
>>
>
>         I chose range() in order to reuse the list (generated outside the
> timing), rather than include the time of the iterator on both loops.
>
>         Ran it three times and only had differences in the noise.
>
>         The main incentive for my "subjective" comment is that I was getting a
> do-nothing loop that was ~half the time you reported, while the print #
> loop was ~twice your reported times.

My original point (printing to console can be quite slow) is supported
by your figures just as much as it is by mine; but the difference
between them is unsurprising, given the number of differences in the
test (list vs iterable range, Linux vs Windows, Py2 vs Py3). So, not
subjective, but still open to huge variation.

ChrisA

[toc] | [prev] | [next] | [standalone]

#73633

On 26/06/2014 19:44, CM wrote:
> Huh. I learned two new Python facts this week:
>
> 1. print statements were slowing down my code enough to
> really notice a particular transition. It went from about
> 2-3 seconds to a bit under 1 second. What at first seemed
> unresponsive now seems almost snappy. The only difference
> was removing a lot of print statements I had used for
> debugging (Python 2.5, on a single core 1.97 Ghz machine).
>
> 2. Merely having a cPython decorator for profiling a
> function significantly slowed down performance...again,
> from a about 2 seconds to just under a second (~1 second
> doesn't seem much but these sorts of delays do affect
> user experience).  There is something ironic or
> Heisenbergian about that.
>

3. use the logging module :)

-- 
My fellow Pythonistas, ask not what our language can do for you, ask 
what you can do for our language.

Mark Lawrence

---
This email is free from viruses and malware because avast! Antivirus protection is active.
http://www.avast.com

[toc] | [prev] | [next] | [standalone]

#73637

On Thursday, June 26, 2014 3:27:48 PM UTC-4, 
Mark Lawrence wrote:
 
> 3. use the logging module :)

I've just never got around to it, but I guess
I should.  Thanks for the nudge.

[toc] | [prev] | [next] | [standalone]

#73648

On Thu, 26 Jun 2014 13:37:41 -0700, CM wrote:

> On Thursday, June 26, 2014 3:27:48 PM UTC-4, Mark Lawrence wrote:
>  
>> 3. use the logging module :)
> 
> I've just never got around to it, but I guess I should.  Thanks for the
> nudge.

While using the logging module is recommended for logging, if you expect 
that logging will be faster than print, I expect you will be disappointed.



-- 
Steven

[toc] | [prev] | [next] | [standalone]

#73649

On Fri, Jun 27, 2014 at 12:55 PM, Steven D'Aprano
<steve+comp.lang.python@pearwood.info> wrote:
> On Thu, 26 Jun 2014 13:37:41 -0700, CM wrote:
>
>> On Thursday, June 26, 2014 3:27:48 PM UTC-4, Mark Lawrence wrote:
>>
>>> 3. use the logging module :)
>>
>> I've just never got around to it, but I guess I should.  Thanks for the
>> nudge.
>
> While using the logging module is recommended for logging, if you expect
> that logging will be faster than print, I expect you will be disappointed.

I would expect it to be faster than print in the case where it ends up
not printing, which means you can make one change to logging level and
very quickly eliminate all the output. I haven't measured, but I would
expect the overhead of the logging module itself to be small compared
to the cost of actual console output.

ChrisA

[toc] | [prev] | [next] | [standalone]

#73657

On 27/06/2014 03:55, Steven D'Aprano wrote:
> On Thu, 26 Jun 2014 13:37:41 -0700, CM wrote:
>
>> On Thursday, June 26, 2014 3:27:48 PM UTC-4, Mark Lawrence wrote:
>>
>>> 3. use the logging module :)
>>
>> I've just never got around to it, but I guess I should.  Thanks for the
>> nudge.
>
> While using the logging module is recommended for logging, if you expect
> that logging will be faster than print, I expect you will be disappointed.
>

Expectations don't count, measure it :)

-- 
My fellow Pythonistas, ask not what our language can do for you, ask 
what you can do for our language.

Mark Lawrence

---
This email is free from viruses and malware because avast! Antivirus protection is active.
http://www.avast.com

[toc] | [prev] | [next] | [standalone]

#73660

On Fri, Jun 27, 2014 at 10:55 AM, Mark Lawrence <breamoreboy@yahoo.co.uk> wrote:
> Expectations don't count, measure it :)

It's no contest. I have measured it (ages ago). The logging module
does so many things that it's impossible for it to ever be as fast as
a simple print statement. Look at the code in LogRecord.__init__. Then
note the doc string:

... LogRecord instances are created every time something is logged. ...

Skip

[toc] | [prev] | [next] | [standalone]

#73674

On Fri, Jun 27, 2014 at 10:05 AM, Skip Montanaro <skip@pobox.com> wrote:
> On Fri, Jun 27, 2014 at 10:55 AM, Mark Lawrence <breamoreboy@yahoo.co.uk> wrote:
>> Expectations don't count, measure it :)
>
> It's no contest. I have measured it (ages ago). The logging module
> does so many things that it's impossible for it to ever be as fast as
> a simple print statement. Look at the code in LogRecord.__init__. Then
> note the doc string:
>
> ... LogRecord instances are created every time something is logged. ...

While I'm not disputing your measurement, doesn't the logging module
delegate the actual I/O to a separate thread?  That's got to count for
something, compared to a raw print that has to wait for the I/O to
finish.

[toc] | [prev] | [next] | [standalone]

#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

[toc] | [prev] | [next] | [standalone]

#73682

On Sat, Jun 28, 2014 at 10:12 AM, Skip Montanaro <skip@pobox.com> wrote:
> threading-doesn't-always-speed-things-up-ly, y'rs,

Threading is a focus of so many myths. People who don't understand it
think that threads are magic pixie dust that fixes everything, or else
magic pixie dust that breaks everything. Or both, at the same time.
Neither notion is true.

ChrisA

[toc] | [prev] | [next] | [standalone]

#73714

Chris Angelico <rosuav@gmail.com>:

> Threading is a focus of so many myths. People who don't understand it
> think that threads are magic pixie dust that fixes everything, or else
> magic pixie dust that breaks everything. Or both, at the same time.
> Neither notion is true.

I'm in the latter camp.

More precisely: threads have their uses but they are used far too much
and not feared nearly enough.


Marko

[toc] | [prev] | [next] | [standalone]

#73717

On Sun, Jun 29, 2014 at 5:20 AM, Marko Rauhamaa <marko@pacujo.net> wrote:
> Chris Angelico <rosuav@gmail.com>:
>
>> Threading is a focus of so many myths. People who don't understand it
>> think that threads are magic pixie dust that fixes everything, or else
>> magic pixie dust that breaks everything. Or both, at the same time.
>> Neither notion is true.
>
> I'm in the latter camp.
>
> More precisely: threads have their uses but they are used far too much
> and not feared nearly enough.

And as I've explained several times in response to your other posts,
that's just as much a myth as the opposite extreme :) Fearing a
perfectly safe feature shackles you, which is better than falling
head-over-ears in love with something and using it everywhere, but
it's still limiting what you can do. Threads aren't that scary!

ChrisA

[toc] | [prev] | [next] | [standalone]

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | comp.lang.python

csiph-web