My favorites | Sign in
Logo
                
New issue | Search
for
| Advanced search | Search tips
Issue 58: Excessive pause (~42 sec) on initial launch of any gosu ruby script
1 person starred this issue and may be notified of changes. Back to list
Status:  Started
Owner:  julianraschke


Sign in to add a comment
 
Reported by grunscga, Feb 21, 2009
----
What steps will reproduce the problem?
NOTE - I have not tried to reproduce my steps, but this is how it happened the first time.

1. Installed gosu 0.7.11 months ago, experimented with some concepts, ran tutorial apps 
successfully.
2. Today, ran 'sudo gem update gosu', got 0.7.12.  Forgot to uninstall 0.7.11 first.
3. Attempted to run script that ran successfully in January.  ~101% processor usage, "ruby not 
responding", garbage** displayed in window.  kill -9 required to kill ruby process
4. Ran 'sudo gem uninstall gosu --version 0.7.11'.  Completed without errors.
5. Attempted to run script, same problem as step 3.
6. Attempted to run tutorial app.  Same problem as step 3.
7. Ran 'sudo gem uninstall gosu'.  Completed without errors.
11. Restarted computer (completed Quicktime & security updates)
12. Ran 'sudo gem install gosu'.  Got 0.7.12 version successfully.
13. Attempted to run tutorial app.  Same problem as step 3.  This time, sat and stared at beach 
ball while trying to decide what to do.  After 30 seconds or so, processor usage spiked to almost 
400% (all 4 processors maxed).  After approximately 42 seconds from app start, window redrew 
and app behavior returned to normal.  Game play proceeded at full speed, with ~5% processor 
usage (expected behavior).
14. This 42 second delay now happens every time I start a script that uses gosu.

----
What is the expected output? What do you see instead?
I expect the application to start at least as fast as gosu 0.7.11, which was essentially instantly for 
small scripts.

----
What operating system are you using?
Mac OS X 10.4.11 on Mac Pro quad 2.66 Xeon, 5GB RAM, stock GeForce 7300 GT
Dual displays
ruby --version:  "ruby 1.8.6 (2007-03-13 patchlevel 0) [i686-darwin8.11.1]"
gem list | grep gosu: "gosu (0.7.12)"

Also have VMWare 2.0.2 installed - probably irrelevant, but see below

----
Please provide any additional information below.

I'm not sure if this is a bug in gosu or a "my system is broken" problem.  However, gosu 0.7.11 
ran flawlessly on this system.  The current output of 'gem list' is 'gosu (0.7.12, 0.7.11)', however /usr/local/lib/ruby/gems/1.8/gems only contains gosu-0.7.12-universal-darwin.

** Re: VMWare.  Every time I tried to run any app before the restart at step 11, the window 
displayed a chunk of Windows Vista, which is what had been running in VMWare on that monitor.  
_Note that VMWare was NOT actually running at this point._  The window contained a garbled 
visual of what had been on the Windows screen at the same position of the window.  After the 
restart, the window simply displayed random garbage (first run), or the last frame displayed by 
the last gosu script run (second+ runs).  After uninstall and reinstall of gem, window displayed 
garbled Windows graphical data again (see attached screenshot).


snapped_while_unresponsive.jpg
318 KB Download
Comment 1 by grunscga, Feb 21, 2009
Sorry, ignore the "additional information" that says both versions 0.7.11 and 0.7.12 are installed.  By the time 
the screenshot was taken, only 0.7.12 was installed.
Comment 2 by julianraschke, Feb 26, 2009
Hmm, I remember that Ruby installations on Tiger sometimes were a bit quirky with both the standard Ruby 
and another one being installed. Did you change anything about your Ruby installations between 0.7.11 and 
0.7.12? In any case it would be helpful to know if the packaged Gosu from the Downloads page works, you 
can verify this i.e. by going into it's examples folder and running:
/usr/bin/ruby -r'../lib/gosu' Tutorial.rb
Status: Started
Comment 3 by grunscga, Feb 26, 2009
Same problem with the standalone package (in addition to some library issues).

I started by uninstalling the gem version of gosu.

Then I checked the local ruby install:

io:~ greg$ which ruby
/usr/local/bin/ruby
io:~ greg$ ruby --version
ruby 1.8.6 (2007-03-13 patchlevel 0) [i686-darwin8.11.1]
io:~ greg$ /usr/bin/ruby --version
ruby 1.8.2 (2004-12-25) [universal-darwin8.0]

Then, I downloaded the "gosu-mac-0.7.12.tar.gz" file (using Safari) and expanded with "gnutar zxf gosu-mac-0.7.12.tar.gz"

Tried to run examples/Tutorial.rb:

Started with copy & paste from your comment:

io:~/Documents/Downloads/gosu/examples greg$ /usr/bin/ruby -r'../lib/gosu' Tutorial.rb 
Tutorial.rb:8:in `require': No such file to load -- gosu (LoadError)
        from Tutorial.rb:8

Next, tried putting in the actual filename:

io:~/Documents/Downloads/gosu/examples greg$ /usr/bin/ruby -r'../lib/gosu.bundle' Tutorial.rb 
Tutorial.rb:8:in `require': No such file to load -- gosu (LoadError)
        from Tutorial.rb:8

Then, I got lazy and cheated:
io:~/Documents/Downloads/gosu/examples greg$ cp ../lib/gosu.bundle ./
io:~/Documents/Downloads/gosu/examples greg$ /usr/bin/ruby Tutorial.rb 

That found the library and executed the Tutorial.  However, I still got the 42-second pause while displaying the last image 
that had been previously displayed in a gosu window.
After the pause, the game worked perfectly.

Also note that /usr/local/bin/ruby also has the same pause effect as /usr/bin/ruby.
Comment 4 by julianraschke, Feb 27, 2009
Huh, weirdest bug I've seen in a LONG time :) Thanks for testing! Could run the following script too, that has 
some more printf() style debugging to narrow down which part of Gosu got slower: 
http://www.raschke.de/julian/temp/TutWithTimestamps.rb
After that, I'll go through the whole changelog between 0.7.11 and 0.7.12 to look for something that could 
cause that.
Owner: julianraschke
Comment 5 by grunscga, Feb 27, 2009
Well, I don't know if this is good or bad, but it's none of those.  :)  All the checkpoints you placed in the file run (nearly) 
instantly, as you'll see from the attached file 'timestamp.log'.  I modified the TutWithTimestamps.rb file (also attached) to log 
various actions, and from there you'll see that the first update() doesn't run until 43 seconds after initialize finishes.


TutWithTimestamps.rb
3.3 KB Download
timestamp.log
2.5 KB Download
Comment 6 by julianraschke, Mar 02, 2009
Phew. Just finished reading through the complete svn diff and still no idea what's causing such a constant 
delay. I uploaded a recent build of Ruby/Gosu here: http://www.raschke.de/julian/temp/gosu.bundle, in 
case it's some sort of obscure bug in the Ruby/Gosu wrapping (I've updated the version of SWIG I use for 
packaging since releasing 0.7.11).

As a last resort, I'd suggest filling the RubyGosu Deployment Template with the tutorial data: just copy over 
the Tutorial.rb file and the media folder to the Resources subfolder, and rename Tutorial.rb to Main.rb. You 
may also throw in the recent gosu.bundle. Then, you can create a CPU usage profile using Shark (from 
Xcode) if the delay is still there.
Comment 7 by grunscga, Mar 10, 2009
(Sorry about the delay--work's been crazy)

Downloaded the new bundle, still saw the pause.

Created the Mac OS X deployable app with the new bundle, still saw the pause.

I've never really used Shark before, so let me know if there is a custom report you want me to run.  I ran the default Time Profile - Everything, 
set to gather for 60 seconds, starting before the app is run and finishing after the game begins responding.

Unfortunately, the mshark file is ~8.7MB, so it doesn't seem to want to attach to this comment.  You can grab it (slowly) from:
http://io.tresghic.com/gosu/Time_Profile_Everything.mshark

I also grabbed another screenshot to show a new pattern that was displayed in the window while the game was blocked.  Mostly, it was bright, 
so it got my attention.  :)  http://io.tresghic.com/gosu/tutorial_app_during_lock.png

Do you know if anyone else has duplicated this behavior, or is it limited to my system?


Comment 8 by julianraschke, Mar 11, 2009
Got the mshark file, you can take it down again, thanks!

In the kernel process, there are two functions with unknown names, one using 43.3% of the time and the 
other one using 26.2%. And 69% of a minute are … 41.4 seconds :)

Both functions come from the library com.apple.driver.AppleIntelCPUPowerManagement, so I think I'll look 
for an Apple mailing list that will be able to help out with that.

You are the only one who reported this bug, but it might be that it happens on all Mac Pros with the same 
spec. And I think the gibberish on the hanging Gosu::Window is whatever was in that part of the video 
memory before Gosu started :)

I'll let you know when I get an explanation of the pause from somewhere!
Sign in to add a comment

Hosted by Google Code